ftrace: WARNING: suspicious RCU usage
Hello Steve,
I've faced the following RCU warning while I ran ftracetest testcase "ftrace - function graph filters with stack tracer" on qemu. The kernel is ftrace/core branch.
[ 10.919174] ============================= [ 10.920077] WARNING: suspicious RCU usage [ 10.920977] 4.12.0-rc5+ #1 Not tainted [ 10.921828] ----------------------------- [ 10.922748] /home/mhiramat/ksrc/linux/include/trace/events/rcu.h:454 suspicious rcu_dereference_check() usage! [ 10.924761] [ 10.924761] other info that might help us debug this: [ 10.924761] [ 10.926775] [ 10.926775] RCU used illegally from idle CPU! [ 10.926775] rcu_scheduler_active = 2, debug_locks = 1 [ 10.929176] RCU used illegally from extended quiescent state! [ 10.930525] no locks held by swapper/7/0. [ 10.931547] [ 10.931547] stack backtrace: [ 10.932777] CPU: 7 PID: 0 Comm: swapper/7 Not tainted 4.12.0-rc5+ #1 [ 10.934025] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.9.3-1.fc25 04/01/2014 [ 10.935869] Call Trace: [ 10.936550] dump_stack+0x86/0xcf [ 10.937359] lockdep_rcu_suspicious+0xc5/0x100 [ 10.938327] ? rcu_eqs_exit_common.isra.53+0x5/0x150 [ 10.939229] rcu_irq_enter+0x18d/0x1a0 [ 10.939902] ? rcu_eqs_exit_common.isra.53+0x5/0x150 [ 10.940683] check_stack+0xbb/0x2f0 [ 10.941333] stack_trace_call+0x3f/0x50 [ 10.942010] 0xffffffffa0000077 [ 10.942620] ? ftrace_graph_caller+0x78/0xa8 [ 10.943342] ? rcu_eqs_exit_common.isra.53+0x5/0x150 [ 10.944214] ? rcu_idle_exit+0x5/0x90 [ 10.944937] rcu_eqs_exit_common.isra.53+0x5/0x150 [ 10.945754] rcu_idle_exit+0x8c/0x90 [ 10.946612] ? rcu_eqs_exit_common.isra.53+0x5/0x150 [ 10.947414] ? rcu_idle_exit+0x8c/0x90 [ 10.948091] do_idle+0x116/0x1c0 [ 10.948797] cpu_startup_entry+0x1d/0x20 [ 10.949569] start_secondary+0xfa/0x100 [ 10.950335] secondary_startup_64+0x9f/0x9f [ 10.951182]
I attached full log and kconfig. I can reproduce it with just running following script.
----
cd tools/testing/selftests/ftrace
while true; do
./ftracetest test.d/ftrace/fgraph-filter-stack.tc
done
----
Thank you,
Signature · 1 line
Masami Hiramatsu <[email protected]>
[ 10.449516] random: fast init done
[ 10.467070] find (723) used greatest stack depth: 12688 bytes left
=== Ftrace unit tests ===
[1] ftrace - function graph filters with stack tracer[ 10.918098]
[ 10.919174] =============================
[ 10.920077] WARNING: suspicious RCU usage
[ 10.920977] 4.12.0-rc5+ #1 Not tainted
[ 10.921828] -----------------------------
[ 10.922748] /home/mhiramat/ksrc/linux/include/trace/events/rcu.h:454 suspicious rcu_dereference_check() usage!
[ 10.924761]
[ 10.924761] other info that might help us debug this:
[ 10.924761]
[ 10.926775]
[ 10.926775] RCU used illegally from idle CPU!
[ 10.926775] rcu_scheduler_active = 2, debug_locks = 1
[ 10.929176] RCU used illegally from extended quiescent state!
[ 10.930525] no locks held by swapper/7/0.
[ 10.931547]
[ 10.931547] stack backtrace:
[ 10.932777] CPU: 7 PID: 0 Comm: swapper/7 Not tainted 4.12.0-rc5+ #1
[ 10.934025] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.9.3-1.fc25 04/01/2014
[ 10.935869] Call Trace:
[ 10.936550] dump_stack+0x86/0xcf
[ 10.937359] lockdep_rcu_suspicious+0xc5/0x100
[ 10.938327] ? rcu_eqs_exit_common.isra.53+0x5/0x150
[ 10.939229] rcu_irq_enter+0x18d/0x1a0
[ 10.939902] ? rcu_eqs_exit_common.isra.53+0x5/0x150
[ 10.940683] check_stack+0xbb/0x2f0
[ 10.941333] stack_trace_call+0x3f/0x50
[ 10.942010] 0xffffffffa0000077
[ 10.942620] ? ftrace_graph_caller+0x78/0xa8
[ 10.943342] ? rcu_eqs_exit_common.isra.53+0x5/0x150
[ 10.944214] ? rcu_idle_exit+0x5/0x90
[ 10.944937] rcu_eqs_exit_common.isra.53+0x5/0x150
[ 10.945754] rcu_idle_exit+0x8c/0x90
[ 10.946612] ? rcu_eqs_exit_common.isra.53+0x5/0x150
[ 10.947414] ? rcu_idle_exit+0x8c/0x90
[ 10.948091] do_idle+0x116/0x1c0
[ 10.948797] cpu_startup_entry+0x1d/0x20
[ 10.949569] start_secondary+0xfa/0x100
[ 10.950335] secondary_startup_64+0x9f/0x9f
[ 10.951182]
[ 10.951189] =============================
[ 10.951190] WARNING: suspicious RCU usage
[ 10.951190] 4.12.0-rc5+ #1 Not tainted
[ 10.951191] -----------------------------
[ 10.951192] /home/mhiramat/ksrc/linux/include/linux/rcupdate.h:847 rcu_read_lock() used illegally while idle!
[ 10.951193]
[ 10.951194] other info that might help us debug this:
[ 10.951194]
[ 10.951195]
[ 10.951196] RCU used illegally from idle CPU!
[ 10.951196] rcu_scheduler_active = 2, debug_locks = 1
[ 10.951197] RCU used illegally from extended quiescent state!
[ 10.951198] 3 locks held by swapper/7/0:
[ 10.951199] #0: (console_lock){+.+...}, at: [<ffffffff810afec9>] vprintk_emit+0x229/0x310
[ 10.951202] #1: (printing_lock){......}, at: [<ffffffff813d1169>] vt_console_print+0x49/0x3b0
[ 10.951205] #2: (rcu_read_lock){......}, at: [<ffffffff8107b1d5>] atomic_notifier_call_chain+0x5/0x110
[ 10.951209]
[ 10.951210] stack backtrace:
[ 10.951210] CPU: 7 PID: 0 Comm: swapper/7 Not tainted 4.12.0-rc5+ #1
[ 10.951211] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.9.3-1.fc25 04/01/2014
[ 10.951212] Call Trace:
[ 10.951213]
[ 10.951213] =============================
[ 10.951214] WARNING: suspicious RCU usage
[ 10.951215] 4.12.0-rc5+ #1 Not tainted
[ 10.951216] -----------------------------
[ 10.951216] /home/mhiramat/ksrc/linux/include/linux/rcupdate.h:847 rcu_read_lock() used illegally while idle!
[ 10.951217]
[ 10.951218] other info that might help us debug this:
[ 10.951219]
[ 10.951219]
[ 10.951220] RCU used illegally from idle CPU!
[ 10.951221] rcu_scheduler_active = 2, debug_locks = 1
[ 10.951221] RCU used illegally from extended quiescent state!
[ 10.951222] 4 locks held by swapper/7/0:
[ 10.951223] #0: (console_lock){+.+...}, at: [<ffffffff810afec9>] vprintk_emit+0x229/0x310
[ 10.951226] #1: (printing_lock){......}, at: [<ffffffff813d1169>] vt_console_print+0x49/0x3b0
[ 10.951229] #2: (rcu_read_lock){......}, at: [<ffffffff8107b1d5>] atomic_notifier_call_chain+0x5/0x110
[ 10.951233] #3: (rcu_read_lock){......}, at: [<ffffffff81116425>] __is_insn_slot_addr+0x5/0x120
[ 10.951236]
[ 10.951237] stack backtrace:
[ 10.951238] CPU: 7 PID: 0 Comm: swapper/7 Not tainted 4.12.0-rc5+ #1
[ 10.951238] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.9.3-1.fc25 04/01/2014
[ 10.951239] Call Trace:
[ 10.951240]
[ 10.951240] =============================
[ 10.951241] WARNING: suspicious RCU usage
[ 10.951242] 4.12.0-rc5+ #1 Not tainted
[ 10.951243] -----------------------------
[ 10.951244] /home/mhiramat/ksrc/linux/include/linux/rcupdate.h:898 rcu_read_unlock() used illegally while idle!
[ 10.951245]
[ 10.951246] other info that might help us debug this:
[ 10.951249]
[ 10.951250]
[ 10.951251] RCU used illegally from idle CPU!
[ 10.951252] rcu_scheduler_active = 2, debug_locks = 1
[ 10.951253] RCU used illegally from extended quiescent state!
[ 10.951254] 5 locks held by swapper/7/0:
[ 10.951255] #0: (console_lock){+.+...}, at: [<ffffffff810afec9>] vprintk_emit+0x229/0x310
[ 10.951261] #1: (printing_lock){......}, at: [<ffffffff813d1169>] vt_console_print+0x49/0x3b0
[ 10.951267] #2: (rcu_read_lock){......}, at: [<ffffffff8107b1d5>] atomic_notifier_call_chain+0x5/0x110
[ 10.951271] #3: (rcu_read_lock){......}, at: [<ffffffff81116425>] __is_insn_slot_addr+0x5/0x120
[ 10.951274] #4: (rcu_read_lock){......}, at: [<ffffffff81116425>] __is_insn_slot_addr+0x5/0x120
[ 10.951278]
[ 10.951278] stack backtrace:
[ 10.951279] CPU: 7 PID: 0 Comm: swapper/7 Not tainted 4.12.0-rc5+ #1
[ 10.951280] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.9.3-1.fc25 04/01/2014
[ 10.951281] Call Trace:
[ 10.951282] dump_stack+0x86/0xcf
[ 10.951282] lockdep_rcu_suspicious+0xc5/0x100
[ 10.951283] __is_insn_slot_addr+0x118/0x120
[ 10.951284] __kernel_text_address+0x69/0xa0
[ 10.951285] show_trace_log_lvl+0x121/0x340
[ 10.951285] ? dump_stack+0x86/0xcf
[ 10.951286] show_stack+0x44/0x60
[ 10.951287] dump_stack+0x86/0xcf
[ 10.951288] lockdep_rcu_suspicious+0xc5/0x100
[ 10.951288] __is_insn_slot_addr+0xe4/0x120
[ 10.951289] __kernel_text_address+0x69/0xa0
[ 10.951290] show_trace_log_lvl+0x121/0x340
[ 10.951291] ? dump_stack+0x86/0xcf
[ 10.951291] show_stack+0x44/0x60
[ 10.951292] dump_stack+0x86/0xcf
[ 10.951293] lockdep_rcu_suspicious+0xc5/0x100
[ 10.951293] atomic_notifier_call_chain+0xd0/0x110
[ 10.951294] vt_console_print+0x17d/0x3b0
[ 10.951295] console_unlock+0x451/0x570
[ 10.951296] vprintk_emit+0x232/0x310
[ 10.951296] vprintk_default+0x1f/0x30
[ 10.951297] vprintk_func+0x20/0x50
[ 10.951298] printk+0x43/0x4b
[ 10.951299] lockdep_rcu_suspicious+0x20/0x100
[ 10.951299] ? rcu_eqs_exit_common.isra.53+0x5/0x150
[ 10.951300] rcu_irq_enter+0x18d/0x1a0
[ 10.951301] ? rcu_eqs_exit_common.isra.53+0x5/0x150
[ 10.951301] check_stack+0xbb/0x2f0
[ 10.951302] stack_trace_call+0x3f/0x50
[ 10.951303] 0xffffffffa0000077
[ 10.951304] ? ftrace_graph_caller+0x78/0xa8
[ 10.951304] ? rcu_eqs_exit_common.isra.53+0x5/0x150
[ 10.951305] ? rcu_idle_exit+0x5/0x90
[ 10.951306] rcu_eqs_exit_common.isra.53+0x5/0x150
[ 10.951307] rcu_idle_exit+0x8c/0x90
[ 10.951307] ? rcu_eqs_exit_common.isra.53+0x5/0x150
[ 10.951308] ? rcu_idle_exit+0x8c/0x90
[ 10.951309] do_idle+0x116/0x1c0
[ 10.951309] cpu_startup_entry+0x1d/0x20
[ 10.951310] start_secondary+0xfa/0x100
[ 10.951311] secondary_startup_64+0x9f/0x9f
[ 10.951312] dump_stack+0x86/0xcf
[ 10.951312] lockdep_rcu_suspicious+0xc5/0x100
[ 10.951313] __is_insn_slot_addr+0xe4/0x120
[ 10.951314] __kernel_text_address+0x69/0xa0
[ 10.951315] show_trace_log_lvl+0x121/0x340
[ 10.951315] ? dump_stack+0x86/0xcf
[ 10.951316] show_stack+0x44/0x60
[ 10.951317] dump_stack+0x86/0xcf
[ 10.951317] lockdep_rcu_suspicious+0xc5/0x100
[ 10.951318] atomic_notifier_call_chain+0xd0/0x110
[ 10.951319] vt_console_print+0x17d/0x3b0
[ 10.951320] console_unlock+0x451/0x570
[ 10.951320] vprintk_emit+0x232/0x310
[ 10.951321] vprintk_default+0x1f/0x30
[ 10.951322] vprintk_func+0x20/0x50
[ 10.951323] printk+0x43/0x4b
[ 10.951323] lockdep_rcu_suspicious+0x20/0x100
[ 10.951324] ? rcu_eqs_exit_common.isra.53+0x5/0x150
[ 10.951325] rcu_irq_enter+0x18d/0x1a0
[ 10.951325] ? rcu_eqs_exit_common.isra.53+0x5/0x150
[ 10.951326] check_stack+0xbb/0x2f0
[ 10.951327] stack_trace_call+0x3f/0x50
[ 10.951328] 0xffffffffa0000077
[ 10.951328] ? ftrace_graph_caller+0x78/0xa8
[ 10.951329] ? rcu_eqs_exit_common.isra.53+0x5/0x150
[ 10.951330] ? rcu_idle_exit+0x5/0x90
[ 10.951331] rcu_eqs_exit_common.isra.53+0x5/0x150
[ 10.951331] rcu_idle_exit+0x8c/0x90
[ 10.951332] ? rcu_eqs_exit_common.isra.53+0x5/0x150
[ 10.951333] ? rcu_idle_exit+0x8c/0x90
[ 10.951333] do_idle+0x116/0x1c0
[ 10.951334] cpu_startup_entry+0x1d/0x20
[ 10.951335] start_secondary+0xfa/0x100
[ 10.951336] secondary_startup_64+0x9f/0x9f
[ 10.951336] dump_stack+0x86/0xcf
[ 10.951337] lockdep_rcu_suspicious+0xc5/0x100
[ 10.951338] atomic_notifier_call_chain+0xd0/0x110
[ 10.951339] vt_console_print+0x17d/0x3b0
[ 10.951339] console_unlock+0x451/0x570
[ 10.951340] vprintk_emit+0x232/0x310
[ 10.951341] vprintk_default+0x1f/0x30
[ 10.951341] vprintk_func+0x20/0x50
[ 10.951342] printk+0x43/0x4b
[ 10.951343] lockdep_rcu_suspicious+0x20/0x100
[ 10.951344] ? rcu_eqs_exit_common.isra.53+0x5/0x150
[ 10.951344] rcu_irq_enter+0x18d/0x1a0
[ 10.951345] ? rcu_eqs_exit_common.isra.53+0x5/0x150
[ 10.951346] check_stack+0xbb/0x2f0
[ 10.951347] stack_trace_call+0x3f/0x50
[ 10.951347] 0xffffffffa0000077
[ 10.951348] ? ftrace_graph_caller+0x78/0xa8
[ 10.951349] ? rcu_eqs_exit_common.isra.53+0x5/0x150
[ 10.951350] ? rcu_idle_exit+0x5/0x90
[ 10.951350] rcu_eqs_exit_common.isra.53+0x5/0x150
[ 10.951351] rcu_idle_exit+0x8c/0x90
[ 10.951352] ? rcu_eqs_exit_common.isra.53+0x5/0x150
[ 10.951353] ? rcu_idle_exit+0x8c/0x90
[ 10.951353] do_idle+0x116/0x1c0
[ 10.951354] cpu_startup_entry+0x1d/0x20
[ 10.951355] start_secondary+0xfa/0x100
[ 10.951355] secondary_startup_64+0x9f/0x9f
[ 10.951356]
[ 10.951357] =============================
[ 10.951358] WARNING: suspicious RCU usage
[ 10.951358] 4.12.0-rc5+ #1 Not tainted
[ 10.951359] -----------------------------
[ 10.951360] /home/mhiramat/ksrc/linux/include/linux/rcupdate.h:898 rcu_read_unlock() used illegally while idle!
[ 10.951361]
[ 10.951361] other info that might help us debug this:
[ 10.951362]
[ 10.951363]
[ 10.951363] RCU used illegally from idle CPU!
[ 10.951364] rcu_scheduler_active = 2, debug_locks = 1
[ 10.951365] RCU used illegally from extended quiescent state!
[ 10.951366] 3 locks held by swapper/7/0:
[ 10.951366] #0: (console_lock){+.+...}, at: [<ffffffff810afec9>] vprintk_emit+0x229/0x310
[ 10.951369] #1: (printing_lock){......}, at: [<ffffffff813d1169>] vt_console_print+0x49/0x3b0
[ 10.951373] #2: (rcu_read_lock){......}, at: [<ffffffff8107b1d5>] atomic_notifier_call_chain+0x5/0x110
[ 10.951376]
[ 10.951377] stack backtrace:
[ 10.951378] CPU: 7 PID: 0 Comm: swapper/7 Not tainted 4.12.0-rc5+ #1
[ 10.951378] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.9.3-1.fc25 04/01/2014
[ 10.951379] Call Trace:
[ 10.951380] dump_stack+0x86/0xcf
[ 10.951380] lockdep_rcu_suspicious+0xc5/0x100
[ 10.951381] atomic_notifier_call_chain+0xfd/0x110
[ 10.951382] vt_console_print+0x17d/0x3b0
[ 10.951383] console_unlock+0x451/0x570
[ 10.951383] vprintk_emit+0x232/0x310
[ 10.951384] vprintk_default+0x1f/0x30
[ 10.951385] vprintk_func+0x20/0x50
[ 10.951386] printk+0x43/0x4b
[ 10.951386] lockdep_rcu_suspicious+0x20/0x100
[ 10.951387] ? rcu_eqs_exit_common.isra.53+0x5/0x150
[ 10.951388] rcu_irq_enter+0x18d/0x1a0
[ 10.951388] ? rcu_eqs_exit_common.isra.53+0x5/0x150
[ 10.951389] check_stack+0xbb/0x2f0
[ 10.951390] stack_trace_call+0x3f/0x50
[ 10.951391] 0xffffffffa0000077
[ 10.951391] ? ftrace_graph_caller+0x78/0xa8
[ 10.951392] ? rcu_eqs_exit_common.isra.53+0x5/0x150
[ 10.951393] ? rcu_idle_exit+0x5/0x90
[ 10.951394] rcu_eqs_exit_common.isra.53+0x5/0x150
[ 10.951394] rcu_idle_exit+0x8c/0x90
[ 10.951395] ? rcu_eqs_exit_common.isra.53+0x5/0x150
[ 10.951396] ? rcu_idle_exit+0x8c/0x90
[ 10.951396] do_idle+0x116/0x1c0
[ 10.951397] cpu_startup_entry+0x1d/0x20
[ 10.951398] start_secondary+0xfa/0x100
[ 10.951399] secondary_startup_64+0x9f/0x9f
[ 12.282399] cat (755) used greatest stack depth: 12656 bytes left
[PASS]# of passed: 1 # of failed: 0 # of unresolved: 0 # of untested: 0 # of unsupported: 0 # of xfailed: 0 # of undefined(test bug): 0
Steven Rostedt
reviewerQuoted 28 lines · On Tue, 27 Jun 2017 20:51:26 +0900 Masami Hiramatsu <[email protected]> wrote:
Hello Steve,
I've faced the following RCU warning while I ran ftracetest testcase "ftrace - function graph filters with stack tracer" on qemu. The kernel is ftrace/core branch.
[ 10.919174] ============================= [ 10.920077] WARNING: suspicious RCU usage [ 10.920977] 4.12.0-rc5+ #1 Not tainted [ 10.921828] ----------------------------- [ 10.922748] /home/mhiramat/ksrc/linux/include/trace/events/rcu.h:454 suspicious rcu_dereference_check() usage! [ 10.924761] [ 10.924761] other info that might help us debug this: [ 10.924761] [ 10.926775] [ 10.926775] RCU used illegally from idle CPU! [ 10.926775] rcu_scheduler_active = 2, debug_locks = 1 [ 10.929176] RCU used illegally from extended quiescent state! [ 10.930525] no locks held by swapper/7/0. [ 10.931547] [ 10.931547] stack backtrace: [ 10.932777] CPU: 7 PID: 0 Comm: swapper/7 Not tainted 4.12.0-rc5+ #1 [ 10.934025] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.9.3-1.fc25 04/01/2014 [ 10.935869] Call Trace: [ 10.936550] dump_stack+0x86/0xcf [ 10.937359] lockdep_rcu_suspicious+0xc5/0x100 [ 10.938327] ? rcu_eqs_exit_common.isra.53+0x5/0x150
Quoted 1 line
[ 10.939229] rcu_irq_enter+0x18d/0x1a0
Strange, it triggered in rcu_irq_enter()?
Quoted 9 lines
[ 10.939902] ? rcu_eqs_exit_common.isra.53+0x5/0x150 [ 10.940683] check_stack+0xbb/0x2f0 [ 10.941333] stack_trace_call+0x3f/0x50 [ 10.942010] 0xffffffffa0000077 [ 10.942620] ? ftrace_graph_caller+0x78/0xa8 [ 10.943342] ? rcu_eqs_exit_common.isra.53+0x5/0x150 [ 10.944214] ? rcu_idle_exit+0x5/0x90[ 10.944937] rcu_eqs_exit_common.isra.53+0x5/0x150
Hmm, we are tracing rcu_eqs_exit_common.
Do you have this commit in this branch?
Commit 03ecd3f4 "rcu/tracing: Add rcu_disabled to denote when rcu_irq_enter() will not work"
-- Steve
Quoted 21 lines
[ 10.945754] rcu_idle_exit+0x8c/0x90 [ 10.946612] ? rcu_eqs_exit_common.isra.53+0x5/0x150 [ 10.947414] ? rcu_idle_exit+0x8c/0x90 [ 10.948091] do_idle+0x116/0x1c0 [ 10.948797] cpu_startup_entry+0x1d/0x20 [ 10.949569] start_secondary+0xfa/0x100 [ 10.950335] secondary_startup_64+0x9f/0x9f [ 10.951182]I attached full log and kconfig. I can reproduce it with just running following script.
----
cdtools/testing/selftests/ftrace
while true; do
./ftracetest test.d/ftrace/fgraph-filter-stack.tc
done
----Thank you,
Quoted 45 lines · On Tue, 27 Jun 2017 09:29:26 -0400 Steven Rostedt <[email protected]> wrote:
Quoted 28 lines · On Tue, 27 Jun 2017 20:51:26 +0900 Masami Hiramatsu <[email protected]> wrote:
Hello Steve,
I've faced the following RCU warning while I ran ftracetest testcase "ftrace - function graph filters with stack tracer" on qemu. The kernel is ftrace/core branch.
[ 10.919174] ============================= [ 10.920077] WARNING: suspicious RCU usage [ 10.920977] 4.12.0-rc5+ #1 Not tainted [ 10.921828] ----------------------------- [ 10.922748] /home/mhiramat/ksrc/linux/include/trace/events/rcu.h:454 suspicious rcu_dereference_check() usage! [ 10.924761] [ 10.924761] other info that might help us debug this: [ 10.924761] [ 10.926775] [ 10.926775] RCU used illegally from idle CPU! [ 10.926775] rcu_scheduler_active = 2, debug_locks = 1 [ 10.929176] RCU used illegally from extended quiescent state! [ 10.930525] no locks held by swapper/7/0. [ 10.931547] [ 10.931547] stack backtrace: [ 10.932777] CPU: 7 PID: 0 Comm: swapper/7 Not tainted 4.12.0-rc5+ #1 [ 10.934025] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.9.3-1.fc25 04/01/2014 [ 10.935869] Call Trace: [ 10.936550] dump_stack+0x86/0xcf [ 10.937359] lockdep_rcu_suspicious+0xc5/0x100 [ 10.938327] ? rcu_eqs_exit_common.isra.53+0x5/0x150Quoted 1 line
[ 10.939229] rcu_irq_enter+0x18d/0x1a0Strange, it triggered in
rcu_irq_enter()?Quoted 9 lines
[ 10.939902] ? rcu_eqs_exit_common.isra.53+0x5/0x150 [ 10.940683] check_stack+0xbb/0x2f0 [ 10.941333] stack_trace_call+0x3f/0x50 [ 10.942010] 0xffffffffa0000077 [ 10.942620] ? ftrace_graph_caller+0x78/0xa8 [ 10.943342] ? rcu_eqs_exit_common.isra.53+0x5/0x150 [ 10.944214] ? rcu_idle_exit+0x5/0x90[ 10.944937] rcu_eqs_exit_common.isra.53+0x5/0x150
Quoted 7 lines
Hmm, we are tracing
rcu_eqs_exit_common.Do you have this commit in this branch?
Commit
03ecd3f4"rcu/tracing: Addrcu_disabledto denote whenrcu_irq_enter()will not work"
Yes, that is merged.
Hmm, I'll check this is correctly enabled again, since this time I couldn't reproduce it.
Thank you,
Quoted 25 lines
-- Steve
Quoted 21 lines
[ 10.945754] rcu_idle_exit+0x8c/0x90 [ 10.946612] ? rcu_eqs_exit_common.isra.53+0x5/0x150 [ 10.947414] ? rcu_idle_exit+0x8c/0x90 [ 10.948091] do_idle+0x116/0x1c0 [ 10.948797] cpu_startup_entry+0x1d/0x20 [ 10.949569] start_secondary+0xfa/0x100 [ 10.950335] secondary_startup_64+0x9f/0x9f [ 10.951182]I attached full log and kconfig. I can reproduce it with just running following script.
----
cdtools/testing/selftests/ftrace
while true; do
./ftracetest test.d/ftrace/fgraph-filter-stack.tc
done
----Thank you,
Signature · 1 line
Masami Hiramatsu <[email protected]>
Hi,
Quoted 34 lines · On Tue, 27 Jun 2017 22:53:56 +0900 Masami Hiramatsu <[email protected]> wrote:
Quoted 34 lines
Quoted 22 lines
[ 10.919174] ============================= [ 10.920077] WARNING: suspicious RCU usage [ 10.920977] 4.12.0-rc5+ #1 Not tainted [ 10.921828] ----------------------------- [ 10.922748] /home/mhiramat/ksrc/linux/include/trace/events/rcu.h:454 suspicious rcu_dereference_check() usage! [ 10.924761] [ 10.924761] other info that might help us debug this: [ 10.924761] [ 10.926775] [ 10.926775] RCU used illegally from idle CPU! [ 10.926775] rcu_scheduler_active = 2, debug_locks = 1 [ 10.929176] RCU used illegally from extended quiescent state! [ 10.930525] no locks held by swapper/7/0. [ 10.931547] [ 10.931547] stack backtrace: [ 10.932777] CPU: 7 PID: 0 Comm: swapper/7 Not tainted 4.12.0-rc5+ #1 [ 10.934025] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.9.3-1.fc25 04/01/2014 [ 10.935869] Call Trace: [ 10.936550] dump_stack+0x86/0xcf [ 10.937359] lockdep_rcu_suspicious+0xc5/0x100 [ 10.938327] ? rcu_eqs_exit_common.isra.53+0x5/0x150Quoted 1 line
[ 10.939229] rcu_irq_enter+0x18d/0x1a0Strange, it triggered in
rcu_irq_enter()?Quoted 7 lines
[ 10.939902] ? rcu_eqs_exit_common.isra.53+0x5/0x150 [ 10.940683] check_stack+0xbb/0x2f0 [ 10.941333] stack_trace_call+0x3f/0x50 [ 10.942010] 0xffffffffa0000077 [ 10.942620] ? ftrace_graph_caller+0x78/0xa8 [ 10.943342] ? rcu_eqs_exit_common.isra.53+0x5/0x150 [ 10.944214] ? rcu_idle_exit+0x5/0x90
Quoted 3 lines
Quoted 3 lines
Quoted 1 line
[ 10.944937] rcu_eqs_exit_common.isra.53+0x5/0x150Hmm, we are tracing
rcu_eqs_exit_common.
Yes, the Commit 03ecd3f4 fixed only rcu_eqs_enter_common() path, but not rcu_eqs_exit().
Quoted 11 lines
Quoted 6 lines
Do you have this commit in this branch?
Commit
03ecd3f4"rcu/tracing: Addrcu_disabledto denote whenrcu_irq_enter()will not work"Yes, that is merged.
Hmm, I'll check this is correctly enabled again, since this time I couldn't reproduce it.
I could reproduce it again with running full ftracetest (not sure why, but with only fgraph-filter-stack.tc, it is hard to be reproduced.
Please see attached patch, after applying that, I didn't see this problem.
Thank you,
Signature · 1 line
Masami Hiramatsu <[email protected]>
Quoted 5 lines · On Wed, 28 Jun 2017 07:52:22 +0900 Masami Hiramatsu <[email protected]> wrote:
kernel/rcu/tree.c +0
-0
kernel/rcu/tree.c static void rcu_eqs_exit(bool user) · line 982
Quoted 10 lines
kernel/rcu/tree.c +2
-0@@ -973,8 +973,10 @@ static void rcu_eqs_exit(bool user)if (oldval &DYNTICK_TASK_NEST_MASK ) { rdtp->dynticks_nesting +=DYNTICK_TASK_NEST_VALUE ; }else { +__this_cpu_inc (disable_rcu_irq_enter); rdtp->dynticks_nesting =DYNTICK_TASK_EXIT_IDLE ;rcu_eqs_exit_common (oldval, user); +__this_cpu_dec (disable_rcu_irq_enter); } }
Looks like a good fix to me. Paul want to take this one?
-- Steve
Paul E. McKenney
Acked-by Steven Rostedt (VMware)Quoted 21 lines · Steven Rostedt
Quoted 5 lines · On Wed, 28 Jun 2017 07:52:22 +0900 Masami Hiramatsu <[email protected]> wrote:
kernel/rcu/tree.c +0
-0kernel/rcu/tree.c static void rcu_eqs_exit(bool user) · line 982
Quoted 10 lines
kernel/rcu/tree.c +2
-0@@ -973,8 +973,10 @@ static void rcu_eqs_exit(bool user)if (oldval &DYNTICK_TASK_NEST_MASK ) { rdtp->dynticks_nesting +=DYNTICK_TASK_NEST_VALUE ; }else { +__this_cpu_inc (disable_rcu_irq_enter); rdtp->dynticks_nesting =DYNTICK_TASK_EXIT_IDLE ;rcu_eqs_exit_common (oldval, user); +__this_cpu_dec (disable_rcu_irq_enter); } }Looks like a good fix to me. Paul want to take this one?
Quoted 1 line
Why not?
How urgent is this, as in what release do you need it in? (Default at this point being v4.14, but non-default available upon request.)
Thanx, Paul
------------------------------------------------------------------------
commit 2165b0a9bb37f0560f261986783e7c02bb37c353
Author: Masami Hiramatsu <[email protected]> Date: Tue Jun 27 17:41:25 2017 -0700
rcu/tracing: Set disable_rcu_irq_enter on rcu_eqs_exit()
Set disable_rcu_irq_enter on not only rcu_eqs_enter_common() but also rcu_eqs_exit(), since rcu_eqs_exit() suffers from the same issue as was fixed for rcu_eqs_enter_common() by commit 03ecd3f48e57 ("rcu/tracing:
Add rcu_disabled to denote when rcu_irq_enter() will not work").
Signed-off-by Masami Hiramatsu <[email protected]>
Signed-off-by Paul E. McKenney <[email protected]>
kernel/rcu/tree.c +2 -0
@@ -952,8 +952,10 @@ static void rcu_eqs_exit(bool user)if (oldval &DYNTICK_TASK_NEST_MASK ) { rdtp->dynticks_nesting +=DYNTICK_TASK_NEST_VALUE ; }else { +__this_cpu_inc (disable_rcu_irq_enter); rdtp->dynticks_nesting =DYNTICK_TASK_EXIT_IDLE ;rcu_eqs_exit_common (oldval, user); +__this_cpu_dec (disable_rcu_irq_enter); } }