diff mbox

Suspend/resume - slow resume

Message ID BANLkTim_1OgqjCeD1a4Ay2fWJSmPHa_XTQ@mail.gmail.com
State Not Applicable, archived
Delegated to: David Miller
Headers show

Commit Message

Linus Torvalds April 18, 2011, 6:49 p.m. UTC
On Mon, Apr 18, 2011 at 11:08 AM, Francois Romieu <romieu@fr.zoreil.com> wrote:
> [...]
>>  - unload not on close, but on device unregister (iow not when you do
>> "ifconfig eth0 down", but when the "eth0" device really goes away)
>
> Without further action, the firmware(s) will thus be locked in until the
> driver is removed.

I do agree. It's a downside. Maybe doing it in "close()" is the right
thing, as long as we don't have that crazy "every four timer ticks"
situation with rtl8169_reinit_task.

As mentioned, the only real reason for me to be worried about the
close thing is that I don't have a good feel for what happens at boot
time. Are the setup scripts going to look at the interface lots of
times? On my desktop, I couldn't care less, but I try to keep boot
time in mind.

Maybe in practice there's just a single open at boot-time (for dhcp or
whatever), and I'm just worried for no good reason.

Without having looked at that whole rtl8169_reinit_task thing, I
probably wouldn't even worry about anything else doing something
similar ;)

> As long as it can be fixed... If the 60s delay is removed and the firmware
> loading emits some messages for programmer barbie, I am more than happy.

So the firmware loading timeout used to be ten seconds (which I
already think is excessive), but then commit
2f65168de7d68a5795e945e781d85b313bdc97b9 increased it to 60s because

    https://bugzilla.redhat.com/bugzilla/show_bug.cgi?id=174589

    The ipw driver sometimes takes a long time to load its firmware.
    Whilst the ipw driver should be using the async interface of
    the firmware loader to make this a non-issue, this is a minimal fix.

although when I actually look at that bugzilla entry, the _timestamps_
for the failed case do not seem to support this being a timeout.

Very odd.

But the real problem is that we do that timeout even in cases where it
cannot help, ie when people load firmware during early boot or during
suspend. So I think drivers/base/firmware_class.c should be made a bit
smarter.

We have a few cases where call_usermodehelper() fails immediately:

 - khelper_wq hasn't been set up yet
 - usermodehelper_disabled is set.

and in particular, during suspend/resume, that
"usermodehelper_disabled" flag will be set.

I don't think it is sensible to do a user request for firmware during
that time either, and that 60-second timeout is just silly. It's not
going to help.

Why doesn't the firmware loader class check the error return from the
kobject_uevent()? I'd expect that if that fails, we should just warn
and abort, rather than wait 60 seconds to time out. Greg?

TOTALLY UNTESTED PATCH ATTACHED!

Ciprian - does this get rid of the 60-second wait? Do you get a nice
kernel traceback in your dmesg instead?

> If someone can tell me where Realtek's firmware should be sent to as David
> W. seems to be busy, it will be perfect.

Hmm. Dunno about that.

                       Linus

Comments

Ben Hutchings April 18, 2011, 7:25 p.m. UTC | #1
On Mon, 2011-04-18 at 11:49 -0700, Linus Torvalds wrote:
> On Mon, Apr 18, 2011 at 11:08 AM, Francois Romieu <romieu@fr.zoreil.com> wrote:
> > [...]
> >>  - unload not on close, but on device unregister (iow not when you do
> >> "ifconfig eth0 down", but when the "eth0" device really goes away)
> >
> > Without further action, the firmware(s) will thus be locked in until the
> > driver is removed.
> 
> I do agree. It's a downside. Maybe doing it in "close()" is the right
> thing, as long as we don't have that crazy "every four timer ticks"
> situation with rtl8169_reinit_task.
> 
> As mentioned, the only real reason for me to be worried about the
> close thing is that I don't have a good feel for what happens at boot
> time. Are the setup scripts going to look at the interface lots of
> times? On my desktop, I couldn't care less, but I try to keep boot
> time in mind.
>
> Maybe in practice there's just a single open at boot-time (for dhcp or
> whatever), and I'm just worried for no good reason.
[...]

Well, net devices are weird - they don't have file descriptors, they
just have names and indices which you can specify in an ioctl on any
socket (or netlink message on an appropriate netlink socket).  Opening
means starting the device, and I can't think of a configuration tool
that implicitly opens a net device.  Normally they get opened by ifup or
network-manager or the local equivalent, and then they stay open until
an explicit action by the administrator.

Ben.
Ciprian Docan April 18, 2011, 7:27 p.m. UTC | #2
> TOTALLY UNTESTED PATCH ATTACHED!
>
> Ciprian - does this get rid of the 60-second wait? Do you get a nice
> kernel traceback in your dmesg instead?

