From mboxrd@z Thu Jan 1 00:00:00 1970 Return-Path: Received: from mail-lf0-f66.google.com ([209.85.215.66]:34043 "EHLO mail-lf0-f66.google.com" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S1750924AbcEYSwF (ORCPT ); Wed, 25 May 2016 14:52:05 -0400 Subject: Re: [PATCH] soc/tegra: pmc: Fix "scheduling while atomic" To: Jon Hunter , Stephen Warren , Thierry Reding , Alexandre Courbot , Peter De Schrijver , Prashant Gaikwad References: <1460900051-3065-1-git-send-email-digetx@gmail.com> <572B47DE.1090804@nvidia.com> <5745C02A.20308@nvidia.com> Cc: linux-clk@vger.kernel.org, linux-tegra@vger.kernel.org, linux-kernel@vger.kernel.org From: Dmitry Osipenko Message-ID: Date: Wed, 25 May 2016 21:51:59 +0300 MIME-Version: 1.0 In-Reply-To: <5745C02A.20308@nvidia.com> Content-Type: text/plain; charset=utf-8; format=flowed Sender: linux-clk-owner@vger.kernel.org List-ID: 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] [] (dump_stack) from [] (__schedule_bug+0x50/0x64) > [ 3.431079] [] (__schedule_bug) from [] (__schedule+0x5c8/0x688) > [ 3.431453] [] (__schedule) from [] (schedule_preempt_disabled+0x24/0x34) > [ 3.431835] [] (schedule_preempt_disabled) from [] (__mutex_lock_slowpath+0xbc/0x170) > [ 3.432204] [] (__mutex_lock_slowpath) from [] (mutex_lock+0x4c/0x50) > [ 3.432427] [] (mutex_lock) from [] (clk_prepare_lock+0x88/0xfc) > [ 3.432800] [] (clk_prepare_lock) from [] (clk_get_rate+0xc/0x60) > [ 3.433177] [] (clk_get_rate) from [] (tegra_pmc_enter_suspend_mode+0x188/0x20c) > [ 3.433580] [] (tegra_pmc_enter_suspend_mode) from [] (tegra_idle_lp2_last+0xc/0x40) > [ 3.433795] [] (tegra_idle_lp2_last) from [] (tegra20_idle_lp2_coupled+0x118/0x1fc) > [ 3.434171] [] (tegra20_idle_lp2_coupled) from [] (cpuidle_enter_state+0x3c/0x160) > [ 3.434551] [] (cpuidle_enter_state) from [] (cpuidle_enter_state_coupled+0x3dc/0x3f4) > [ 3.434959] [] (cpuidle_enter_state_coupled) from [] (cpu_startup_entry+0x240/0x288) > [ 3.435340] [] (cpu_startup_entry) from [] (start_kernel+0x3b4/0x3c0) > [ 3.435557] [] (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] [] (unwind_backtrace) from [] (show_stack+0x10/0x14) [ 3.927252] [] (show_stack) from [] (dump_stack+0x94/0xa8) [ 3.927488] [] (dump_stack) from [] (__schedule_bug+0x50/0x64) [ 3.927865] [] (__schedule_bug) from [] (__schedule+0x5c8/0x688) [ 3.928235] [] (__schedule) from [] (schedule_preempt_disabled+0x24/0x34) [ 3.928608] [] (schedule_preempt_disabled) from [] (__mutex_lock_slowpath+0xbc/0x170) [ 3.928820] [] (__mutex_lock_slowpath) from [] (mutex_lock+0x4c/0x50) [ 3.929230] [] (mutex_lock) from [] (clk_prepare_lock+0x88/0xfc) [ 3.929602] [] (clk_prepare_lock) from [] (clk_get_rate+0x30/0xa4) [ 3.930005] [] (clk_get_rate) from [] (tegra_pmc_enter_suspend_mode+0x188/0x20c) [ 3.930259] [] (tegra_pmc_enter_suspend_mode) from [] (tegra_idle_lp2_last+0xc/0x40) [ 3.930627] [] (tegra_idle_lp2_last) from [] (tegra20_idle_lp2_coupled+0x118/0x1fc) [ 3.931051] [] (tegra20_idle_lp2_coupled) from [] (cpuidle_enter_state+0x3c/0x160) [ 3.931437] [] (cpuidle_enter_state) from [] (cpuidle_enter_state_coupled+0x3dc/0x3f4) [ 3.931846] [] (cpuidle_enter_state_coupled) from [] (cpu_startup_entry+0x240/0x288) [ 3.932247] [] (cpu_startup_entry) from [] (start_kernel+0x3b4/0x3c0) [ 3.932472] [] (start_kernel) from [<00008074>] (0x8074) [ 3.932881] bad: scheduling from the idle thread! [snip] [ 4.131017] [] (ttwu_do_activate.constprop.15) from [] (try_to_wake_up+0x264/0x308) [ 4.131239] [] (try_to_wake_up) from [] (__mutex_unlock_slowpath+0x34/0x40) [ 4.131612] [] (__mutex_unlock_slowpath) from [] (clk_set_rate+0xac/0xd8) [ 4.131991] [] (clk_set_rate) from [] (tegra_target+0x74/0x134) [ 4.132401] [] (tegra_target) from [] (__cpufreq_driver_target+0x164/0x294) [ 4.132619] [] (__cpufreq_driver_target) from [] (cpufreq_interactive_speedchange_task+0x23c/0x28c) [ 4.133010] [] (cpufreq_interactive_speedchange_task) from [] (kthread+0xd0/0xe8) [ 4.133385] [] (kthread) from [] (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