Hang while loading firmware when going into suspend

Hang while loading firmware when going into suspend

[Daniel Drake]

Hi,

I can easily reproduce a hang related to loading firmware
(asynchronously) while going into suspend.

This is running on kernel 3.3.3.

I run:

echo mem > /sys/power/state; echo mem > /sys/power/state

i.e. I tell the system to suspend, and when I wake it up it will go
very quickly into suspend again.

After waking up, it will start to re-detect the libertas SDIO wifi
card which was completely powered down during suspend.
This triggers a firmware loading sequence.
However, the system then immediately goes into suspend, and at this
point the system becomes unhappy.

Here are the logs from the first wakeup into the second suspend,
including DEBUG enabled in firmware_class.c

[   49.389773] Restarting tasks ...
[   49.404539] olpc-dcon: The CPU has control
[   49.419371] done.
[   49.440444] PM: Syncing filesystems ...
[   49.505994] sdhci-pci 0000:00:0c.0: setting latency timer to 64
[   49.540921] done.
[   49.542865] PM: Preparing system for mem sleep
[   49.577882] sdhci-pci 0000:00:0c.0: setting latency timer to 64
[   49.654932] sdhci-pci 0000:00:0c.0: setting latency timer to 64
[   49.753343] sdhci-pci 0000:00:0c.0: setting latency timer to 64
[   49.890879] mmc1: new SDIO card at address 0001
[   49.914515] libertas_sdio: get async now
[   49.918506] Requesting libertas/sd8686_v9_helper.bin
[   49.940231] libertas_sdio mmc1:0001:1: firmware: requesting
libertas/sd8686_v9_helper.bin
[   49.961299] helper_firmware_cb   (null)
[   49.965200] Requesting libertas/sd8686_v8_helper.bin
[   49.970283] Freezing user space processes ... (elapsed 0.11 seconds) done.
[   50.092922] Freezing remaining freezable tasks ... (elapsed 0.01
seconds) done.
[   50.112828] PM: Entering mem sleep
[   50.116749] dcon_source_switch to DCON
[   50.142874] olpc-dcon: The DCON has control
[   50.147634] i8042 kbd 00:04: wake-up capability enabled by ACPI
[   50.153871] i8042 aux 00:03: wake-up capability disabled by ACPI
[   50.160268] sdhci-pci 0000:00:0c.0: setting latency timer to 64
[   50.167265] libertas_sdio mmc1:0001:1: mmc1:0001:1: suspend: PM flags = 0x3
[   50.174370] viafb_suspend!
[  109.980122] libertas_sdio mmc1:0001:1: firmware:
libertas/sd8686_v8_helper.bin loading timed out
[  109.989070] helper_firmware_cb   (null)
[  109.992952] Requesting sd8686_helper.bin
[  169.990109] libertas_sdio mmc1:0001:1: firmware: sd8686_helper.bin
loading timed out
[  169.997960] helper_firmware_cb   (null)
[  170.001859] libertas_sdio: sdio got firmware -2   (null)   (null)
[  170.008047] libertas_sdio: failed to find firmware (-2)
[  170.013351] libertas: INIT FAILED
[  170.016719] libertas: ret new state 2
[  170.020781] mmc1: card 0001 removed
[  170.024397] sdhci-pci 0000:00:0c.0: setting latency timer to 64
[  170.031423] sdhci-pci 0000:00:0c.0: setting latency timer to 64
[  170.038496] sdhci-pci 0000:00:0c.0: setting latency timer to 64
[  170.060137] PM: suspend of devices complete after 119943.496 msecs

Some weird things here:

Early during the routine, we request a firmware that cannot be found:

[   49.918506] Requesting libertas/sd8686_v9_helper.bin
[   49.940231] libertas_sdio mmc1:0001:1: firmware: requesting
libertas/sd8686_v9_helper.bin
[   49.961299] helper_firmware_cb   (null)

(The first and last lines are debug output from my driver, line 2
comes from firmware_class)

Then when we try to find a different firmware file, we don't get the
firmware_class debug line that we saw above, only my driver debug:
[   49.965200] Requesting libertas/sd8686_v8_helper.bin
[   49.970283] Freezing user space processes ... (elapsed 0.11 seconds) done.

Eventually we get a timeout, then we request another firmware, which
also times out, and finally we fall into suspend after a long delay.


Sidenote:
There is a driver race in the current libertas code - in the above
situation it will attempt to call the driver suspend routine even if
probe hasn't finished (i.e. async firmware loading still underway). I
have that solved locally in the tests above - the suspend routine will
detect that probing/firmware loading is still ongoing and wait for
that to complete before asking the hardware to suspend. However, in
testing this change, I am facing the above issue with the firmware
loader behaving badly when going into suspend.

