lkml.org 
[lkml]   [2016]   [May]   [25]   [last100]   RSS Feed
Views: [wrap][no wrap]   [headers]  [forward] 
 
Messages in this thread
/
SubjectRe: [PATCH] soc/tegra: pmc: Fix "scheduling while atomic"
From
Date
On 25.05.2016 18:09, Jon Hunter wrote:
>
> On 05/05/16 15:24, Dmitry Osipenko wrote:
>> Hello, Jon!
>>
>> On 05.05.2016 16:17, Jon Hunter wrote:
>>>
>>> Thanks for the report. I have been unable to reproduce this, but then I
>>> don't see my tegra20 entering LP2 during cpuidle. I did force my tegra20
>>> into LP2 during suspend which will exercise the same code but I did not
>>> trigger this either. However, from looking at the code it does appear
>>> that we could hit this.
>>>
>>
>> As I wrote before, it's quite difficult to reproduce.
>
> So far I have been unable to reproduce this. I did noticed that in the
> upstream kernel we disable LP2 on Tegra20 if PCIE is enabled (see
> arch/arm/mach-tegra/cpuidle-tegra20.c) ...
>
> /*
> * Tegra20 HW appears to have a bug such that PCIe device interrupts, whether
> * they are legacy IRQs or MSI, are lost when LP2 is enabled. To work around
> * this, simply disable LP2 if the PCI driver and DT node are both enabled.
> */
> void tegra20_cpuidle_pcie_irqs_in_use(void)
> {
> pr_info_once(
> "Disabling cpuidle LP2 state, since PCIe IRQs are in use\n");
> tegra_idle_driver.states[1].disabled = true;
> }
>
> Even if I remove this and verify that I can enter LP2, I have been unable
> to reproduce this. I know that you said that it is difficult to reproduce
> and there needs to be a specific workload, however, from looking at the
> code I am trying to understand the situation that would trigger this.
>
> Your backtrace shows ...
>
> [ 3.430853] [<c0850fcc>] (dump_stack) from [<c00411f8>] (__schedule_bug+0x50/0x64)
> [ 3.431079] [<c00411f8>] (__schedule_bug) from [<c08553a8>] (__schedule+0x5c8/0x688)
> [ 3.431453] [<c08553a8>] (__schedule) from [<c08558f4>] (schedule_preempt_disabled+0x24/0x34)
> [ 3.431835] [<c08558f4>] (schedule_preempt_disabled) from [<c0856f24>] (__mutex_lock_slowpath+0xbc/0x170)
> [ 3.432204] [<c0856f24>] (__mutex_lock_slowpath) from [<c0857024>] (mutex_lock+0x4c/0x50)
> [ 3.432427] [<c0857024>] (mutex_lock) from [<c0610368>] (clk_prepare_lock+0x88/0xfc)
> [ 3.432800] [<c0610368>] (clk_prepare_lock) from [<c0611034>] (clk_get_rate+0xc/0x60)
> [ 3.433177] [<c0611034>] (clk_get_rate) from [<c034f10c>] (tegra_pmc_enter_suspend_mode+0x188/0x20c)
> [ 3.433580] [<c034f10c>] (tegra_pmc_enter_suspend_mode) from [<c0020d48>] (tegra_idle_lp2_last+0xc/0x40)
> [ 3.433795] [<c0020d48>] (tegra_idle_lp2_last) from [<c0021e1c>] (tegra20_idle_lp2_coupled+0x118/0x1fc)
> [ 3.434171] [<c0021e1c>] (tegra20_idle_lp2_coupled) from [<c055ec24>] (cpuidle_enter_state+0x3c/0x160)
> [ 3.434551] [<c055ec24>] (cpuidle_enter_state) from [<c0560ce8>] (cpuidle_enter_state_coupled+0x3dc/0x3f4)
> [ 3.434959] [<c0560ce8>] (cpuidle_enter_state_coupled) from [<c0055f1c>] (cpu_startup_entry+0x240/0x288)
> [ 3.435340] [<c0055f1c>] (cpu_startup_entry) from [<c0b29c84>] (start_kernel+0x3b4/0x3c0)
> [ 3.435557] [<c0b29c84>] (start_kernel) from [<00008074>] (0x8074)
>
> ... however, when we call tegra_idle_lp2_last(), CPU1 should be down and
> so I would not expect that the call to mutex_trylock() in clk_get_rate()
> would fail (ie. return 0 for contention) at this point and cause us to
> call mutex_lock and sleep. Therefore, I am wondering if there could be
> another bug in the v3.18 kernel that you are using that could be
> triggering this.
>
> If you are able to reproduce this on v3.18, then it would be good if you
> could trace the CCF calls around this WARNING to see what is causing the
> contention.
>

I managed to reproduce it with some CCF "tracing".
Full kmsg log is here: https://bpaste.net/show/d8ab7b7534b7

Looks like CPU freq governor thread yields during clk_set_rate() and then CPU
idle kicks in, taking the same mutex.

However, cpufreq_interactive governor is android specific governor and isn't in
upstream kernel yet. Quick googling shows that recent "upstreaming" patch uses
same cpufreq_interactive_speedchange_task: https://lkml.org/lkml/2016/5/20/41

