* 4.19-rc1: ./include/linux/rcupdate.h:631 rcu_read_lock() used illegally while idle!
@ 2018-09-01 17:35 Borislav Petkov
2018-09-01 17:54 ` Paul E. McKenney
0 siblings, 1 reply; 11+ messages in thread
From: Borislav Petkov @ 2018-09-01 17:35 UTC (permalink / raw)
To: x86-ml; +Cc: Peter Zijlstra, Paul E. McKenney, lkml
This is a huge splat! It haz some perf* and sched* in it, I guess for
peterz to stare at. And lemme add Paul for good measure too :)
Kernel is -rc1 + 3 microcode loader patches ontop which should not be
related.
Thx.
---
[ 62.409125] =============================
[ 62.409129] WARNING: suspicious RCU usage
[ 62.409133] 4.19.0-rc1+ #1 Not tainted
[ 62.409136] -----------------------------
[ 62.409140] ./include/linux/rcupdate.h:631 rcu_read_lock() used illegally while idle!
[ 62.409143]
other info that might help us debug this:
[ 62.409147]
RCU used illegally from idle CPU!
rcu_scheduler_active = 2, debug_locks = 1
[ 62.409151] RCU used illegally from extended quiescent state!
[ 62.409155] 1 lock held by swapper/0/0:
[ 62.409158] #0: 000000004557ee0e (rcu_read_lock){....}, at: perf_event_output_forward+0x0/0x130
[ 62.409175]
stack backtrace:
[ 62.409180] CPU: 0 PID: 0 Comm: swapper/0 Not tainted 4.19.0-rc1+ #1
[ 62.409183] Hardware name: LENOVO 2320CTO/2320CTO, BIOS G2ET86WW (2.06 ) 11/13/2012
[ 62.409187] Call Trace:
[ 62.409196] dump_stack+0x85/0xcb
[ 62.409203] perf_event_output_forward+0xf6/0x130
[ 62.409215] __perf_event_overflow+0x52/0xe0
[ 62.409223] perf_swevent_overflow+0x91/0xb0
[ 62.409229] perf_tp_event+0x11a/0x350
[ 62.409235] ? find_held_lock+0x2d/0x90
[ 62.409251] ? __lock_acquire+0x2ce/0x1350
[ 62.409263] ? __lock_acquire+0x2ce/0x1350
[ 62.409270] ? retint_kernel+0x2d/0x2d
[ 62.409278] ? find_held_lock+0x2d/0x90
[ 62.409285] ? tick_nohz_get_sleep_length+0x83/0xb0
[ 62.409299] ? perf_trace_cpu+0xbb/0xd0
[ 62.409306] ? perf_trace_buf_alloc+0x5a/0xa0
[ 62.409311] perf_trace_cpu+0xbb/0xd0
[ 62.409323] cpuidle_enter_state+0x185/0x340
[ 62.409332] do_idle+0x1eb/0x260
[ 62.409340] cpu_startup_entry+0x5f/0x70
[ 62.409347] start_kernel+0x49b/0x4a6
[ 62.409357] secondary_startup_64+0xa4/0xb0
[ 62.409374] =============================
[ 62.409375] WARNING: suspicious RCU usage
[ 62.409377] 4.19.0-rc1+ #1 Not tainted
[ 62.409378] -----------------------------
[ 62.409380] kernel/events/ring_buffer.c:138 suspicious rcu_dereference_check() usage!
[ 62.409381]
other info that might help us debug this:
[ 62.409382]
RCU used illegally from idle CPU!
rcu_scheduler_active = 2, debug_locks = 1
[ 62.409384] RCU used illegally from extended quiescent state!
[ 62.409386] 2 locks held by swapper/0/0:
[ 62.409387] #0: 000000004557ee0e (
[ 62.409390] =============================
[ 62.409391] WARNING: suspicious RCU usage
[ 62.409393] rcu_read_lock){....}, at: perf_event_output_forward+0x0/0x130
[ 62.409398] 4.19.0-rc1+ #1 Not tainted
[ 62.409399] -----------------------------
[ 62.409400] #1: 000000004557ee0e
[ 62.409403] ./include/linux/rcupdate.h:631 rcu_read_lock() used illegally while idle!
[ 62.409403] (rcu_read_lock){....}
[ 62.409406]
other info that might help us debug this:
[ 62.409408] , at: perf_output_begin_forward+0x5/0x320
[ 62.409409]
stack backtrace:
[ 62.409412] CPU: 0 PID: 0 Comm: swapper/0 Not tainted 4.19.0-rc1+ #1
[ 62.409413] Hardware name: LENOVO 2320CTO/2320CTO, BIOS G2ET86WW (2.06 ) 11/13/2012
[ 62.409414] Call Trace:
[ 62.409418] dump_stack+0x85/0xcb
[ 62.409422] perf_output_begin_forward+0x2d2/0x320
[ 62.409423]
RCU used illegally from idle CPU!
rcu_scheduler_active = 2, debug_locks = 1
[ 62.409424] RCU used illegally from extended quiescent state!
[ 62.409428] ? find_held_lock+0x2d/0x90
[ 62.409433] ? vprintk_emit+0x2ce/0x340
[ 62.409434] 2 locks held by swapper/2/0:
[ 62.409435] #0: 000000004557ee0e (rcu_read_lock){....}, at: perf_event_output_forward+0x0/0x130
[ 62.409445] ? find_held_lock+0x2d/0x90
[ 62.409449] ? is_bpf_text_address+0x65/0xe0
[ 62.409450] #1: 000000004557ee0e (rcu_read_lock){....}, at: perf_output_begin_forward+0x5/0x320
[ 62.409457]
stack backtrace:
[ 62.409462] ? rcu_dynticks_eqs_enter+0x12/0x30
[ 62.409466] ? kernel_text_address+0x8f/0xf0
[ 62.409472] ? __kernel_text_address+0xe/0x30
[ 62.409477] ? show_trace_log_lvl+0x19f/0x3d0
[ 62.409484] ? secondary_startup_64+0xa4/0xb0
[ 62.409492] =============================
[ 62.409494] ? sched_clock+0x5/0x10
[ 62.409496] ? sched_clock+0x5/0x10
[ 62.409500] ? sched_clock_cpu+0x10/0xd0
[ 62.409504] WARNING: suspicious RCU usage
[ 62.409506] ? perf_event_output_forward+0x70/0x130
[ 62.409508] ? perf_prepare_sample+0x53/0x460
[ 62.409513] 4.19.0-rc1+ #1 Not tainted
[ 62.409514] perf_event_output_forward+0x70/0x130
[ 62.409518] -----------------------------
[ 62.409522] ./include/linux/rcupdate.h:680 rcu_read_unlock() used illegally while idle!
[ 62.409523] __perf_event_overflow+0x52/0xe0
[ 62.409528] perf_swevent_overflow+0x91/0xb0
[ 62.409529]
other info that might help us debug this:
[ 62.409531]
RCU used illegally from idle CPU!
rcu_scheduler_active = 2, debug_locks = 1
[ 62.409533] RCU used illegally from extended quiescent state!
[ 62.409536] 2 locks held by swapper/3/0:
[ 62.409537] #0: 000000004557ee0e (rcu_read_lock){....}
[ 62.409544] perf_tp_event+0x11a/0x350
[ 62.409547] ? find_held_lock+0x2d/0x90
[ 62.409552] , at: perf_event_output_forward+0x0/0x130
[ 62.409555] #1: 000000004557ee0e (
[ 62.409560] ? __lock_acquire+0x2ce/0x1350
[ 62.409564] rcu_read_lock){....}, at: perf_output_begin_forward+0x5/0x320
[ 62.409569] ? __lock_acquire+0x2ce/0x1350
[ 62.409573] ? retint_kernel+0x2d/0x2d
[ 62.409576]
stack backtrace:
[ 62.409579] ? find_held_lock+0x2d/0x90
[ 62.409583] ? tick_nohz_get_sleep_length+0x83/0xb0
[ 62.409595] ? perf_trace_cpu+0xbb/0xd0
[ 62.409601] ? perf_trace_buf_alloc+0x5a/0xa0
[ 62.409606] perf_trace_cpu+0xbb/0xd0
[ 62.409615] cpuidle_enter_state+0x185/0x340
[ 62.409624] do_idle+0x1eb/0x260
[ 62.409631] cpu_startup_entry+0x5f/0x70
[ 62.409637] start_kernel+0x49b/0x4a6
[ 62.409644] secondary_startup_64+0xa4/0xb0
[ 62.409661] CPU: 3 PID: 0 Comm: swapper/3 Not tainted 4.19.0-rc1+ #1
[ 62.409662] =============================
[ 62.409664] WARNING: suspicious RCU usage
[ 62.409666] 4.19.0-rc1+ #1 Not tainted
[ 62.409667] -----------------------------
[ 62.409669] ./include/linux/rcupdate.h:680 rcu_read_unlock() used illegally while idle!
[ 62.409670]
other info that might help us debug this:
[ 62.409673]
RCU used illegally from idle CPU!
rcu_scheduler_active = 2, debug_locks = 1
[ 62.409675] RCU used illegally from extended quiescent state!
[ 62.409678] 1 lock held by swapper/0/0:
[ 62.409679] #0: 000000004557ee0e (
[ 62.409683] Hardware name: LENOVO 2320CTO/2320CTO, BIOS G2ET86WW (2.06 ) 11/13/2012
[ 62.409684] Call Trace:
[ 62.409689] dump_stack+0x85/0xcb
[ 62.409693] perf_output_end+0x61/0x70
[ 62.409693] rcu_read_lock){....}, at: perf_event_output_forward+0x0/0x130
[ 62.409699] perf_event_output_forward+0x90/0x130
[ 62.409702]
stack backtrace:
[ 62.409708] __perf_event_overflow+0x52/0xe0
[ 62.409715] perf_swevent_overflow+0x91/0xb0
[ 62.409720] perf_tp_event+0x11a/0x350
[ 62.409740] ? __lock_acquire+0x2ce/0x1350
[ 62.409745] ? retint_kernel+0x2d/0x2d
[ 62.409753] ? find_held_lock+0x2d/0x90
[ 62.409757] ? tick_nohz_get_sleep_length+0x83/0xb0
[ 62.409768] ? timer_clear_idle+0x12/0x30
[ 62.409776] ? perf_trace_cpu+0xbb/0xd0
[ 62.409780] perf_trace_cpu+0xbb/0xd0
[ 62.409789] cpuidle_enter_state+0x185/0x340
[ 62.409797] do_idle+0x1eb/0x260
[ 62.409804] cpu_startup_entry+0x5f/0x70
[ 62.409810] start_secondary+0x192/0x1b0
[ 62.409815] secondary_startup_64+0xa4/0xb0
[ 62.409830] CPU: 2 PID: 0 Comm: swapper/2 Not tainted 4.19.0-rc1+ #1
[ 62.409833] Hardware name: LENOVO 2320CTO/2320CTO, BIOS G2ET86WW (2.06 ) 11/13/2012
[ 62.409836] Call Trace:
[ 62.409841] dump_stack+0x85/0xcb
[ 62.409846] perf_output_begin_forward+0x2a1/0x320
[ 62.409864] ? __lock_acquire+0x2ce/0x1350
[ 62.409882] ? sched_clock+0x5/0x10
[ 62.409890] ? sched_clock+0x5/0x10
[ 62.409897] ? sched_clock_cpu+0x10/0xd0
[ 62.409904] ? perf_event_output_forward+0x70/0x130
[ 62.409908] ? perf_prepare_sample+0x53/0x460
[ 62.409914] perf_event_output_forward+0x70/0x130
[ 62.409920] ? unwind_next_frame+0x5b/0x540
[ 62.409928] __perf_event_overflow+0x52/0xe0
[ 62.409934] perf_swevent_overflow+0x91/0xb0
[ 62.409940] perf_tp_event+0x11a/0x350
[ 62.409960] ? lock_acquire+0x9e/0x1b0
[ 62.409969] ? lock_acquire+0x9e/0x1b0
[ 62.409973] ? find_held_lock+0x2d/0x90
[ 62.409978] ? hrtimer_next_event_without+0x67/0x90
[ 62.409991] ? perf_trace_cpu+0xbb/0xd0
[ 62.409995] perf_trace_cpu+0xbb/0xd0
[ 62.410003] cpuidle_enter_state+0x185/0x340
[ 62.411086] do_idle+0x1eb/0x260
[ 62.411092] cpu_startup_entry+0x5f/0x70
[ 62.411108] start_secondary+0x192/0x1b0
[ 62.411111] secondary_startup_64+0xa4/0xb0
[ 62.411127] CPU: 0 PID: 0 Comm: swapper/0 Not tainted 4.19.0-rc1+ #1
[ 62.411217] =============================
[ 62.411218] Hardware name: LENOVO 2320CTO/2320CTO, BIOS G2ET86WW (2.06 ) 11/13/2012
[ 62.411219] WARNING: suspicious RCU usage
[ 62.411219] Call Trace:
[ 62.411220] 4.19.0-rc1+ #1 Not tainted
[ 62.411220] -----------------------------
[ 62.411221] ./include/trace/events/sched.h:90 suspicious rcu_dereference_check() usage!
[ 62.411224] dump_stack+0x85/0xcb
[ 62.411225] other info that might help us debug this:
[ 62.411228] perf_event_output_forward+0x123/0x130
[ 62.411230] RCU used illegally from idle CPU!
[ 62.411231] rcu_scheduler_active = 2, debug_locks = 1
[ 62.411232] RCU used illegally from extended quiescent state!
[ 62.411233] 4 locks held by swapper/2/0:
[ 62.411233] #0: 000000004557ee0e (rcu_read_lock
[ 62.411237] __perf_event_overflow+0x52/0xe0
[ 62.411238] ){....}, at: perf_event_output_forward+0x0/0x130
[ 62.411240] #1: 000000004557ee0e (
[ 62.411242] perf_swevent_overflow+0x91/0xb0
[ 62.411243] rcu_read_lock){....}, at: perf_output_begin_forward+0x5/0x320
[ 62.411246] #2:
[ 62.411247] perf_tp_event+0x11a/0x350
[ 62.411247] 00000000e39f6018 (
[ 62.411250] ? find_held_lock+0x2d/0x90
[ 62.411250] (console_sem).lock){-.-.}, at: up+0x12/0x60
[ 62.411253] #3: 00000000c62ce8a4 (&p->pi_lock){-.-.}, at: try_to_wake_up+0x2d/0x4f0
[ 62.411259] stack backtrace:
[ 62.411260] CPU: 2 PID: 0 Comm: swapper/2 Not tainted 4.19.0-rc1+ #1
[ 62.411261] Hardware name: LENOVO 2320CTO/2320CTO, BIOS G2ET86WW (2.06 ) 11/13/2012
[ 62.411263] ? __lock_acquire+0x2ce/0x1350
[ 62.411263] Call Trace:
[ 62.411264] dump_stack+0x85/0xcb
[ 62.411265] try_to_wake_up+0x45b/0x4f0
[ 62.411266] ? console_unlock+0x226/0x5f0
[ 62.411267] up+0x40/0x60
[ 62.411268] __up_console_sem+0x41/0x70
[ 62.411268] console_unlock+0x125/0x5f0
[ 62.411270] vprintk_emit+0x116/0x340
[ 62.411270] ? is_bpf_text_address+0x65/0xe0
[ 62.411271] ? cpuidle_enter_state+0x185/0x340
[ 62.411273] ? __lock_acquire+0x2ce/0x1350
[ 62.411273] printk+0x43/0x4b
[ 62.411274] ? rcu_dynticks_eqs_enter+0x12/0x30
[ 62.411275] ? cpuidle_enter_state+0x185/0x340
[ 62.411277] ? retint_kernel+0x2d/0x2d
[ 62.411278] ? cpuidle_enter_state+0x185/0x340
[ 62.411279] show_trace_log_lvl+0x217/0x3d0
[ 62.411280] ? cpuidle_enter_state+0x185/0x340
[ 62.411281] ? cpuidle_enter_state+0x185/0x340
[ 62.411281] dump_stack+0x85/0xcb
[ 62.411283] perf_output_begin_forward+0x2a1/0x320
[ 62.411284] ? find_held_lock+0x2d/0x90
[ 62.411284] ? __lock_acquire+0x2ce/0x1350
[ 62.411285] ? sched_clock+0x5/0x10
[ 62.411286] ? sched_clock+0x5/0x10
[ 62.411288] ? tick_nohz_get_sleep_length+0x83/0xb0
[ 62.411289] ? sched_clock_cpu+0x10/0xd0
[ 62.411290] ? perf_event_output_forward+0x70/0x130
[ 62.411291] ? perf_prepare_sample+0x53/0x460
[ 62.411291] perf_event_output_forward+0x70/0x130
[ 62.411292] ? unwind_next_frame+0x5b/0x540
[ 62.411293] __perf_event_overflow+0x52/0xe0
[ 62.411294] perf_swevent_overflow+0x91/0xb0
[ 62.411295] perf_tp_event+0x11a/0x350
[ 62.411296] ? lock_acquire+0x9e/0x1b0
[ 62.411297] ? lock_acquire+0x9e/0x1b0
[ 62.411298] ? perf_trace_cpu+0xbb/0xd0
[ 62.411299] ? find_held_lock+0x2d/0x90
[ 62.411300] ? hrtimer_next_event_without+0x67/0x90
[ 62.411301] ? perf_trace_cpu+0xbb/0xd0
[ 62.411303] ? perf_trace_buf_alloc+0x5a/0xa0
[ 62.411304] perf_trace_cpu+0xbb/0xd0
[ 62.411305] cpuidle_enter_state+0x185/0x340
[ 62.411306] perf_trace_cpu+0xbb/0xd0
[ 62.411307] do_idle+0x1eb/0x260
[ 62.411308] cpu_startup_entry+0x5f/0x70
[ 62.411309] start_secondary+0x192/0x1b0
[ 62.411310] secondary_startup_64+0xa4/0xb0
[ 62.411311] =============================
[ 62.411312] WARNING: suspicious RCU usage
[ 62.411314] cpuidle_enter_state+0x185/0x340
[ 62.411315] 4.19.0-rc1+ #1 Not tainted
[ 62.411316] -----------------------------
[ 62.411317] ./include/linux/rcupdate.h:631 rcu_read_lock() used illegally while idle!
[ 62.411319] other info that might help us debug this:
[ 62.411321] do_idle+0x1eb/0x260
[ 62.411322] RCU used illegally from idle CPU!
[ 62.411323] rcu_scheduler_active = 2, debug_locks = 1
[ 62.411324] RCU used illegally from extended quiescent state!
[ 62.411325] 5 locks held by swapper/2/0:
[ 62.411326] #0:
[ 62.411327] cpu_startup_entry+0x5f/0x70
[ 62.411328] 000000004557ee0e (rcu_read_lock){....}
[ 62.411332] start_kernel+0x49b/0x4a6
[ 62.411332] , at: perf_event_output_forward+0x0/0x130
[ 62.411333] #1: 000000004557ee0e (rcu_read_lock){....}, at: perf_output_begin_forward+0x5/0x320
[ 62.411338] secondary_startup_64+0xa4/0xb0
[ 62.411339] #2: 00000000e39f6018 ((console_sem).lock){-.-.}, at: up+0x12/0x60
[ 62.411344] #3: 00000000c62ce8a4 (&p->pi_lock){-.-.}, at: try_to_wake_up+0x2d/0x4f0
[ 62.411348] #4: 000000004557ee0e (rcu_read_lock){....}, at: select_task_rq_fair+0x142/0xcf0
[ 62.411353] stack backtrace:
[ 62.411354] CPU: 2 PID: 0 Comm: swapper/2 Not tainted 4.19.0-rc1+ #1
[ 62.411355] Hardware name: LENOVO 2320CTO/2320CTO, BIOS G2ET86WW (2.06 ) 11/13/2012
[ 62.411356] Call Trace:
[ 62.411357] dump_stack+0x85/0xcb
[ 62.411358] select_task_rq_fair+0x32a/0xcf0
[ 62.411358] try_to_wake_up+0x11c/0x4f0
[ 62.411359] ? console_unlock+0x226/0x5f0
[ 62.411359] up+0x40/0x60
[ 62.411361] __up_console_sem+0x41/0x70
[ 62.411361] console_unlock+0x125/0x5f0
[ 62.411362] vprintk_emit+0x116/0x340
[ 62.411363] ? is_bpf_text_address+0x65/0xe0
[ 62.411364] ? cpuidle_enter_state+0x185/0x340
[ 62.411365] printk+0x43/0x4b
[ 62.411366] ? rcu_dynticks_eqs_enter+0x12/0x30
[ 62.411367] ? cpuidle_enter_state+0x185/0x340
[ 62.411368] ? cpuidle_enter_state+0x185/0x340
[ 62.411368] show_trace_log_lvl+0x217/0x3d0
[ 62.411370] ? cpuidle_enter_state+0x185/0x340
[ 62.411370] ? cpuidle_enter_state+0x185/0x340
[ 62.411371] dump_stack+0x85/0xcb
[ 62.411372] perf_output_begin_forward+0x2a1/0x320
[ 62.411373] ? __lock_acquire+0x2ce/0x1350
[ 62.411374] ? sched_clock+0x5/0x10
[ 62.411375] ? sched_clock+0x5/0x10
[ 62.411376] ? sched_clock_cpu+0x10/0xd0
[ 62.411377] ? perf_event_output_forward+0x70/0x130
[ 62.411377] ? perf_prepare_sample+0x53/0x460
[ 62.411379] perf_event_output_forward+0x70/0x130
[ 62.411379] ? unwind_next_frame+0x5b/0x540
[ 62.411380] __perf_event_overflow+0x52/0xe0
[ 62.411381] perf_swevent_overflow+0x91/0xb0
[ 62.411382] perf_tp_event+0x11a/0x350
[ 62.411383] ? lock_acquire+0x9e/0x1b0
[ 62.411384] ? lock_acquire+0x9e/0x1b0
[ 62.411385] ? find_held_lock+0x2d/0x90
[ 62.411386] ? hrtimer_next_event_without+0x67/0x90
[ 62.411386] ? perf_trace_cpu+0xbb/0xd0
[ 62.411387] perf_trace_cpu+0xbb/0xd0
[ 62.411388] cpuidle_enter_state+0x185/0x340
[ 62.411389] do_idle+0x1eb/0x260
[ 62.411390] cpu_startup_entry+0x5f/0x70
[ 62.411391] start_secondary+0x192/0x1b0
[ 62.411392] secondary_startup_64+0xa4/0xb0
[ 62.411393] =============================
[ 62.411395] WARNING: suspicious RCU usage
[ 62.411395] 4.19.0-rc1+ #1 Not tainted
[ 62.411396] -----------------------------
[ 62.411397] kernel/sched/fair.c:6231 suspicious rcu_dereference_check() usage!
[ 62.411399] other info that might help us debug this:
[ 62.411402] RCU used illegally from idle CPU!
[ 62.411402] rcu_scheduler_active = 2, debug_locks = 1
[ 62.411403] RCU used illegally from extended quiescent state!
[ 62.411404] 5 locks held by swapper/2/0:
[ 62.411405] #0: 000000004557ee0e (rcu_read_lock){....}, at: perf_event_output_forward+0x0/0x130
[ 62.411410] #1: 000000004557ee0e (rcu_read_lock){....}, at: perf_output_begin_forward+0x5/0x320
[ 62.411414] #2: 00000000e39f6018 ((console_sem).lock){-.-.}, at: up+0x12/0x60
[ 62.411420] #3: 00000000c62ce8a4 (&p->pi_lock){-.-.}, at: try_to_wake_up+0x2d/0x4f0
[ 62.411424] #4: 000000004557ee0e (rcu_read_lock){....}, at: select_task_rq_fair+0x142/0xcf0
[ 62.411429] stack backtrace:
[ 62.411431] CPU: 2 PID: 0 Comm: swapper/2 Not tainted 4.19.0-rc1+ #1
[ 62.411432] Hardware name: LENOVO 2320CTO/2320CTO, BIOS G2ET86WW (2.06 ) 11/13/2012
[ 62.411433] Call Trace:
[ 62.411433] dump_stack+0x85/0xcb
[ 62.411434] select_task_rq_fair+0x3a5/0xcf0
[ 62.411435] try_to_wake_up+0x11c/0x4f0
[ 62.411436] ? console_unlock+0x226/0x5f0
[ 62.411437] up+0x40/0x60
[ 62.411438] __up_console_sem+0x41/0x70
[ 62.411439] console_unlock+0x125/0x5f0
[ 62.411440] vprintk_emit+0x116/0x340
[ 62.411441] ? is_bpf_text_address+0x65/0xe0
[ 62.411442] ? cpuidle_enter_state+0x185/0x340
[ 62.411442] printk+0x43/0x4b
[ 62.411444] ? rcu_dynticks_eqs_enter+0x12/0x30
[ 62.411444] ? cpuidle_enter_state+0x185/0x340
[ 62.411445] ? cpuidle_enter_state+0x185/0x340
[ 62.411446] show_trace_log_lvl+0x217/0x3d0
[ 62.411447] ? cpuidle_enter_state+0x185/0x340
[ 62.411448] ? cpuidle_enter_state+0x185/0x340
[ 62.411449] dump_stack+0x85/0xcb
[ 62.411450] perf_output_begin_forward+0x2a1/0x320
[ 62.411451] ? __lock_acquire+0x2ce/0x1350
[ 62.411451] ? sched_clock+0x5/0x10
[ 62.411452] ? sched_clock+0x5/0x10
[ 62.411453] ? sched_clock_cpu+0x10/0xd0
[ 62.411454] ? perf_event_output_forward+0x70/0x130
[ 62.411455] ? perf_prepare_sample+0x53/0x460
[ 62.411456] perf_event_output_forward+0x70/0x130
[ 62.411457] ? unwind_next_frame+0x5b/0x540
[ 62.411458] __perf_event_overflow+0x52/0xe0
[ 62.411459] perf_swevent_overflow+0x91/0xb0
[ 62.411460] perf_tp_event+0x11a/0x350
[ 62.411460] ? lock_acquire+0x9e/0x1b0
[ 62.411461] ? lock_acquire+0x9e/0x1b0
[ 62.411462] ? find_held_lock+0x2d/0x90
[ 62.411463] ? hrtimer_next_event_without+0x67/0x90
[ 62.411464] ? perf_trace_cpu+0xbb/0xd0
[ 62.411465] perf_trace_cpu+0xbb/0xd0
[ 62.411466] cpuidle_enter_state+0x185/0x340
[ 62.411467] do_idle+0x1eb/0x260
[ 62.411467] cpu_startup_entry+0x5f/0x70
[ 62.411469] start_secondary+0x192/0x1b0
[ 62.411469] secondary_startup_64+0xa4/0xb0
[ 62.411471] =============================
[ 62.411472] WARNING: suspicious RCU usage
[ 62.411473] 4.19.0-rc1+ #1 Not tainted
[ 62.411474] -----------------------------
[ 62.411475] ./include/linux/rcupdate.h:680 rcu_read_unlock() used illegally while idle!
[ 62.411477] other info that might help us debug this:
[ 62.411479] RCU used illegally from idle CPU!
[ 62.411480] rcu_scheduler_active = 2, debug_locks = 1
[ 62.411481] RCU used illegally from extended quiescent state!
[ 62.411482] 5 locks held by swapper/2/0:
[ 62.411483] #0: 000000004557ee0e (rcu_read_lock){....}, at: perf_event_output_forward+0x0/0x130
[ 62.411487] #1: 000000004557ee0e (rcu_read_lock){....}, at: perf_output_begin_forward+0x5/0x320
[ 62.411492] #2: 00000000e39f6018 ((console_sem).lock){-.-.}, at: up+0x12/0x60
[ 62.411496] #3: 00000000c62ce8a4 (&p->pi_lock){-.-.}, at: try_to_wake_up+0x2d/0x4f0
[ 62.411500] #4: 000000004557ee0e (rcu_read_lock){....}, at: select_task_rq_fair+0x142/0xcf0
[ 62.411506] stack backtrace:
[ 62.411507] CPU: 2 PID: 0 Comm: swapper/2 Not tainted 4.19.0-rc1+ #1
[ 62.411508] Hardware name: LENOVO 2320CTO/2320CTO, BIOS G2ET86WW (2.06 ) 11/13/2012
[ 62.411508] Call Trace:
[ 62.411509] dump_stack+0x85/0xcb
[ 62.411510] select_task_rq_fair+0x35b/0xcf0
[ 62.411511] try_to_wake_up+0x11c/0x4f0
[ 62.411512] ? console_unlock+0x226/0x5f0
[ 62.411513] up+0x40/0x60
[ 62.411514] __up_console_sem+0x41/0x70
[ 62.411515] console_unlock+0x125/0x5f0
[ 62.411515] vprintk_emit+0x116/0x340
[ 62.411517] ? is_bpf_text_address+0x65/0xe0
[ 62.411517] ? cpuidle_enter_state+0x185/
[ 62.411519] Lost 290 message(s)!
--
Regards/Gruss,
Boris.
Good mailing practices for 400: avoid top-posting and trim the reply.
^ permalink raw reply [flat|nested] 11+ messages in thread
* Re: 4.19-rc1: ./include/linux/rcupdate.h:631 rcu_read_lock() used illegally while idle!
2018-09-01 17:35 4.19-rc1: ./include/linux/rcupdate.h:631 rcu_read_lock() used illegally while idle! Borislav Petkov
@ 2018-09-01 17:54 ` Paul E. McKenney
2018-09-01 22:45 ` Steven Rostedt
0 siblings, 1 reply; 11+ messages in thread
From: Paul E. McKenney @ 2018-09-01 17:54 UTC (permalink / raw)
To: Borislav Petkov; +Cc: x86-ml, Peter Zijlstra, lkml, rostedt, joel
On Sat, Sep 01, 2018 at 07:35:59PM +0200, Borislav Petkov wrote:
> This is a huge splat! It haz some perf* and sched* in it, I guess for
> peterz to stare at. And lemme add Paul for good measure too :)
>
> Kernel is -rc1 + 3 microcode loader patches ontop which should not be
> related.
It really is tracing from the idle loop. But I thought that the event
tracing took care of that. Adding Steve and Joel for their thoughts.
Thanx, Paul
> Thx.
>
> ---
> [ 62.409125] =============================
> [ 62.409129] WARNING: suspicious RCU usage
> [ 62.409133] 4.19.0-rc1+ #1 Not tainted
> [ 62.409136] -----------------------------
> [ 62.409140] ./include/linux/rcupdate.h:631 rcu_read_lock() used illegally while idle!
> [ 62.409143]
> other info that might help us debug this:
>
> [ 62.409147]
> RCU used illegally from idle CPU!
> rcu_scheduler_active = 2, debug_locks = 1
> [ 62.409151] RCU used illegally from extended quiescent state!
> [ 62.409155] 1 lock held by swapper/0/0:
> [ 62.409158] #0: 000000004557ee0e (rcu_read_lock){....}, at: perf_event_output_forward+0x0/0x130
> [ 62.409175]
> stack backtrace:
> [ 62.409180] CPU: 0 PID: 0 Comm: swapper/0 Not tainted 4.19.0-rc1+ #1
> [ 62.409183] Hardware name: LENOVO 2320CTO/2320CTO, BIOS G2ET86WW (2.06 ) 11/13/2012
> [ 62.409187] Call Trace:
> [ 62.409196] dump_stack+0x85/0xcb
> [ 62.409203] perf_event_output_forward+0xf6/0x130
> [ 62.409215] __perf_event_overflow+0x52/0xe0
> [ 62.409223] perf_swevent_overflow+0x91/0xb0
> [ 62.409229] perf_tp_event+0x11a/0x350
> [ 62.409235] ? find_held_lock+0x2d/0x90
> [ 62.409251] ? __lock_acquire+0x2ce/0x1350
> [ 62.409263] ? __lock_acquire+0x2ce/0x1350
> [ 62.409270] ? retint_kernel+0x2d/0x2d
> [ 62.409278] ? find_held_lock+0x2d/0x90
> [ 62.409285] ? tick_nohz_get_sleep_length+0x83/0xb0
> [ 62.409299] ? perf_trace_cpu+0xbb/0xd0
> [ 62.409306] ? perf_trace_buf_alloc+0x5a/0xa0
> [ 62.409311] perf_trace_cpu+0xbb/0xd0
> [ 62.409323] cpuidle_enter_state+0x185/0x340
> [ 62.409332] do_idle+0x1eb/0x260
> [ 62.409340] cpu_startup_entry+0x5f/0x70
> [ 62.409347] start_kernel+0x49b/0x4a6
>
> [ 62.409357] secondary_startup_64+0xa4/0xb0
>
> [ 62.409374] =============================
> [ 62.409375] WARNING: suspicious RCU usage
> [ 62.409377] 4.19.0-rc1+ #1 Not tainted
> [ 62.409378] -----------------------------
> [ 62.409380] kernel/events/ring_buffer.c:138 suspicious rcu_dereference_check() usage!
> [ 62.409381]
> other info that might help us debug this:
>
> [ 62.409382]
> RCU used illegally from idle CPU!
> rcu_scheduler_active = 2, debug_locks = 1
> [ 62.409384] RCU used illegally from extended quiescent state!
> [ 62.409386] 2 locks held by swapper/0/0:
> [ 62.409387] #0: 000000004557ee0e (
> [ 62.409390] =============================
> [ 62.409391] WARNING: suspicious RCU usage
> [ 62.409393] rcu_read_lock){....}, at: perf_event_output_forward+0x0/0x130
> [ 62.409398] 4.19.0-rc1+ #1 Not tainted
> [ 62.409399] -----------------------------
> [ 62.409400] #1: 000000004557ee0e
> [ 62.409403] ./include/linux/rcupdate.h:631 rcu_read_lock() used illegally while idle!
> [ 62.409403] (rcu_read_lock){....}
> [ 62.409406]
> other info that might help us debug this:
>
> [ 62.409408] , at: perf_output_begin_forward+0x5/0x320
> [ 62.409409]
> stack backtrace:
> [ 62.409412] CPU: 0 PID: 0 Comm: swapper/0 Not tainted 4.19.0-rc1+ #1
> [ 62.409413] Hardware name: LENOVO 2320CTO/2320CTO, BIOS G2ET86WW (2.06 ) 11/13/2012
> [ 62.409414] Call Trace:
> [ 62.409418] dump_stack+0x85/0xcb
> [ 62.409422] perf_output_begin_forward+0x2d2/0x320
> [ 62.409423]
> RCU used illegally from idle CPU!
> rcu_scheduler_active = 2, debug_locks = 1
> [ 62.409424] RCU used illegally from extended quiescent state!
> [ 62.409428] ? find_held_lock+0x2d/0x90
> [ 62.409433] ? vprintk_emit+0x2ce/0x340
> [ 62.409434] 2 locks held by swapper/2/0:
> [ 62.409435] #0: 000000004557ee0e (rcu_read_lock){....}, at: perf_event_output_forward+0x0/0x130
> [ 62.409445] ? find_held_lock+0x2d/0x90
> [ 62.409449] ? is_bpf_text_address+0x65/0xe0
> [ 62.409450] #1: 000000004557ee0e (rcu_read_lock){....}, at: perf_output_begin_forward+0x5/0x320
> [ 62.409457]
> stack backtrace:
> [ 62.409462] ? rcu_dynticks_eqs_enter+0x12/0x30
> [ 62.409466] ? kernel_text_address+0x8f/0xf0
> [ 62.409472] ? __kernel_text_address+0xe/0x30
> [ 62.409477] ? show_trace_log_lvl+0x19f/0x3d0
> [ 62.409484] ? secondary_startup_64+0xa4/0xb0
>
> [ 62.409492] =============================
> [ 62.409494] ? sched_clock+0x5/0x10
> [ 62.409496] ? sched_clock+0x5/0x10
> [ 62.409500] ? sched_clock_cpu+0x10/0xd0
> [ 62.409504] WARNING: suspicious RCU usage
> [ 62.409506] ? perf_event_output_forward+0x70/0x130
> [ 62.409508] ? perf_prepare_sample+0x53/0x460
> [ 62.409513] 4.19.0-rc1+ #1 Not tainted
> [ 62.409514] perf_event_output_forward+0x70/0x130
> [ 62.409518] -----------------------------
> [ 62.409522] ./include/linux/rcupdate.h:680 rcu_read_unlock() used illegally while idle!
> [ 62.409523] __perf_event_overflow+0x52/0xe0
> [ 62.409528] perf_swevent_overflow+0x91/0xb0
> [ 62.409529]
> other info that might help us debug this:
>
> [ 62.409531]
> RCU used illegally from idle CPU!
> rcu_scheduler_active = 2, debug_locks = 1
> [ 62.409533] RCU used illegally from extended quiescent state!
> [ 62.409536] 2 locks held by swapper/3/0:
> [ 62.409537] #0: 000000004557ee0e (rcu_read_lock){....}
> [ 62.409544] perf_tp_event+0x11a/0x350
> [ 62.409547] ? find_held_lock+0x2d/0x90
> [ 62.409552] , at: perf_event_output_forward+0x0/0x130
> [ 62.409555] #1: 000000004557ee0e (
> [ 62.409560] ? __lock_acquire+0x2ce/0x1350
> [ 62.409564] rcu_read_lock){....}, at: perf_output_begin_forward+0x5/0x320
> [ 62.409569] ? __lock_acquire+0x2ce/0x1350
> [ 62.409573] ? retint_kernel+0x2d/0x2d
> [ 62.409576]
> stack backtrace:
> [ 62.409579] ? find_held_lock+0x2d/0x90
> [ 62.409583] ? tick_nohz_get_sleep_length+0x83/0xb0
> [ 62.409595] ? perf_trace_cpu+0xbb/0xd0
> [ 62.409601] ? perf_trace_buf_alloc+0x5a/0xa0
> [ 62.409606] perf_trace_cpu+0xbb/0xd0
> [ 62.409615] cpuidle_enter_state+0x185/0x340
> [ 62.409624] do_idle+0x1eb/0x260
> [ 62.409631] cpu_startup_entry+0x5f/0x70
> [ 62.409637] start_kernel+0x49b/0x4a6
> [ 62.409644] secondary_startup_64+0xa4/0xb0
> [ 62.409661] CPU: 3 PID: 0 Comm: swapper/3 Not tainted 4.19.0-rc1+ #1
>
> [ 62.409662] =============================
> [ 62.409664] WARNING: suspicious RCU usage
> [ 62.409666] 4.19.0-rc1+ #1 Not tainted
> [ 62.409667] -----------------------------
> [ 62.409669] ./include/linux/rcupdate.h:680 rcu_read_unlock() used illegally while idle!
> [ 62.409670]
> other info that might help us debug this:
>
> [ 62.409673]
> RCU used illegally from idle CPU!
> rcu_scheduler_active = 2, debug_locks = 1
> [ 62.409675] RCU used illegally from extended quiescent state!
> [ 62.409678] 1 lock held by swapper/0/0:
> [ 62.409679] #0: 000000004557ee0e (
> [ 62.409683] Hardware name: LENOVO 2320CTO/2320CTO, BIOS G2ET86WW (2.06 ) 11/13/2012
> [ 62.409684] Call Trace:
> [ 62.409689] dump_stack+0x85/0xcb
> [ 62.409693] perf_output_end+0x61/0x70
> [ 62.409693] rcu_read_lock){....}, at: perf_event_output_forward+0x0/0x130
> [ 62.409699] perf_event_output_forward+0x90/0x130
> [ 62.409702]
> stack backtrace:
> [ 62.409708] __perf_event_overflow+0x52/0xe0
> [ 62.409715] perf_swevent_overflow+0x91/0xb0
> [ 62.409720] perf_tp_event+0x11a/0x350
> [ 62.409740] ? __lock_acquire+0x2ce/0x1350
> [ 62.409745] ? retint_kernel+0x2d/0x2d
> [ 62.409753] ? find_held_lock+0x2d/0x90
> [ 62.409757] ? tick_nohz_get_sleep_length+0x83/0xb0
> [ 62.409768] ? timer_clear_idle+0x12/0x30
> [ 62.409776] ? perf_trace_cpu+0xbb/0xd0
> [ 62.409780] perf_trace_cpu+0xbb/0xd0
> [ 62.409789] cpuidle_enter_state+0x185/0x340
> [ 62.409797] do_idle+0x1eb/0x260
> [ 62.409804] cpu_startup_entry+0x5f/0x70
> [ 62.409810] start_secondary+0x192/0x1b0
> [ 62.409815] secondary_startup_64+0xa4/0xb0
> [ 62.409830] CPU: 2 PID: 0 Comm: swapper/2 Not tainted 4.19.0-rc1+ #1
> [ 62.409833] Hardware name: LENOVO 2320CTO/2320CTO, BIOS G2ET86WW (2.06 ) 11/13/2012
> [ 62.409836] Call Trace:
> [ 62.409841] dump_stack+0x85/0xcb
> [ 62.409846] perf_output_begin_forward+0x2a1/0x320
> [ 62.409864] ? __lock_acquire+0x2ce/0x1350
> [ 62.409882] ? sched_clock+0x5/0x10
> [ 62.409890] ? sched_clock+0x5/0x10
> [ 62.409897] ? sched_clock_cpu+0x10/0xd0
> [ 62.409904] ? perf_event_output_forward+0x70/0x130
> [ 62.409908] ? perf_prepare_sample+0x53/0x460
> [ 62.409914] perf_event_output_forward+0x70/0x130
> [ 62.409920] ? unwind_next_frame+0x5b/0x540
> [ 62.409928] __perf_event_overflow+0x52/0xe0
> [ 62.409934] perf_swevent_overflow+0x91/0xb0
> [ 62.409940] perf_tp_event+0x11a/0x350
> [ 62.409960] ? lock_acquire+0x9e/0x1b0
> [ 62.409969] ? lock_acquire+0x9e/0x1b0
> [ 62.409973] ? find_held_lock+0x2d/0x90
> [ 62.409978] ? hrtimer_next_event_without+0x67/0x90
> [ 62.409991] ? perf_trace_cpu+0xbb/0xd0
> [ 62.409995] perf_trace_cpu+0xbb/0xd0
> [ 62.410003] cpuidle_enter_state+0x185/0x340
> [ 62.411086] do_idle+0x1eb/0x260
> [ 62.411092] cpu_startup_entry+0x5f/0x70
> [ 62.411108] start_secondary+0x192/0x1b0
> [ 62.411111] secondary_startup_64+0xa4/0xb0
> [ 62.411127] CPU: 0 PID: 0 Comm: swapper/0 Not tainted 4.19.0-rc1+ #1
>
> [ 62.411217] =============================
> [ 62.411218] Hardware name: LENOVO 2320CTO/2320CTO, BIOS G2ET86WW (2.06 ) 11/13/2012
> [ 62.411219] WARNING: suspicious RCU usage
> [ 62.411219] Call Trace:
> [ 62.411220] 4.19.0-rc1+ #1 Not tainted
> [ 62.411220] -----------------------------
> [ 62.411221] ./include/trace/events/sched.h:90 suspicious rcu_dereference_check() usage!
> [ 62.411224] dump_stack+0x85/0xcb
>
> [ 62.411225] other info that might help us debug this:
>
> [ 62.411228] perf_event_output_forward+0x123/0x130
>
> [ 62.411230] RCU used illegally from idle CPU!
> [ 62.411231] rcu_scheduler_active = 2, debug_locks = 1
> [ 62.411232] RCU used illegally from extended quiescent state!
> [ 62.411233] 4 locks held by swapper/2/0:
> [ 62.411233] #0: 000000004557ee0e (rcu_read_lock
> [ 62.411237] __perf_event_overflow+0x52/0xe0
> [ 62.411238] ){....}, at: perf_event_output_forward+0x0/0x130
> [ 62.411240] #1: 000000004557ee0e (
> [ 62.411242] perf_swevent_overflow+0x91/0xb0
> [ 62.411243] rcu_read_lock){....}, at: perf_output_begin_forward+0x5/0x320
> [ 62.411246] #2:
> [ 62.411247] perf_tp_event+0x11a/0x350
> [ 62.411247] 00000000e39f6018 (
> [ 62.411250] ? find_held_lock+0x2d/0x90
> [ 62.411250] (console_sem).lock){-.-.}, at: up+0x12/0x60
> [ 62.411253] #3: 00000000c62ce8a4 (&p->pi_lock){-.-.}, at: try_to_wake_up+0x2d/0x4f0
>
> [ 62.411259] stack backtrace:
> [ 62.411260] CPU: 2 PID: 0 Comm: swapper/2 Not tainted 4.19.0-rc1+ #1
> [ 62.411261] Hardware name: LENOVO 2320CTO/2320CTO, BIOS G2ET86WW (2.06 ) 11/13/2012
> [ 62.411263] ? __lock_acquire+0x2ce/0x1350
> [ 62.411263] Call Trace:
> [ 62.411264] dump_stack+0x85/0xcb
> [ 62.411265] try_to_wake_up+0x45b/0x4f0
> [ 62.411266] ? console_unlock+0x226/0x5f0
> [ 62.411267] up+0x40/0x60
> [ 62.411268] __up_console_sem+0x41/0x70
> [ 62.411268] console_unlock+0x125/0x5f0
> [ 62.411270] vprintk_emit+0x116/0x340
> [ 62.411270] ? is_bpf_text_address+0x65/0xe0
> [ 62.411271] ? cpuidle_enter_state+0x185/0x340
> [ 62.411273] ? __lock_acquire+0x2ce/0x1350
> [ 62.411273] printk+0x43/0x4b
> [ 62.411274] ? rcu_dynticks_eqs_enter+0x12/0x30
> [ 62.411275] ? cpuidle_enter_state+0x185/0x340
> [ 62.411277] ? retint_kernel+0x2d/0x2d
> [ 62.411278] ? cpuidle_enter_state+0x185/0x340
> [ 62.411279] show_trace_log_lvl+0x217/0x3d0
> [ 62.411280] ? cpuidle_enter_state+0x185/0x340
> [ 62.411281] ? cpuidle_enter_state+0x185/0x340
> [ 62.411281] dump_stack+0x85/0xcb
> [ 62.411283] perf_output_begin_forward+0x2a1/0x320
> [ 62.411284] ? find_held_lock+0x2d/0x90
> [ 62.411284] ? __lock_acquire+0x2ce/0x1350
> [ 62.411285] ? sched_clock+0x5/0x10
> [ 62.411286] ? sched_clock+0x5/0x10
> [ 62.411288] ? tick_nohz_get_sleep_length+0x83/0xb0
> [ 62.411289] ? sched_clock_cpu+0x10/0xd0
> [ 62.411290] ? perf_event_output_forward+0x70/0x130
> [ 62.411291] ? perf_prepare_sample+0x53/0x460
> [ 62.411291] perf_event_output_forward+0x70/0x130
> [ 62.411292] ? unwind_next_frame+0x5b/0x540
> [ 62.411293] __perf_event_overflow+0x52/0xe0
> [ 62.411294] perf_swevent_overflow+0x91/0xb0
> [ 62.411295] perf_tp_event+0x11a/0x350
> [ 62.411296] ? lock_acquire+0x9e/0x1b0
> [ 62.411297] ? lock_acquire+0x9e/0x1b0
> [ 62.411298] ? perf_trace_cpu+0xbb/0xd0
> [ 62.411299] ? find_held_lock+0x2d/0x90
> [ 62.411300] ? hrtimer_next_event_without+0x67/0x90
> [ 62.411301] ? perf_trace_cpu+0xbb/0xd0
> [ 62.411303] ? perf_trace_buf_alloc+0x5a/0xa0
> [ 62.411304] perf_trace_cpu+0xbb/0xd0
> [ 62.411305] cpuidle_enter_state+0x185/0x340
> [ 62.411306] perf_trace_cpu+0xbb/0xd0
> [ 62.411307] do_idle+0x1eb/0x260
> [ 62.411308] cpu_startup_entry+0x5f/0x70
> [ 62.411309] start_secondary+0x192/0x1b0
> [ 62.411310] secondary_startup_64+0xa4/0xb0
>
> [ 62.411311] =============================
> [ 62.411312] WARNING: suspicious RCU usage
> [ 62.411314] cpuidle_enter_state+0x185/0x340
> [ 62.411315] 4.19.0-rc1+ #1 Not tainted
> [ 62.411316] -----------------------------
> [ 62.411317] ./include/linux/rcupdate.h:631 rcu_read_lock() used illegally while idle!
>
> [ 62.411319] other info that might help us debug this:
>
> [ 62.411321] do_idle+0x1eb/0x260
>
> [ 62.411322] RCU used illegally from idle CPU!
> [ 62.411323] rcu_scheduler_active = 2, debug_locks = 1
> [ 62.411324] RCU used illegally from extended quiescent state!
> [ 62.411325] 5 locks held by swapper/2/0:
> [ 62.411326] #0:
> [ 62.411327] cpu_startup_entry+0x5f/0x70
> [ 62.411328] 000000004557ee0e (rcu_read_lock){....}
> [ 62.411332] start_kernel+0x49b/0x4a6
> [ 62.411332] , at: perf_event_output_forward+0x0/0x130
> [ 62.411333] #1: 000000004557ee0e (rcu_read_lock){....}, at: perf_output_begin_forward+0x5/0x320
> [ 62.411338] secondary_startup_64+0xa4/0xb0
> [ 62.411339] #2: 00000000e39f6018 ((console_sem).lock){-.-.}, at: up+0x12/0x60
> [ 62.411344] #3: 00000000c62ce8a4 (&p->pi_lock){-.-.}, at: try_to_wake_up+0x2d/0x4f0
> [ 62.411348] #4: 000000004557ee0e (rcu_read_lock){....}, at: select_task_rq_fair+0x142/0xcf0
>
> [ 62.411353] stack backtrace:
> [ 62.411354] CPU: 2 PID: 0 Comm: swapper/2 Not tainted 4.19.0-rc1+ #1
> [ 62.411355] Hardware name: LENOVO 2320CTO/2320CTO, BIOS G2ET86WW (2.06 ) 11/13/2012
> [ 62.411356] Call Trace:
> [ 62.411357] dump_stack+0x85/0xcb
> [ 62.411358] select_task_rq_fair+0x32a/0xcf0
> [ 62.411358] try_to_wake_up+0x11c/0x4f0
> [ 62.411359] ? console_unlock+0x226/0x5f0
> [ 62.411359] up+0x40/0x60
> [ 62.411361] __up_console_sem+0x41/0x70
> [ 62.411361] console_unlock+0x125/0x5f0
> [ 62.411362] vprintk_emit+0x116/0x340
> [ 62.411363] ? is_bpf_text_address+0x65/0xe0
> [ 62.411364] ? cpuidle_enter_state+0x185/0x340
> [ 62.411365] printk+0x43/0x4b
> [ 62.411366] ? rcu_dynticks_eqs_enter+0x12/0x30
> [ 62.411367] ? cpuidle_enter_state+0x185/0x340
> [ 62.411368] ? cpuidle_enter_state+0x185/0x340
> [ 62.411368] show_trace_log_lvl+0x217/0x3d0
> [ 62.411370] ? cpuidle_enter_state+0x185/0x340
> [ 62.411370] ? cpuidle_enter_state+0x185/0x340
> [ 62.411371] dump_stack+0x85/0xcb
> [ 62.411372] perf_output_begin_forward+0x2a1/0x320
> [ 62.411373] ? __lock_acquire+0x2ce/0x1350
> [ 62.411374] ? sched_clock+0x5/0x10
> [ 62.411375] ? sched_clock+0x5/0x10
> [ 62.411376] ? sched_clock_cpu+0x10/0xd0
> [ 62.411377] ? perf_event_output_forward+0x70/0x130
> [ 62.411377] ? perf_prepare_sample+0x53/0x460
> [ 62.411379] perf_event_output_forward+0x70/0x130
> [ 62.411379] ? unwind_next_frame+0x5b/0x540
> [ 62.411380] __perf_event_overflow+0x52/0xe0
> [ 62.411381] perf_swevent_overflow+0x91/0xb0
> [ 62.411382] perf_tp_event+0x11a/0x350
> [ 62.411383] ? lock_acquire+0x9e/0x1b0
> [ 62.411384] ? lock_acquire+0x9e/0x1b0
> [ 62.411385] ? find_held_lock+0x2d/0x90
> [ 62.411386] ? hrtimer_next_event_without+0x67/0x90
> [ 62.411386] ? perf_trace_cpu+0xbb/0xd0
> [ 62.411387] perf_trace_cpu+0xbb/0xd0
> [ 62.411388] cpuidle_enter_state+0x185/0x340
> [ 62.411389] do_idle+0x1eb/0x260
> [ 62.411390] cpu_startup_entry+0x5f/0x70
> [ 62.411391] start_secondary+0x192/0x1b0
> [ 62.411392] secondary_startup_64+0xa4/0xb0
>
> [ 62.411393] =============================
> [ 62.411395] WARNING: suspicious RCU usage
> [ 62.411395] 4.19.0-rc1+ #1 Not tainted
> [ 62.411396] -----------------------------
> [ 62.411397] kernel/sched/fair.c:6231 suspicious rcu_dereference_check() usage!
>
> [ 62.411399] other info that might help us debug this:
>
>
> [ 62.411402] RCU used illegally from idle CPU!
> [ 62.411402] rcu_scheduler_active = 2, debug_locks = 1
> [ 62.411403] RCU used illegally from extended quiescent state!
> [ 62.411404] 5 locks held by swapper/2/0:
> [ 62.411405] #0: 000000004557ee0e (rcu_read_lock){....}, at: perf_event_output_forward+0x0/0x130
> [ 62.411410] #1: 000000004557ee0e (rcu_read_lock){....}, at: perf_output_begin_forward+0x5/0x320
> [ 62.411414] #2: 00000000e39f6018 ((console_sem).lock){-.-.}, at: up+0x12/0x60
> [ 62.411420] #3: 00000000c62ce8a4 (&p->pi_lock){-.-.}, at: try_to_wake_up+0x2d/0x4f0
> [ 62.411424] #4: 000000004557ee0e (rcu_read_lock){....}, at: select_task_rq_fair+0x142/0xcf0
>
> [ 62.411429] stack backtrace:
> [ 62.411431] CPU: 2 PID: 0 Comm: swapper/2 Not tainted 4.19.0-rc1+ #1
> [ 62.411432] Hardware name: LENOVO 2320CTO/2320CTO, BIOS G2ET86WW (2.06 ) 11/13/2012
> [ 62.411433] Call Trace:
> [ 62.411433] dump_stack+0x85/0xcb
> [ 62.411434] select_task_rq_fair+0x3a5/0xcf0
> [ 62.411435] try_to_wake_up+0x11c/0x4f0
> [ 62.411436] ? console_unlock+0x226/0x5f0
> [ 62.411437] up+0x40/0x60
> [ 62.411438] __up_console_sem+0x41/0x70
> [ 62.411439] console_unlock+0x125/0x5f0
> [ 62.411440] vprintk_emit+0x116/0x340
> [ 62.411441] ? is_bpf_text_address+0x65/0xe0
> [ 62.411442] ? cpuidle_enter_state+0x185/0x340
> [ 62.411442] printk+0x43/0x4b
> [ 62.411444] ? rcu_dynticks_eqs_enter+0x12/0x30
> [ 62.411444] ? cpuidle_enter_state+0x185/0x340
> [ 62.411445] ? cpuidle_enter_state+0x185/0x340
> [ 62.411446] show_trace_log_lvl+0x217/0x3d0
> [ 62.411447] ? cpuidle_enter_state+0x185/0x340
> [ 62.411448] ? cpuidle_enter_state+0x185/0x340
> [ 62.411449] dump_stack+0x85/0xcb
> [ 62.411450] perf_output_begin_forward+0x2a1/0x320
> [ 62.411451] ? __lock_acquire+0x2ce/0x1350
> [ 62.411451] ? sched_clock+0x5/0x10
> [ 62.411452] ? sched_clock+0x5/0x10
> [ 62.411453] ? sched_clock_cpu+0x10/0xd0
> [ 62.411454] ? perf_event_output_forward+0x70/0x130
> [ 62.411455] ? perf_prepare_sample+0x53/0x460
> [ 62.411456] perf_event_output_forward+0x70/0x130
> [ 62.411457] ? unwind_next_frame+0x5b/0x540
> [ 62.411458] __perf_event_overflow+0x52/0xe0
> [ 62.411459] perf_swevent_overflow+0x91/0xb0
> [ 62.411460] perf_tp_event+0x11a/0x350
> [ 62.411460] ? lock_acquire+0x9e/0x1b0
> [ 62.411461] ? lock_acquire+0x9e/0x1b0
> [ 62.411462] ? find_held_lock+0x2d/0x90
> [ 62.411463] ? hrtimer_next_event_without+0x67/0x90
> [ 62.411464] ? perf_trace_cpu+0xbb/0xd0
> [ 62.411465] perf_trace_cpu+0xbb/0xd0
> [ 62.411466] cpuidle_enter_state+0x185/0x340
> [ 62.411467] do_idle+0x1eb/0x260
> [ 62.411467] cpu_startup_entry+0x5f/0x70
> [ 62.411469] start_secondary+0x192/0x1b0
> [ 62.411469] secondary_startup_64+0xa4/0xb0
>
> [ 62.411471] =============================
> [ 62.411472] WARNING: suspicious RCU usage
> [ 62.411473] 4.19.0-rc1+ #1 Not tainted
> [ 62.411474] -----------------------------
> [ 62.411475] ./include/linux/rcupdate.h:680 rcu_read_unlock() used illegally while idle!
>
> [ 62.411477] other info that might help us debug this:
>
>
> [ 62.411479] RCU used illegally from idle CPU!
> [ 62.411480] rcu_scheduler_active = 2, debug_locks = 1
> [ 62.411481] RCU used illegally from extended quiescent state!
> [ 62.411482] 5 locks held by swapper/2/0:
> [ 62.411483] #0: 000000004557ee0e (rcu_read_lock){....}, at: perf_event_output_forward+0x0/0x130
> [ 62.411487] #1: 000000004557ee0e (rcu_read_lock){....}, at: perf_output_begin_forward+0x5/0x320
> [ 62.411492] #2: 00000000e39f6018 ((console_sem).lock){-.-.}, at: up+0x12/0x60
> [ 62.411496] #3: 00000000c62ce8a4 (&p->pi_lock){-.-.}, at: try_to_wake_up+0x2d/0x4f0
> [ 62.411500] #4: 000000004557ee0e (rcu_read_lock){....}, at: select_task_rq_fair+0x142/0xcf0
>
> [ 62.411506] stack backtrace:
> [ 62.411507] CPU: 2 PID: 0 Comm: swapper/2 Not tainted 4.19.0-rc1+ #1
> [ 62.411508] Hardware name: LENOVO 2320CTO/2320CTO, BIOS G2ET86WW (2.06 ) 11/13/2012
> [ 62.411508] Call Trace:
> [ 62.411509] dump_stack+0x85/0xcb
> [ 62.411510] select_task_rq_fair+0x35b/0xcf0
> [ 62.411511] try_to_wake_up+0x11c/0x4f0
> [ 62.411512] ? console_unlock+0x226/0x5f0
> [ 62.411513] up+0x40/0x60
> [ 62.411514] __up_console_sem+0x41/0x70
> [ 62.411515] console_unlock+0x125/0x5f0
> [ 62.411515] vprintk_emit+0x116/0x340
> [ 62.411517] ? is_bpf_text_address+0x65/0xe0
> [ 62.411517] ? cpuidle_enter_state+0x185/
> [ 62.411519] Lost 290 message(s)!
>
> --
> Regards/Gruss,
> Boris.
>
> Good mailing practices for 400: avoid top-posting and trim the reply.
>
^ permalink raw reply [flat|nested] 11+ messages in thread
* Re: 4.19-rc1: ./include/linux/rcupdate.h:631 rcu_read_lock() used illegally while idle!
2018-09-01 17:54 ` Paul E. McKenney
@ 2018-09-01 22:45 ` Steven Rostedt
2018-09-02 4:16 ` Paul E. McKenney
0 siblings, 1 reply; 11+ messages in thread
From: Steven Rostedt @ 2018-09-01 22:45 UTC (permalink / raw)
To: Paul E. McKenney; +Cc: Borislav Petkov, x86-ml, Peter Zijlstra, lkml, joel
On Sat, 1 Sep 2018 10:54:42 -0700
"Paul E. McKenney" <paulmck@linux.vnet.ibm.com> wrote:
> On Sat, Sep 01, 2018 at 07:35:59PM +0200, Borislav Petkov wrote:
> > This is a huge splat! It haz some perf* and sched* in it, I guess for
> > peterz to stare at. And lemme add Paul for good measure too :)
> >
> > Kernel is -rc1 + 3 microcode loader patches ontop which should not be
> > related.
>
> It really is tracing from the idle loop. But I thought that the event
> tracing took care of that. Adding Steve and Joel for their thoughts.
>
> Thanx, Paul
>
> > Thx.
> >
> > ---
> > [ 62.409125] =============================
> > [ 62.409129] WARNING: suspicious RCU usage
> > [ 62.409133] 4.19.0-rc1+ #1 Not tainted
> > [ 62.409136] -----------------------------
> > [ 62.409140] ./include/linux/rcupdate.h:631 rcu_read_lock() used illegally while idle!
> > [ 62.409143]
> > other info that might help us debug this:
> >
> > [ 62.409147]
> > RCU used illegally from idle CPU!
> > rcu_scheduler_active = 2, debug_locks = 1
> > [ 62.409151] RCU used illegally from extended quiescent state!
> > [ 62.409155] 1 lock held by swapper/0/0:
> > [ 62.409158] #0: 000000004557ee0e (rcu_read_lock){....}, at: perf_event_output_forward+0x0/0x130
> > [ 62.409175]
> > stack backtrace:
> > [ 62.409180] CPU: 0 PID: 0 Comm: swapper/0 Not tainted 4.19.0-rc1+ #1
> > [ 62.409183] Hardware name: LENOVO 2320CTO/2320CTO, BIOS G2ET86WW (2.06 ) 11/13/2012
> > [ 62.409187] Call Trace:
> > [ 62.409196] dump_stack+0x85/0xcb
> > [ 62.409203] perf_event_output_forward+0xf6/0x130
I think this is because we switched the trace point code to be
protected by srcu instead of rcu_lock_sched() and a song and dance to
"make RCU watch again" if it is not, but perf is using normal
rcu_read_lock() internally even though it is hooked into the
tracepoint code. Should perf switch to SRCU, or perhaps it can do the
song and dance to make RCU watch again?
-- Steve
> > [ 62.409215] __perf_event_overflow+0x52/0xe0
> > [ 62.409223] perf_swevent_overflow+0x91/0xb0
> > [ 62.409229] perf_tp_event+0x11a/0x350
> > [ 62.409235] ? find_held_lock+0x2d/0x90
> > [ 62.409251] ? __lock_acquire+0x2ce/0x1350
> > [ 62.409263] ? __lock_acquire+0x2ce/0x1350
> > [ 62.409270] ? retint_kernel+0x2d/0x2d
> > [ 62.409278] ? find_held_lock+0x2d/0x90
> > [ 62.409285] ? tick_nohz_get_sleep_length+0x83/0xb0
> > [ 62.409299] ? perf_trace_cpu+0xbb/0xd0
> > [ 62.409306] ? perf_trace_buf_alloc+0x5a/0xa0
> > [ 62.409311] perf_trace_cpu+0xbb/0xd0
> > [ 62.409323] cpuidle_enter_state+0x185/0x340
> > [ 62.409332] do_idle+0x1eb/0x260
> > [ 62.409340] cpu_startup_entry+0x5f/0x70
> > [ 62.409347] start_kernel+0x49b/0x4a6
> >
> > [ 62.409357] secondary_startup_64+0xa4/0xb0
^ permalink raw reply [flat|nested] 11+ messages in thread
* Re: 4.19-rc1: ./include/linux/rcupdate.h:631 rcu_read_lock() used illegally while idle!
2018-09-01 22:45 ` Steven Rostedt
@ 2018-09-02 4:16 ` Paul E. McKenney
2018-09-04 20:26 ` Steven Rostedt
0 siblings, 1 reply; 11+ messages in thread
From: Paul E. McKenney @ 2018-09-02 4:16 UTC (permalink / raw)
To: Steven Rostedt; +Cc: Borislav Petkov, x86-ml, Peter Zijlstra, lkml, joel
On Sat, Sep 01, 2018 at 06:45:31PM -0400, Steven Rostedt wrote:
> On Sat, 1 Sep 2018 10:54:42 -0700
> "Paul E. McKenney" <paulmck@linux.vnet.ibm.com> wrote:
>
> > On Sat, Sep 01, 2018 at 07:35:59PM +0200, Borislav Petkov wrote:
> > > This is a huge splat! It haz some perf* and sched* in it, I guess for
> > > peterz to stare at. And lemme add Paul for good measure too :)
> > >
> > > Kernel is -rc1 + 3 microcode loader patches ontop which should not be
> > > related.
> >
> > It really is tracing from the idle loop. But I thought that the event
> > tracing took care of that. Adding Steve and Joel for their thoughts.
> >
> > Thanx, Paul
> >
> > > Thx.
> > >
> > > ---
> > > [ 62.409125] =============================
> > > [ 62.409129] WARNING: suspicious RCU usage
> > > [ 62.409133] 4.19.0-rc1+ #1 Not tainted
> > > [ 62.409136] -----------------------------
> > > [ 62.409140] ./include/linux/rcupdate.h:631 rcu_read_lock() used illegally while idle!
> > > [ 62.409143]
> > > other info that might help us debug this:
> > >
> > > [ 62.409147]
> > > RCU used illegally from idle CPU!
> > > rcu_scheduler_active = 2, debug_locks = 1
> > > [ 62.409151] RCU used illegally from extended quiescent state!
> > > [ 62.409155] 1 lock held by swapper/0/0:
> > > [ 62.409158] #0: 000000004557ee0e (rcu_read_lock){....}, at: perf_event_output_forward+0x0/0x130
> > > [ 62.409175]
> > > stack backtrace:
> > > [ 62.409180] CPU: 0 PID: 0 Comm: swapper/0 Not tainted 4.19.0-rc1+ #1
> > > [ 62.409183] Hardware name: LENOVO 2320CTO/2320CTO, BIOS G2ET86WW (2.06 ) 11/13/2012
> > > [ 62.409187] Call Trace:
> > > [ 62.409196] dump_stack+0x85/0xcb
> > > [ 62.409203] perf_event_output_forward+0xf6/0x130
>
> I think this is because we switched the trace point code to be
> protected by srcu instead of rcu_lock_sched() and a song and dance to
> "make RCU watch again" if it is not, but perf is using normal
> rcu_read_lock() internally even though it is hooked into the
> tracepoint code. Should perf switch to SRCU, or perhaps it can do the
> song and dance to make RCU watch again?
Well, this is a regression, so in theory we could push my three SRCU
patches into the current merge window, which would allow perf going
to SRCU, thus fixing the above splat. I am OK either way. What would
you prefer?
Thanx, Paul
> -- Steve
>
>
> > > [ 62.409215] __perf_event_overflow+0x52/0xe0
> > > [ 62.409223] perf_swevent_overflow+0x91/0xb0
> > > [ 62.409229] perf_tp_event+0x11a/0x350
> > > [ 62.409235] ? find_held_lock+0x2d/0x90
> > > [ 62.409251] ? __lock_acquire+0x2ce/0x1350
> > > [ 62.409263] ? __lock_acquire+0x2ce/0x1350
> > > [ 62.409270] ? retint_kernel+0x2d/0x2d
> > > [ 62.409278] ? find_held_lock+0x2d/0x90
> > > [ 62.409285] ? tick_nohz_get_sleep_length+0x83/0xb0
> > > [ 62.409299] ? perf_trace_cpu+0xbb/0xd0
> > > [ 62.409306] ? perf_trace_buf_alloc+0x5a/0xa0
> > > [ 62.409311] perf_trace_cpu+0xbb/0xd0
> > > [ 62.409323] cpuidle_enter_state+0x185/0x340
> > > [ 62.409332] do_idle+0x1eb/0x260
> > > [ 62.409340] cpu_startup_entry+0x5f/0x70
> > > [ 62.409347] start_kernel+0x49b/0x4a6
> > >
> > > [ 62.409357] secondary_startup_64+0xa4/0xb0
>
^ permalink raw reply [flat|nested] 11+ messages in thread
* Re: 4.19-rc1: ./include/linux/rcupdate.h:631 rcu_read_lock() used illegally while idle!
2018-09-02 4:16 ` Paul E. McKenney
@ 2018-09-04 20:26 ` Steven Rostedt
2018-09-04 20:53 ` Paul E. McKenney
0 siblings, 1 reply; 11+ messages in thread
From: Steven Rostedt @ 2018-09-04 20:26 UTC (permalink / raw)
To: Paul E. McKenney; +Cc: Borislav Petkov, x86-ml, Peter Zijlstra, lkml, joel
On Sat, 1 Sep 2018 21:16:39 -0700
"Paul E. McKenney" <paulmck@linux.vnet.ibm.com> wrote:
> On Sat, Sep 01, 2018 at 06:45:31PM -0400, Steven Rostedt wrote:
> > On Sat, 1 Sep 2018 10:54:42 -0700
> > "Paul E. McKenney" <paulmck@linux.vnet.ibm.com> wrote:
> >
> > > On Sat, Sep 01, 2018 at 07:35:59PM +0200, Borislav Petkov wrote:
> > > > This is a huge splat! It haz some perf* and sched* in it, I guess for
> > > > peterz to stare at. And lemme add Paul for good measure too :)
> > > >
> > > > Kernel is -rc1 + 3 microcode loader patches ontop which should not be
> > > > related.
> > >
> > > It really is tracing from the idle loop. But I thought that the event
> > > tracing took care of that. Adding Steve and Joel for their thoughts.
> > >
> > > Thanx, Paul
> > >
> > > > Thx.
> > > >
> > > > ---
> > > > [ 62.409125] =============================
> > > > [ 62.409129] WARNING: suspicious RCU usage
> > > > [ 62.409133] 4.19.0-rc1+ #1 Not tainted
> > > > [ 62.409136] -----------------------------
> > > > [ 62.409140] ./include/linux/rcupdate.h:631 rcu_read_lock() used illegally while idle!
> > > > [ 62.409143]
> > > > other info that might help us debug this:
> > > >
> > > > [ 62.409147]
> > > > RCU used illegally from idle CPU!
> > > > rcu_scheduler_active = 2, debug_locks = 1
> > > > [ 62.409151] RCU used illegally from extended quiescent state!
> > > > [ 62.409155] 1 lock held by swapper/0/0:
> > > > [ 62.409158] #0: 000000004557ee0e (rcu_read_lock){....}, at: perf_event_output_forward+0x0/0x130
> > > > [ 62.409175]
> > > > stack backtrace:
> > > > [ 62.409180] CPU: 0 PID: 0 Comm: swapper/0 Not tainted 4.19.0-rc1+ #1
> > > > [ 62.409183] Hardware name: LENOVO 2320CTO/2320CTO, BIOS G2ET86WW (2.06 ) 11/13/2012
> > > > [ 62.409187] Call Trace:
> > > > [ 62.409196] dump_stack+0x85/0xcb
> > > > [ 62.409203] perf_event_output_forward+0xf6/0x130
> >
> > I think this is because we switched the trace point code to be
> > protected by srcu instead of rcu_lock_sched() and a song and dance to
> > "make RCU watch again" if it is not, but perf is using normal
> > rcu_read_lock() internally even though it is hooked into the
> > tracepoint code. Should perf switch to SRCU, or perhaps it can do the
> > song and dance to make RCU watch again?
>
> Well, this is a regression, so in theory we could push my three SRCU
> patches into the current merge window, which would allow perf going
> to SRCU, thus fixing the above splat. I am OK either way. What would
> you prefer?
>
>
I wonder if this partial revert will fix things?
-- Steve
diff --git a/include/linux/tracepoint.h b/include/linux/tracepoint.h
index 7f2e16e76ac4..041f7e56a289 100644
--- a/include/linux/tracepoint.h
+++ b/include/linux/tracepoint.h
@@ -158,8 +158,10 @@ extern void syscall_unregfunc(void);
* For rcuidle callers, use srcu since sched-rcu \
* doesn't work from the idle path. \
*/ \
- if (rcuidle) \
+ if (rcuidle) { \
idx = srcu_read_lock_notrace(&tracepoint_srcu); \
+ rcu_irq_enter_irqson(); \
+ } \
\
it_func_ptr = rcu_dereference_raw((tp)->funcs); \
\
@@ -171,8 +173,10 @@ extern void syscall_unregfunc(void);
} while ((++it_func_ptr)->func); \
} \
\
- if (rcuidle) \
+ if (rcuidle) { \
+ rcu_irq_exit_irqson(); \
srcu_read_unlock_notrace(&tracepoint_srcu, idx);\
+ } \
\
preempt_enable_notrace(); \
} while (0)
^ permalink raw reply related [flat|nested] 11+ messages in thread
* Re: 4.19-rc1: ./include/linux/rcupdate.h:631 rcu_read_lock() used illegally while idle!
2018-09-04 20:26 ` Steven Rostedt
@ 2018-09-04 20:53 ` Paul E. McKenney
2018-09-05 8:22 ` Borislav Petkov
0 siblings, 1 reply; 11+ messages in thread
From: Paul E. McKenney @ 2018-09-04 20:53 UTC (permalink / raw)
To: Steven Rostedt; +Cc: Borislav Petkov, x86-ml, Peter Zijlstra, lkml, joel
On Tue, Sep 04, 2018 at 04:26:11PM -0400, Steven Rostedt wrote:
> On Sat, 1 Sep 2018 21:16:39 -0700
> "Paul E. McKenney" <paulmck@linux.vnet.ibm.com> wrote:
>
> > On Sat, Sep 01, 2018 at 06:45:31PM -0400, Steven Rostedt wrote:
> > > On Sat, 1 Sep 2018 10:54:42 -0700
> > > "Paul E. McKenney" <paulmck@linux.vnet.ibm.com> wrote:
> > >
> > > > On Sat, Sep 01, 2018 at 07:35:59PM +0200, Borislav Petkov wrote:
> > > > > This is a huge splat! It haz some perf* and sched* in it, I guess for
> > > > > peterz to stare at. And lemme add Paul for good measure too :)
> > > > >
> > > > > Kernel is -rc1 + 3 microcode loader patches ontop which should not be
> > > > > related.
> > > >
> > > > It really is tracing from the idle loop. But I thought that the event
> > > > tracing took care of that. Adding Steve and Joel for their thoughts.
> > > >
> > > > Thanx, Paul
> > > >
> > > > > Thx.
> > > > >
> > > > > ---
> > > > > [ 62.409125] =============================
> > > > > [ 62.409129] WARNING: suspicious RCU usage
> > > > > [ 62.409133] 4.19.0-rc1+ #1 Not tainted
> > > > > [ 62.409136] -----------------------------
> > > > > [ 62.409140] ./include/linux/rcupdate.h:631 rcu_read_lock() used illegally while idle!
> > > > > [ 62.409143]
> > > > > other info that might help us debug this:
> > > > >
> > > > > [ 62.409147]
> > > > > RCU used illegally from idle CPU!
> > > > > rcu_scheduler_active = 2, debug_locks = 1
> > > > > [ 62.409151] RCU used illegally from extended quiescent state!
> > > > > [ 62.409155] 1 lock held by swapper/0/0:
> > > > > [ 62.409158] #0: 000000004557ee0e (rcu_read_lock){....}, at: perf_event_output_forward+0x0/0x130
> > > > > [ 62.409175]
> > > > > stack backtrace:
> > > > > [ 62.409180] CPU: 0 PID: 0 Comm: swapper/0 Not tainted 4.19.0-rc1+ #1
> > > > > [ 62.409183] Hardware name: LENOVO 2320CTO/2320CTO, BIOS G2ET86WW (2.06 ) 11/13/2012
> > > > > [ 62.409187] Call Trace:
> > > > > [ 62.409196] dump_stack+0x85/0xcb
> > > > > [ 62.409203] perf_event_output_forward+0xf6/0x130
> > >
> > > I think this is because we switched the trace point code to be
> > > protected by srcu instead of rcu_lock_sched() and a song and dance to
> > > "make RCU watch again" if it is not, but perf is using normal
> > > rcu_read_lock() internally even though it is hooked into the
> > > tracepoint code. Should perf switch to SRCU, or perhaps it can do the
> > > song and dance to make RCU watch again?
> >
> > Well, this is a regression, so in theory we could push my three SRCU
> > patches into the current merge window, which would allow perf going
> > to SRCU, thus fixing the above splat. I am OK either way. What would
> > you prefer?
>
> I wonder if this partial revert will fix things?
I must defer to Borislav on this one. Assuming it has the desired
effect, I am good with it. Nicer and more contained fix than three
SRCU patches! ;-)
Thanx, Paul
> -- Steve
>
>
> diff --git a/include/linux/tracepoint.h b/include/linux/tracepoint.h
> index 7f2e16e76ac4..041f7e56a289 100644
> --- a/include/linux/tracepoint.h
> +++ b/include/linux/tracepoint.h
> @@ -158,8 +158,10 @@ extern void syscall_unregfunc(void);
> * For rcuidle callers, use srcu since sched-rcu \
> * doesn't work from the idle path. \
> */ \
> - if (rcuidle) \
> + if (rcuidle) { \
> idx = srcu_read_lock_notrace(&tracepoint_srcu); \
> + rcu_irq_enter_irqson(); \
> + } \
> \
> it_func_ptr = rcu_dereference_raw((tp)->funcs); \
> \
> @@ -171,8 +173,10 @@ extern void syscall_unregfunc(void);
> } while ((++it_func_ptr)->func); \
> } \
> \
> - if (rcuidle) \
> + if (rcuidle) { \
> + rcu_irq_exit_irqson(); \
> srcu_read_unlock_notrace(&tracepoint_srcu, idx);\
> + } \
> \
> preempt_enable_notrace(); \
> } while (0)
>
^ permalink raw reply [flat|nested] 11+ messages in thread
* Re: 4.19-rc1: ./include/linux/rcupdate.h:631 rcu_read_lock() used illegally while idle!
2018-09-04 20:53 ` Paul E. McKenney
@ 2018-09-05 8:22 ` Borislav Petkov
2018-09-05 12:59 ` Paul E. McKenney
0 siblings, 1 reply; 11+ messages in thread
From: Borislav Petkov @ 2018-09-05 8:22 UTC (permalink / raw)
To: Paul E. McKenney, Steven Rostedt; +Cc: x86-ml, Peter Zijlstra, lkml, joel
On Tue, Sep 04, 2018 at 01:53:21PM -0700, Paul E. McKenney wrote:
> I must defer to Borislav on this one. Assuming it has the desired
> effect, I am good with it.
It did survive a bunch of reboots (the WARN would fire after boot
finishes, normally) so I guess we can run with it and see how it works
out in the next couple of weeks.
Thanks guys!
--
Regards/Gruss,
Boris.
Good mailing practices for 400: avoid top-posting and trim the reply.
^ permalink raw reply [flat|nested] 11+ messages in thread
* Re: 4.19-rc1: ./include/linux/rcupdate.h:631 rcu_read_lock() used illegally while idle!
2018-09-05 8:22 ` Borislav Petkov
@ 2018-09-05 12:59 ` Paul E. McKenney
2018-09-05 13:07 ` Steven Rostedt
2018-09-05 13:26 ` [PATCH] tracing: Add back in rcu_irq_enter/exit_irqson() for rcuidle tracepoints Steven Rostedt
0 siblings, 2 replies; 11+ messages in thread
From: Paul E. McKenney @ 2018-09-05 12:59 UTC (permalink / raw)
To: Borislav Petkov; +Cc: Steven Rostedt, x86-ml, Peter Zijlstra, lkml, joel
On Wed, Sep 05, 2018 at 10:22:54AM +0200, Borislav Petkov wrote:
> On Tue, Sep 04, 2018 at 01:53:21PM -0700, Paul E. McKenney wrote:
> > I must defer to Borislav on this one. Assuming it has the desired
> > effect, I am good with it.
>
> It did survive a bunch of reboots (the WARN would fire after boot
> finishes, normally) so I guess we can run with it and see how it works
> out in the next couple of weeks.
>
> Thanks guys!
Woo-hoo!!! Thank you for testing this!
Thanx, Paul
^ permalink raw reply [flat|nested] 11+ messages in thread
* Re: 4.19-rc1: ./include/linux/rcupdate.h:631 rcu_read_lock() used illegally while idle!
2018-09-05 12:59 ` Paul E. McKenney
@ 2018-09-05 13:07 ` Steven Rostedt
2018-09-05 13:26 ` [PATCH] tracing: Add back in rcu_irq_enter/exit_irqson() for rcuidle tracepoints Steven Rostedt
1 sibling, 0 replies; 11+ messages in thread
From: Steven Rostedt @ 2018-09-05 13:07 UTC (permalink / raw)
To: Paul E. McKenney; +Cc: Borislav Petkov, x86-ml, Peter Zijlstra, lkml, joel
On Wed, 5 Sep 2018 05:59:41 -0700
"Paul E. McKenney" <paulmck@linux.vnet.ibm.com> wrote:
> On Wed, Sep 05, 2018 at 10:22:54AM +0200, Borislav Petkov wrote:
> > On Tue, Sep 04, 2018 at 01:53:21PM -0700, Paul E. McKenney wrote:
> > > I must defer to Borislav on this one. Assuming it has the desired
> > > effect, I am good with it.
> >
> > It did survive a bunch of reboots (the WARN would fire after boot
> > finishes, normally) so I guess we can run with it and see how it works
> > out in the next couple of weeks.
> >
> > Thanks guys!
>
> Woo-hoo!!! Thank you for testing this!
OK, I'll make this into an official patch and put it into my test
suite. I should be able to push it out to Linus tomorrow.
-- Steve
^ permalink raw reply [flat|nested] 11+ messages in thread
* [PATCH] tracing: Add back in rcu_irq_enter/exit_irqson() for rcuidle tracepoints
2018-09-05 12:59 ` Paul E. McKenney
2018-09-05 13:07 ` Steven Rostedt
@ 2018-09-05 13:26 ` Steven Rostedt
2018-09-05 15:05 ` Paul E. McKenney
1 sibling, 1 reply; 11+ messages in thread
From: Steven Rostedt @ 2018-09-05 13:26 UTC (permalink / raw)
To: Paul E. McKenney; +Cc: Borislav Petkov, x86-ml, Peter Zijlstra, lkml, joel
On Wed, 5 Sep 2018 05:59:41 -0700
"Paul E. McKenney" <paulmck@linux.vnet.ibm.com> wrote:
> On Wed, Sep 05, 2018 at 10:22:54AM +0200, Borislav Petkov wrote:
> > On Tue, Sep 04, 2018 at 01:53:21PM -0700, Paul E. McKenney wrote:
> > > I must defer to Borislav on this one. Assuming it has the desired
> > > effect, I am good with it.
> >
> > It did survive a bunch of reboots (the WARN would fire after boot
> > finishes, normally) so I guess we can run with it and see how it works
> > out in the next couple of weeks.
> >
> > Thanks guys!
>
> Woo-hoo!!! Thank you for testing this!
>
Here's the official patch if you want to add an Ack/review/tested-by:
-- Steve
From: "Steven Rostedt (VMware)" <rostedt@goodmis.org>
Borislav reported the following splat:
=============================
WARNING: suspicious RCU usage
4.19.0-rc1+ #1 Not tainted
-----------------------------
./include/linux/rcupdate.h:631 rcu_read_lock() used illegally while idle!
other info that might help us debug this:
RCU used illegally from idle CPU!
rcu_scheduler_active = 2, debug_locks = 1
RCU used illegally from extended quiescent state!
1 lock held by swapper/0/0:
#0: 000000004557ee0e (rcu_read_lock){....}, at: perf_event_output_forward+0x0/0x130
stack backtrace:
CPU: 0 PID: 0 Comm: swapper/0 Not tainted 4.19.0-rc1+ #1
Hardware name: LENOVO 2320CTO/2320CTO, BIOS G2ET86WW (2.06 ) 11/13/2012
Call Trace:
dump_stack+0x85/0xcb
perf_event_output_forward+0xf6/0x130
__perf_event_overflow+0x52/0xe0
perf_swevent_overflow+0x91/0xb0
perf_tp_event+0x11a/0x350
? find_held_lock+0x2d/0x90
? __lock_acquire+0x2ce/0x1350
? __lock_acquire+0x2ce/0x1350
? retint_kernel+0x2d/0x2d
? find_held_lock+0x2d/0x90
? tick_nohz_get_sleep_length+0x83/0xb0
? perf_trace_cpu+0xbb/0xd0
? perf_trace_buf_alloc+0x5a/0xa0
perf_trace_cpu+0xbb/0xd0
cpuidle_enter_state+0x185/0x340
do_idle+0x1eb/0x260
cpu_startup_entry+0x5f/0x70
start_kernel+0x49b/0x4a6
secondary_startup_64+0xa4/0xb0
This is due to the tracepoints moving to SRCU usage which does not require
RCU to be "watching". But perf uses these tracepoints with RCU and expects
it to be. Hence, we still need to add in the rcu_irq_enter/exit_irqson()
calls for "rcuidle" tracepoints. This is a temporary fix until we have SRCU
working in NMI context, and then perf can be converted to use that instead
of normal RCU.
Link: http://lkml.kernel.org/r/20180904162611.6a120068@gandalf.local.home
Cc: x86-ml <x86@kernel.org>
Cc: Peter Zijlstra <peterz@infradead.org>
Cc: "Paul E. McKenney" <paulmck@linux.vnet.ibm.com>
Reported-by: Borislav Petkov <bp@alien8.de>
Fixes: e6753f23d961d ("tracepoint: Make rcuidle tracepoint callers use SRCU")
Signed-off-by: Steven Rostedt (VMware) <rostedt@goodmis.org>
---
include/linux/tracepoint.h | 8 ++++++--
1 file changed, 6 insertions(+), 2 deletions(-)
diff --git a/include/linux/tracepoint.h b/include/linux/tracepoint.h
index 7f2e16e76ac4..041f7e56a289 100644
--- a/include/linux/tracepoint.h
+++ b/include/linux/tracepoint.h
@@ -158,8 +158,10 @@ extern void syscall_unregfunc(void);
* For rcuidle callers, use srcu since sched-rcu \
* doesn't work from the idle path. \
*/ \
- if (rcuidle) \
+ if (rcuidle) { \
idx = srcu_read_lock_notrace(&tracepoint_srcu); \
+ rcu_irq_enter_irqson(); \
+ } \
\
it_func_ptr = rcu_dereference_raw((tp)->funcs); \
\
@@ -171,8 +173,10 @@ extern void syscall_unregfunc(void);
} while ((++it_func_ptr)->func); \
} \
\
- if (rcuidle) \
+ if (rcuidle) { \
+ rcu_irq_exit_irqson(); \
srcu_read_unlock_notrace(&tracepoint_srcu, idx);\
+ } \
\
preempt_enable_notrace(); \
} while (0)
--
2.13.6
^ permalink raw reply related [flat|nested] 11+ messages in thread
* Re: [PATCH] tracing: Add back in rcu_irq_enter/exit_irqson() for rcuidle tracepoints
2018-09-05 13:26 ` [PATCH] tracing: Add back in rcu_irq_enter/exit_irqson() for rcuidle tracepoints Steven Rostedt
@ 2018-09-05 15:05 ` Paul E. McKenney
0 siblings, 0 replies; 11+ messages in thread
From: Paul E. McKenney @ 2018-09-05 15:05 UTC (permalink / raw)
To: Steven Rostedt; +Cc: Borislav Petkov, x86-ml, Peter Zijlstra, lkml, joel
On Wed, Sep 05, 2018 at 09:26:29AM -0400, Steven Rostedt wrote:
> On Wed, 5 Sep 2018 05:59:41 -0700
> "Paul E. McKenney" <paulmck@linux.vnet.ibm.com> wrote:
>
> > On Wed, Sep 05, 2018 at 10:22:54AM +0200, Borislav Petkov wrote:
> > > On Tue, Sep 04, 2018 at 01:53:21PM -0700, Paul E. McKenney wrote:
> > > > I must defer to Borislav on this one. Assuming it has the desired
> > > > effect, I am good with it.
> > >
> > > It did survive a bunch of reboots (the WARN would fire after boot
> > > finishes, normally) so I guess we can run with it and see how it works
> > > out in the next couple of weeks.
> > >
> > > Thanks guys!
> >
> > Woo-hoo!!! Thank you for testing this!
> >
>
> Here's the official patch if you want to add an Ack/review/tested-by:
>
> -- Steve
>
> From: "Steven Rostedt (VMware)" <rostedt@goodmis.org>
>
> Borislav reported the following splat:
>
> =============================
> WARNING: suspicious RCU usage
> 4.19.0-rc1+ #1 Not tainted
> -----------------------------
> ./include/linux/rcupdate.h:631 rcu_read_lock() used illegally while idle!
> other info that might help us debug this:
>
> RCU used illegally from idle CPU!
> rcu_scheduler_active = 2, debug_locks = 1
> RCU used illegally from extended quiescent state!
> 1 lock held by swapper/0/0:
> #0: 000000004557ee0e (rcu_read_lock){....}, at: perf_event_output_forward+0x0/0x130
>
> stack backtrace:
> CPU: 0 PID: 0 Comm: swapper/0 Not tainted 4.19.0-rc1+ #1
> Hardware name: LENOVO 2320CTO/2320CTO, BIOS G2ET86WW (2.06 ) 11/13/2012
> Call Trace:
> dump_stack+0x85/0xcb
> perf_event_output_forward+0xf6/0x130
> __perf_event_overflow+0x52/0xe0
> perf_swevent_overflow+0x91/0xb0
> perf_tp_event+0x11a/0x350
> ? find_held_lock+0x2d/0x90
> ? __lock_acquire+0x2ce/0x1350
> ? __lock_acquire+0x2ce/0x1350
> ? retint_kernel+0x2d/0x2d
> ? find_held_lock+0x2d/0x90
> ? tick_nohz_get_sleep_length+0x83/0xb0
> ? perf_trace_cpu+0xbb/0xd0
> ? perf_trace_buf_alloc+0x5a/0xa0
> perf_trace_cpu+0xbb/0xd0
> cpuidle_enter_state+0x185/0x340
> do_idle+0x1eb/0x260
> cpu_startup_entry+0x5f/0x70
> start_kernel+0x49b/0x4a6
> secondary_startup_64+0xa4/0xb0
>
> This is due to the tracepoints moving to SRCU usage which does not require
> RCU to be "watching". But perf uses these tracepoints with RCU and expects
> it to be. Hence, we still need to add in the rcu_irq_enter/exit_irqson()
> calls for "rcuidle" tracepoints. This is a temporary fix until we have SRCU
> working in NMI context, and then perf can be converted to use that instead
> of normal RCU.
>
> Link: http://lkml.kernel.org/r/20180904162611.6a120068@gandalf.local.home
>
> Cc: x86-ml <x86@kernel.org>
> Cc: Peter Zijlstra <peterz@infradead.org>
> Cc: "Paul E. McKenney" <paulmck@linux.vnet.ibm.com>
> Reported-by: Borislav Petkov <bp@alien8.de>
> Fixes: e6753f23d961d ("tracepoint: Make rcuidle tracepoint callers use SRCU")
> Signed-off-by: Steven Rostedt (VMware) <rostedt@goodmis.org>
Reviewed-by: "Paul E. McKenney" <paulmck@linux.vnet.ibm.com>
> ---
> include/linux/tracepoint.h | 8 ++++++--
> 1 file changed, 6 insertions(+), 2 deletions(-)
>
> diff --git a/include/linux/tracepoint.h b/include/linux/tracepoint.h
> index 7f2e16e76ac4..041f7e56a289 100644
> --- a/include/linux/tracepoint.h
> +++ b/include/linux/tracepoint.h
> @@ -158,8 +158,10 @@ extern void syscall_unregfunc(void);
> * For rcuidle callers, use srcu since sched-rcu \
> * doesn't work from the idle path. \
> */ \
> - if (rcuidle) \
> + if (rcuidle) { \
> idx = srcu_read_lock_notrace(&tracepoint_srcu); \
> + rcu_irq_enter_irqson(); \
> + } \
> \
> it_func_ptr = rcu_dereference_raw((tp)->funcs); \
> \
> @@ -171,8 +173,10 @@ extern void syscall_unregfunc(void);
> } while ((++it_func_ptr)->func); \
> } \
> \
> - if (rcuidle) \
> + if (rcuidle) { \
> + rcu_irq_exit_irqson(); \
> srcu_read_unlock_notrace(&tracepoint_srcu, idx);\
> + } \
> \
> preempt_enable_notrace(); \
> } while (0)
> --
> 2.13.6
>
^ permalink raw reply [flat|nested] 11+ messages in thread
end of thread, other threads:[~2018-09-05 15:05 UTC | newest]
Thread overview: 11+ messages (download: mbox.gz / follow: Atom feed)
-- links below jump to the message on this page --
2018-09-01 17:35 4.19-rc1: ./include/linux/rcupdate.h:631 rcu_read_lock() used illegally while idle! Borislav Petkov
2018-09-01 17:54 ` Paul E. McKenney
2018-09-01 22:45 ` Steven Rostedt
2018-09-02 4:16 ` Paul E. McKenney
2018-09-04 20:26 ` Steven Rostedt
2018-09-04 20:53 ` Paul E. McKenney
2018-09-05 8:22 ` Borislav Petkov
2018-09-05 12:59 ` Paul E. McKenney
2018-09-05 13:07 ` Steven Rostedt
2018-09-05 13:26 ` [PATCH] tracing: Add back in rcu_irq_enter/exit_irqson() for rcuidle tracepoints Steven Rostedt
2018-09-05 15:05 ` Paul E. McKenney
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.