Trying to move my nexus7 work to -next, I started seeing boot time
hangs. Enabling some debug options provided with a lockdep spew.
Reverting "regulator: core: Propagate voltage changes to supply
regulators" - fc42112c0eaa avoids the hang, but I still see lockdep
noise.
Full log of -next based tree without any reverts follows:
thanks
-john
[ 2.458139] =============================================
[ 2.459709] [ INFO: possible recursive locking detected ]
[ 2.463873] input: Elan Touchscreen as
/devices/platform/soc/16200000.gsbi/16280000.i2c/i2c-1/1-0010/input/input0
[ 2.470412] 4.3.0-rc7-next-20151102-00022-gb347b1e #660 Not tainted
[ 2.475393] elants_i2c 1-0010: unknown packet ff ff ff ff
[ 2.486706] ---------------------------------------------
[ 2.492265] swapper/0/1 is trying to acquire lock:
[ 2.497642] ([ 2.501146] mmc0: new high speed MMC card at address 0001
[ 2.503979] &rdev->mutex[ 2.504689] mmcblk0: mmc0:0001 016GE2 14.6 GiB
[ 2.506461] mmcblk0boot0: mmc0:0001 016GE2 partition 1 4.00 MiB
[ 2.507983] mmcblk0boot1: mmc0:0001 016GE2 partition 2 4.00 MiB
[ 2.509745] mmcblk0rpmb: mmc0:0001 016GE2 partition 3 4.00 MiB
[ 2.518637] mmcblk0: p1 p2 p3 p4 p5 p6 p7 p8 p9 p10 p11 p12 p13
p14 p15 p16 p17 p18 p19 p20 p21 p22 p23 p24 p25 p260
[ 2.533857] ){+.+.+.}, at: [<c04edfc0>] regulator_get_voltage+0x18/0x38
[ 2.548423]
[ 2.548423] but task is already holding lock:
[ 2.552415] (&rdev->mutex){+.+.+.}, at: [<c04ef080>]
regulator_set_voltage+0x2c/0x78
[ 2.562051]
[ 2.562051] other info that might help us debug this:
[ 2.566051] Possible unsafe locking scenario:
[ 2.566051]
[ 2.572470] CPU0
[ 2.578278] ----
[ 2.580706] lock(&rdev->mutex);
[ 2.586083] lock(&rdev->mutex);
[ 2.589384]
[ 2.589384] *** DEADLOCK ***
[ 2.589384]
[ 2.589745] May be due to missing lock nesting notation
[ 2.589745]
[ 2.595655] 4 locks held by swapper/0/1:
[ 2.602585] #0: (&dev->mutex){......}, at: [<c0520db0>]
__driver_attach+0x48/0x98
[ 2.610662] #1: (&dev->mutex){......}, at: [<c0520dc0>]
__driver_attach+0x58/0x98
[ 2.618297] #2: (&rdev->mutex){+.+.+.}, at: [<c04ef080>]
regulator_set_voltage+0x2c/0x78
[ 2.626025] #3: (&rdev->mutex/1){+.+...}, at: [<c04ef080>]
regulator_set_voltage+0x2c/0x78
[ 2.634446]
[ 2.634446] stack backtrace:
[ 2.638458] CPU: 2 PID: 1 Comm: swapper/0 Not tainted
4.3.0-rc7-next-20151102-00022-gb347b1e #660
[ 2.642795] Hardware name: Qualcomm (Flattened Device Tree)
[ 2.651699] [<c0216f90>] (unwind_backtrace) from [<c0213c18>]
(show_stack+0x10/0x14)
[ 2.657062] [<c0213c18>] (show_stack) from [<c04a3c98>]
(dump_stack+0x70/0xbc)
[ 2.665046] [<c04a3c98>] (dump_stack) from [<c0273018>]
(__lock_acquire+0xe28/0x1af8)
[ 2.672071] [<c0273018>] (__lock_acquire) from [<c0274b50>]
(lock_acquire+0xf8/0x250)
[ 2.679986] [<c0274b50>] (lock_acquire) from [<c087db54>]
(mutex_lock_nested+0x54/0x44c)
[ 2.687796] [<c087db54>] (mutex_lock_nested) from [<c04edfc0>]
(regulator_get_voltage+0x18/0x38)
[ 2.695953] [<c04edfc0>] (regulator_get_voltage) from [<c04ee084>]
(_regulator_get_voltage+0xa4/0xb0)
[ 2.704720] [<c04ee084>] (_regulator_get_voltage) from [<c04eef44>]
(regulator_set_voltage_unlocked+0x10c/0x21c)
[ 2.713837] [<c04eef44>] (regulator_set_voltage_unlocked) from
[<c04ef0a0>] (regulator_set_voltage+0x4c/0x78)
[ 2.724094] [<c04ef0a0>] (regulator_set_voltage) from [<c0643c18>]
(mmci_sig_volt_switch+0x4c/0xe8)
[ 2.733894] [<c0643c18>] (mmci_sig_volt_switch) from [<c063285c>]
(mmc_power_up+0x6c/0x210)
[ 2.742740] [<c063285c>] (mmc_power_up) from [<c0633c08>]
(mmc_start_host+0x50/0x80)
[ 2.751071] [<c0633c08>] (mmc_start_host) from [<c063509c>]
(mmc_add_host+0x44/0x68)
[ 2.759057] [<c063509c>] (mmc_add_host) from [<c06444cc>]
(mmci_probe+0x5b8/0x8dc)
[ 2.766793] [<c06444cc>] (mmci_probe) from [<c04e6f78>]
(amba_probe+0xcc/0x148)
[ 2.774161] [<c04e6f78>] (amba_probe) from [<c0520b20>]
(driver_probe_device+0x1e4/0x42c)
[ 2.781364] [<c0520b20>] (driver_probe_device) from [<c0520dfc>]
(__driver_attach+0x94/0x98)
[ 2.789697] [<c0520dfc>] (__driver_attach) from [<c051ef7c>]
(bus_for_each_dev+0x54/0x88)
[ 2.798200] [<c051ef7c>] (bus_for_each_dev) from [<c051f838>]
(bus_add_driver+0x170/0x24c)
[ 2.806277] [<c051f838>] (bus_add_driver) from [<c0521b2c>]
(driver_register+0x78/0xf4)
[ 2.814444] [<c0521b2c>] (driver_register) from [<c0a7cdbc>]
(do_one_initcall+0x10c/0x1ec)
[ 2.822341] [<c0a7cdbc>] (do_one_initcall) from [<c0a7cfb8>]
(kernel_init_freeable+0x11c/0x1ec)
[ 2.830667] [<c0a7cfb8>] (kernel_init_freeable) from [<c087a030>]
(kernel_init+0x8/0xec)
[ 2.839262] [<c087a030>] (kernel_init) from [<c02100d0>]
(ret_from_fork+0x14/0x24)
[long stall here before hung task detection triggers]
[ 240.371648] INFO: task swapper/0:1 blocked for more than 120 seconds.
[ 240.371719] Not tainted 4.3.0-rc7-next-20151102-00022-gb347b1e #660
[ 240.377101] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs"
disables this message.
[ 240.384021] swapper/0 D c087c620 0 1 0 0x00000000
[ 240.395358] [<c087c620>] (__schedule) from [<c087cea8>] (schedule+0x40/0xac)
[ 240.397970] [<c087cea8>] (schedule) from [<c087cf28>]
(schedule_preempt_disabled+0x14/0x20)
[ 240.405326] [<c087cf28>] (schedule_preempt_disabled) from
[<c087dcac>] (mutex_lock_nested+0x1ac/0x44c)
[ 240.413383] [<c087dcac>] (mutex_lock_nested) from [<c04edfc0>]
(regulator_get_voltage+0x18/0x38)
[ 240.422750] [<c04edfc0>] (regulator_get_voltage) from [<c04ee084>]
(_regulator_get_voltage+0xa4/0xb0)
[ 240.431692] [<c04ee084>] (_regulator_get_voltage) from [<c04eef44>]
(regulator_set_voltage_unlocked+0x10c/0x21c)
[ 240.440686] [<c04eef44>] (regulator_set_voltage_unlocked) from
[<c04ef0a0>] (regulator_set_voltage+0x4c/0x78)
[ 240.451074] [<c04ef0a0>] (regulator_set_voltage) from [<c0643c18>]
(mmci_sig_volt_switch+0x4c/0xe8)
[ 240.460869] [<c0643c18>] (mmci_sig_volt_switch) from [<c063285c>]
(mmc_power_up+0x6c/0x210)
[ 240.469712] [<c063285c>] (mmc_power_up) from [<c0633c08>]
(mmc_start_host+0x50/0x80)
[ 240.478045] [<c0633c08>] (mmc_start_host) from [<c063509c>]
(mmc_add_host+0x44/0x68)
[ 240.486044] [<c063509c>] (mmc_add_host) from [<c06444cc>]
(mmci_probe+0x5b8/0x8dc)
[ 240.493767] [<c06444cc>] (mmci_probe) from [<c04e6f78>]
(amba_probe+0xcc/0x148)
[ 240.501010] [<c04e6f78>] (amba_probe) from [<c0520b20>]
(driver_probe_device+0x1e4/0x42c)
[ 240.508348] [<c0520b20>] (driver_probe_device) from [<c0520dfc>]
(__driver_attach+0x94/0x98)
[ 240.516677] [<c0520dfc>] (__driver_attach) from [<c051ef7c>]
(bus_for_each_dev+0x54/0x88)
[ 240.525190] [<c051ef7c>] (bus_for_each_dev) from [<c051f838>]
(bus_add_driver+0x170/0x24c)
[ 240.533248] [<c051f838>] (bus_add_driver) from [<c0521b2c>]
(driver_register+0x78/0xf4)
[ 240.541285] [<c0521b2c>] (driver_register) from [<c0a7cdbc>]
(do_one_initcall+0x10c/0x1ec)
[ 240.549187] [<c0a7cdbc>] (do_one_initcall) from [<c0a7cfb8>]
(kernel_init_freeable+0x11c/0x1ec)
[ 240.557660] [<c0a7cfb8>] (kernel_init_freeable) from [<c087a030>]
(kernel_init+0x8/0xec)
[ 240.566236] [<c087a030>] (kernel_init) from [<c02100d0>]
(ret_from_fork+0x14/0x24)
[ 240.574539] INFO: lockdep is turned off.
[ 240.581926] Sending NMI to all CPUs:
[ 250.592662] Kernel panic - not syncing: hung_task: blocked tasks
[ 250.592731] CPU: 1 PID: 29 Comm: khungtaskd Not tainted
4.3.0-rc7-next-20151102-00022-gb347b1e #660
[ 250.597766] Hardware name: Qualcomm (Flattened Device Tree)
[ 250.606566] [<c0216f90>] (unwind_backtrace) from [<c0213c18>]
(show_stack+0x10/0x14)
[ 250.612117] [<c0213c18>] (show_stack) from [<c04a3c98>]
(dump_stack+0x70/0xbc)
[ 250.620117] [<c04a3c98>] (dump_stack) from [<c02f1bac>] (panic+0x94/0x220)
[ 250.627143] [<c02f1bac>] (panic) from [<c02c4e74>] (watchdog+0x418/0x654)
[ 250.633998] [<c02c4e74>] (watchdog) from [<c0245e90>] (kthread+0xd8/0xf4)
[ 250.640852] [<c0245e90>] (kthread) from [<c02100d0>]
(ret_from_fork+0x14/0x24)
[ 250.647620] CPU2: stopping
[ 250.654707] CPU: 2 PID: 0 Comm: swapper/2 Not tainted
4.3.0-rc7-next-20151102-00022-gb347b1e #660
[ 250.657402] Hardware name: Qualcomm (Flattened Device Tree)
[ 250.666376] [<c0216f90>] (unwind_backtrace) from [<c0213c18>]
(show_stack+0x10/0x14)
[ 250.671755] [<c0213c18>] (show_stack) from [<c04a3c98>]
(dump_stack+0x70/0xbc)
[ 250.679732] [<c04a3c98>] (dump_stack) from [<c0215f8c>]
(handle_IPI+0x1c0/0x388)
[ 250.686770] [<c0215f8c>] (handle_IPI) from [<c02094c0>]
(gic_handle_irq+0x7c/0x88)
[ 250.694318] [<c02094c0>] (gic_handle_irq) from [<c0214738>]
(__irq_svc+0x58/0x98)
[ 250.701677] Exception stack(0xe8cedf88 to 0xe8cedfd0)
[ 250.709253] df80: c0210b10 00000000 e8cedfd8
00000000 c0ae4728 c0b61d6c
[ 250.714304] dfa0: c0884a44 00000000 00000000 c0adf848 c0b60b3e
c0ae4730 00000001 e8cedfd8
[ 250.722443] dfc0: c0210b10 c0210b14 60000013 ffffffff
[ 250.730601] [<c0214738>] (__irq_svc) from [<c0210b14>]
(arch_cpu_idle+0x20/0x3c)
[ 250.735660] [<c0210b14>] (arch_cpu_idle) from [<c026bbc4>]
(cpu_startup_entry+0x214/0x464)
[ 250.743107] [<c026bbc4>] (cpu_startup_entry) from [<8020956c>] (0x8020956c)
[ 250.751147] CPU0: stopping
[ 250.757992] CPU: 0 PID: 0 Comm: swapper/0 Not tainted
4.3.0-rc7-next-20151102-00022-gb347b1e #660
[ 250.760775] Hardware name: Qualcomm (Flattened Device Tree)
[ 250.769731] [<c0216f90>] (unwind_backtrace) from [<c0213c18>]
(show_stack+0x10/0x14)
[ 250.775108] [<c0213c18>] (show_stack) from [<c04a3c98>]
(dump_stack+0x70/0xbc)
[ 250.783092] [<c04a3c98>] (dump_stack) from [<c0215f8c>]
(handle_IPI+0x1c0/0x388)
[ 250.790122] [<c0215f8c>] (handle_IPI) from [<c02094c0>]
(gic_handle_irq+0x7c/0x88)
[ 250.797672] [<c02094c0>] (gic_handle_irq) from [<c0214738>]
(__irq_svc+0x58/0x98)
[ 250.805043] Exception stack(0xc0ae3f50 to 0xc0ae3f98)
[ 250.812605] 3f40: c0210b10
00000000 c0ae3fa0 00000000
[ 250.817658] 3f60: c0ae4728 c0b61d6c c0884a44 00000000 00000000
c0adf848 c0b60b3e c0ae4730
[ 250.825813] 3f80: 00000001 c0ae3fa0 c0210b10 c0210b14 60000113 ffffffff
[ 250.833961] [<c0214738>] (__irq_svc) from [<c0210b14>]
(arch_cpu_idle+0x20/0x3c)
[ 250.840388] [<c0210b14>] (arch_cpu_idle) from [<c026bbc4>]
(cpu_startup_entry+0x214/0x464)
[ 250.848028] [<c026bbc4>] (cpu_startup_entry) from [<c0a7cc48>]
(start_kernel+0x374/0x3dc)
[ 250.856094] [<c0a7cc48>] (start_kernel) from [<8020807c>] (0x8020807c)
[ 250.864339] CPU3: stopping
[ 250.870772] CPU: 3 PID: 0 Comm: swapper/3 Not tainted
4.3.0-rc7-next-20151102-00022-gb347b1e #660
[ 250.873461] Hardware name: Qualcomm (Flattened Device Tree)
[ 250.882435] [<c0216f90>] (unwind_backtrace) from [<c0213c18>]
(show_stack+0x10/0x14)
[ 250.887811] [<c0213c18>] (show_stack) from [<c04a3c98>]
(dump_stack+0x70/0xbc)
[ 250.895792] [<c04a3c98>] (dump_stack) from [<c0215f8c>]
(handle_IPI+0x1c0/0x388)
[ 250.902825] [<c0215f8c>] (handle_IPI) from [<c02094c0>]
(gic_handle_irq+0x7c/0x88)
[ 250.910374] [<c02094c0>] (gic_handle_irq) from [<c0214738>]
(__irq_svc+0x58/0x98)
[ 250.917731] Exception stack(0xe8ceff88 to 0xe8ceffd0)
[ 250.925316] ff80: c0210b10 00000000 e8ceffd8
00000000 c0ae4728 c0b61d6c
[ 250.930369] ffa0: c0884a44 00000000 00000000 c0adf848 c0b60b3e
c0ae4730 00000001 e8ceffd8
[ 250.938505] ffc0: c0210b10 c0210b14 60000013 ffffffff
[ 250.946659] [<c0214738>] (__irq_svc) from [<c0210b14>]
(arch_cpu_idle+0x20/0x3c)
[ 250.951709] [<c0210b14>] (arch_cpu_idle) from [<c026bbc4>]
(cpu_startup_entry+0x214/0x464)
[ 250.959164] [<c026bbc4>] (cpu_startup_entry) from [<8020956c>] (0x8020956c)
On Mon 02 Nov 11:57 PST 2015, John Stultz wrote:
> Trying to move my nexus7 work to -next, I started seeing boot time
> hangs. Enabling some debug options provided with a lockdep spew.
>
> Reverting "regulator: core: Propagate voltage changes to supply
> regulators" - fc42112c0eaa avoids the hang, but I still see lockdep
> noise.
>
> Full log of -next based tree without any reverts follows:
It sure does lock like a deadlock to me. Can you figure out which
regulator we're talking about here? And confirm that this is 8064 we're
talking about
Regards,
Bjorn
On Mon, Nov 2, 2015 at 12:46 PM, Bjorn Andersson
<[email protected]> wrote:
> On Mon 02 Nov 11:57 PST 2015, John Stultz wrote:
>
>> Trying to move my nexus7 work to -next, I started seeing boot time
>> hangs. Enabling some debug options provided with a lockdep spew.
>>
>> Reverting "regulator: core: Propagate voltage changes to supply
>> regulators" - fc42112c0eaa avoids the hang, but I still see lockdep
>> noise.
>>
>> Full log of -next based tree without any reverts follows:
>
> It sure does lock like a deadlock to me. Can you figure out which
> regulator we're talking about here? And confirm that this is 8064 we're
> talking about
Yep. It is an 8064. I'll add some debug messages to figure out which
regulators are having trouble.
thanks
-john
On Mon, Nov 02, 2015 at 11:57:40AM -0800, John Stultz wrote:
> Trying to move my nexus7 work to -next, I started seeing boot time
> hangs. Enabling some debug options provided with a lockdep spew.
Please don't send upstream things to my work address, it's unlikely to
get read normally.
> Reverting "regulator: core: Propagate voltage changes to supply
> regulators" - fc42112c0eaa avoids the hang, but I still see lockdep
> noise.
To repeat what I said off-list the lockdep splat looks like yet another
case of lockdep generating false positives by being unable to work out
that two different instances of objects of the same type are different
objects.
Without more information on the system you're looking at, especially
what regulators are involved and how they are related it's hard to tell
what's going on as a result, getting some trace from the tracepoints
would be more useful. Nothing obvious is jumping out from the code.
On Mon, Nov 2, 2015 at 12:46 PM, Bjorn Andersson
<[email protected]> wrote:
> On Mon 02 Nov 11:57 PST 2015, John Stultz wrote:
>
>> Trying to move my nexus7 work to -next, I started seeing boot time
>> hangs. Enabling some debug options provided with a lockdep spew.
>>
>> Reverting "regulator: core: Propagate voltage changes to supply
>> regulators" - fc42112c0eaa avoids the hang, but I still see lockdep
>> noise.
>>
>> Full log of -next based tree without any reverts follows:
>
> It sure does lock like a deadlock to me. Can you figure out which
> regulator we're talking about here? And confirm that this is 8064 we're
> talking about
So it looks like we're setting the voltage on lvs1, which then calls
get_voltage() on s4. At that point the lockdep spew hits.
But as Mark noted *this* spew looks like a false positive, but I
suspect lockdep is then disabled and can't detect the real hang
happens shortly afterwards.
The key bit needed to revert to get things booting for me in
fc42112c0eaa ("regulator: core: Propagate voltage changes to supply
regulators") is (sorry, copy pasted text here, apologies for the
whitespace damage):
--- a/drivers/regulator/core.c
+++ b/drivers/regulator/core.c
@@ -2952,11 +2952,12 @@ int regulator_set_voltage(struct regulator
*regulator, int min_uV, int max_uV)
{
int ret = 0;
- regulator_lock_supply(regulator->rdev);
+ mutex_lock(®ulator->rdev->mutex);
ret = regulator_set_voltage_unlocked(regulator, min_uV, max_uV);
- regulator_unlock_supply(regulator->rdev);
+ mutex_unlock(®ulator->rdev->mutex);
return ret;
}
Might the problem be here that we lock the supply in set_voltage, then
if we call _regulator_get_voltage on the supply later, we try to grab
the same lock and we're stuck?
thanks
-john
On Mon, Nov 2, 2015 at 2:03 PM, John Stultz <[email protected]> wrote:
> On Mon, Nov 2, 2015 at 12:46 PM, Bjorn Andersson
> <[email protected]> wrote:
>> On Mon 02 Nov 11:57 PST 2015, John Stultz wrote:
>>
>>> Trying to move my nexus7 work to -next, I started seeing boot time
>>> hangs. Enabling some debug options provided with a lockdep spew.
>>>
>>> Reverting "regulator: core: Propagate voltage changes to supply
>>> regulators" - fc42112c0eaa avoids the hang, but I still see lockdep
>>> noise.
>>>
>>> Full log of -next based tree without any reverts follows:
>>
>> It sure does lock like a deadlock to me. Can you figure out which
>> regulator we're talking about here? And confirm that this is 8064 we're
>> talking about
>
> So it looks like we're setting the voltage on lvs1, which then calls
> get_voltage() on s4. At that point the lockdep spew hits.
>
> But as Mark noted *this* spew looks like a false positive, but I
> suspect lockdep is then disabled and can't detect the real hang
> happens shortly afterwards.
Further on this, the lockdep spew happens w/ v4.3 as well. Its just
the deadlock in -next got me to add lockdep in my config.
thanks
-john
On Mon, Nov 02, 2015 at 02:03:14PM -0800, John Stultz wrote:
> Might the problem be here that we lock the supply in set_voltage, then
> if we call _regulator_get_voltage on the supply later, we try to grab
> the same lock and we're stuck?
No, the internal get voltage call shouldn't be locking in the first
place (and indeed it doesn't do so AFAICT?).
On Mon, Nov 2, 2015 at 2:58 PM, Mark Brown <[email protected]> wrote:
> On Mon, Nov 02, 2015 at 02:03:14PM -0800, John Stultz wrote:
>
>> Might the problem be here that we lock the supply in set_voltage, then
>> if we call _regulator_get_voltage on the supply later, we try to grab
>> the same lock and we're stuck?
>
> No, the internal get voltage call shouldn't be locking in the first
> place (and indeed it doesn't do so AFAICT?).
drivers/regulator/core.c: @3063
static int _regulator_get_voltage(struct regulator_dev *rdev)
{
int sel, ret;
if (rdev->desc->ops->get_voltage_sel) {
...
} else if (rdev->supply) {
ret = regulator_get_voltage(rdev->supply); <-----
} else {
Where _regulator_get_voltage() is called from
regulator_set_voltage_unlocked(), called from regulator_set_voltage().
thanks
-john
On Mon, Nov 02, 2015 at 03:04:29PM -0800, John Stultz wrote:
> On Mon, Nov 2, 2015 at 2:58 PM, Mark Brown <[email protected]> wrote:
> > No, the internal get voltage call shouldn't be locking in the first
> > place (and indeed it doesn't do so AFAICT?).
> } else if (rdev->supply) {
> ret = regulator_get_voltage(rdev->supply); <-----
> } else {
> Where _regulator_get_voltage() is called from
> regulator_set_voltage_unlocked(), called from regulator_set_voltage().
>
Well, that's the issue then - get_voltage() needs to be locking the
supplies like set_voltage() does.