2020-09-09 04:41:56

by Naresh Kamboju

[permalink] [raw]
Subject: WARNING: suspicious RCU usage: race/events/tlb.h:57 suspicious rcu_dereference_check() usage!

While booting x86_64 with Linux next 20200908 tag kernel this warning
was noticed.

metadata:
git branch: master
git repo: https://git.kernel.org/pub/scm/linux/kernel/git/next/linux-next.git
git commit: dff9f829e5b0181d4ed9d35aa62d695292399b54
git describe: next-20200908
kernel-config:
http://snapshots.linaro.org/openembedded/lkft/lkft/sumo/intel-corei7-64/lkft/linux-next/853/config

warning logs:
---------------------
[ 18.874329] Freeing unused kernel image (rodata/data gap) memory: 2012K
[ 18.881107] Run /sbin/init as init process
[ 18.905611]
[ 18.907190] =============================
[ 18.911194] WARNING: suspicious RCU usage
[ 18.915199] 5.9.0-rc4-next-20200908 #1 Not tainted
[ 18.919982] -----------------------------
[ 18.923984] /usr/src/kernel/include/trace/events/tlb.h:57
suspicious rcu_dereference_check() usage!
[ 18.933016]
[ 18.933016] other info that might help us debug this:
[ 18.933016]
[ 18.941006]
[ 18.941006] rcu_scheduler_active = 2, debug_locks = 1
[ 18.947523] RCU used illegally from extended quiescent state!
[ 18.953261] no locks held by swapper/2/0.
[ 18.957264]
[ 18.957264] stack backtrace:
[ 18.961619] CPU: 2 PID: 0 Comm: swapper/2 Not tainted
5.9.0-rc4-next-20200908 #1
[ 18.969007] Hardware name: Supermicro SYS-5019S-ML/X11SSH-F, BIOS
2.2 05/23/2018
[ 18.976392] Call Trace:
[ 18.978844] dump_stack+0x7d/0x9f
[ 18.982158] lockdep_rcu_suspicious+0xce/0xf0
[ 18.986517] switch_mm_irqs_off+0x441/0x450
[ 18.990702] switch_mm+0x1b/0x50
[ 18.993936] leave_mm+0x34/0x40
[ 18.997082] acpi_idle_enter_bm+0x23/0x120
[ 19.001180] acpi_idle_enter+0x189/0x2a0
[ 19.005104] ? rcu_eqs_enter.constprop.85+0xb2/0x180
[ 19.010072] cpuidle_enter_state+0xa5/0x4b0
[ 19.015265] cpuidle_enter+0x2e/0x40
[ 19.015268] do_idle+0x226/0x2b0
[ 19.015273] cpu_startup_entry+0x1d/0x20
[ 19.015275] start_secondary+0x114/0x150
[ 19.029943] secondary_startup_64+0xb6/0xc0
[ 19.034141]
[ 19.034142] =============================
[ 19.034142] WARNING: suspicious RCU usage
[ 19.034142] 5.9.0-rc4-next-20200908 #1 Not tainted
[ 19.034143] -----------------------------
[ 19.034143] /usr/src/kernel/include/trace/events/lock.h:37
suspicious rcu_dereference_check() usage!
[ 19.034143]
[ 19.034144] other info that might help us debug this:
[ 19.034144]
[ 19.034144]
[ 19.034145] rcu_scheduler_active = 2, debug_locks = 1
[ 19.034145] RCU used illegally from extended quiescent state!
[ 19.034146] no locks held by swapper/2/0.
[ 19.034146]
[ 19.034146] stack backtrace:
[ 19.034147] CPU: 2 PID: 0 Comm: swapper/2 Not tainted
5.9.0-rc4-next-20200908 #1
[ 19.034147] Hardware name: Supermicro SYS-5019S-ML/X11SSH-F, BIOS
2.2 05/23/2018
[ 19.034147] Call Trace:
[ 19.034148] dump_stack+0x7d/0x9f
[ 19.034148] lockdep_rcu_suspicious+0xce/0xf0
[ 19.034148] lock_acquire+0x327/0x390
[ 19.034149] _raw_spin_lock+0x2f/0x40
[ 19.034149] ? vprintk_emit+0x78/0x2f0
[ 19.034149] vprintk_emit+0x78/0x2f0
[ 19.034149] vprintk_default+0x1f/0x30
[ 19.034150] vprintk_func+0x51/0xf0
[ 19.034150] printk+0x52/0x6e
[ 19.034150] ? __lock_acquire+0x32a/0x19f0
[ 19.034151] lockdep_rcu_suspicious+0x20/0xf0
[ 19.034151] switch_mm_irqs_off+0x441/0x450
[ 19.034151] switch_mm+0x1b/0x50
[ 19.034152] leave_mm+0x34/0x40
[ 19.034152] acpi_idle_enter_bm+0x23/0x120
[ 19.034152] acpi_idle_enter+0x189/0x2a0
[ 19.034153] ? rcu_eqs_enter.constprop.85+0xb2/0x180
[ 19.034153] cpuidle_enter_state+0xa5/0x4b0
[ 19.034153] cpuidle_enter+0x2e/0x40
[ 19.034154] do_idle+0x226/0x2b0
[ 19.034154] cpu_startup_entry+0x1d/0x20
[ 19.034154] start_secondary+0x114/0x150
[ 19.034155] secondary_startup_64+0xb6/0xc0
[ 19.034155]
[ 19.034155] =============================
[ 19.034156] WARNING: suspicious RCU usage
[ 19.034156] 5.9.0-rc4-next-20200908 #1 Not tainted
[ 19.034156] -----------------------------
[ 19.034157] /usr/src/kernel/include/trace/events/lock.h:63
suspicious rcu_dereference_check() usage!
[ 19.034157]
[ 19.034157] other info that might help us debug this:
[ 19.034158]
[ 19.034158]
[ 19.034158] rcu_scheduler_active = 2, debug_locks = 1
[ 19.034159] RCU used illegally from extended quiescent state!
[ 19.034159] 1 lock held by swapper/2/0:
[ 19.034159] #0: ffffffffbed25f58 (logbuf_lock){-...}-{2:2}, at:
vprintk_emit+0x78/0x2f0
[ 19.034161]
[ 19.034161] stack backtrace:
[ 19.034162] CPU: 2 PID: 0 Comm: swapper/2 Not tainted
5.9.0-rc4-next-20200908 #1
[ 19.034162] Hardware name: Supermicro SYS-5019S-ML/X11SSH-F, BIOS
2.2 05/23/2018
[ 19.034162] Call Trace:
[ 19.034163] dump_stack+0x7d/0x9f
[ 19.034163] lockdep_rcu_suspicious+0xce/0xf0
[ 19.034163] ? vprintk_emit+0x9e/0x2f0
[ 19.034164] lock_release+0x246/0x270
[ 19.034164] _raw_spin_unlock+0x1a/0x30
[ 19.034164] vprintk_emit+0x9e/0x2f0
[ 19.034165] vprintk_default+0x1f/0x30
[ 19.034165] vprintk_func+0x51/0xf0
[ 19.034165] printk+0x52/0x6e
[ 19.034166] ? __lock_acquire+0x32a/0x19f0
[ 19.034166] lockdep_rcu_suspicious+0x20/0xf0
[ 19.034166] switch_mm_irqs_off+0x441/0x450
[ 19.034167] switch_mm+0x1b/0x50
[ 19.034167] leave_mm+0x34/0x40
[ 19.034167] acpi_idle_enter_bm+0x23/0x120
[ 19.034167] acpi_idle_enter+0x189/0x2a0
[ 19.034168] ? rcu_eqs_enter.constprop.85+0xb2/0x180
[ 19.034168] cpuidle_enter_state+0xa5/0x4b0
[ 19.034168] cpuidle_enter+0x2e/0x40
[ 19.034169] do_idle+0x226/0x2b0
[ 19.034169] cpu_startup_entry+0x1d/0x20
[ 19.034169] start_secondary+0x114/0x150
[ 19.034170] secondary_startup_64+0xb6/0xc0
[ 19.034170]
[ 19.034170] =============================
[ 19.034171] WARNING: suspicious RCU usage
[ 19.034171] 5.9.0-rc4-next-20200908 #1 Not tainted
[ 19.034171] -----------------------------
[ 19.034172] /usr/src/kernel/include/trace/events/sched.h:90
suspicious rcu_dereference_check() usage!
[ 19.034172]
[ 19.034172] other info that might help us debug this:
[ 19.034173]
[ 19.034173]
[ 19.034173] rcu_scheduler_active = 2, debug_locks = 1
[ 19.034174] RCU used illegally from extended quiescent state!
[ 19.034174] 2 locks held by swapper/2/0:
[ 19.034174] #0: ffffffffbed25ff8 ((console_sem).lock){-...}-{2:2},
at: up+0x16/0x50
[ 19.034176] #1: ffff90dbeea90800 (&p->pi_lock){-.-.}-{2:2}, at:
try_to_wake_up+0x52/0x7a0
[ 19.034178]
[ 19.034178] stack backtrace:
[ 19.034178] CPU: 2 PID: 0 Comm: swapper/2 Not tainted
5.9.0-rc4-next-20200908 #1
[ 19.034179] Hardware name: Supermicro SYS-5019S-ML/X11SSH-F, BIOS
2.2 05/23/2018
[ 19.034179] Call Trace:
[ 19.034179] dump_stack+0x7d/0x9f
[ 19.034180] lockdep_rcu_suspicious+0xce/0xf0
[ 19.034180] try_to_wake_up+0x6a4/0x7a0
[ 19.034180] ? find_held_lock+0x35/0xa0
[ 19.034181] wake_up_process+0x15/0x20
[ 19.034181] __up.isra.4+0x39/0x40
[ 19.034181] up+0x46/0x50
[ 19.034182] __up_console_sem+0x32/0x60
[ 19.034182] console_unlock+0x346/0x5c0
[ 19.034182] vprintk_emit+0x1d1/0x2f0
[ 19.034183] ? cpuidle_enter_state+0xa5/0x4b0
[ 19.034183] vprintk_default+0x1f/0x30
[ 19.034183] vprintk_func+0x51/0xf0
[ 19.034184] ? rcu_nmi_exit+0x12a/0x260
[ 19.034184] printk+0x52/0x6e
[ 19.034184] ? kernel_text_address+0x96/0xf0
[ 19.034185] ? cpuidle_enter_state+0xa5/0x4b0
[ 19.034185] ? cpuidle_enter_state+0xa5/0x4b0
[ 19.034185] show_trace_log_lvl+0x32f/0x3b0
[ 19.034186] ? cpuidle_enter_state+0xa5/0x4b0
[ 19.034186] show_stack+0x30/0x40
[ 19.034186] dump_stack+0x7d/0x9f
[ 19.034186] lockdep_rcu_suspicious+0xce/0xf0
[ 19.034187] switch_mm_irqs_off+0x441/0x450
[ 19.034187] switch_mm+0x1b/0x50
[ 19.034187] leave_mm+0x34/0x40
[ 19.034188] acpi_idle_enter_bm+0x23/0x120
[ 19.034188] acpi_idle_enter+0x189/0x2a0
[ 19.034188] ? rcu_eqs_enter.constprop.85+0xb2/0x180
[ 19.034189] cpuidle_enter_state+0xa5/0x4b0
[ 19.034189] cpuidle_enter+0x2e/0x40
[ 19.034189] do_idle+0x226/0x2b0
[ 19.034190] cpu_startup_entry+0x1d/0x20
[ 19.034190] start_secondary+0x114/0x150
[ 19.034190] secondary_startup_64+0xb6/0xc0
[ 19.034191]
[ 19.034191] =============================
[ 19.034191] WARNING: suspicious RCU usage
[ 19.034192] 5.9.0-rc4-next-20200908 #1 Not tainted
[ 19.034192] -----------------------------
[ 19.034192] /usr/src/kernel/include/linux/rcupdate.h:643
rcu_read_lock() used illegally while idle!
[ 19.034193]
[ 19.034193] other info that might help us debug this:
[ 19.034193]
[ 19.034194]
[ 19.034194] rcu_scheduler_active = 2, debug_locks = 1
[ 19.034194] RCU used illegally from extended quiescent state!
[ 19.034195] 3 locks held by swapper/2/0:
[ 19.034195] #0: ffffffffbed25ff8 ((console_sem).lock){-...}-{2:2},
at: up+0x16/0x50
[ 19.034196] #1: ffff90dbeea90800 (&p->pi_lock){-.-.}-{2:2}, at:
try_to_wake_up+0x52/0x7a0
[ 19.034198] #2: ffffffffbed28580 (rcu_read_lock){....}-{1:2}, at:
select_task_rq_fair+0xd0/0x10a0
[ 19.034199]
[ 19.034200] stack backtrace:
[ 19.034200] CPU: 2 PID: 0 Comm: swapper/2 Not tainted
5.9.0-rc4-next-20200908 #1
[ 19.034201] Hardware name: Supermicro SYS-5019S-ML/X11SSH-F, BIOS
2.2 05/23/2018
[ 19.034201] Call Trace:
[ 19.034201] dump_stack+0x7d/0x9f
[ 19.034202] lockdep_rcu_suspicious+0xce/0xf0
[ 19.034202] select_task_rq_fair+0x4aa/0x10a0
[ 19.034202] ? show_stack+0x30/0x40
[ 19.034203] try_to_wake_up+0x181/0x7a0
[ 19.034203] ? find_held_lock+0x35/0xa0
[ 19.034203] wake_up_process+0x15/0x20
[ 19.034203] __up.isra.4+0x39/0x40
[ 19.034204] up+0x46/0x50
[ 19.034204] __up_console_sem+0x32/0x60
[ 19.034204] console_unlock+0x346/0x5c0
[ 19.034205] vprintk_emit+0x1d1/0x2f0
[ 19.034205] ? cpuidle_enter_state+0xa5/0x4b0
[ 19.034205] vprintk_default+0x1f/0x30
[ 19.034206] vprintk_func+0x51/0xf0
[ 19.034206] ? rcu_nmi_exit+0x12a/0x260
[ 19.034206] printk+0x52/0x6e
[ 19.034207] ? kernel_text_address+0x96/0xf0
[ 19.034207] ? cpuidle_enter_state+0xa5/0x4b0
[ 19.034207] ? cpuidle_enter_state+0xa5/0x4b0
[ 19.034208] show_trace_log_lvl+0x32f/0x3b0
[ 19.034208] ? cpuidle_enter_state+0xa5/0x4b0
[ 19.034208] show_stack+0x30/0x40
[ 19.034209] dump_stack+0x7d/0x9f
[ 19.034209] lockdep_rcu_suspicious+0xce/0xf0
[ 19.034209] switch_mm_irqs_off+0x441/0x450
[ 19.034210] switch_mm+0x1b/0x50
[ 19.034210] leave_mm+0x34/0x40
[ 19.034210] acpi_idle_enter_bm+0x23/0x120
[ 19.034211] acpi_idle_enter+0x189/0x2a0
[ 19.034211] ? rcu_eqs_enter.constprop.85+0xb2/0x180
[ 19.034211] cpuidle_enter_state+0xa5/0x4b0
[ 19.034212] cpuidle_enter+0x2e/0x40
[ 19.034212] do_idle+0x226/0x2b0
[ 19.034212] cpu_startup_entry+0x1d/0x20
[ 19.034213] start_secondary+0x114/0x150
[ 19.034213] secondary_startup_64+0xb6/0xc0
[ 19.034213]
[ 19.034214] =============================
[ 19.034214] WARNING: suspicious RCU usage
[ 19.034214] 5.9.0-rc4-next-20200908 #1 Not tainted
[ 19.034215] -----------------------------
[ 19.034215] /usr/src/kernel/kernel/sched/fair.c:6694 suspicious
rcu_dereference_check() usage!
[ 19.034215]
[ 19.034216] other info that might help us debug this:
[ 19.034216]
[ 19.034216]
[ 19.034217] rcu_scheduler_active = 2, debug_locks = 1
[ 19.034217] RCU used illegally from extended quiescent state!
[ 19.034217] 3 locks held by swapper/2/0:
[ 19.034217] #0: ffffffffbed25ff8 ((console_sem).lock){-...}-{2:2},
at: up+0x16/0x50
[ 19.034219] #1: ffff90dbeea90800 (&p->pi_lock){-.-.}-{2:2}, at:
try_to_wake_up+0x52/0x7a0
[ 19.034220] #2: ffffffffbed28580 (rcu_read_lock){....}-{1:2}, at:
select_task_rq_fair+0xd0/0x10a0
[ 19.034222]
[ 19.034222] stack backtrace:
[ 19.034223] CPU: 2 PID: 0 Comm: swapper/2 Not tainted
5.9.0-rc4-next-20200908 #1
[ 19.034223] Hardware name: Supermicro SYS-5019S-ML/X11SSH-F, BIOS
2.2 05/23/2018
[ 19.034223] Call Trace:
[ 19.034224] dump_stack+0x7d/0x9f
[ 19.034224] lockdep_rcu_suspicious+0xce/0xf0
[ 19.034224] select_task_rq_fair+0x448/0x10a0
[ 19.034225] ? show_stack+0x30/0x40
[ 19.034225] try_to_wake_up+0x181/0x7a0
[ 19.034225] ? find_held_lock+0x35/0xa0
[ 19.034226] wake_up_process+0x15/0x20
[ 19.034226] __up.isra.4+0x39/0x40
[ 19.034226] up+0x46/0x50
[ 19.034227] __up_console_sem+0x32/0x60
[ 19.034227] console_unlock+0x346/0x5c0
[ 19.034227] vprintk_emit+0x1d1/0x2f0
[ 19.034228] ? cpuidle_enter_state+0xa5/0x4b0
[ 19.034228] vprintk_default+0x1f/0x30
[ 19.034228] vprintk_func+0x51/0xf0
[ 19.034228] ? rcu_nmi_exit+0x12a/0x260
[ 19.034229] printk+0x52/0x6e
[ 19.034229] ? kernel_text_address+0x96/0xf0
[ 19.034229] ? cpuidle_enter_state+0xa5/0x4b0
[ 19.034230] ? cpuidle_enter_state+0xa5/0x4b0
[ 19.034230] show_trace_log_lvl+0x32f/0x3b0
[ 19.034230] ? cpuidle_enter_state+0xa5/0x4b0
[ 19.034231] show_stack+0x30/0x40
[ 19.034231] dump_stack+0x7d/0x9f
[ 19.034231] lockdep_rcu_suspicious+0xce/0xf0
[ 19.034232] switch_mm_irqs_off+0x441/0x450
[ 19.034232] switch_mm+0x1b/0x50
[ 19.034232] leave_mm+0x34/0x40
[ 19.034233] acpi_idle_enter_bm+0x23/0x120
[ 19.034233] acpi_idle_enter+0x189/0x2a0
[ 19.034233] ? rcu_eqs_enter.constprop.85+0xb2/0x180
[ 19.034234] cpuidle_enter_state+0xa5/0x4b0
[ 19.034234] cpuidle_enter+0x2e/0x40
[ 19.034234] do_idle+0x226/0x2b0
[ 19.034235] cpu_startup_entry+0x1d/0x20
[ 19.034235] start_secondary+0x114/0x150
[ 19.034235] secondary_startup_64+0xb6/0xc0