Thanks
Daniel

Re: Hang while loading firmware when going into suspend

[Rafael J. Wysocki]

On Thursday, April 26, 2012, Daniel Drake wrote:
> Hi,
> 
> I can easily reproduce a hang related to loading firmware
> (asynchronously) while going into suspend.
> 
> This is running on kernel 3.3.3.
> 
> I run:
> 
> echo mem > /sys/power/state; echo mem > /sys/power/state
> 
> i.e. I tell the system to suspend, and when I wake it up it will go
> very quickly into suspend again.
> 
> After waking up, it will start to re-detect the libertas SDIO wifi
> card which was completely powered down during suspend.
> This triggers a firmware loading sequence.
> However, the system then immediately goes into suspend, and at this
> point the system becomes unhappy.

Is this a new bug or did we do that before too?

> Here are the logs from the first wakeup into the second suspend,
> including DEBUG enabled in firmware_class.c
> 
> [   49.389773] Restarting tasks ...
> [   49.404539] olpc-dcon: The CPU has control
> [   49.419371] done.
> [   49.440444] PM: Syncing filesystems ...
> [   49.505994] sdhci-pci 0000:00:0c.0: setting latency timer to 64
> [   49.540921] done.
> [   49.542865] PM: Preparing system for mem sleep
> [   49.577882] sdhci-pci 0000:00:0c.0: setting latency timer to 64
> [   49.654932] sdhci-pci 0000:00:0c.0: setting latency timer to 64
> [   49.753343] sdhci-pci 0000:00:0c.0: setting latency timer to 64
> [   49.890879] mmc1: new SDIO card at address 0001
> [   49.914515] libertas_sdio: get async now
> [   49.918506] Requesting libertas/sd8686_v9_helper.bin
> [   49.940231] libertas_sdio mmc1:0001:1: firmware: requesting
> libertas/sd8686_v9_helper.bin
> [   49.961299] helper_firmware_cb   (null)
> [   49.965200] Requesting libertas/sd8686_v8_helper.bin
> [   49.970283] Freezing user space processes ... (elapsed 0.11 seconds) done.
> [   50.092922] Freezing remaining freezable tasks ... (elapsed 0.01
> seconds) done.
> [   50.112828] PM: Entering mem sleep
> [   50.116749] dcon_source_switch to DCON
> [   50.142874] olpc-dcon: The DCON has control
> [   50.147634] i8042 kbd 00:04: wake-up capability enabled by ACPI
> [   50.153871] i8042 aux 00:03: wake-up capability disabled by ACPI
> [   50.160268] sdhci-pci 0000:00:0c.0: setting latency timer to 64
> [   50.167265] libertas_sdio mmc1:0001:1: mmc1:0001:1: suspend: PM flags = 0x3
> [   50.174370] viafb_suspend!
> [  109.980122] libertas_sdio mmc1:0001:1: firmware:
> libertas/sd8686_v8_helper.bin loading timed out
> [  109.989070] helper_firmware_cb   (null)
> [  109.992952] Requesting sd8686_helper.bin
> [  169.990109] libertas_sdio mmc1:0001:1: firmware: sd8686_helper.bin
> loading timed out
> [  169.997960] helper_firmware_cb   (null)
> [  170.001859] libertas_sdio: sdio got firmware -2   (null)   (null)
> [  170.008047] libertas_sdio: failed to find firmware (-2)
> [  170.013351] libertas: INIT FAILED
> [  170.016719] libertas: ret new state 2
> [  170.020781] mmc1: card 0001 removed
> [  170.024397] sdhci-pci 0000:00:0c.0: setting latency timer to 64
> [  170.031423] sdhci-pci 0000:00:0c.0: setting latency timer to 64
> [  170.038496] sdhci-pci 0000:00:0c.0: setting latency timer to 64
> [  170.060137] PM: suspend of devices complete after 119943.496 msecs
> 
> Some weird things here:
> 
> Early during the routine, we request a firmware that cannot be found:
> 
> [   49.918506] Requesting libertas/sd8686_v9_helper.bin
> [   49.940231] libertas_sdio mmc1:0001:1: firmware: requesting
> libertas/sd8686_v9_helper.bin
> [   49.961299] helper_firmware_cb   (null)
> 
> (The first and last lines are debug output from my driver, line 2
> comes from firmware_class)
> 
> Then when we try to find a different firmware file, we don't get the
> firmware_class debug line that we saw above, only my driver debug:
> [   49.965200] Requesting libertas/sd8686_v8_helper.bin
> [   49.970283] Freezing user space processes ... (elapsed 0.11 seconds) done.
> 
> Eventually we get a timeout, then we request another firmware, which
> also times out, and finally we fall into suspend after a long delay.

