On Mon, Aug 31, 2020 at 12:02:31PM +0530, Naresh Kamboju wrote:
While booting linux mainline kernel on arm64 db410c this kernel warning noticed.
metadata: git branch: master git repo: https://git.kernel.org/pub/scm/linux/kernel/git/torvalds/linux.git git commit: f75aef392f869018f78cfedf3c320a6b3fcfda6b git describe: v5.9-rc3 make_kernelversion: 5.9.0-rc3 kernel-config: http://snapshots.linaro.org/openembedded/lkft/lkft/sumo/dragonboard-410c/lkf...
Boot log,
[ 0.000000] Booting Linux on physical CPU 0x0000000000 [0x410fd030] [ 0.000000] Linux version 5.9.0-rc3 (oe-user@oe-host) (aarch64-linaro-linux-gcc (GCC) 7.3.0, GNU ld (GNU Binutils) 2.30.0.20180208) #1 SMP PREEMPT Mon Aug 31 00:23:15 UTC 2020 [ 0.000000] Machine model: Qualcomm Technologies, Inc. APQ 8016 SBC <> [ 5.299090] sdhci: Secure Digital Host Controller Interface driver [ 5.299140] sdhci: Copyright(c) Pierre Ossman [ 5.304313] [ 5.307771] Synopsys Designware Multimedia Card Interface Driver [ 5.308588] ============================= [ 5.308593] WARNING: suspicious RCU usage [ 5.316628] sdhci-pltfm: SDHCI platform and OF driver helper [ 5.320052] 5.9.0-rc3 #1 Not tainted [ 5.320057] ----------------------------- [ 5.320063] /usr/src/kernel/include/trace/events/lock.h:37 suspicious rcu_dereference_check() usage! [ 5.320068] [ 5.320068] other info that might help us debug this: [ 5.320068] [ 5.320074] [ 5.320074] rcu_scheduler_active = 2, debug_locks = 1 [ 5.320078] RCU used illegally from extended quiescent state! [ 5.320084] no locks held by swapper/0/0. [ 5.320089] [ 5.320089] stack backtrace: [ 5.320098] CPU: 0 PID: 0 Comm: swapper/0 Not tainted 5.9.0-rc3 #1 [ 5.346354] sdhci_msm 7864900.sdhci: Got CD GPIO [ 5.346446] Hardware name: Qualcomm Technologies, Inc. APQ 8016 SBC (DT) [ 5.346452] Call trace: [ 5.346463] dump_backtrace+0x0/0x1f8 [ 5.346471] show_stack+0x2c/0x38 [ 5.346480] dump_stack+0xec/0x15c [ 5.346490] lockdep_rcu_suspicious+0xd4/0xf8 [ 5.346499] lock_acquire+0x3d0/0x440 [ 5.346510] _raw_spin_lock_irqsave+0x80/0xb0 [ 5.413118] __pm_runtime_suspend+0x34/0x1d0 [ 5.417457] psci_enter_domain_idle_state+0x4c/0xb0 [ 5.421795] cpuidle_enter_state+0xc8/0x610 [ 5.426392] cpuidle_enter+0x3c/0x50 [ 5.430561] call_cpuidle+0x44/0x80 [ 5.434378] do_idle+0x240/0x2a0
RCU ignores CPUs in the idle loop, which means that you cannot use rcu_read_lock() from the idle loop without use of something like RCU_NONIDLE(). If this is due to event tracing, you should use the _rcuidle() variant of the event trace statement.
Note also that Peter Zijlstra (CCed) is working to shrink the portion of the idle loop that RCU ignores. Not sure that it covers your case, but it is worth checking.
Thanx, Paul
[ 5.437589] cpu_startup_entry+0x2c/0x78 [ 5.441063] rest_init+0x1ac/0x280 [ 5.444970] arch_call_rest_init+0x14/0x1c [ 5.448180] start_kernel+0x50c/0x544 [ 5.452395] [ 5.452399] [ 5.452403] ============================= [ 5.452406] WARNING: suspicious RCU usage [ 5.452409] 5.9.0-rc3 #1 Not tainted [ 5.452412] ----------------------------- [ 5.452417] /usr/src/kernel/include/trace/events/ipi.h:36 suspicious rcu_dereference_check() usage! [ 5.452420] [ 5.452424] other info that might help us debug this: [ 5.452426] [ 5.452429] [ 5.452432] rcu_scheduler_active = 2, debug_locks = 1 [ 5.452436] RCU used illegally from extended quiescent state! [ 5.452440] 1 lock held by swapper/0/0: [ 5.452443] #0: ffff8000127408f8 (logbuf_lock){-...}-{2:2}, at: vprintk_emit+0xb0/0x358 [ 5.452458] [ 5.452461] stack backtrace: [ 5.452465] CPU: 0 PID: 0 Comm: swapper/0 Not tainted 5.9.0-rc3 #1 [ 5.452469] Hardware name: Qualcomm Technologies, Inc. APQ 8016 SBC (DT) [ 5.452472] Call trace: [ 5.452476] dump_backtrace+0x0/0x1f8 [ 5.452479] show_stack+0x2c/0x38 [ 5.452481] dump_stack+0xec/0x15c [ 5.452485] lockdep_rcu_suspicious+0xd4/0xf8 [ 5.452489] arch_irq_work_raise+0x208/0x210 [ 5.452493] __irq_work_queue_local+0x64/0x88 [ 5.452495] irq_work_queue+0x3c/0x88 [ 5.452499] printk_safe_log_store+0x148/0x178 [ 5.452502] vprintk_func+0x1cc/0x2b8 [ 5.452506] printk+0x74/0x94 [ 5.452509] lockdep_rcu_suspicious+0x28/0xf8 [ 5.452512] lock_release+0x338/0x360 [ 5.452516] _raw_spin_unlock+0x3c/0xa0 [ 5.452519] vprintk_emit+0xf8/0x358 [ 5.452522] vprintk_default+0x48/0x58 [ 5.452526] vprintk_func+0xec/0x2b8 [ 5.452528] printk+0x74/0x94 [ 5.452532] lockdep_rcu_suspicious+0x28/0xf8 [ 5.452535] lock_acquire+0x3d0/0x440 [ 5.452538] _raw_spin_lock_irqsave+0x80/0xb0 [ 5.452542] __pm_runtime_suspend+0x34/0x1d0 [ 5.452545] psci_enter_domain_idle_state+0x4c/0xb0 [ 5.452549] cpuidle_enter_state+0xc8/0x610 [ 5.452552] cpuidle_enter+0x3c/0x50 [ 5.452555] call_cpuidle+0x44/0x80 [ 5.452559] do_idle+0x240/0x2a0 [ 5.452562] cpu_startup_entry+0x2c/0x78 [ 5.452564] rest_init+0x1ac/0x280 [ 5.452568] arch_call_rest_init+0x14/0x1c [ 5.452571] start_kernel+0x50c/0x544 [ 5.452575] ============================= [ 5.452578] WARNING: suspicious RCU usage [ 5.452582] 5.9.0-rc3 #1 Not tainted [ 5.452585] ----------------------------- [ 5.452590] /usr/src/kernel/include/trace/events/lock.h:63 suspicious rcu_dereference_check() usage! [ 5.452593] [ 5.452596] other info that might help us debug this: [ 5.452599] [ 5.452601] [ 5.452605] rcu_scheduler_active = 2, debug_locks = 1 [ 5.452609] RCU used illegally from extended quiescent state! [ 5.452612] 1 lock held by swapper/0/0: [ 5.452615] #0: ffff8000127408f8 (logbuf_lock){-...}-{2:2}, at: vprintk_emit+0xb0/0x358 [ 5.452630] [ 5.452633] stack backtrace: [ 5.452636] CPU: 0 PID: 0 Comm: swapper/0 Not tainted 5.9.0-rc3 #1 [ 5.452640] Hardware name: Qualcomm Technologies, Inc. APQ 8016 SBC (DT) [ 5.452643] Call trace: [ 5.452646] dump_backtrace+0x0/0x1f8 [ 5.452649] show_stack+0x2c/0x38 [ 5.452652] dump_stack+0xec/0x15c [ 5.452656] lockdep_rcu_suspicious+0xd4/0xf8 [ 5.452659] lock_release+0x338/0x360 [ 5.452662] _raw_spin_unlock+0x3c/0xa0 [ 5.452665] vprintk_emit+0xf8/0x358 [ 5.452669] vprintk_default+0x48/0x58 [ 5.452671] vprintk_func+0xec/0x2b8 [ 5.452674] printk+0x74/0x94 [ 5.452677] lockdep_rcu_suspicious+0x28/0xf8 [ 5.452680] lock_acquire+0x3d0/0x440 [ 5.452683] _raw_spin_lock_irqsave+0x80/0xb0 [ 5.452686] __pm_runtime_suspend+0x34/0x1d0 [ 5.452690] psci_enter_domain_idle_state+0x4c/0xb0 [ 5.452693] cpuidle_enter_state+0xc8/0x610 [ 5.452696] cpuidle_enter+0x3c/0x50 [ 5.452698] call_cpuidle+0x44/0x80 [ 5.452701] do_idle+0x240/0x2a0 [ 5.452704] cpu_startup_entry+0x2c/0x78 [ 5.452708] rest_init+0x1ac/0x280 [ 5.452711] arch_call_rest_init+0x14/0x1c [ 5.452714] start_kernel+0x50c/0x544
full test log link, https://qa-reports.linaro.org/lkft/linux-mainline-oe/build/v5.9-rc3/testrun/...
-- Linaro LKFT https://lkft.linaro.org