Linus - I applied your patch and attached the diff between output of dmesg 
before and after the patch as resume_timing.diff. This patch alone does 
not seem to fix the issue; however, applying Francois's patch in addition 
to yours make the resume smooth. I have also attached the diff output of 
dmesg before and after, with both patched applied as resume2_timing.diff. 
Both cases were tested after a fresh reboot. Please let me know if you 
need any other information.

Thank you,
--
 	Ciprian
1003a1004,1167
> [   65.618866] wl_ops_bss_info_changed: qos enabled: false (implement)

> [   65.618883] brcmsmac: wl_ops_bss_info_changed: disassociated

> [   65.618888] wl_ops_bss_info_changed: use_cts_prot: false (implement)

> [   65.618892] wl_ops_bss_info_changed: short preamble: false (implement)

> [   65.618903] wl_ops_bss_info_changed: arp filtering: enabled false, count 1 (implement)

> [   65.618911] wlan0: deauthenticating from 00:1c:10:9c:3c:98 by local choice (reason=3)

> [   65.642295] wl_ops_bss_info_changed: BSS idle: true (implement)

> [   65.642338] cfg80211: All devices are disconnected, going to restore regulatory settings

> [   65.642346] cfg80211: Restoring regulatory settings

> [   65.642356] cfg80211: Calling CRDA to update world regulatory domain

> [   65.642419] wl_ops_bss_info_changed: BSS idle: false (implement)

> [   65.647025] cfg80211: Updating information on frequency 2412 MHz for a 20 MHz width channel with regulatory rule:

> [   65.647033] cfg80211: 2402000 KHz - 2472000 KHz @  KHz), (300 mBi, 2700 mBm)

> [   65.647038] cfg80211: Updating information on frequency 2417 MHz for a 20 MHz width channel with regulatory rule:

> [   65.647043] cfg80211: 2402000 KHz - 2472000 KHz @  KHz), (300 mBi, 2700 mBm)

> [   65.647047] cfg80211: Updating information on frequency 2422 MHz for a 20 MHz width channel with regulatory rule:

> [   65.647052] cfg80211: 2402000 KHz - 2472000 KHz @  KHz), (300 mBi, 2700 mBm)

> [   65.647056] cfg80211: Updating information on frequency 2427 MHz for a 20 MHz width channel with regulatory rule:

> [   65.647061] cfg80211: 2402000 KHz - 2472000 KHz @  KHz), (300 mBi, 2700 mBm)

> [   65.647065] cfg80211: Updating information on frequency 2432 MHz for a 20 MHz width channel with regulatory rule:

> [   65.647070] cfg80211: 2402000 KHz - 2472000 KHz @  KHz), (300 mBi, 2700 mBm)

> [   65.647075] cfg80211: Updating information on frequency 2437 MHz for a 20 MHz width channel with regulatory rule:

> [   65.647079] cfg80211: 2402000 KHz - 2472000 KHz @  KHz), (300 mBi, 2700 mBm)

> [   65.647084] cfg80211: Updating information on frequency 2442 MHz for a 20 MHz width channel with regulatory rule:

> [   65.647089] cfg80211: 2402000 KHz - 2472000 KHz @  KHz), (300 mBi, 2700 mBm)

> [   65.647093] cfg80211: Updating information on frequency 2447 MHz for a 20 MHz width channel with regulatory rule:

> [   65.647098] cfg80211: 2402000 KHz - 2472000 KHz @  KHz), (300 mBi, 2700 mBm)

> [   65.647102] cfg80211: Updating information on frequency 2452 MHz for a 20 MHz width channel with regulatory rule:

> [   65.647107] cfg80211: 2402000 KHz - 2472000 KHz @  KHz), (300 mBi, 2700 mBm)

> [   65.647111] cfg80211: Updating information on frequency 2457 MHz for a 20 MHz width channel with regulatory rule:

> [   65.647116] cfg80211: 2402000 KHz - 2472000 KHz @  KHz), (300 mBi, 2700 mBm)

> [   65.647120] cfg80211: Updating information on frequency 2462 MHz for a 20 MHz width channel with regulatory rule:

> [   65.647125] cfg80211: 2402000 KHz - 2472000 KHz @  KHz), (300 mBi, 2700 mBm)

> [   65.647129] cfg80211: Disabling freq 2467 MHz

> [   65.647132] cfg80211: Disabling freq 2472 MHz

> [   65.647135] cfg80211: Disabling freq 2484 MHz

> [   65.647139] cfg80211: World regulatory domain updated:

> [   65.647141] cfg80211:     (start_freq - end_freq @ bandwidth), (max_antenna_gain, max_eirp)