Full test log,

https://qa-reports.linaro.org/lkft/linux-next-master/build/next-20200908/testrun/3171064/suite/linux-log-parser/test/check-kernel-bug-1743477/log


--
Linaro LKFT
https://lkft.linaro.org


2020-09-14 17:34:37

by Qian Cai

[permalink] [raw]
Subject: Re: WARNING: suspicious RCU usage: race/events/tlb.h:57 suspicious rcu_dereference_check() usage!

On Wed, 2020-09-09 at 10:08 +0530, Naresh Kamboju wrote:
> While booting x86_64 with Linux next 20200908 tag kernel this warning
> was noticed.

This pretty much looks like the same issue in:

https://lore.kernel.org/lkml/[email protected]/

Can you revert the patchset to see if it is related?

>
> metadata:
> git branch: master
> git repo:
> https://git.kernel.org/pub/scm/linux/kernel/git/next/linux-next.git
> git commit: dff9f829e5b0181d4ed9d35aa62d695292399b54
> git describe: next-20200908
> kernel-config:
> http://snapshots.linaro.org/openembedded/lkft/lkft/sumo/intel-corei7-64/lkft/linux-next/853/config
>
> warning logs:
> ---------------------
> [ 18.874329] Freeing unused kernel image (rodata/data gap) memory: 2012K
> [ 18.881107] Run /sbin/init as init process
> [ 18.905611]
> [ 18.907190] =============================
> [ 18.911194] WARNING: suspicious RCU usage
> [ 18.915199] 5.9.0-rc4-next-20200908 #1 Not tainted
> [ 18.919982] -----------------------------
> [ 18.923984] /usr/src/kernel/include/trace/events/tlb.h:57
> suspicious rcu_dereference_check() usage!
> [ 18.933016]
> [ 18.933016] other info that might help us debug this:
> [ 18.933016]
> [ 18.941006]
> [ 18.941006] rcu_scheduler_active = 2, debug_locks = 1
> [ 18.947523] RCU used illegally from extended quiescent state!
> [ 18.953261] no locks held by swapper/2/0.
> [ 18.957264]
> [ 18.957264] stack backtrace:
> [ 18.961619] CPU: 2 PID: 0 Comm: swapper/2 Not tainted
> 5.9.0-rc4-next-20200908 #1
> [ 18.969007] Hardware name: Supermicro SYS-5019S-ML/X11SSH-F, BIOS
> 2.2 05/23/2018
> [ 18.976392] Call Trace:
> [ 18.978844] dump_stack+0x7d/0x9f
> [ 18.982158] lockdep_rcu_suspicious+0xce/0xf0
> [ 18.986517] switch_mm_irqs_off+0x441/0x450
> [ 18.990702] switch_mm+0x1b/0x50
> [ 18.993936] leave_mm+0x34/0x40
> [ 18.997082] acpi_idle_enter_bm+0x23/0x120
> [ 19.001180] acpi_idle_enter+0x189/0x2a0
> [ 19.005104] ? rcu_eqs_enter.constprop.85+0xb2/0x180
> [ 19.010072] cpuidle_enter_state+0xa5/0x4b0
> [ 19.015265] cpuidle_enter+0x2e/0x40
> [ 19.015268] do_idle+0x226/0x2b0
> [ 19.015273] cpu_startup_entry+0x1d/0x20
> [ 19.015275] start_secondary+0x114/0x150
> [ 19.029943] secondary_startup_64+0xb6/0xc0
> [ 19.034141]
> [ 19.034142] =============================
> [ 19.034142] WARNING: suspicious RCU usage
> [ 19.034142] 5.9.0-rc4-next-20200908 #1 Not tainted
> [ 19.034143] -----------------------------
> [ 19.034143] /usr/src/kernel/include/trace/events/lock.h:37
> suspicious rcu_dereference_check() usage!
> [ 19.034143]
> [ 19.034144] other info that might help us debug this:
> [ 19.034144]
> [ 19.034144]
> [ 19.034145] rcu_scheduler_active = 2, debug_locks = 1
> [ 19.034145] RCU used illegally from extended quiescent state!
> [ 19.034146] no locks held by swapper/2/0.
> [ 19.034146]
> [ 19.034146] stack backtrace:
> [ 19.034147] CPU: 2 PID: 0 Comm: swapper/2 Not tainted
> 5.9.0-rc4-next-20200908 #1
> [ 19.034147] Hardware name: Supermicro SYS-5019S-ML/X11SSH-F, BIOS
> 2.2 05/23/2018
> [ 19.034147] Call Trace:
> [ 19.034148] dump_stack+0x7d/0x9f
> [ 19.034148] lockdep_rcu_suspicious+0xce/0xf0
> [ 19.034148] lock_acquire+0x327/0x390
> [ 19.034149] _raw_spin_lock+0x2f/0x40
> [ 19.034149] ? vprintk_emit+0x78/0x2f0
> [ 19.034149] vprintk_emit+0x78/0x2f0
> [ 19.034149] vprintk_default+0x1f/0x30
> [ 19.034150] vprintk_func+0x51/0xf0
> [ 19.034150] printk+0x52/0x6e
> [ 19.034150] ? __lock_acquire+0x32a/0x19f0
> [ 19.034151] lockdep_rcu_suspicious+0x20/0xf0
> [ 19.034151] switch_mm_irqs_off+0x441/0x450
> [ 19.034151] switch_mm+0x1b/0x50
> [ 19.034152] leave_mm+0x34/0x40
> [ 19.034152] acpi_idle_enter_bm+0x23/0x120
> [ 19.034152] acpi_idle_enter+0x189/0x2a0
> [ 19.034153] ? rcu_eqs_enter.constprop.85+0xb2/0x180
> [ 19.034153] cpuidle_enter_state+0xa5/0x4b0
> [ 19.034153] cpuidle_enter+0x2e/0x40
> [ 19.034154] do_idle+0x226/0x2b0
> [ 19.034154] cpu_startup_entry+0x1d/0x20
> [ 19.034154] start_secondary+0x114/0x150
> [ 19.034155] secondary_startup_64+0xb6/0xc0
> [ 19.034155]
> [ 19.034155] =============================
> [ 19.034156] WARNING: suspicious RCU usage
> [ 19.034156] 5.9.0-rc4-next-20200908 #1 Not tainted
> [ 19.034156] -----------------------------
> [ 19.034157] /usr/src/kernel/include/trace/events/lock.h:63
> suspicious rcu_dereference_check() usage!
> [ 19.034157]
> [ 19.034157] other info that might help us debug this:
> [ 19.034158]
> [ 19.034158]
> [ 19.034158] rcu_scheduler_active = 2, debug_locks = 1
> [ 19.034159] RCU used illegally from extended quiescent state!
> [ 19.034159] 1 lock held by swapper/2/0:
> [ 19.034159] #0: ffffffffbed25f58 (logbuf_lock){-...}-{2:2}, at:
> vprintk_emit+0x78/0x2f0
> [ 19.034161]
> [ 19.034161] stack backtrace:
> [ 19.034162] CPU: 2 PID: 0 Comm: swapper/2 Not tainted
> 5.9.0-rc4-next-20200908 #1
> [ 19.034162] Hardware name: Supermicro SYS-5019S-ML/X11SSH-F, BIOS
> 2.2 05/23/2018
> [ 19.034162] Call Trace:
> [ 19.034163] dump_stack+0x7d/0x9f
> [ 19.034163] lockdep_rcu_suspicious+0xce/0xf0
> [ 19.034163] ? vprintk_emit+0x9e/0x2f0
> [ 19.034164] lock_release+0x246/0x270
> [ 19.034164] _raw_spin_unlock+0x1a/0x30
> [ 19.034164] vprintk_emit+0x9e/0x2f0
> [ 19.034165] vprintk_default+0x1f/0x30
> [ 19.034165] vprintk_func+0x51/0xf0
> [ 19.034165] printk+0x52/0x6e
> [ 19.034166] ? __lock_acquire+0x32a/0x19f0
> [ 19.034166] lockdep_rcu_suspicious+0x20/0xf0
> [ 19.034166] switch_mm_irqs_off+0x441/0x450
> [ 19.034167] switch_mm+0x1b/0x50
> [ 19.034167] leave_mm+0x34/0x40
> [ 19.034167] acpi_idle_enter_bm+0x23/0x120
> [ 19.034167] acpi_idle_enter+0x189/0x2a0
> [ 19.034168] ? rcu_eqs_enter.constprop.85+0xb2/0x180
> [ 19.034168] cpuidle_enter_state+0xa5/0x4b0
> [ 19.034168] cpuidle_enter+0x2e/0x40
> [ 19.034169] do_idle+0x226/0x2b0
> [ 19.034169] cpu_startup_entry+0x1d/0x20
> [ 19.034169] start_secondary+0x114/0x150
> [ 19.034170] secondary_startup_64+0xb6/0xc0
> [ 19.034170]
> [ 19.034170] =============================
> [ 19.034171] WARNING: suspicious RCU usage
> [ 19.034171] 5.9.0-rc4-next-20200908 #1 Not tainted
> [ 19.034171] -----------------------------
> [ 19.034172] /usr/src/kernel/include/trace/events/sched.h:90
> suspicious rcu_dereference_check() usage!
> [ 19.034172]
> [ 19.034172] other info that might help us debug this:
> [ 19.034173]
> [ 19.034173]
> [ 19.034173] rcu_scheduler_active = 2, debug_locks = 1
> [ 19.034174] RCU used illegally from extended quiescent state!
> [ 19.034174] 2 locks held by swapper/2/0:
> [ 19.034174] #0: ffffffffbed25ff8 ((console_sem).lock){-...}-{2:2},
> at: up+0x16/0x50
> [ 19.034176] #1: ffff90dbeea90800 (&p->pi_lock){-.-.}-{2:2}, at:
> try_to_wake_up+0x52/0x7a0
> [ 19.034178]
> [ 19.034178] stack backtrace:
> [ 19.034178] CPU: 2 PID: 0 Comm: swapper/2 Not tainted
> 5.9.0-rc4-next-20200908 #1
> [ 19.034179] Hardware name: Supermicro SYS-5019S-ML/X11SSH-F, BIOS
> 2.2 05/23/2018
> [ 19.034179] Call Trace:
> [ 19.034179] dump_stack+0x7d/0x9f
> [ 19.034180] lockdep_rcu_suspicious+0xce/0xf0
> [ 19.034180] try_to_wake_up+0x6a4/0x7a0
> [ 19.034180] ? find_held_lock+0x35/0xa0
> [ 19.034181] wake_up_process+0x15/0x20
> [ 19.034181] __up.isra.4+0x39/0x40
> [ 19.034181] up+0x46/0x50
> [ 19.034182] __up_console_sem+0x32/0x60
> [ 19.034182] console_unlock+0x346/0x5c0
> [ 19.034182] vprintk_emit+0x1d1/0x2f0
> [ 19.034183] ? cpuidle_enter_state+0xa5/0x4b0
> [ 19.034183] vprintk_default+0x1f/0x30
> [ 19.034183] vprintk_func+0x51/0xf0
> [ 19.034184] ? rcu_nmi_exit+0x12a/0x260
> [ 19.034184] printk+0x52/0x6e
> [ 19.034184] ? kernel_text_address+0x96/0xf0
> [ 19.034185] ? cpuidle_enter_state+0xa5/0x4b0
> [ 19.034185] ? cpuidle_enter_state+0xa5/0x4b0
> [ 19.034185] show_trace_log_lvl+0x32f/0x3b0
> [ 19.034186] ? cpuidle_enter_state+0xa5/0x4b0
> [ 19.034186] show_stack+0x30/0x40
> [ 19.034186] dump_stack+0x7d/0x9f
> [ 19.034186] lockdep_rcu_suspicious+0xce/0xf0
> [ 19.034187] switch_mm_irqs_off+0x441/0x450
> [ 19.034187] switch_mm+0x1b/0x50
> [ 19.034187] leave_mm+0x34/0x40
> [ 19.034188] acpi_idle_enter_bm+0x23/0x120
> [ 19.034188] acpi_idle_enter+0x189/0x2a0
> [ 19.034188] ? rcu_eqs_enter.constprop.85+0xb2/0x180
> [ 19.034189] cpuidle_enter_state+0xa5/0x4b0
> [ 19.034189] cpuidle_enter+0x2e/0x40
> [ 19.034189] do_idle+0x226/0x2b0
> [ 19.034190] cpu_startup_entry+0x1d/0x20
> [ 19.034190] start_secondary+0x114/0x150
> [ 19.034190] secondary_startup_64+0xb6/0xc0
> [ 19.034191]
> [ 19.034191] =============================
> [ 19.034191] WARNING: suspicious RCU usage
> [ 19.034192] 5.9.0-rc4-next-20200908 #1 Not tainted
> [ 19.034192] -----------------------------
> [ 19.034192] /usr/src/kernel/include/linux/rcupdate.h:643
> rcu_read_lock() used illegally while idle!
> [ 19.034193]
> [ 19.034193] other info that might help us debug this:
> [ 19.034193]
> [ 19.034194]
> [ 19.034194] rcu_scheduler_active = 2, debug_locks = 1
> [ 19.034194] RCU used illegally from extended quiescent state!
> [ 19.034195] 3 locks held by swapper/2/0:
> [ 19.034195] #0: ffffffffbed25ff8 ((console_sem).lock){-...}-{2:2},
> at: up+0x16/0x50
> [ 19.034196] #1: ffff90dbeea90800 (&p->pi_lock){-.-.}-{2:2}, at:
> try_to_wake_up+0x52/0x7a0
> [ 19.034198] #2: ffffffffbed28580 (rcu_read_lock){....}-{1:2}, at:
> select_task_rq_fair+0xd0/0x10a0
> [ 19.034199]
> [ 19.034200] stack backtrace:
> [ 19.034200] CPU: 2 PID: 0 Comm: swapper/2 Not tainted
> 5.9.0-rc4-next-20200908 #1
> [ 19.034201] Hardware name: Supermicro SYS-5019S-ML/X11SSH-F, BIOS
> 2.2 05/23/2018
> [ 19.034201] Call Trace:
> [ 19.034201] dump_stack+0x7d/0x9f
> [ 19.034202] lockdep_rcu_suspicious+0xce/0xf0
> [ 19.034202] select_task_rq_fair+0x4aa/0x10a0
> [ 19.034202] ? show_stack+0x30/0x40
> [ 19.034203] try_to_wake_up+0x181/0x7a0
> [ 19.034203] ? find_held_lock+0x35/0xa0
> [ 19.034203] wake_up_process+0x15/0x20
> [ 19.034203] __up.isra.4+0x39/0x40
> [ 19.034204] up+0x46/0x50
> [ 19.034204] __up_console_sem+0x32/0x60
> [ 19.034204] console_unlock+0x346/0x5c0
> [ 19.034205] vprintk_emit+0x1d1/0x2f0
> [ 19.034205] ? cpuidle_enter_state+0xa5/0x4b0
> [ 19.034205] vprintk_default+0x1f/0x30
> [ 19.034206] vprintk_func+0x51/0xf0
> [ 19.034206] ? rcu_nmi_exit+0x12a/0x260
> [ 19.034206] printk+0x52/0x6e
> [ 19.034207] ? kernel_text_address+0x96/0xf0
> [ 19.034207] ? cpuidle_enter_state+0xa5/0x4b0
> [ 19.034207] ? cpuidle_enter_state+0xa5/0x4b0
> [ 19.034208] show_trace_log_lvl+0x32f/0x3b0
> [ 19.034208] ? cpuidle_enter_state+0xa5/0x4b0
> [ 19.034208] show_stack+0x30/0x40
> [ 19.034209] dump_stack+0x7d/0x9f
> [ 19.034209] lockdep_rcu_suspicious+0xce/0xf0
> [ 19.034209] switch_mm_irqs_off+0x441/0x450
> [ 19.034210] switch_mm+0x1b/0x50
> [ 19.034210] leave_mm+0x34/0x40
> [ 19.034210] acpi_idle_enter_bm+0x23/0x120
> [ 19.034211] acpi_idle_enter+0x189/0x2a0
> [ 19.034211] ? rcu_eqs_enter.constprop.85+0xb2/0x180
> [ 19.034211] cpuidle_enter_state+0xa5/0x4b0
> [ 19.034212] cpuidle_enter+0x2e/0x40
> [ 19.034212] do_idle+0x226/0x2b0
> [ 19.034212] cpu_startup_entry+0x1d/0x20
> [ 19.034213] start_secondary+0x114/0x150
> [ 19.034213] secondary_startup_64+0xb6/0xc0
> [ 19.034213]
> [ 19.034214] =============================
> [ 19.034214] WARNING: suspicious RCU usage
> [ 19.034214] 5.9.0-rc4-next-20200908 #1 Not tainted
> [ 19.034215] -----------------------------
> [ 19.034215] /usr/src/kernel/kernel/sched/fair.c:6694 suspicious
> rcu_dereference_check() usage!
> [ 19.034215]
> [ 19.034216] other info that might help us debug this:
> [ 19.034216]
> [ 19.034216]
> [ 19.034217] rcu_scheduler_active = 2, debug_locks = 1
> [ 19.034217] RCU used illegally from extended quiescent state!
> [ 19.034217] 3 locks held by swapper/2/0:
> [ 19.034217] #0: ffffffffbed25ff8 ((console_sem).lock){-...}-{2:2},
> at: up+0x16/0x50
> [ 19.034219] #1: ffff90dbeea90800 (&p->pi_lock){-.-.}-{2:2}, at:
> try_to_wake_up+0x52/0x7a0
> [ 19.034220] #2: ffffffffbed28580 (rcu_read_lock){....}-{1:2}, at:
> select_task_rq_fair+0xd0/0x10a0
> [ 19.034222]
> [ 19.034222] stack backtrace:
> [ 19.034223] CPU: 2 PID: 0 Comm: swapper/2 Not tainted
> 5.9.0-rc4-next-20200908 #1
> [ 19.034223] Hardware name: Supermicro SYS-5019S-ML/X11SSH-F, BIOS
> 2.2 05/23/2018
> [ 19.034223] Call Trace:
> [ 19.034224] dump_stack+0x7d/0x9f
> [ 19.034224] lockdep_rcu_suspicious+0xce/0xf0
> [ 19.034224] select_task_rq_fair+0x448/0x10a0
> [ 19.034225] ? show_stack+0x30/0x40
> [ 19.034225] try_to_wake_up+0x181/0x7a0
> [ 19.034225] ? find_held_lock+0x35/0xa0
> [ 19.034226] wake_up_process+0x15/0x20
> [ 19.034226] __up.isra.4+0x39/0x40
> [ 19.034226] up+0x46/0x50
> [ 19.034227] __up_console_sem+0x32/0x60
> [ 19.034227] console_unlock+0x346/0x5c0
> [ 19.034227] vprintk_emit+0x1d1/0x2f0
> [ 19.034228] ? cpuidle_enter_state+0xa5/0x4b0
> [ 19.034228] vprintk_default+0x1f/0x30
> [ 19.034228] vprintk_func+0x51/0xf0
> [ 19.034228] ? rcu_nmi_exit+0x12a/0x260
> [ 19.034229] printk+0x52/0x6e
> [ 19.034229] ? kernel_text_address+0x96/0xf0
> [ 19.034229] ? cpuidle_enter_state+0xa5/0x4b0
> [ 19.034230] ? cpuidle_enter_state+0xa5/0x4b0
> [ 19.034230] show_trace_log_lvl+0x32f/0x3b0
> [ 19.034230] ? cpuidle_enter_state+0xa5/0x4b0
> [ 19.034231] show_stack+0x30/0x40
> [ 19.034231] dump_stack+0x7d/0x9f
> [ 19.034231] lockdep_rcu_suspicious+0xce/0xf0
> [ 19.034232] switch_mm_irqs_off+0x441/0x450
> [ 19.034232] switch_mm+0x1b/0x50
> [ 19.034232] leave_mm+0x34/0x40
> [ 19.034233] acpi_idle_enter_bm+0x23/0x120
> [ 19.034233] acpi_idle_enter+0x189/0x2a0
> [ 19.034233] ? rcu_eqs_enter.constprop.85+0xb2/0x180
> [ 19.034234] cpuidle_enter_state+0xa5/0x4b0
> [ 19.034234] cpuidle_enter+0x2e/0x40
> [ 19.034234] do_idle+0x226/0x2b0
> [ 19.034235] cpu_startup_entry+0x1d/0x20
> [ 19.034235] start_secondary+0x114/0x150
> [ 19.034235] secondary_startup_64+0xb6/0xc0
>
> Full test log,
>
> https://qa-reports.linaro.org/lkft/linux-next-master/build/next-20200908/testrun/3171064/suite/linux-log-parser/test/check-kernel-bug-1743477/log
>
>

2020-09-15 10:37:33

by Peter Zijlstra

[permalink] [raw]
Subject: Re: WARNING: suspicious RCU usage: race/events/tlb.h:57 suspicious rcu_dereference_check() usage!

On Mon, Sep 14, 2020 at 01:29:34PM -0400, Qian Cai wrote:
> On Wed, 2020-09-09 at 10:08 +0530, Naresh Kamboju wrote:
> > While booting x86_64 with Linux next 20200908 tag kernel this warning
> > was noticed.
>
> This pretty much looks like the same issue in:
>
> https://lore.kernel.org/lkml/[email protected]/
>
> Can you revert the patchset to see if it is related?

Don't bother.. I'll be sending patches soon.