lists.openwall.net   lists  /  announce  owl-users  owl-dev  john-users  john-dev  passwdqc-users  yescrypt  popa3d-users  /  oss-security  kernel-hardening  musl  sabotage  tlsify  passwords  /  crypt-dev  xvendor  /  Bugtraq  Full-Disclosure  linux-kernel  linux-netdev  linux-ext4  linux-hardening  linux-cve-announce  PHC 
Open Source and information security mailing list archives
 
Hash Suite: Windows password security audit tool. GUI, reports in PDF.
[<prev] [next>] [<thread-prev] [thread-next>] [day] [month] [year] [list]
Message-ID: <20200326091256.GR11705@shao2-debian>
Date:   Thu, 26 Mar 2020 17:12:56 +0800
From:   kernel test robot <rong.a.chen@...el.com>
To:     Steven Rostedt <rostedt@...dmis.org>
Cc:     linux-kernel@...r.kernel.org, Ingo Molnar <mingo@...nel.org>,
        Andrew Morton <akpm@...ux-foundation.org>,
        Peter Zijlstra <peterz@...radead.org>,
        Masami Hiramatsu <mhiramat@...nel.org>,
        Alexei Starovoitov <alexei.starovoitov@...il.com>,
        Peter Wu <peter@...ensteyn.nl>,
        Jonathan Corbet <corbet@....net>,
        Tom Zanussi <zanussi@...nel.org>,
        Shuah Khan <shuahkhan@...il.com>, bpf <bpf@...r.kernel.org>,
        lkp@...ts.01.org
Subject: [tracing] cd8f62b481:
 BUG:sleeping_function_called_from_invalid_context_at_mm/slab.h

FYI, we noticed the following commit (built with gcc-7):

commit: cd8f62b481530fafbeacee0d3283b60bcf42d854 ("[PATCH 02/12 v2] tracing: Save off entry when peeking at next entry")
url: https://github.com/0day-ci/linux/commits/Steven-Rostedt/ring-buffer-tracing-Remove-disabling-of-ring-buffer-while-reading-trace-file/20200320-073240


in testcase: rcuperf
with following parameters:

	runtime: 300s
	perf_type: rcu



on test machine: qemu-system-i386 -enable-kvm -cpu SandyBridge -smp 2 -m 8G

caused below changes (please refer to attached dmesg/kmsg for entire log/backtrace):


+----------------------------------------------------------------+------------+------------+
|                                                                | 2e2bf17ca0 | cd8f62b481 |
+----------------------------------------------------------------+------------+------------+
| boot_successes                                                 | 13         | 0          |
| boot_failures                                                  | 0          | 8          |
| BUG:sleeping_function_called_from_invalid_context_at_mm/slab.h | 0          | 8          |
+----------------------------------------------------------------+------------+------------+


If you fix the issue, kindly add following tag
Reported-by: kernel test robot <rong.a.chen@...el.com>


[   16.821280] BUG: sleeping function called from invalid context at mm/slab.h:565
[   16.822211] in_atomic(): 0, irqs_disabled(): 1, non_block: 0, pid: 158, name: rcu_perf_writer
[   16.823164] no locks held by rcu_perf_writer/158.
[   16.823650] CPU: 0 PID: 158 Comm: rcu_perf_writer Not tainted 5.6.0-rc6-00081-gcd8f62b481530f #1
[   16.824856] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.12.0-1 04/01/2014
[   16.826220] Call Trace:
[   16.826667]  dump_stack+0x16/0x18
[   16.827265]  ___might_sleep+0x104/0x118
[   16.827947]  __might_sleep+0x69/0x70
[   16.828600]  ? __fs_reclaim_release+0x17/0x19
[   16.829374]  slab_pre_alloc_hook+0x34/0x6e
[   16.830107]  __kmalloc+0x48/0xe8
[   16.830710]  ? rb_reader_unlock+0x2b/0x3c
[   16.831205]  ? trace_find_next_entry+0x84/0x133
[   16.831723]  trace_find_next_entry+0x84/0x133
[   16.832217]  trace_print_lat_context+0x4b/0x437
[   16.832730]  ? rb_event_length+0x56/0x67
[   16.833186]  ? ring_buffer_event_length+0x34/0x79
[   16.833728]  ? __find_next_entry+0xd3/0x1c2
[   16.834190]  print_trace_line+0x69d/0x767
[   16.834666]  ftrace_dump+0x285/0x437
[   16.835055]  rcu_perf_writer+0x25f/0x34e
[   16.835476]  kthread+0xdf/0xe1
[   16.835823]  ? rcu_perf_reader+0x9c/0x9c
[   16.836264]  ? kthread_create_worker_on_cpu+0x1c/0x1c
[   16.836834]  ret_from_fork+0x2e/0x38
[   16.837270] rb_produ-160     0.... 6528532us : ring_buffer_producer: Starting ring buffer hammer
[   16.838318] rb_produ-160     0.... 16529141us : ring_buffer_producer: End ring buffer hammer
[   16.839349] rb_produ-160     0.... 16558157us : ring_buffer_producer: Running Consumer at nice: 19
[   16.840382] rb_produ-160     0.... 16558162us : ring_buffer_producer: Running Producer at nice: 19
[   16.841401] rb_produ-160     0.... 16558163us : ring_buffer_producer: WARNING!!! This test is running at lowest priority.
[   16.854781] rb_produ-160     0.... 16558164us : ring_buffer_producer: Time:     10000604 (usecs)
[   16.857354] rb_produ-160     0.... 16558165us : ring_buffer_producer: Overruns: 6117960
[   16.858322] rb_produ-160     0.... 16558166us : ring_buffer_producer: Read:     4356190  (by events)
[   16.859404] rb_produ-160     0.... 16558167us : ring_buffer_producer: Entries:  44650
[   16.860329] rb_produ-160     0.... 16558167us : ring_buffer_producer: Total:    10518800
[   16.861226] rb_produ-160     0.... 16558168us : ring_buffer_producer: Missed:   0
[   16.862124] rb_produ-160     0.... 16558169us : ring_buffer_producer: Hit:      10518800
[   16.863087] rb_produ-160     0.... 16558170us : ring_buffer_producer: Entries per millisec: 1051
[   16.864123] rb_produ-160     0.... 16558171us : ring_buffer_producer: 951 ns per entry
[   16.865074] rb_produ-160     0.... 16558172us : ring_buffer_producer_thread: Sleeping for 10 secs
[   16.866105] ---------------------------------
[   16.866725] rcu-perf: Test complete
[   16.878198] random: fast init done