OK, so the system suspends eventually?

> Sidenote:
> There is a driver race in the current libertas code - in the above
> situation it will attempt to call the driver suspend routine even if
> probe hasn't finished (i.e. async firmware loading still underway). I
> have that solved locally in the tests above - the suspend routine will
> detect that probing/firmware loading is still ongoing and wait for
> that to complete before asking the hardware to suspend. However, in
> testing this change, I am facing the above issue with the firmware
> loader behaving badly when going into suspend.

That looks like a bug in the driver, to be honest.  I'll have a look at it
in the next few days.

Thanks,
Rafael

Re: Hang while loading firmware when going into suspend

[Daniel Drake]

On Sun, Apr 29, 2012 at 3:46 PM, Rafael J. Wysocki <rjw@sisk.pl> wrote:
> On Thursday, April 26, 2012, Daniel Drake wrote:
>> Hi,
>>
>> I can easily reproduce a hang related to loading firmware
>> (asynchronously) while going into suspend.
>>
>> This is running on kernel 3.3.3.
>>
>> I run:
>>
>> echo mem > /sys/power/state; echo mem > /sys/power/state
>>
>> i.e. I tell the system to suspend, and when I wake it up it will go
>> very quickly into suspend again.
>>
>> After waking up, it will start to re-detect the libertas SDIO wifi
>> card which was completely powered down during suspend.
>> This triggers a firmware loading sequence.
>> However, the system then immediately goes into suspend, and at this
>> point the system becomes unhappy.
>
> Is this a new bug or did we do that before too?

It's hard to say. Now that drivers aren't allowed to load firmware
from probe(), we've had to convert libertas to use asynchronous
firmware loading, which has moved things around quite a bit, and we're
only now getting wide testing on the new libertas-async-firmware code.

> OK, so the system suspends eventually?

Yes - exactly two minutes after starting to suspend.

>> Sidenote:
>> There is a driver race in the current libertas code - in the above
>> situation it will attempt to call the driver suspend routine even if
>> probe hasn't finished (i.e. async firmware loading still underway). I
>> have that solved locally in the tests above - the suspend routine will
>> detect that probing/firmware loading is still ongoing and wait for
>> that to complete before asking the hardware to suspend. However, in
>> testing this change, I am facing the above issue with the firmware
>> loader behaving badly when going into suspend.
>
> That looks like a bug in the driver, to be honest.  I'll have a look at it
> in the next few days.

A libertas driver bug, you mean?
Yes, it is definitely a bug that libertas suspend routine will not
wait for any ongoing firmware loading before trying to do
suspend-related  stuff with that device.
However, I have that solved locally. The suspend routine is now hooked
up to behave properly. Now what I'm facing is problems with (described
in the above mail) is what happens when firmware is being loaded and
the system starts to suspend - i.e. a problem on a very generic basis,
as far as I can see.

Thanks,
Daniel

Re: Hang while loading firmware when going into suspend

[Daniel Drake]

Hi,

On Thu, Apr 26, 2012 at 1:15 PM, Daniel Drake <dsd@laptop.org> wrote:
> I can easily reproduce a hang related to loading firmware
> (asynchronously) while going into suspend.
>
> This is running on kernel 3.3.3.
>
> I run:
>
> echo mem > /sys/power/state; echo mem > /sys/power/state
>
> i.e. I tell the system to suspend, and when I wake it up it will go
> very quickly into suspend again.
>
> After waking up, it will start to re-detect the libertas SDIO wifi
> card which was completely powered down during suspend.
> This triggers a firmware loading sequence.
> However, the system then immediately goes into suspend, and at this
> point the system becomes unhappy.

We're still suffering from this issue.

As far as I can see there are 2 items in question:

1. If a firmware load is in-progress as the system goes into suspend,
the relevant userspace processes get frozen and then we have to wait
for the timeout - the firmware loader in the kernel doesn't do
anything special on this important event.

2. There are no safety traps for if a new firmware load request
happens while the system is being suspended with userspace processes
already frozen. Then we have to wait for another timeout.


Do you have any suggested approaches to solve this?

I'm wondering if this is appropriate: firmware_class should add a
pm_notifier so that it is notified when the system is going into
suspend. It would set an internal flag noting that the system is
suspending, and then it can call fw_load_abort() on any active
firmware loads, making them fail immediately.
_request_firmware() would check the internal flag when it is called,
immediately returning failure -ENODATA (?) when the system is going
into suspend.

Does this sound reasonable or should I be looking for another approach?

Thanks,
Daniel