[BUG] ftrace: WARNING: suspicious RCU usage
From: Masami Hiramatsu
Date: Tue Jun 27 2017 - 07:51:42 EST
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,
--
Masami Hiramatsu <mhiramat@xxxxxxxxxx>
[ 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
Attachment:
ftrace-core-rcubug.kconfig
Description: Binary data