> [   65.647146] cfg80211:     (2402000 KHz - 2472000 KHz @ 40000 KHz), (300 mBi, 2000 mBm)

> [   65.647151] cfg80211:     (2457000 KHz - 2482000 KHz @ 20000 KHz), (300 mBi, 2000 mBm)

> [   65.647156] cfg80211:     (2474000 KHz - 2494000 KHz @ 20000 KHz), (300 mBi, 2000 mBm)

> [   65.647160] cfg80211:     (5170000 KHz - 5250000 KHz @ 40000 KHz), (300 mBi, 2000 mBm)

> [   65.647182] cfg80211:     (5735000 KHz - 5835000 KHz @ 40000 KHz), (300 mBi, 2000 mBm)

> [   65.661205] wl_ops_bss_info_changed: BSS idle: true (implement)

> [   67.149409] PM: Syncing filesystems ... done.

> [   67.150612] PM: Preparing system for mem sleep

> [   67.294102] Freezing user space processes ... (elapsed 0.01 seconds) done.

> [   67.304765] Freezing remaining freezable tasks ... (elapsed 0.01 seconds) done.

> [   67.315716] PM: Entering mem sleep

> [   67.315872] Suspending console(s) (use no_console_suspend to debug)

> [   67.316505] sd 0:0:0:0: [sda] Synchronizing SCSI cache

> [   67.319105] sd 0:0:0:0: [sda] Stopping disk

> [   67.355568] brcmsmac 0000:03:00.0: PCI INT A disabled

> [   67.366638] ehci_hcd 0000:00:1d.0: PCI INT A disabled

> [   67.366650] ehci_hcd 0000:00:1a.0: PCI INT A disabled

> [   67.455454] HDA Intel 0000:01:00.1: PCI INT B disabled

> [   67.455488] ACPI handle has no context!

> [   67.457872] HDA Intel 0000:00:1b.0: PCI INT A disabled

> [   69.824037] PM: suspend of devices complete after 2514.601 msecs

> [   69.824247] r8169 0000:02:00.0: PME# enabled

> [   69.832945] r8169 0000:02:00.0: wake-up capability enabled by ACPI

> [   69.865924] PM: late suspend of devices complete after 42.000 msecs

> [   69.866079] ACPI: Preparing to enter system sleep state S3

> [   69.911889] PM: Saving platform NVS memory

> [   69.915560] Disabling non-boot CPUs ...

> [   69.917358] CPU 1 is now offline

> [   69.929978] CPU 2 is now offline

> [   69.931819] Broke affinity for irq 9

> [   69.932857] CPU 3 is now offline

> [   69.933182] Extended CMOS year: 2000

> [   69.933377] ACPI: Low-level resume complete

> [   69.933432] PM: Restoring platform NVS memory

> [   69.933979] Extended CMOS year: 2000

> [   69.934000] Enabling non-boot CPUs ...

> [   69.934120] Booting Node 0 Processor 1 APIC 0x1

> [   69.934121] smpboot cpu 1: start_ip = 98000

> [   70.025135] Switched to NOHz mode on CPU #1

> [   70.026670] CPU1 is up

> [   70.026831] Booting Node 0 Processor 2 APIC 0x4

> [   70.026834] smpboot cpu 2: start_ip = 98000

> [   70.117565] CPU2 is up

> [   70.117646] Booting Node 0 Processor 3 APIC 0x5

> [   70.117648] smpboot cpu 3: start_ip = 98000

> [   70.117845] Switched to NOHz mode on CPU #2

> [   70.208157] CPU3 is up

> [   70.209353] Switched to NOHz mode on CPU #3

> [   70.209710] ACPI: Waking up from system sleep state S3

> [   70.277137] pcieport 0000:00:01.0: restoring config space at offset 0x7 (was 0x20003030, writing 0x3030)

> [   70.277142] pcieport 0000:00:01.0: restoring config space at offset 0x1 (was 0x100007, writing 0x100407)

> [   70.277162] i915 0000:00:02.0: restoring config space at offset 0x1 (was 0x900007, writing 0x900407)

> [   70.277190] pci 0000:00:16.0: restoring config space at offset 0x1 (was 0x180006, writing 0x100006)

> [   70.277222] ehci_hcd 0000:00:1a.0: restoring config space at offset 0x1 (was 0x2900006, writing 0x2900002)

> [   70.277257] HDA Intel 0000:00:1b.0: restoring config space at offset 0x1 (was 0x100006, writing 0x100002)

> [   70.277286] pcieport 0000:00:1c.0: restoring config space at offset 0x7 (was 0x20002020, writing 0x2020)

> [   70.277362] ehci_hcd 0000:00:1d.0: restoring config space at offset 0x1 (was 0x2900006, writing 0x2900002)

> [   70.277384] pci 0000:00:1e.0: restoring config space at offset 0xa (was 0xffffffff, writing 0x0)

