New issue
Advanced search Search tips

Issue 721518 link

Starred by 1 user

Issue metadata

Status: Started
Owner:
Cc:
Components:
EstimatedDays: ----
NextAction: ----
OS: Chrome
Pri: 2
Type: Bug



Sign in to add a comment

kevin: ARM PMU interrupts cause RCU warnings

Project Member Reported by diand...@chromium.org, May 11 2017

Issue description

My ToT kernel is:

  fbcb3ab08e68 UPSTREAM: drm/atomic: Add drm_atomic_helper_best_encoder()

...make sure you're not too much older, since we've been fixing lots of RCU / Lockdep stuff

I also have the following relevant changes:
* A revert of commit 161967830028 ("CHROMIUM: MALI: Move fence signaling earlier").  See b/35586182
* Patch set #4 from <https://chromium-review.googlesource.com/c/500109/4>.
* This CL to turn on lockdep <https://chromium-review.googlesource.com/c/497931/>.  There are other ways, but that's what I have right now.

---

When I do that, sometimes I see this when I login:

[  123.934728] ===============================
[  123.938915] [ INFO: suspicious RCU usage. ]
[  123.943110] 4.4.64 #167 Not tainted
[  123.946600] -------------------------------
[  123.950782] /mnt/host/source/src/third_party/kernel/v4.4/include/linux/rcupdate.h:863 rcu_read_lock() used illegally while idle!
[  123.954978] 
[  123.954980] ===============================
[  123.954982] [ INFO: suspicious RCU usage. ]
[  123.954986] 4.4.64 #167 Not tainted
[  123.954987] -------------------------------
[  123.954991] /mnt/host/source/src/third_party/kernel/v4.4/kernel/events/core.c:4476 suspicious rcu_dereference_check() usage!
[  123.954992] 
[  123.954992] other info that might help us debug this:
[  123.954992] 
[  123.954995] 
[  123.954995] RCU used illegally from idle CPU!
[  123.954995] rcu_scheduler_active = 1, debug_locks = 1
[  123.954996] RCU used illegally from extended quiescent state!
[  123.954999] 2 locks held by swapper/0/0:
[  123.955018]  #0:  (cpu_pm_notifier_lock){......}, at: [<ffffffc0003245e4>] cpu_pm_exit+0x24/0x50
[  123.955030]  #1:  (rcu_read_lock){......}, at: [<ffffffc00032b708>] perf_event_update_userpage+0x0/0x258
[  123.955031] 
[  123.955031] stack backtrace:
[  123.955035] CPU: 0 PID: 0 Comm: swapper/0 Not tainted 4.4.64 #167
[  123.955037] Hardware name: Google Kevin (DT)
[  123.955039] Call trace:
[  123.955045] [<ffffffc000208ae4>] dump_backtrace+0x0/0x160
[  123.955049] [<ffffffc000208d74>] show_stack+0x20/0x28
[  123.955054] [<ffffffc000514470>] dump_stack+0xb4/0xf0
[  123.955060] [<ffffffc000282de0>] lockdep_rcu_suspicious+0x104/0x114
[  123.955065] [<ffffffc00032b7d8>] perf_event_update_userpage+0xd0/0x258
[  123.955071] [<ffffffc000814b18>] armpmu_event_set_period+0x90/0xa0
[  123.955075] [<ffffffc000814b80>] armpmu_start+0x58/0x70
[  123.955079] [<ffffffc000814f6c>] cpu_pm_pmu_notify+0x158/0x174
[  123.955085] [<ffffffc000247b28>] notifier_call_chain+0x60/0x94
[  123.955088] [<ffffffc000247b9c>] __raw_notifier_call_chain+0x40/0x4c
[  123.955092] [<ffffffc000324510>] cpu_pm_notify+0x40/0x64
[  123.955096] [<ffffffc0003245f4>] cpu_pm_exit+0x34/0x50
[  123.955100] [<ffffffc0007aa194>] arm_enter_idle_state+0x48/0x5c
[  123.955106] [<ffffffc0007a800c>] cpuidle_enter_state+0x204/0x3bc
[  123.955110] [<ffffffc0007a8238>] cpuidle_enter+0x34/0x40
[  123.955114] [<ffffffc000276ca0>] call_cpuidle+0x68/0x74
[  123.955117] [<ffffffc000277064>] cpu_startup_entry+0x3b8/0x424
[  123.955122] [<ffffffc0009cb7c8>] rest_init+0x154/0x164
[  123.955129] [<ffffffc000e0099c>] start_kernel+0x3c0/0x418
[  123.955132] [<0000000000bd5000>] 0xbd5000
[  123.955135] 
[  123.955136] ===============================
[  123.955137] [ INFO: suspicious RCU usage. ]
[  123.955139] 4.4.64 #167 Not tainted
[  123.955141] -------------------------------
[  123.955143] /mnt/host/source/src/third_party/kernel/v4.4/include/linux/rcupdate.h:914 rcu_read_unlock() used illegally while idle!
[  123.955144] 
[  123.955144] other info that might help us debug this:
[  123.955144] 
[  123.955146] 
[  123.955146] RCU used illegally from idle CPU!
[  123.955146] rcu_scheduler_active = 1, debug_locks = 1
[  123.955148] RCU used illegally from extended quiescent state!
[  123.955149] 2 locks held by swapper/0/0:
[  123.955158]  #0:  (cpu_pm_notifier_lock){......}, at: [<ffffffc0003245e4>] cpu_pm_exit+0x24/0x50
[  123.955167]  #1:  (rcu_read_lock){......}, at: [<ffffffc00032b708>] perf_event_update_userpage+0x0/0x258
[  123.955169] 
[  123.955169] stack backtrace:
[  123.955172] CPU: 0 PID: 0 Comm: swapper/0 Not tainted 4.4.64 #167
[  123.955173] Hardware name: Google Kevin (DT)
[  123.955174] Call trace:
[  123.955178] [<ffffffc000208ae4>] dump_backtrace+0x0/0x160
[  123.955183] [<ffffffc000208d74>] show_stack+0x20/0x28
[  123.955185] [<ffffffc000514470>] dump_stack+0xb4/0xf0
[  123.955190] [<ffffffc000282de0>] lockdep_rcu_suspicious+0x104/0x114
[  123.955194] [<ffffffc00032b928>] perf_event_update_userpage+0x220/0x258
[  123.955199] [<ffffffc000814b18>] armpmu_event_set_period+0x90/0xa0
[  123.955202] [<ffffffc000814b80>] armpmu_start+0x58/0x70
[  123.955206] [<ffffffc000814f6c>] cpu_pm_pmu_notify+0x158/0x174
[  123.955211] [<ffffffc000247b28>] notifier_call_chain+0x60/0x94
[  123.955215] [<ffffffc000247b9c>] __raw_notifier_call_chain+0x40/0x4c
[  123.955218] [<ffffffc000324510>] cpu_pm_notify+0x40/0x64
[  123.955222] [<ffffffc0003245f4>] cpu_pm_exit+0x34/0x50
[  123.955225] [<ffffffc0007aa194>] arm_enter_idle_state+0x48/0x5c
[  123.955229] [<ffffffc0007a800c>] cpuidle_enter_state+0x204/0x3bc
[  123.955233] [<ffffffc0007a8238>] cpuidle_enter+0x34/0x40
[  123.955237] [<ffffffc000276ca0>] call_cpuidle+0x68/0x74
[  123.955240] [<ffffffc000277064>] cpu_startup_entry+0x3b8/0x424
[  123.955244] [<ffffffc0009cb7c8>] rest_init+0x154/0x164
[  123.955248] [<ffffffc000e0099c>] start_kernel+0x3c0/0x418
[  123.955250] [<0000000000bd5000>] 0xbd5000
[  123.979529] perf interrupt took too long (2536 > 2500), lowering kernel.perf_event_max_sample_rate to 50000
[  124.046726] perf interrupt took too long (5016 > 5000), lowering kernel.perf_event_max_sample_rate to 25000
[  124.389106] 
[  124.389106] other info that might help us debug this:
[  124.389106] 
[  124.397103] 
[  124.397103] RCU used illegally from idle CPU!
[  124.397103] rcu_scheduler_active = 1, debug_locks = 1
tended quiescent state!
0:
[  124.417622]  #0:  (cpu_pm_notifier_lock){......}, at: [<ffffffc0003245e4>] cpu_pm_exit+0x24/0x50
[  124.426480]  #1:  (rcu_read_lock){......}, at: [<ffffffc00032b708>] perf_event_update_userpage+0x0/0x258
[  124.436025]                           
[  124.436025] stack backtrace:          
r/3 Not tainted 4.4.64 #167
n (DT)
[  124.450739] Call trace:               
[  124.453191] [<ffffffc000208ae4>] dump_backtrace+0x0/0x160
[  124.458586] [<ffffffc000208d74>] show_stack+0x20/0x28
[  124.463637] [<ffffffc000514470>] dump_stack+0xb4/0xf0
[  124.468691] [<ffffffc000282de0>] lockdep_rcu_suspicious+0x104/0x114
[  124.474957] [<ffffffc00032b794>] perf_event_update_userpage+0x8c/0x258
[  124.481484] [<ffffffc000814b18>] armpmu_event_set_period+0x90/0xa0
[  124.487661] [<ffffffc000814b80>] armpmu_start+0x58/0x70
[  124.492883] [<ffffffc000814f6c>] cpu_pm_pmu_notify+0x158/0x174
[  124.498714] [<ffffffc000247b28>] notifier_call_chain+0x60/0x94
[  124.504544] [<ffffffc000247b9c>] __raw_notifier_call_chain+0x40/0x4c
[  124.510896] [<ffffffc000324510>] cpu_pm_notify+0x40/0x64
[  124.516207] [<ffffffc0003245f4>] cpu_pm_exit+0x34/0x50
[  124.521344] [<ffffffc0007aa194>] arm_enter_idle_state+0x48/0x5c
[  124.527261] [<ffffffc0007a800c>] cpuidle_enter_state+0x204/0x3bc
[  124.533265] [<ffffffc0007a8238>] cpuidle_enter+0x34/0x40
[  124.538574] [<ffffffc000276ca0>] call_cpuidle+0x68/0x74
[  124.543796] [<ffffffc000277064>] cpu_startup_entry+0x3b8/0x424
[  124.549624] [<ffffffc00020e708>] secondary_start_kernel+0x150/0x15c
[  124.555887] [<0000000000400e8c>] 0x400e8c
[  124.641720] perf interrupt took too long (13307 > 9615), lowering kernel.perf_event_max_sample_rate to 13000

 
Easy to reproduce with:

  cd /var
  perf record -a

--

Looks like this was introduced by this pick:

  https://chromium-review.googlesource.com/423931
  UPSTREAM: drivers/perf: arm_pmu: implement CPU_PM notifier

--

Fix posted at:

  https://chromium-review.googlesource.com/503568
  UPSTREAM: drivers/perf: arm-pmu: fix RCU usage on pmu resume from low-power        

Sign in to add a comment