kevin: lockdep splat between DDRFreq and VOP |
||||
Issue descriptionI'm on: 3aa5037e23f0 (m/master, cros/chromeos-4.4) CHROMIUM: OPP: Fix RCU lockdep issues with opp I've also got: https://chromium-review.googlesource.com/498947 ANDROID: sched/walt: kill {min,max}_capacity --- When I turn on lockdep (USE="lockdebug" should do it, I think) then I get this splat at bootup: [ 6.620072] ====================================================== [ 6.626245] [ INFO: possible circular locking dependency detected ] [ 6.632505] 4.4.64 #129 Not tainted [ 6.635988] ------------------------------------------------------- [ 6.642246] kworker/0:1H/166 is trying to acquire lock: [ 6.647463] (&vop->vop_lock){+.+.+.}, at: [<ffffffc000613ad8>] rockchip_drm_wait_vact_end+0x48/0x334 [ 6.656735] [ 6.656735] but task is already holding lock: [ 6.662559] (&ddrclk->lock){+.+...}, at: [<ffffffc000809a68>] rockchip_ddrclk_set_rate_func+0x6c/0x13c [ 6.671998] [ 6.671998] which lock already depends on the new lock. [ 6.671998] [ 6.680164] [ 6.680164] the existing dependency chain (in reverse order) is: [ 6.687636] -> #5 (&ddrclk->lock){+.+...}: [ 6.691953] [<ffffffc0002872f4>] __lock_acquire+0x172c/0x1a74 [ 6.698314] [<ffffffc000287d18>] lock_acquire+0x248/0x280 [ 6.704327] [<ffffffc0009d6cc0>] mutex_lock_nested+0x94/0x794 [ 6.710689] [<ffffffc000809a68>] rockchip_ddrclk_set_rate_func+0x6c/0x13c [ 6.718088] [<ffffffc00023f520>] process_one_work+0x3e4/0x700 [ 6.724451] [<ffffffc000240170>] worker_thread+0x360/0x428 [ 6.730551] [<ffffffc0002463dc>] kthread+0x120/0x128 [ 6.736130] [<ffffffc000203dd0>] ret_from_fork+0x10/0x40 [ 6.742059] -> #4 ((&ddrclk->set_rate_work)){+.+...}: [ 6.747328] [<ffffffc0002872f4>] __lock_acquire+0x172c/0x1a74 [ 6.753688] [<ffffffc000287d18>] lock_acquire+0x248/0x280 [ 6.759701] [<ffffffc00023f890>] flush_work+0x54/0x280 [ 6.765453] [<ffffffc00080996c>] rockchip_ddrclk_wait_set_rate+0x28/0x34 [ 6.772766] [<ffffffc00080eec0>] rk3399_dmcfreq_target+0x334/0x448 [ 6.779560] [<ffffffc00080ca70>] update_devfreq+0x108/0x1b0 [ 6.785747] [<ffffffc00080f04c>] rk3399_boost_kthread_fn+0x78/0x128 [ 6.792627] [<ffffffc0002463dc>] kthread+0x120/0x128 [ 6.798205] [<ffffffc000203dd0>] ret_from_fork+0x10/0x40 [ 6.804123] -> #3 (&data->lock){+.+...}: [ 6.808266] [<ffffffc0002872f4>] __lock_acquire+0x172c/0x1a74 [ 6.814625] [<ffffffc000287d18>] lock_acquire+0x248/0x280 [ 6.820637] [<ffffffc0009d6cc0>] mutex_lock_nested+0x94/0x794 [ 6.826997] [<ffffffc00080ed4c>] rk3399_dmcfreq_target+0x1c0/0x448 [ 6.833790] [<ffffffc00080ca70>] update_devfreq+0x108/0x1b0 [ 6.839976] [<ffffffc00080f04c>] rk3399_boost_kthread_fn+0x78/0x128 [ 6.846856] [<ffffffc0002463dc>] kthread+0x120/0x128 [ 6.852434] [<ffffffc000203dd0>] ret_from_fork+0x10/0x40 [ 6.858359] -> #2 (&pmu->mutex){+.+...}: [ 6.862502] [<ffffffc0002872f4>] __lock_acquire+0x172c/0x1a74 [ 6.868861] [<ffffffc000287d18>] lock_acquire+0x248/0x280 [ 6.874872] [<ffffffc0009d6cc0>] mutex_lock_nested+0x94/0x794 [ 6.881232] [<ffffffc0005949f8>] rockchip_pd_power+0x38/0x28c [ 6.887594] [<ffffffc0005951cc>] rockchip_pd_power_off+0x24/0x30 [ 6.894213] [<ffffffc00066cee0>] genpd_power_off+0x6c/0xc0 [ 6.900315] [<ffffffc00066de58>] genpd_poweroff+0x100/0x158 [ 6.906501] [<ffffffc00066e158>] genpd_runtime_suspend+0x168/0x188 [ 6.913295] [<ffffffc0006609d0>] __rpm_callback+0x48/0x7c [ 6.919308] [<ffffffc000660a88>] rpm_callback+0x84/0xa4 [ 6.925148] [<ffffffc00066135c>] rpm_suspend+0x394/0x6b4 [ 6.931074] [<ffffffc000661ce8>] rpm_idle+0x5b4/0x5cc [ 6.936731] [<ffffffc000662b64>] pm_runtime_work+0x6c/0xa0 [ 6.942832] [<ffffffc00023f520>] process_one_work+0x3e4/0x700 [ 6.949192] [<ffffffc000240110>] worker_thread+0x300/0x428 [ 6.955291] [<ffffffc0002463dc>] kthread+0x120/0x128 [ 6.960862] [<ffffffc000203dd0>] ret_from_fork+0x10/0x40 [ 6.966789] -> #1 (&genpd->lock){+.+.+.}: [ 6.971019] [<ffffffc0002872f4>] __lock_acquire+0x172c/0x1a74 [ 6.977378] [<ffffffc000287d18>] lock_acquire+0x248/0x280 [ 6.983391] [<ffffffc0009d6cc0>] mutex_lock_nested+0x94/0x794 [ 6.989751] [<ffffffc00066e5d4>] genpd_runtime_resume+0x74/0x164 [ 6.996371] [<ffffffc0006609d0>] __rpm_callback+0x48/0x7c [ 7.002384] [<ffffffc000660a88>] rpm_callback+0x84/0xa4 [ 7.008223] [<ffffffc0006623f8>] rpm_resume+0x64c/0x704 [ 7.014062] [<ffffffc000662528>] __pm_runtime_resume+0x78/0x9c [ 7.020508] [<ffffffc000614528>] vop_crtc_enable+0x88/0xbd0 [ 7.026694] [<ffffffc0005debc0>] drm_atomic_helper_commit_modeset_enables+0x184/0x1a0 [ 7.035136] [<ffffffc0006116c8>] rockchip_atomic_commit_complete+0x234/0x3c0 [ 7.042797] [<ffffffc00061197c>] rockchip_drm_atomic_commit+0x128/0x148 [ 7.050023] [<ffffffc000604130>] drm_atomic_commit+0x70/0x7c [ 7.056297] [<ffffffc0005e0f10>] drm_atomic_helper_set_config+0x5c/0xac [ 7.063524] [<ffffffc0005f1980>] drm_mode_set_config_internal+0x68/0xe4 [ 7.070752] [<ffffffc0005f7184>] drm_mode_setcrtc+0x404/0x48c [ 7.077112] [<ffffffc0005e736c>] drm_ioctl+0x2ac/0x42c [ 7.082865] [<ffffffc00060572c>] drm_compat_ioctl+0x3c/0x70 [ 7.089050] [<ffffffc0003ed8b8>] compat_SyS_ioctl+0x134/0x10ac [ 7.095498] [<ffffffc000203e34>] el0_svc_naked+0x24/0x28 [ 7.101423] -> #0 (&vop->vop_lock){+.+.+.}: [ 7.105827] [<ffffffc000282f70>] print_circular_bug+0x68/0x2c8 [ 7.112274] [<ffffffc000286f14>] __lock_acquire+0x134c/0x1a74 [ 7.118633] [<ffffffc000287d18>] lock_acquire+0x248/0x280 [ 7.124644] [<ffffffc0009d6cc0>] mutex_lock_nested+0x94/0x794 [ 7.131002] [<ffffffc000613ad8>] rockchip_drm_wait_vact_end+0x48/0x334 [ 7.138142] [<ffffffc000616170>] dmc_notify+0x40/0x90 [ 7.143807] [<ffffffc000247be4>] notifier_call_chain+0x60/0x94 [ 7.150254] [<ffffffc000247c9c>] raw_notifier_call_chain+0x38/0x44 [ 7.157047] [<ffffffc000809a78>] rockchip_ddrclk_set_rate_func+0x7c/0x13c [ 7.164447] [<ffffffc00023f520>] process_one_work+0x3e4/0x700 [ 7.170807] [<ffffffc000240170>] worker_thread+0x360/0x428 [ 7.176905] [<ffffffc0002463dc>] kthread+0x120/0x128 [ 7.182484] [<ffffffc000203dd0>] ret_from_fork+0x10/0x40 [ 7.188411] [ 7.188411] other info that might help us debug this: [ 7.188411] [ 7.196403] Chain exists of: &vop->vop_lock --> (&ddrclk->set_rate_work) --> &ddrclk->lock [ 7.205169] Possible unsafe locking scenario: [ 7.205169] [ 7.211080] CPU0 CPU1 [ 7.215603] ---- ---- [ 7.220126] lock(&ddrclk->lock); [ 7.223550] lock((&ddrclk->set_rate_work)); [ 7.230441] lock(&ddrclk->lock); [ 7.236376] lock(&vop->vop_lock); [ 7.239887] [ 7.239887] *** DEADLOCK *** [ 7.239887] [ 7.245800] 3 locks held by kworker/0:1H/166: [ 7.250149] #0: ("events_highpri"){.+.+..}, at: [<ffffffc00023f324>] process_one_work+0x1e8/0x700 [ 7.259249] #1: ((&ddrclk->set_rate_work)){+.+...}, at: [<ffffffc00023f324>] process_one_work+0x1e8/0x700 [ 7.269044] #2: (&ddrclk->lock){+.+...}, at: [<ffffffc000809a68>] rockchip_ddrclk_set_rate_func+0x6c/0x13c [ 7.278925] [ 7.278925] stack backtrace: [ 7.283280] CPU: 0 PID: 166 Comm: kworker/0:1H Not tainted 4.4.64 #129 [ 7.289797] Hardware name: Google Kevin (DT) [ 7.294063] Workqueue: events_highpri rockchip_ddrclk_set_rate_func [ 7.300334] Call trace: [ 7.302780] [<ffffffc000208ae4>] dump_backtrace+0x0/0x160 [ 7.308173] [<ffffffc000208d74>] show_stack+0x20/0x28 [ 7.313221] [<ffffffc00051af70>] dump_stack+0xb4/0xf0 [ 7.318267] [<ffffffc0002831b4>] print_circular_bug+0x2ac/0x2c8 [ 7.324179] [<ffffffc000286f14>] __lock_acquire+0x134c/0x1a74 [ 7.329917] [<ffffffc000287d18>] lock_acquire+0x248/0x280 [ 7.335310] [<ffffffc0009d6cc0>] mutex_lock_nested+0x94/0x794 [ 7.341049] [<ffffffc000613ad8>] rockchip_drm_wait_vact_end+0x48/0x334 [ 7.347566] [<ffffffc000616170>] dmc_notify+0x40/0x90 [ 7.352613] [<ffffffc000247be4>] notifier_call_chain+0x60/0x94 [ 7.358438] [<ffffffc000247c9c>] raw_notifier_call_chain+0x38/0x44 [ 7.364611] [<ffffffc000809a78>] rockchip_ddrclk_set_rate_func+0x7c/0x13c [ 7.371390] [<ffffffc00023f520>] process_one_work+0x3e4/0x700 [ 7.377129] [<ffffffc000240170>] worker_thread+0x360/0x428 [ 7.382608] [<ffffffc0002463dc>] kthread+0x120/0x128 [ 7.387567] [<ffffffc000203dd0>] ret_from_fork+0x10/0x40
,
May 8 2017
Flushing the entire high priority system workqueue very much looks like a hack to me. Not that I understand why the flush_work() would result in a deadlock.
,
May 8 2017
@2: It's not as bad as you imply by "entire", but yeah it does feel like a hack. Specifically: * If you queue your work, it effectively needs to wait for everyone else anyway, right? Basically a flush shouldn't take any longer than queuing and waiting for one item (I think? I have to grok the nature of how this works across multiple CPUs). * Not many things use the high priority work queue. --- I have nearly finished code for moving this whole thing to a kthread_worker, but I'm not quite done. I suspect that this will also make the lockdep splat go away, but since I don't fully understand the deadlock I'm a little worried that this is just another way to hide something...
,
May 8 2017
#3: But only because the high prio workqueue isn't used much which by itself suggests that it is maybe not such a good idea to use it in the first place. I suspect other drivers define their own workqueues. Either case I would assume that a flush on an entire system wq will result in all workers on that wq to be flushed, not just the one we are interested in. Assuming that there won't be many running seems at the very least unusual. I don't like writing code based on such assumptions. Re kthreads - I thought those were out of favor and that workqueues should be used instead since they are more flexible ? Or does my memory defeat me ? Anyway I don't see much point in arguing about this. I don't feel comfortable, and I am concerned that we are missing something, but that is nothing that I can back up with hard data. So maybe just ignore my rambling.
,
May 8 2017
@4: Ah, interesting. I could do something just like the above, but with a private workqueue. It would be less hacky in that way, but I still really want to understand what lockdep is trying to say before I do something like that.
,
May 9 2017
hi #5, i think it is trying to warn this: we have these lock deps: 1/ dmc lock(set freq) -> vop lock(wait line flag) 2/ vop lock(vop_crtc_enable) -> pm domain lock -> dmc lock
,
May 9 2017
sorry, dmc lock should be ddr clk lock: vop->vop_lock(vop_crtc_enable) -> dmc_pmu->mutex(pm_domain) -> ddrclk->lock(update_devfreq->rockchip_ddrclk_wait_set_rate->flush_work->rockchip_ddrclk_set_rate_func) -> vop->vop_lock(wait line flag) i'll try to add some logs to confirm it
,
May 9 2017
Hi guys,
break the lockdep chain with this hack:
+++ b/drivers/soc/rockchip/pm_domains.c
@@ -253,7 +253,7 @@ static int rockchip_pd_power(struct rockchip_pm_domain *pd, bool power_on)
{
int i;
- mutex_lock(&pd->pmu->mutex);
+ //mutex_lock(&pd->pmu->mutex);
if (rockchip_pmu_domain_is_on(pd) != power_on) {
for (i = 0; i < pd->num_clks; i++)
@@ -279,7 +279,7 @@ static int rockchip_pd_power(struct rockchip_pm_domain *pd, bool power_on)
clk_disable(pd->clks[i]);
}
- mutex_unlock(&pd->pmu->mutex);
+ //mutex_unlock(&pd->pmu->mutex);
return 0;
}
i cannot repro that warning anymore.
and this warning is harmless actually, since we would only register the dmc_notify at the end of vop_crtc_enable, so it's not possible to hit that deadlock.
the vop_lock is added to protect the race of wait line flag and vop crtc disable, by:
https://chromium-review.googlesource.com/411552
if we really wanna fix this warning, maybe we can do this:
1/ maybe we can move pm_runtime_* ops out of vop_lock's lock area
2/ maybe we can even remove vop_lock from vop_crtc_enable
3/ maybe we can remove the whole vop_lock, and accept the 100ms timeout when wait line flag hit vop_crtc_disable
attached patch is for 1/, and i'll ask zain to check it too.
,
May 9 2017
hmm...looking into the original issue of CL:411552, it looks like the vop_lock is for vop->is_enabled WARN_ON check. so CL uploaded: https://chromium-review.googlesource.com/500109
,
May 9 2017
I think we should be able to remove vop_lock completely. Please see my comments on the CL from #9.
,
May 9 2017
#10: The lock was introduced in CL:411552. Do we have reason to believe that the condition it tries to address no longer applies ?
,
May 9 2017
#11, yes, copying from my reply on gerrit: "Yes, the whole PSR framework code was redesigned and it is now ensured that PSR callbacks cannot be called during an atomic commit. Atomic commit is the only way in which is_enabled can change, as I pointed in my previous comment. (This happened in February, as a part of bug 35587377, which was few months after 35581652.)" And, anyway, on gerrit I posted a whole analysis of how the affected code is invoked, so please see my comments to the CL from #9 for details.
,
May 9 2017
#12: Again, please pardon my ignorance. Thanks a lot for the clarification. maybe we can then just revert CL:411552 ?
,
May 9 2017
Revert sounds good to me, although it might not apply cleanly with all the changes that happened since that commit. On the other hand, it might be a good idea to actually add a comment to rockchip_drm_wait_vact_end(), which says that it must be called from a context that is mutually exclusive with VOP enable/disable.
,
May 9 2017
Seems that Jeffy doesn't have an account on this tracker, so I can't set him as the owner. I'm content to let you guys hash out how this should best be solved (thanks!) since this isn't an area I'm massively familiar with. Setting Tomasz as the onwer--hope that's OK.
,
May 10 2017
reverted that CL, and also add the comment tomasz mentioned at #14.
,
May 10 2017
,
May 19 2017
,
Jan 22 2018
|
||||
►
Sign in to add a comment |
||||
Comment 1 by diand...@chromium.org
, May 8 2017Trying to decipher this a little bit... One part of this is: * High Priority Workqueue -> rockchip_ddrclk_set_rate_func() -> mutex_lock(&ddrclk->lock) -> raw_notifier_call_chain() -> dmc_notify() -> rockchip_drm_wait_vact_end() -> mutex_lock(&vop->vop_lock) The other part has to do with workqueues. We have a callchain that looks like: * rk3399_dmcfreq_target() -> rockchip_ddrclk_wait_set_rate() -> flush_work() => block on high priority workqueue If I get rid of that "flush_work()" then the splat goes away. This stupid patch "works": === $ git diff diff --git a/drivers/clk/rockchip/clk-ddr.c b/drivers/clk/rockchip/clk-ddr.c index f1f5b35b21b6..3256b92685e9 100644 --- a/drivers/clk/rockchip/clk-ddr.c +++ b/drivers/clk/rockchip/clk-ddr.c @@ -141,7 +141,8 @@ void rockchip_ddrclk_wait_set_rate(struct clk *clk) struct clk_hw *hw = __clk_get_hw(clk); struct rockchip_ddrclk *ddrclk = to_rockchip_ddrclk_hw(hw); - flush_work(&ddrclk->set_rate_work); + if (work_busy(&ddrclk->set_rate_work)) + flush_workqueue(system_highpri_wq); } EXPORT_SYMBOL_GPL(rockchip_ddrclk_wait_set_rate); === ...but I haven't completely understood if this is a "fix" or just a hack to avoid the lockdep splat. If I understand correctly lockdep thinks that we might end up with some sort of implicit dependency where we have: * grab a vop lock * flush a work queue * If ddr work is sitting on the work queue, it might never be able to run Not only do I not see the path of "grab vop lock -> flush work queue" but also the DDR work is on the "high priority" work queue and (I think) the VOP isn't using that (right?). Certainly flush_work() doesn't know what work queue you might be working on... Actually, there's really only one other place using the high priority workqueue: drivers/cpufreq/cpu-boost.c: queue_work(system_highpri_wq, &cpuboost_input_boost_work); === If anyone has any better ideas, please yell. I can keep trying to poke at it too...