> [   70.277465] ahci 0000:00:1f.2: restoring config space at offset 0x1 (was 0x2b00007, writing 0x2b00407)

> [   70.277588] HDA Intel 0000:01:00.1: restoring config space at offset 0x1 (was 0x100007, writing 0x100003)

> [   70.277642] r8169 0000:02:00.0: restoring config space at offset 0x1 (was 0x100007, writing 0x100407)

> [   70.277728] brcmsmac 0000:03:00.0: restoring config space at offset 0xf (was 0x100, writing 0x10a)

> [   70.277748] brcmsmac 0000:03:00.0: restoring config space at offset 0x4 (was 0x4, writing 0xc2400004)

> [   70.277753] brcmsmac 0000:03:00.0: restoring config space at offset 0x3 (was 0x0, writing 0x10)

> [   70.277759] brcmsmac 0000:03:00.0: restoring config space at offset 0x1 (was 0x100000, writing 0x100006)

> [   70.277907] PM: early resume of devices complete after 0.832 msecs

> [   70.278058] i915 0000:00:02.0: setting latency timer to 64

> [   70.278063] ehci_hcd 0000:00:1a.0: PCI INT A -> GSI 16 (level, low) -> IRQ 16

> [   70.278069] ehci_hcd 0000:00:1a.0: setting latency timer to 64

> [   70.278084] HDA Intel 0000:00:1b.0: PCI INT A -> GSI 22 (level, low) -> IRQ 22

> [   70.278091] ehci_hcd 0000:00:1d.0: PCI INT A -> GSI 20 (level, low) -> IRQ 20

> [   70.278093] HDA Intel 0000:00:1b.0: setting latency timer to 64

> [   70.278100] ehci_hcd 0000:00:1d.0: setting latency timer to 64

> [   70.278110] pci 0000:00:1e.0: setting latency timer to 64

> [   70.278132] ahci 0000:00:1f.2: setting latency timer to 64

> [   70.278140] HDA Intel 0000:01:00.1: PCI INT B -> GSI 17 (level, low) -> IRQ 17

> [   70.278145] HDA Intel 0000:01:00.1: setting latency timer to 64

> [   70.278160] HDA Intel 0000:00:1b.0: irq 46 for MSI/MSI-X

> [   70.278194] HDA Intel 0000:01:00.1: irq 47 for MSI/MSI-X

> [   70.278338] sd 0:0:0:0: [sda] Starting disk

> [   70.278461] brcmsmac 0000:03:00.0: PCI INT A -> GSI 17 (level, low) -> IRQ 17

> [   70.278467] brcmsmac 0000:03:00.0: setting latency timer to 64

> [   70.286439] r8169 0000:02:00.0: wake-up capability disabled by ACPI

> [   70.286445] r8169 0000:02:00.0: PME# disabled

> [   70.508985] usb 1-1.4: reset full speed USB device number 3 using ehci_hcd

> [   70.583638] ata2: SATA link up 1.5 Gbps (SStatus 113 SControl 300)

> [   70.585644] ata5: SATA link down (SStatus 0 SControl 300)

> [   70.617518] ata2.00: configured for UDMA/100

> [   70.666598] usb 2-1.3: reset full speed USB device number 3 using ehci_hcd

> [   70.753366] btusb 2-1.3:1.0: no reset_resume for driver btusb?

> [   70.753372] btusb 2-1.3:1.1: no reset_resume for driver btusb?

> [   70.824183] usb 2-1.6: reset high speed USB device number 5 using ehci_hcd

> [   71.753512] hci_cmd_timer: hci0 command tx timeout

> [   73.023083] ata1: SATA link up 3.0 Gbps (SStatus 123 SControl 300)

> [   73.035133] ata1.00: configured for UDMA/133

> [   73.642069] PM: resume of devices complete after 3373.220 msecs

> [   73.642418] PM: Finishing wakeup.

> [   73.642420] Restarting tasks ... done.

> [   73.648564] video LNXVIDEO:00: Restoring backlight state

> [   73.648712] video LNXVIDEO:01: Restoring backlight state

> [   74.082737] wl_ops_bss_info_changed: use_cts_prot: false (implement)

> [   74.082742] wl_ops_bss_info_changed: short preamble: false (implement)

> [   74.082760] wl_ops_config: change monitor mode: false (implement)

> [   74.082763] wl_ops_config: change power-save mode: false (implement)

> [   74.084986] wl_ops_bss_info_changed: qos enabled: false (implement)

> [   74.085682] wl_ops_bss_info_changed: BSS idle: false (implement)

> [   74.085702] ADDRCONF(NETDEV_UP): wlan0: link is not ready

> [   74.174940] wl_ops_bss_info_changed: BSS idle: true (implement)