I'm not aware of other possibility to reproduce this issue, it needs some CCF
interaction from a separate task. So the current upstream kernel shouldn't be
affected, I guess.

[snip]
[ 3.923019] clk_set_rate: cpu_emc CPU: 0 +
[ 3.923151] clk_get_rate: cpu_emc CPU: 0 +
[ 3.923287] clk_get_rate: cpu_emc CPU: 0 -
[ 3.923423] clk_set_rate: emc CPU: 0 +
[ 3.923664] clk_get_rate: emc CPU: 0 +
[ 3.923799] clk_get_rate: emc CPU: 0 -
[ 3.925405] clk_get_rate: pclk CPU: 0 +
[ 3.925776] BUG: scheduling while atomic: swapper/0/0/0x00000002
[ 3.925975] Modules linked in:
[ 3.926377] CPU: 0 PID: 0 Comm: swapper/0 Not tainted
3.18.31-digetx-thor-01336-g63f7b8f-dirty #1184
[ 3.926860] [<c010d3e8>] (unwind_backtrace) from [<c0109b28>]
(show_stack+0x10/0x14)
[ 3.927252] [<c0109b28>] (show_stack) from [<c0941cd4>] (dump_stack+0x94/0xa8)
[ 3.927488] [<c0941cd4>] (dump_stack) from [<c01390c8>]
(__schedule_bug+0x50/0x64)
[ 3.927865] [<c01390c8>] (__schedule_bug) from [<c09460b0>]
(__schedule+0x5c8/0x688)
[ 3.928235] [<c09460b0>] (__schedule) from [<c09465fc>]
(schedule_preempt_disabled+0x24/0x34)
[ 3.928608] [<c09465fc>] (schedule_preempt_disabled) from [<c0947c2c>]
(__mutex_lock_slowpath+0xbc/0x170)
[ 3.928820] [<c0947c2c>] (__mutex_lock_slowpath) from [<c0947d2c>]
(mutex_lock+0x4c/0x50)
[ 3.929230] [<c0947d2c>] (mutex_lock) from [<c0700d54>]
(clk_prepare_lock+0x88/0xfc)
[ 3.929602] [<c0700d54>] (clk_prepare_lock) from [<c0701aa0>]
(clk_get_rate+0x30/0xa4)
[ 3.930005] [<c0701aa0>] (clk_get_rate) from [<c04511cc>]
(tegra_pmc_enter_suspend_mode+0x188/0x20c)
[ 3.930259] [<c04511cc>] (tegra_pmc_enter_suspend_mode) from [<c0118c08>]
(tegra_idle_lp2_last+0xc/0x40)
[ 3.930627] [<c0118c08>] (tegra_idle_lp2_last) from [<c0119c9c>]
(tegra20_idle_lp2_coupled+0x118/0x1fc)
[ 3.931051] [<c0119c9c>] (tegra20_idle_lp2_coupled) from [<c065007c>]
(cpuidle_enter_state+0x3c/0x160)
[ 3.931437] [<c065007c>] (cpuidle_enter_state) from [<c0652140>]
(cpuidle_enter_state_coupled+0x3dc/0x3f4)
[ 3.931846] [<c0652140>] (cpuidle_enter_state_coupled) from [<c014ddec>]
(cpu_startup_entry+0x240/0x288)
[ 3.932247] [<c014ddec>] (cpu_startup_entry) from [<c0d00c84>]
(start_kernel+0x3b4/0x3c0)
[ 3.932472] [<c0d00c84>] (start_kernel) from [<00008074>] (0x8074)
[ 3.932881] bad: scheduling from the idle thread!

[snip]

[ 4.131017] [<c013b754>] (ttwu_do_activate.constprop.15) from [<c013dc04>]
(try_to_wake_up+0x264/0x308)
[ 4.131239] [<c013dc04>] (try_to_wake_up) from [<c0947d64>]
(__mutex_unlock_slowpath+0x34/0x40)
[ 4.131612] [<c0947d64>] (__mutex_unlock_slowpath) from [<c0702d0c>]
(clk_set_rate+0xac/0xd8)
[ 4.131991] [<c0702d0c>] (clk_set_rate) from [<c064fa24>]
(tegra_target+0x74/0x134)
[ 4.132401] [<c064fa24>] (tegra_target) from [<c0647720>]
(__cpufreq_driver_target+0x164/0x294)
[ 4.132619] [<c0647720>] (__cpufreq_driver_target) from [<c064eba4>]
(cpufreq_interactive_speedchange_task+0x23c/0x28c)
[ 4.133010] [<c064eba4>] (cpufreq_interactive_speedchange_task) from
[<c0134fbc>] (kthread+0xd0/0xe8)
[ 4.133385] [<c0134fbc>] (kthread) from [<c0106460>] (ret_from_fork+0x14/0x34)
[ 4.133748] Code: bad PC value
[ 4.133955] ---[ end trace e93befbb37372e27 ]---
[ 4.134162] note: cfinteractive[53] exited with preempt_count 3

--
Dmitry

\
 
 \ /
  Last update: 2016-05-25 21:01    [W:0.088 / U:0.916 seconds]
©2003-2020 Jasper Spaans|hosted at Digital Ocean and TransIP|Read the blog|Advertise on this site