Groups | Search | Server Info | Keyboard shortcuts | Login | Register [http] [https] [nntp] [nntps]

Groups > linux.kernel > #1406994 > unrolled thread

Re: [PATCH] soc/tegra: pmc: Fix "scheduling while atomic"

Started byJon Hunter <jonathanh@nvidia.com>
First post2016-05-25 17:10 +0200
Last post2016-05-27 16:50 +0200
Articles 10 — 2 participants

Back to article view | Back to linux.kernel

This discussion starts older than the indexed window; earlier articles aren't shown. The article labeled Started by below is the oldest one visible, not the original post.

Contents

  Re: [PATCH] soc/tegra: pmc: Fix "scheduling while atomic" Jon Hunter <jonathanh@nvidia.com> - 2016-05-25 17:10 +0200
    Re: [PATCH] soc/tegra: pmc: Fix "scheduling while atomic" Dmitry Osipenko <digetx@gmail.com> - 2016-05-25 21:00 +0200
      Re: [PATCH] soc/tegra: pmc: Fix "scheduling while atomic" Jon Hunter <jonathanh@nvidia.com> - 2016-05-26 10:50 +0200
        Re: [PATCH] soc/tegra: pmc: Fix "scheduling while atomic" Dmitry Osipenko <digetx@gmail.com> - 2016-05-26 13:50 +0200
          Re: [PATCH] soc/tegra: pmc: Fix "scheduling while atomic" Jon Hunter <jonathanh@nvidia.com> - 2016-05-26 16:40 +0200
            Re: [PATCH] soc/tegra: pmc: Fix "scheduling while atomic" Dmitry Osipenko <digetx@gmail.com> - 2016-05-26 17:00 +0200
              Re: [PATCH] soc/tegra: pmc: Fix "scheduling while atomic" Jon Hunter <jonathanh@nvidia.com> - 2016-05-26 17:30 +0200
                Re: [PATCH] soc/tegra: pmc: Fix "scheduling while atomic" Dmitry Osipenko <digetx@gmail.com> - 2016-05-26 19:10 +0200
                  Re: [PATCH] soc/tegra: pmc: Fix "scheduling while atomic" Jon Hunter <jonathanh@nvidia.com> - 2016-05-27 14:50 +0200
                    Re: [PATCH] soc/tegra: pmc: Fix "scheduling while atomic" Dmitry Osipenko <digetx@gmail.com> - 2016-05-27 16:50 +0200

#1406994 — Re: [PATCH] soc/tegra: pmc: Fix "scheduling while atomic"

FromJon Hunter <jonathanh@nvidia.com>
Date2016-05-25 17:10 +0200
SubjectRe: [PATCH] soc/tegra: pmc: Fix "scheduling while atomic"
Message-ID<rCIBz-2uj-13@gated-at.bofh.it>
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.

Cheers
Jon

-- 
nvpublic

[toc] | [next] | [standalone]

#1407166

FromDmitry Osipenko <digetx@gmail.com>
Date2016-05-25 21:00 +0200
Message-ID<rCMca-4qa-9@gated-at.bofh.it>
In reply to#1406994
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

[toc] | [prev] | [next] | [standalone]

#1407460

FromJon Hunter <jonathanh@nvidia.com>
Date2016-05-26 10:50 +0200
Message-ID<rCZ9n-48C-1@gated-at.bofh.it>
In reply to#1407166
On 25/05/16 19:51, Dmitry Osipenko wrote:
> On 25.05.2016 18:09, Jon Hunter wrote:

...

>> 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.

On the surface that sounds odd to me, but without understanding the
details, I guess I don't know if this is a valid thing to be doing or
even how that actually works!

> 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

Do you know if this version they are upstreaming could also yield during
the clk_set_rate()?

> 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.

What still does not make sense to me is why any frequency changes have
not completed before we attempt to enter the LP2 state?

OK, well may be we will hold off on this change for the moment.

Cheers
Jon

-- 
nvpublic

[toc] | [prev] | [next] | [standalone]

#1407532