> [   74.174977] wl_ops_bss_info_changed: BSS idle: false (implement)

> [   74.264656] wl_ops_bss_info_changed: BSS idle: true (implement)

> [   74.293752] wl_ops_bss_info_changed: BSS idle: false (implement)

> [   74.293812] wlan0: deauthenticating from 00:1c:10:9c:3c:98 by local choice (reason=3)

> [   74.383350] wlan0: authenticate with 00:1c:10:9c:3c:98 (try 1)

> [   74.398331] wlan0: authenticated

> [   74.398347] wl_ops_bss_info_changed: BSS idle: true (implement)

> [   74.398374] wl_ops_bss_info_changed: BSS idle: false (implement)

> [   74.398381] wlan0: associate with 00:1c:10:9c:3c:98 (try 1)

> [   74.402842] wlan0: RX AssocResp from 00:1c:10:9c:3c:98 (capab=0x411 status=0 aid=11)

> [   74.402846] wlan0: associated

> [   74.403886] wl_ops_bss_info_changed: qos enabled: false (implement)

> [   74.403891] brcmsmac: wl_ops_bss_info_changed: associated

> [   74.403898] wl_ops_bss_info_changed: Need to change Basic Rates: 0xf (implement)

> [   74.403904] wl_ops_bss_info_changed: arp filtering: enabled true, count 0 (implement)

> [   74.405021] ADDRCONF(NETDEV_CHANGE): wlan0: link becomes ready

> [   74.647583] hci_cmd_timer: hci0 command tx timeout

> [   74.776522] wl_ops_bss_info_changed: arp filtering: enabled true, count 1 (implement)
1031a1032,1197
> [   75.923864] wl_ops_bss_info_changed: qos enabled: false (implement)

> [   75.923874] brcmsmac: wl_ops_bss_info_changed: disassociated

> [   75.923877] wl_ops_bss_info_changed: use_cts_prot: false (implement)

> [   75.923880] wl_ops_bss_info_changed: short preamble: false (implement)

> [   75.923889] wl_ops_bss_info_changed: arp filtering: enabled false, count 1 (implement)

> [   75.923895] wlan0: deauthenticating from 00:1c:10:9c:3c:98 by local choice (reason=3)

> [   75.943322] wl_ops_bss_info_changed: BSS idle: true (implement)

> [   75.943339] cfg80211: All devices are disconnected, going to restore regulatory settings

> [   75.943348] cfg80211: Restoring regulatory settings

> [   75.943357] cfg80211: Calling CRDA to update world regulatory domain

> [   75.943362] wl_ops_bss_info_changed: BSS idle: false (implement)

> [   75.948033] cfg80211: Updating information on frequency 2412 MHz for a 20 MHz width channel with regulatory rule:

> [   75.948041] cfg80211: 2402000 KHz - 2472000 KHz @  KHz), (300 mBi, 2700 mBm)

> [   75.948046] cfg80211: Updating information on frequency 2417 MHz for a 20 MHz width channel with regulatory rule:

> [   75.948051] cfg80211: 2402000 KHz - 2472000 KHz @  KHz), (300 mBi, 2700 mBm)

> [   75.948055] cfg80211: Updating information on frequency 2422 MHz for a 20 MHz width channel with regulatory rule:

> [   75.948060] cfg80211: 2402000 KHz - 2472000 KHz @  KHz), (300 mBi, 2700 mBm)

> [   75.948065] cfg80211: Updating information on frequency 2427 MHz for a 20 MHz width channel with regulatory rule:

> [   75.948069] cfg80211: 2402000 KHz - 2472000 KHz @  KHz), (300 mBi, 2700 mBm)

> [   75.948074] cfg80211: Updating information on frequency 2432 MHz for a 20 MHz width channel with regulatory rule:

> [   75.948079] cfg80211: 2402000 KHz - 2472000 KHz @  KHz), (300 mBi, 2700 mBm)

> [   75.948083] cfg80211: Updating information on frequency 2437 MHz for a 20 MHz width channel with regulatory rule:

> [   75.948088] cfg80211: 2402000 KHz - 2472000 KHz @  KHz), (300 mBi, 2700 mBm)

> [   75.948092] cfg80211: Updating information on frequency 2442 MHz for a 20 MHz width channel with regulatory rule:

> [   75.948097] cfg80211: 2402000 KHz - 2472000 KHz @  KHz), (300 mBi, 2700 mBm)

> [   75.948101] cfg80211: Updating information on frequency 2447 MHz for a 20 MHz width channel with regulatory rule:

> [   75.948106] cfg80211: 2402000 KHz - 2472000 KHz @  KHz), (300 mBi, 2700 mBm)

> [   75.948110] cfg80211: Updating information on frequency 2452 MHz for a 20 MHz width channel with regulatory rule:

> [   75.948115] cfg80211: 2402000 KHz - 2472000 KHz @  KHz), (300 mBi, 2700 mBm)

> [   75.948119] cfg80211: Updating information on frequency 2457 MHz for a 20 MHz width channel with regulatory rule:

> [   75.948124] cfg80211: 2402000 KHz - 2472000 KHz @  KHz), (300 mBi, 2700 mBm)

> [   75.948149] cfg80211: Updating information on frequency 2462 MHz for a 20 MHz width channel with regulatory rule:

> [   75.948154] cfg80211: 2402000 KHz - 2472000 KHz @  KHz), (300 mBi, 2700 mBm)

> [   75.948157] cfg80211: Disabling freq 2467 MHz

> [   75.948160] cfg80211: Disabling freq 2472 MHz

> [   75.948163] cfg80211: Disabling freq 2484 MHz

> [   75.948167] cfg80211: World regulatory domain updated:

> [   75.948170] cfg80211:     (start_freq - end_freq @ bandwidth), (max_antenna_gain, max_eirp)

> [   75.948175] cfg80211:     (2402000 KHz - 2472000 KHz @ 40000 KHz), (300 mBi, 2000 mBm)

> [   75.948180] cfg80211:     (2457000 KHz - 2482000 KHz @ 20000 KHz), (300 mBi, 2000 mBm)

> [   75.948185] cfg80211:     (2474000 KHz - 2494000 KHz @ 20000 KHz), (300 mBi, 2000 mBm)

> [   75.948189] cfg80211:     (5170000 KHz - 5250000 KHz @ 40000 KHz), (300 mBi, 2000 mBm)

> [   75.948194] cfg80211:     (5735000 KHz - 5835000 KHz @ 40000 KHz), (300 mBi, 2000 mBm)

> [   75.957206] wl_ops_bss_info_changed: BSS idle: true (implement)

> [   77.705556] PM: Syncing filesystems ... done.

> [   77.706722] PM: Preparing system for mem sleep

> [   77.850189] Freezing user space processes ... (elapsed 0.01 seconds) done.

> [   77.861052] Freezing remaining freezable tasks ... (elapsed 0.01 seconds) done.

> [   77.872039] PM: Entering mem sleep

> [   77.872191] Suspending console(s) (use no_console_suspend to debug)

> [   77.872837] sd 0:0:0:0: [sda] Synchronizing SCSI cache

> [   77.888620] sd 0:0:0:0: [sda] Stopping disk

> [   77.912060] brcmsmac 0000:03:00.0: PCI INT A disabled

> [   77.923064] ehci_hcd 0000:00:1d.0: PCI INT A disabled

> [   77.923076] ehci_hcd 0000:00:1a.0: PCI INT A disabled

> [   78.013092] HDA Intel 0000:01:00.1: PCI INT B disabled

> [   78.013126] ACPI handle has no context!

> [   78.014369] HDA Intel 0000:00:1b.0: PCI INT A disabled

> [   80.399749] PM: suspend of devices complete after 2527.459 msecs

> [   80.399924] r8169 0000:02:00.0: PME# enabled

> [   80.408697] r8169 0000:02:00.0: wake-up capability enabled by ACPI

> [   80.441740] PM: late suspend of devices complete after 41.997 msecs

> [   80.441884] ACPI: Preparing to enter system sleep state S3

> [   80.487834] PM: Saving platform NVS memory

> [   80.493177] Disabling non-boot CPUs ...

> [   80.494806] CPU 1 is now offline

> [   80.496529] CPU 2 is now offline

> [   80.504829] Broke affinity for irq 20

> [   80.505876] CPU 3 is now offline

> [   80.506220] Extended CMOS year: 2000

> [   80.506416] ACPI: Low-level resume complete

> [   80.506471] PM: Restoring platform NVS memory

> [   80.507040] Extended CMOS year: 2000

> [   80.507079] Enabling non-boot CPUs ...

> [   80.507182] Booting Node 0 Processor 1 APIC 0x1

> [   80.507183] smpboot cpu 1: start_ip = 98000

> [   80.598507] Switched to NOHz mode on CPU #1

> [   80.599960] CPU1 is up

> [   80.600052] Booting Node 0 Processor 2 APIC 0x4

> [   80.600053] smpboot cpu 2: start_ip = 98000

> [   80.691078] CPU2 is up

> [   80.691178] Booting Node 0 Processor 3 APIC 0x5

> [   80.691180] smpboot cpu 3: start_ip = 98000

> [   80.691471] Switched to NOHz mode on CPU #2

> [   80.782157] CPU3 is up

> [   80.783357] Switched to NOHz mode on CPU #3

> [   80.783681] ACPI: Waking up from system sleep state S3