Elapsed time: 60

qemu-img create -f qcow2 disk-vm-snb-i386-9-0 256G
qemu-img create -f qcow2 disk-vm-snb-i386-9-1 256G
qemu-img create -f qcow2 disk-vm-snb-i386-9-2 256G
qemu-img create -f qcow2 disk-vm-snb-i386-9-3 256G
qemu-img create -f qcow2 disk-vm-snb-i386-9-4 256G
qemu-img create -f qcow2 disk-vm-snb-i386-9-5 256G
qemu-img create -f qcow2 disk-vm-snb-i386-9-6 256G

kvm=(
	qemu-system-i386
	-enable-kvm
	-cpu SandyBridge
	-kernel $kernel
	-initrd initrd-vm-snb-i386-9.cgz
	-m 8192
	-smp 2
	-device e1000,netdev=net0
	-netdev user,id=net0,hostfwd=tcp::32032-:22
	-boot order=nc
	-no-reboot
	-watchdog i6300esb
	-watchdog-action debug
	-rtc base=localtime
	-drive file=disk-vm-snb-i386-9-0,media=disk,if=virtio
	-drive file=disk-vm-snb-i386-9-1,media=disk,if=virtio
	-drive file=disk-vm-snb-i386-9-2,media=disk,if=virtio
	-drive file=disk-vm-snb-i386-9-3,media=disk,if=virtio
	-drive file=disk-vm-snb-i386-9-4,media=disk,if=virtio
	-drive file=disk-vm-snb-i386-9-5,media=disk,if=virtio
	-drive file=disk-vm-snb-i386-9-6,media=disk,if=virtio
	-serial stdio
	-display none
	-monitor null
)

append=(
	ip=::::vm-snb-i386-9::dhcp
	root=/dev/ram0
	user=lkp
	job=/job-script
	ARCH=i386
	kconfig=i386-randconfig-g003-20200324
	branch=linux-devel/devel-hourly-2020032505
	commit=cd8f62b481530fafbeacee0d3283b60bcf42d854
	BOOT_IMAGE=/pkg/linux/i386-randconfig-g003-20200324/gcc-7/cd8f62b481530fafbeacee0d3283b60bcf42d854/vmlinuz-5.6.0-rc6-00081-gcd8f62b481530f
	max_uptime=1500
	RESULT_ROOT=/result/rcuperf/rcu-300s/vm-snb-i386/yocto-i386-minimal-20190520.cgz/i386-randconfig-g003-20200324/gcc-7/cd8f62b481530fafbeacee0d3283b60bcf42d854/3
	result_service=tmpfs
	selinux=0
	debug
	apic=debug
	sysrq_always_enabled
	rcupdate.rcu_cpu_stall_timeout=100
	net.ifnames=0


To reproduce:

        # build kernel
	cd linux
	cp config-5.6.0-rc6-00081-gcd8f62b481530f .config
	make HOSTCC=gcc-7 CC=gcc-7 ARCH=i386 olddefconfig prepare modules_prepare bzImage

        git clone https://github.com/intel/lkp-tests.git
        cd lkp-tests
        bin/lkp qemu -k <bzImage> job-script # job-script is attached in this email



Thanks,
Rong Chen


View attachment "config-5.6.0-rc6-00081-gcd8f62b481530f" of type "text/plain" (111786 bytes)

View attachment "job-script" of type "text/plain" (4468 bytes)

Download attachment "dmesg.xz" of type "application/x-xz" (11948 bytes)

Powered by blists - more mailing lists

Powered by Openwall GNU/*/Linux Powered by OpenVZ