From: Masami Hiramatsu <mhiramat@kernel.org>
To: kernel test robot <rong.a.chen@intel.com>
Cc: Steven Rostedt <rostedt@goodmis.org>,
linux-kernel@vger.kernel.org, Ingo Molnar <mingo@kernel.org>,
Andrew Morton <akpm@linux-foundation.org>,
Peter Zijlstra <peterz@infradead.org>,
Masami Hiramatsu <mhiramat@kernel.org>,
Alexei Starovoitov <alexei.starovoitov@gmail.com>,
Peter Wu <peter@lekensteyn.nl>, Jonathan Corbet <corbet@lwn.net>,
Tom Zanussi <zanussi@kernel.org>,
Shuah Khan <shuahkhan@gmail.com>, bpf <bpf@vger.kernel.org>,
lkp@lists.01.org
Subject: Re: [tracing] cd8f62b481: BUG:sleeping_function_called_from_invalid_context_at_mm/slab.h
Date: Wed, 1 Apr 2020 23:07:00 +0900 [thread overview]
Message-ID: <20200401230700.d9ddb42b3459dca98144b55c@kernel.org> (raw)
In-Reply-To: <20200326091256.GR11705@shao2-debian>
Hi Steve,
On Thu, 26 Mar 2020 17:12:56 +0800
kernel test robot <rong.a.chen@intel.com> wrote:
> 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
>
Hmm, this seems that we can not call kmalloc() in ftrace_dump().
Maybe we can fix it by
- Use GFP_ATOMIC.
or
- Do not use iter->temp if it is NULL. (it is safe since ftrace_dump() stops tracing)
What would you think?
Thank you,
>
> 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@intel.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
>
--
Masami Hiramatsu <mhiramat@kernel.org>
WARNING: multiple messages have this Message-ID (diff)
From: Masami Hiramatsu <mhiramat@kernel.org>
To: lkp@lists.01.org
Subject: Re: [tracing] cd8f62b481: BUG:sleeping_function_called_from_invalid_context_at_mm/slab.h
Date: Wed, 01 Apr 2020 23:07:00 +0900 [thread overview]
Message-ID: <20200401230700.d9ddb42b3459dca98144b55c@kernel.org> (raw)
In-Reply-To: <20200326091256.GR11705@shao2-debian>
[-- Attachment #1: Type: text/plain, Size: 7262 bytes --]
Hi Steve,
On Thu, 26 Mar 2020 17:12:56 +0800
kernel test robot <rong.a.chen@intel.com> wrote:
> 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
>
Hmm, this seems that we can not call kmalloc() in ftrace_dump().
Maybe we can fix it by
- Use GFP_ATOMIC.
or
- Do not use iter->temp if it is NULL. (it is safe since ftrace_dump() stops tracing)
What would you think?
Thank you,
>
> 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@intel.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
>
--
Masami Hiramatsu <mhiramat@kernel.org>
next prev parent reply other threads:[~2020-04-01 14:07 UTC|newest]
Thread overview: 36+ messages / expand[flat|nested] mbox.gz Atom feed top
2020-03-19 23:22 [PATCH 00/12 v2] ring-buffer/tracing: Remove disabling of ring buffer while reading trace file Steven Rostedt
2020-03-19 23:22 ` [PATCH 01/12 v2] selftest/ftrace: Fix function trigger test to handle trace not disabling the tracer Steven Rostedt
2020-03-19 23:22 ` [PATCH 02/12 v2] tracing: Save off entry when peeking at next entry Steven Rostedt
2020-03-20 2:57 ` Masami Hiramatsu
2020-03-26 9:12 ` [tracing] cd8f62b481: BUG:sleeping_function_called_from_invalid_context_at_mm/slab.h kernel test robot
2020-03-26 9:12 ` kernel test robot
2020-04-01 14:07 ` Masami Hiramatsu [this message]
2020-04-01 14:07 ` Masami Hiramatsu
2020-04-01 14:21 ` Steven Rostedt
2020-04-01 14:21 ` Steven Rostedt
2020-04-01 15:04 ` Steven Rostedt
2020-04-01 15:04 ` Steven Rostedt
2020-04-02 7:19 ` Masami Hiramatsu
2020-04-02 7:19 ` Masami Hiramatsu
2020-04-02 18:14 ` Steven Rostedt
2020-04-02 18:14 ` Steven Rostedt
2020-04-03 6:47 ` Masami Hiramatsu
2020-04-03 6:47 ` Masami Hiramatsu
2020-04-03 13:16 ` Steven Rostedt
2020-04-03 13:16 ` Steven Rostedt
2020-03-19 23:22 ` [PATCH 03/12 v2] ring-buffer: Have ring_buffer_empty() not depend on tracing stopped Steven Rostedt
2020-03-19 23:22 ` [PATCH 04/12 v2] ring-buffer: Rename ring_buffer_read() to read_buffer_iter_advance() Steven Rostedt
2020-03-19 23:22 ` [PATCH 05/12 v2] ring-buffer: Add page_stamp to iterator for synchronization Steven Rostedt
2020-03-19 23:22 ` [PATCH 06/12 v2] ring-buffer: Have rb_iter_head_event() handle concurrent writer Steven Rostedt
2020-03-19 23:22 ` [PATCH 07/12 v2] ring-buffer: Do not die if rb_iter_peek() fails more than thrice Steven Rostedt
2020-03-19 23:22 ` [PATCH 08/12 v2] ring-buffer: Optimize rb_iter_head_event() Steven Rostedt
2020-03-19 23:22 ` [PATCH 09/12 v2] ring-buffer: Do not disable recording when there is an iterator Steven Rostedt
2020-03-19 23:22 ` [PATCH 10/12 v2] tracing: Do not disable tracing when reading the trace file Steven Rostedt
2020-03-19 23:22 ` [PATCH 11/12 v2] ring-buffer/tracing: Have iterator acknowledge dropped events Steven Rostedt
2020-03-19 23:22 ` [PATCH 12/12 v2] tracing: Have the document reflect that the trace file keeps tracing enabled Steven Rostedt
2020-03-21 19:13 ` [PATCH 00/12 v2] ring-buffer/tracing: Remove disabling of ring buffer while reading trace file David Laight
2020-03-22 18:07 ` Steven Rostedt
2020-03-27 1:46 ` Steven Rostedt
2020-03-27 10:07 ` David Laight
2020-03-27 14:30 ` Steven Rostedt
2020-03-27 14:56 ` David Laight
Reply instructions:
You may reply publicly to this message via plain-text email
using any one of the following methods:
* Save the following mbox file, import it into your mail client,
and reply-to-all from there: mbox
Avoid top-posting and favor interleaved quoting:
https://en.wikipedia.org/wiki/Posting_style#Interleaved_style
* Reply using the --to, --cc, and --in-reply-to
switches of git-send-email(1):
git send-email \
--in-reply-to=20200401230700.d9ddb42b3459dca98144b55c@kernel.org \
--to=mhiramat@kernel.org \
--cc=akpm@linux-foundation.org \
--cc=alexei.starovoitov@gmail.com \
--cc=bpf@vger.kernel.org \
--cc=corbet@lwn.net \
--cc=linux-kernel@vger.kernel.org \
--cc=lkp@lists.01.org \
--cc=mingo@kernel.org \
--cc=peter@lekensteyn.nl \
--cc=peterz@infradead.org \
--cc=rong.a.chen@intel.com \
--cc=rostedt@goodmis.org \
--cc=shuahkhan@gmail.com \
--cc=zanussi@kernel.org \
/path/to/YOUR_REPLY
https://kernel.org/pub/software/scm/git/docs/git-send-email.html
* If your mail client supports setting the In-Reply-To header
via mailto: links, try the mailto: link
Be sure your reply has a Subject: header at the top and a blank line
before the message body.
This is an external index of several public inboxes,
see mirroring instructions on how to clone and mirror
all data and code used by this external index.