> [   80.851177] pcieport 0000:00:01.0: restoring config space at offset 0x7 (was 0x20003030, writing 0x3030)

> [   80.851181] pcieport 0000:00:01.0: restoring config space at offset 0x1 (was 0x100007, writing 0x100407)

> [   80.851201] i915 0000:00:02.0: restoring config space at offset 0x1 (was 0x900007, writing 0x900407)

> [   80.851229] pci 0000:00:16.0: restoring config space at offset 0x1 (was 0x180006, writing 0x100006)

> [   80.851262] ehci_hcd 0000:00:1a.0: restoring config space at offset 0x1 (was 0x2900006, writing 0x2900002)

> [   80.851297] HDA Intel 0000:00:1b.0: restoring config space at offset 0x1 (was 0x100006, writing 0x100002)

> [   80.851327] pcieport 0000:00:1c.0: restoring config space at offset 0x7 (was 0x20002020, writing 0x2020)

> [   80.851402] ehci_hcd 0000:00:1d.0: restoring config space at offset 0x1 (was 0x2900006, writing 0x2900002)

> [   80.851424] pci 0000:00:1e.0: restoring config space at offset 0xa (was 0xffffffff, writing 0x0)

> [   80.851504] ahci 0000:00:1f.2: restoring config space at offset 0x1 (was 0x2b00007, writing 0x2b00407)

> [   80.851627] HDA Intel 0000:01:00.1: restoring config space at offset 0x1 (was 0x100007, writing 0x100003)

> [   80.851680] r8169 0000:02:00.0: restoring config space at offset 0x1 (was 0x100007, writing 0x100407)

> [   80.851768] brcmsmac 0000:03:00.0: restoring config space at offset 0xf (was 0x100, writing 0x10a)

> [   80.851787] brcmsmac 0000:03:00.0: restoring config space at offset 0x4 (was 0x4, writing 0xc2400004)

> [   80.851792] brcmsmac 0000:03:00.0: restoring config space at offset 0x3 (was 0x0, writing 0x10)

> [   80.851798] brcmsmac 0000:03:00.0: restoring config space at offset 0x1 (was 0x100000, writing 0x100006)

> [   80.851949] PM: early resume of devices complete after 0.833 msecs

> [   80.852100] i915 0000:00:02.0: setting latency timer to 64

> [   80.852107] ehci_hcd 0000:00:1a.0: PCI INT A -> GSI 16 (level, low) -> IRQ 16

> [   80.852113] ehci_hcd 0000:00:1a.0: setting latency timer to 64

> [   80.852148] HDA Intel 0000:00:1b.0: PCI INT A -> GSI 22 (level, low) -> IRQ 22

> [   80.852152] HDA Intel 0000:00:1b.0: setting latency timer to 64

> [   80.852191] HDA Intel 0000:00:1b.0: irq 46 for MSI/MSI-X

> [   80.852231] ehci_hcd 0000:00:1d.0: PCI INT A -> GSI 20 (level, low) -> IRQ 20

> [   80.852236] ehci_hcd 0000:00:1d.0: setting latency timer to 64

> [   80.852265] pci 0000:00:1e.0: setting latency timer to 64

> [   80.852277] ahci 0000:00:1f.2: setting latency timer to 64

> [   80.852326] HDA Intel 0000:01:00.1: PCI INT B -> GSI 17 (level, low) -> IRQ 17

> [   80.852330] HDA Intel 0000:01:00.1: setting latency timer to 64

> [   80.852363] HDA Intel 0000:01:00.1: irq 47 for MSI/MSI-X

> [   80.852480] brcmsmac 0000:03:00.0: PCI INT A -> GSI 17 (level, low) -> IRQ 17

> [   80.852485] brcmsmac 0000:03:00.0: setting latency timer to 64

> [   80.852598] sd 0:0:0:0: [sda] Starting disk

> [   80.865473] r8169 0000:02:00.0: wake-up capability disabled by ACPI

> [   80.865479] r8169 0000:02:00.0: PME# disabled

> [   81.083607] usb 1-1.4: reset full speed USB device number 3 using ehci_hcd

> [   81.158479] ata2: SATA link up 1.5 Gbps (SStatus 113 SControl 300)

> [   81.160479] ata5: SATA link down (SStatus 0 SControl 300)

> [   81.192446] ata2.00: configured for UDMA/100

> [   81.241617] usb 2-1.3: reset full speed USB device number 3 using ehci_hcd

> [   81.328714] btusb 2-1.3:1.0: no reset_resume for driver btusb?

> [   81.328719] btusb 2-1.3:1.1: no reset_resume for driver btusb?

> [   81.399752] usb 2-1.6: reset high speed USB device number 5 using ehci_hcd