FromDmitry Osipenko <digetx@gmail.com>
Date2016-05-26 13:50 +0200
Message-ID<rD1XA-5UX-5@gated-at.bofh.it>
In reply to#1407460
On 26.05.2016 11:42, Jon Hunter wrote:
>
> On 25/05/16 19:51, Dmitry Osipenko wrote:
>> On 25.05.2016 18:09, Jon Hunter wrote:
>
> ...
>
>>> 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.
>
> On the surface that sounds odd to me, but without understanding the
> details, I guess I don't know if this is a valid thing to be doing or
> even how that actually works!
>

The reason of that happening should be that I'm using clk PRE/POST rate change 
notifiers in my DVFS driver that takes other mutexes and they could be locked, 
causing schedule. I haven't mentioned it before, sorry.

 From drivers/clk/clk.c:

static struct task_struct *prepare_owner;

...

/***           locking             ***/
static void clk_prepare_lock(void)
{
	if (!mutex_trylock(&prepare_lock)) {
		if (prepare_owner == current) {
			prepare_refcnt++;
			return;
		}
		mutex_lock(&prepare_lock);
	}

You can see that it would lock the mutex if prepare_owner != current, in my case 
it's idle thread != interactive gov. thread.

>> 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
>
> Do you know if this version they are upstreaming could also yield during
> the clk_set_rate()?
>

I think it should be assumed that any clk_set_rate() potentially could. Please 
correct me if I'm wrong.

>> 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.
>
> What still does not make sense to me is why any frequency changes have
> not completed before we attempt to enter the LP2 state?
>

Why not? I don't see any CPUIDLE <-> CPUFREQ interlocking. Do you think it could 
be harmful somehow?

> OK, well may be we will hold off on this change for the moment.

-- 
Dmitry

[toc] | [prev] | [next] | [standalone]

#1407585

FromJon Hunter <jonathanh@nvidia.com>
Date2016-05-26 16:40 +0200
Message-ID<rD4C6-7At-15@gated-at.bofh.it>
In reply to#1407532
On 26/05/16 12:42, Dmitry Osipenko wrote:
> On 26.05.2016 11:42, Jon Hunter wrote:
>>
>> On 25/05/16 19:51, Dmitry Osipenko wrote:
>>> On 25.05.2016 18:09, Jon Hunter wrote:
>>
>> ...
>>
>>>> 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.
>>
>> On the surface that sounds odd to me, but without understanding the
>> details, I guess I don't know if this is a valid thing to be doing or
>> even how that actually works!
>>
> 
> The reason of that happening should be that I'm using clk PRE/POST rate
> change notifiers in my DVFS driver that takes other mutexes and they
> could be locked, causing schedule. I haven't mentioned it before, sorry.

OK, but I am not sure how these "other mutexes" would be relevant here
without any more details.

> From drivers/clk/clk.c:
> 
> static struct task_struct *prepare_owner;
> 
> ...
> 
> /***           locking             ***/
> static void clk_prepare_lock(void)
> {
>     if (!mutex_trylock(&prepare_lock)) {
>         if (prepare_owner == current) {
>             prepare_refcnt++;
>             return;
>         }
>         mutex_lock(&prepare_lock);
>     }
> 
> You can see that it would lock the mutex if prepare_owner != current, in
> my case it's idle thread != interactive gov. thread.

Right, but that would imply that someone else is actively doing
something with a clock. However, if we are entering LP2, then that
implies that all CPUs are idle and so I still don't understand the
scenario where this would be locked in that case. May be there is
something I am overlooking here?

>>> 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
>>
>> Do you know if this version they are upstreaming could also yield during
>> the clk_set_rate()?
>>
> 
> I think it should be assumed that any clk_set_rate() potentially could.
> Please correct me if I'm wrong.
> 
>>> 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.
>>
>> What still does not make sense to me is why any frequency changes have
>> not completed before we attempt to enter the LP2 state?
>>
> Why not? I don't see any CPUIDLE <-> CPUFREQ interlocking. Do you think
> it could be harmful somehow?

Like I said before, I still don't understand that scenario that is
causing this and without being able to fully understand it, I have no
idea what the exact problem we are trying to fix here is.

Cheers
Jon

-- 
nvpublic

[toc] | [prev] | [next] | [standalone]

#1407593

FromDmitry Osipenko <digetx@gmail.com>
Date2016-05-26 17:00 +0200
Message-ID<rD4Vs-7H3-13@gated-at.bofh.it>
In reply to#1407585
On 26.05.2016 17:32, Jon Hunter wrote:
>
> On 26/05/16 12:42, Dmitry Osipenko wrote:
>> On 26.05.2016 11:42, Jon Hunter wrote:
>>>
>>> On 25/05/16 19:51, Dmitry Osipenko wrote:
>>>> On 25.05.2016 18:09, Jon Hunter wrote:
>>>
>>> ...
>>>
>>>>> 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.
>>>
>>> On the surface that sounds odd to me, but without understanding the
>>> details, I guess I don't know if this is a valid thing to be doing or
>>> even how that actually works!
>>>
>>
>> The reason of that happening should be that I'm using clk PRE/POST rate
>> change notifiers in my DVFS driver that takes other mutexes and they
>> could be locked, causing schedule. I haven't mentioned it before, sorry.
>
> OK, but I am not sure how these "other mutexes" would be relevant here
> without any more details.
>
>> From drivers/clk/clk.c:
>>
>> static struct task_struct *prepare_owner;
>>
>> ...
>>
>> /***           locking             ***/
>> static void clk_prepare_lock(void)
>> {
>>     if (!mutex_trylock(&prepare_lock)) {
>>         if (prepare_owner == current) {
>>             prepare_refcnt++;
>>             return;
>>         }
>>         mutex_lock(&prepare_lock);
>>     }
>>
>> You can see that it would lock the mutex if prepare_owner != current, in
>> my case it's idle thread != interactive gov. thread.
>
> Right, but that would imply that someone else is actively doing
> something with a clock. However, if we are entering LP2, then that
> implies that all CPUs are idle and so I still don't understand the
> scenario where this would be locked in that case. May be there is
> something I am overlooking here?
>
>>>> 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
>>>
>>> Do you know if this version they are upstreaming could also yield during
>>> the clk_set_rate()?
>>>
>>
>> I think it should be assumed that any clk_set_rate() potentially could.
>> Please correct me if I'm wrong.
>>
>>>> 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.
>>>
>>> What still does not make sense to me is why any frequency changes have
>>> not completed before we attempt to enter the LP2 state?
>>>
>> Why not? I don't see any CPUIDLE <-> CPUFREQ interlocking. Do you think
>> it could be harmful somehow?
>
> Like I said before, I still don't understand that scenario that is
> causing this and without being able to fully understand it, I have no
> idea what the exact problem we are trying to fix here is.
>

That's how I see it:

+----------------------------------------------+
|                    CPU 0                     |
+-------------------+--------------------------+
|    Idle thread    | Interactive gov. thread  |
+----------------------------------------------+
|     inactive      |                          |
|                   |                          |
|                   |   CPU freq. change       |
|                   |                          |
|                   |   clk_set_rate()         |
|                   |                          |
|       ...         |   clk_prepare_lock()     |
|                   |                          |
|                   |   PRE rate notifier call |
|                   |                          |
|                   |   schedule               |
|                   |                          |
| irqs_disable()    |                          |
|                   |                          |
| enter CPU idle    |                          |
|                   |                          |
| clk_get_rate(pclk)|                          |
|                   |                          |
| clk_prepare_lock()|                          |
|                   |                          |
| schedule bug()    |                          |
|                   |                          |
+-------------------+--------------------------+

-- 
Dmitry

[toc] | [prev] | [next] | [standalone]

#1407601

FromJon Hunter <jonathanh@nvidia.com>
Date2016-05-26 17:30 +0200
Message-ID<rD5ou-86j-15@gated-at.bofh.it>
In reply to#1407593
On 26/05/16 15:57, Dmitry Osipenko wrote:
> On 26.05.2016 17:32, Jon Hunter wrote:
>>
>> On 26/05/16 12:42, Dmitry Osipenko wrote:
>>> On 26.05.2016 11:42, Jon Hunter wrote:
>>>>
>>>> On 25/05/16 19:51, Dmitry Osipenko wrote:
>>>>> On 25.05.2016 18:09, Jon Hunter wrote:
>>>>
>>>> ...
>>>>
>>>>>> 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.
>>>>
>>>> On the surface that sounds odd to me, but without understanding the
>>>> details, I guess I don't know if this is a valid thing to be doing or
>>>> even how that actually works!
>>>>
>>>
>>> The reason of that happening should be that I'm using clk PRE/POST rate
>>> change notifiers in my DVFS driver that takes other mutexes and they
>>> could be locked, causing schedule. I haven't mentioned it before, sorry.
>>
>> OK, but I am not sure how these "other mutexes" would be relevant here
>> without any more details.
>>
>>> From drivers/clk/clk.c:
>>>
>>> static struct task_struct *prepare_owner;
>>>
>>> ...
>>>
>>> /***           locking             ***/
>>> static void clk_prepare_lock(void)
>>> {
>>>     if (!mutex_trylock(&prepare_lock)) {
>>>         if (prepare_owner == current) {
>>>             prepare_refcnt++;
>>>             return;
>>>         }
>>>         mutex_lock(&prepare_lock);
>>>     }
>>>
>>> You can see that it would lock the mutex if prepare_owner != current, in
>>> my case it's idle thread != interactive gov. thread.
>>
>> Right, but that would imply that someone else is actively doing
>> something with a clock. However, if we are entering LP2, then that
>> implies that all CPUs are idle and so I still don't understand the
>> scenario where this would be locked in that case. May be there is
>> something I am overlooking here?
>>
>>>>> 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
>>>>
>>>> Do you know if this version they are upstreaming could also yield
>>>> during
>>>> the clk_set_rate()?
>>>>
>>>
>>> I think it should be assumed that any clk_set_rate() potentially could.
>>> Please correct me if I'm wrong.
>>>
>>>>> 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.
>>>>
>>>> What still does not make sense to me is why any frequency changes have
>>>> not completed before we attempt to enter the LP2 state?
>>>>
>>> Why not? I don't see any CPUIDLE <-> CPUFREQ interlocking. Do you think
>>> it could be harmful somehow?
>>
>> Like I said before, I still don't understand that scenario that is
>> causing this and without being able to fully understand it, I have no
>> idea what the exact problem we are trying to fix here is.
>>
> 
> That's how I see it:
> 
> +----------------------------------------------+
> |                    CPU 0                     |
> +-------------------+--------------------------+
> |    Idle thread    | Interactive gov. thread  |
> +----------------------------------------------+
> |     inactive      |                          |
> |                   |                          |
> |                   |   CPU freq. change       |
> |                   |                          |
> |                   |   clk_set_rate()         |
> |                   |                          |
> |       ...         |   clk_prepare_lock()     |
> |                   |                          |
> |                   |   PRE rate notifier call |
> |                   |                          |
> |                   |   schedule               |

What is this notifier doing? Is there some sort of hardware activity
that it is waiting for to complete?

Cheers
Jon

-- 
nvpublic

[toc] | [prev] | [next] | [standalone]

#1407642

FromDmitry Osipenko <digetx@gmail.com>
Date2016-05-26 19:10 +0200
Message-ID<rD6Xg-Hl-7@gated-at.bofh.it>
In reply to#1407601
On 26.05.2016 18:27, Jon Hunter wrote:
>
> On 26/05/16 15:57, Dmitry Osipenko wrote:
>> On 26.05.2016 17:32, Jon Hunter wrote:
>>>
>>> On 26/05/16 12:42, Dmitry Osipenko wrote:
>>>> On 26.05.2016 11:42, Jon Hunter wrote:
>>>>>
>>>>> On 25/05/16 19:51, Dmitry Osipenko wrote:
>>>>>> On 25.05.2016 18:09, Jon Hunter wrote:
>>>>>
>>>>> ...
>>>>>
>>>>>>> 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.
>>>>>
>>>>> On the surface that sounds odd to me, but without understanding the
>>>>> details, I guess I don't know if this is a valid thing to be doing or
>>>>> even how that actually works!
>>>>>
>>>>
>>>> The reason of that happening should be that I'm using clk PRE/POST rate
>>>> change notifiers in my DVFS driver that takes other mutexes and they
>>>> could be locked, causing schedule. I haven't mentioned it before, sorry.
>>>
>>> OK, but I am not sure how these "other mutexes" would be relevant here
>>> without any more details.
>>>
>>>> From drivers/clk/clk.c:
>>>>
>>>> static struct task_struct *prepare_owner;
>>>>
>>>> ...
>>>>
>>>> /***           locking             ***/
>>>> static void clk_prepare_lock(void)
>>>> {
>>>>     if (!mutex_trylock(&prepare_lock)) {
>>>>         if (prepare_owner == current) {
>>>>             prepare_refcnt++;
>>>>             return;
>>>>         }
>>>>         mutex_lock(&prepare_lock);
>>>>     }
>>>>
>>>> You can see that it would lock the mutex if prepare_owner != current, in
>>>> my case it's idle thread != interactive gov. thread.
>>>
>>> Right, but that would imply that someone else is actively doing
>>> something with a clock. However, if we are entering LP2, then that
>>> implies that all CPUs are idle and so I still don't understand the
>>> scenario where this would be locked in that case. May be there is
>>> something I am overlooking here?
>>>
>>>>>> 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
>>>>>
>>>>> Do you know if this version they are upstreaming could also yield
>>>>> during
>>>>> the clk_set_rate()?
>>>>>
>>>>
>>>> I think it should be assumed that any clk_set_rate() potentially could.
>>>> Please correct me if I'm wrong.
>>>>
>>>>>> 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.
>>>>>
>>>>> What still does not make sense to me is why any frequency changes have
>>>>> not completed before we attempt to enter the LP2 state?
>>>>>
>>>> Why not? I don't see any CPUIDLE <-> CPUFREQ interlocking. Do you think
>>>> it could be harmful somehow?
>>>
>>> Like I said before, I still don't understand that scenario that is
>>> causing this and without being able to fully understand it, I have no
>>> idea what the exact problem we are trying to fix here is.
>>>
>>
>> That's how I see it:
>>
>> +----------------------------------------------+
>> |                    CPU 0                     |
>> +-------------------+--------------------------+
>> |    Idle thread    | Interactive gov. thread  |
>> +----------------------------------------------+
>> |     inactive      |                          |
>> |                   |                          |
>> |                   |   CPU freq. change       |
>> |                   |                          |
>> |                   |   clk_set_rate()         |
>> |                   |                          |
>> |       ...         |   clk_prepare_lock()     |
>> |                   |                          |
>> |                   |   PRE rate notifier call |
>> |                   |                          |
>> |                   |   schedule               |
>
> What is this notifier doing? Is there some sort of hardware activity
> that it is waiting for to complete?
>

It changes regulator voltage if required. So at least I2C would cause scheduling 
on wait_for_completion_timeout().

-- 
Dmitry

[toc] | [prev] | [next] | [standalone]

#1408041

FromJon Hunter <jonathanh@nvidia.com>
Date2016-05-27 14:50 +0200
Message-ID<rDpnb-3ub-3@gated-at.bofh.it>
In reply to#1407642
On 26/05/16 18:01, Dmitry Osipenko wrote:
> On 26.05.2016 18:27, Jon Hunter wrote:
>> On 26/05/16 15:57, Dmitry Osipenko wrote:

...

>>> That's how I see it:
>>>
>>> +----------------------------------------------+
>>> |                    CPU 0                     |
>>> +-------------------+--------------------------+
>>> |    Idle thread    | Interactive gov. thread  |
>>> +----------------------------------------------+
>>> |     inactive      |                          |
>>> |                   |                          |
>>> |                   |   CPU freq. change       |
>>> |                   |                          |
>>> |                   |   clk_set_rate()         |
>>> |                   |                          |
>>> |       ...         |   clk_prepare_lock()     |
>>> |                   |                          |
>>> |                   |   PRE rate notifier call |
>>> |                   |                          |
>>> |                   |   schedule               |
>>
>> What is this notifier doing? Is there some sort of hardware activity
>> that it is waiting for to complete?
>>
> 
> It changes regulator voltage if required. So at least I2C would cause
> scheduling on wait_for_completion_timeout().

Yes, of course that would make sense. What is interesting/odd in this
case is that the frequency is increasing (voltage scaled pre frequency
change) but yet you are entering LP2. May be that is possible? I guess
this problem may also occur on reducing frequency as well?

What are you using in the v3.18 kernel for exit_latency and
target_residency? The current mainline has 5000us and 10000us,
respectively.

It does seem that this could be triggered in the right circumstances and
I have to say I don't like the fact that this could be fragile as it is
today. Have you thought about adding a post clock notifier for pclk in
the PMC driver as an alternative to the change you are suggesting?

Cheers
Jon

-- 
nvpublic

[toc] | [prev] | [next] | [standalone]

#1408117

FromDmitry Osipenko <digetx@gmail.com>
Date2016-05-27 16:50 +0200
Message-ID<rDrfj-4Hd-5@gated-at.bofh.it>
In reply to#1408041
On 27.05.2016 15:46, Jon Hunter wrote:
>
> On 26/05/16 18:01, Dmitry Osipenko wrote:
>> On 26.05.2016 18:27, Jon Hunter wrote:
>>> On 26/05/16 15:57, Dmitry Osipenko wrote:
>
> ...
>
>>>> That's how I see it:
>>>>
>>>> +----------------------------------------------+
>>>> |                    CPU 0                     |
>>>> +-------------------+--------------------------+
>>>> |    Idle thread    | Interactive gov. thread  |
>>>> +----------------------------------------------+
>>>> |     inactive      |                          |
>>>> |                   |                          |
>>>> |                   |   CPU freq. change       |
>>>> |                   |                          |
>>>> |                   |   clk_set_rate()         |
>>>> |                   |                          |
>>>> |       ...         |   clk_prepare_lock()     |
>>>> |                   |                          |
>>>> |                   |   PRE rate notifier call |
>>>> |                   |                          |
>>>> |                   |   schedule               |
>>>
>>> What is this notifier doing? Is there some sort of hardware activity
>>> that it is waiting for to complete?
>>>
>>
>> It changes regulator voltage if required. So at least I2C would cause
>> scheduling on wait_for_completion_timeout().
>
> Yes, of course that would make sense. What is interesting/odd in this
> case is that the frequency is increasing (voltage scaled pre frequency
> change) but yet you are entering LP2. May be that is possible? I guess
> this problem may also occur on reducing frequency as well?
>

Sorry, possible what? Surely it might happen on the POST notify, I just used PRE 
for example.

There are no active tasks while CPU changing the frequency, so kernel enters 
idle mode while waiting for the HW completion - the interrupt. I don't see 
anything wrong here.

> What are you using in the v3.18 kernel for exit_latency and
> target_residency? The current mainline has 5000us and 10000us,
> respectively.
>

Default stock latencies, not sure why you are asking. It's essentially a 
mainline kernel with some added device drivers and android patches.

> It does seem that this could be triggered in the right circumstances and
> I have to say I don't like the fact that this could be fragile as it is
> today. Have you thought about adding a post clock notifier for pclk in
> the PMC driver as an alternative to the change you are suggesting?
>

No, I haven't. Sounds like a good idea, thanks for the suggestion! I'll try it 
and send V2 if it will be okay, otherwise will report the problem.

-- 
Dmitry

[toc] | [prev] | [standalone]

Back to top | Article view | linux.kernel

csiph-web