> [   82.329405] hci_cmd_timer: hci0 command tx timeout

> [   83.604299] ata1: SATA link up 3.0 Gbps (SStatus 123 SControl 300)

> [   83.616192] ata1.00: configured for UDMA/133

> [  141.955556] r8169 0000:02:00.0: eth0: unable to apply firmware patch

> [  142.557969] PM: resume of devices complete after 61712.246 msecs

> [  142.558474] PM: Finishing wakeup.

> [  142.558475] Restarting tasks ... done.

> [  142.563742] video LNXVIDEO:00: Restoring backlight state

> [  142.563923] video LNXVIDEO:01: Restoring backlight state

> [  143.565055] hci_cmd_timer: hci0 command tx timeout

> [  143.591177] wl_ops_bss_info_changed: use_cts_prot: false (implement)

> [  143.591183] wl_ops_bss_info_changed: short preamble: false (implement)

> [  143.591202] wl_ops_config: change monitor mode: false (implement)

> [  143.591205] wl_ops_config: change power-save mode: false (implement)

> [  143.593448] wl_ops_bss_info_changed: qos enabled: false (implement)

> [  143.594031] wl_ops_bss_info_changed: BSS idle: false (implement)

> [  143.594061] ADDRCONF(NETDEV_UP): wlan0: link is not ready

> [  143.684097] wl_ops_bss_info_changed: BSS idle: true (implement)

> [  143.684157] wl_ops_bss_info_changed: BSS idle: false (implement)

> [  143.774118] wl_ops_bss_info_changed: BSS idle: true (implement)

> [  143.798174] wl_ops_bss_info_changed: BSS idle: false (implement)

> [  143.798222] wlan0: deauthenticating from 00:1c:10:9c:3c:98 by local choice (reason=3)

> [  143.888109] wlan0: authenticate with 00:1c:10:9c:3c:98 (try 1)

> [  143.911758] wlan0: authenticated

> [  143.911781] wl_ops_bss_info_changed: BSS idle: true (implement)

> [  143.911815] wl_ops_bss_info_changed: BSS idle: false (implement)

> [  143.911821] wlan0: associate with 00:1c:10:9c:3c:98 (try 1)

> [  143.914372] wlan0: RX AssocResp from 00:1c:10:9c:3c:98 (capab=0x411 status=0 aid=11)

> [  143.914377] wlan0: associated

> [  143.915137] wl_ops_bss_info_changed: qos enabled: false (implement)

> [  143.915141] brcmsmac: wl_ops_bss_info_changed: associated

> [  143.915147] wl_ops_bss_info_changed: Need to change Basic Rates: 0xf (implement)

> [  143.915153] wl_ops_bss_info_changed: arp filtering: enabled true, count 0 (implement)

> [  143.915987] ADDRCONF(NETDEV_CHANGE): wlan0: link becomes ready

> [  143.974405] wl_ops_bss_info_changed: arp filtering: enabled true, count 1 (implement)

> [  154.004056] wlan0: no IPv6 routers present
Linus Torvalds April 18, 2011, 7:51 p.m. UTC | #3
On Mon, Apr 18, 2011 at 12:27 PM, Ciprian Docan <docan@eden.rutgers.edu> wrote:
>
> Linus - I applied your patch and attached the diff between output of dmesg
> before and after the patch as resume_timing.diff. This patch alone does not
> seem to fix the issue;

Ok, that just means that the error return from call_usermodehelper()
gets lost somewhere along the way to kobject_uevent(). Or that I
misread the whole thing.

>  however, applying Francois's patch in addition to
> yours make the resume smooth.

Well, Francois' patch on its own should already have fixed it for you,
and made the whole issue moot.

Francois' patch is fine and improves on things, I only had a few
arguments with it. The problems I think it had were really about some
rather special cases.

                      Linus
--
To unsubscribe from this list: send the line "unsubscribe netdev" in
the body of a message to majordomo@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html
diff mbox

Patch

 drivers/base/firmware_class.c |    3 ++-
 1 files changed, 2 insertions(+), 1 deletions(-)

diff --git a/drivers/base/firmware_class.c b/drivers/base/firmware_class.c
index 8c798ef7f13f..956dd34e59da 100644
--- a/drivers/base/firmware_class.c
+++ b/drivers/base/firmware_class.c
@@ -549,7 +549,8 @@  static int _request_firmware(const struct firmware **firmware_p,
 				  round_jiffies_up(jiffies +
 						   loading_timeout * HZ));
 
-		kobject_uevent(&fw_priv->dev.kobj, KOBJ_ADD);
+		if (WARN_ON(kobject_uevent(&fw_priv->dev.kobj, KOBJ_ADD)))
+			fw_load_abort(fw_priv);
 	}
 
 	wait_for_completion(&fw_priv->completion);