Re: Suspend/resume - slow resume

[Ciprian Docan]

Hello Francois,

I tried your patch and my machine resumes properly.

> The firmware is cached during the first successfull call to open() and
> released once the network device is unregistered. The driver uses the
> cached firmware between open() and unregister_netdev().

Here is what I did to test it: I compiled the patched module, unloaded the 
previous module, loaded the new one, and then suspend & resume. Output of 
dmesg attached. Please let me know if you need any other information.

Regards,
--
	Ciprian[74001.664088] r8169 0000:02:00.0: PCI INT A disabled
[74033.821473] r8169 Gigabit Ethernet driver 2.3LK-NAPI loaded
[74033.821497] r8169 0000:02:00.0: PCI INT A -> GSI 16 (level, low) -> IRQ 16
[74033.822310] r8169 0000:02:00.0: setting latency timer to 64
[74033.822364] r8169 0000:02:00.0: irq 45 for MSI/MSI-X
[74033.822572] r8169 0000:02:00.0: eth0: RTL8168d/8111d at 0xffffc90027e2e000, 64:31:50:69:2c:61, XID 083000c0 IRQ 45
[74058.429717] wl_ops_bss_info_changed: qos enabled: false (implement)
[74058.429729] brcmsmac: wl_ops_bss_info_changed: disassociated
[74058.429735] wl_ops_bss_info_changed: use_cts_prot: false (implement)
[74058.429741] wl_ops_bss_info_changed: short preamble: false (implement)
[74058.429754] wl_ops_bss_info_changed: arp filtering: enabled false, count 1 (implement)
[74058.429764] wlan0: deauthenticating from 00:1e:2a:01:3e:bb by local choice (reason=3)
[74058.455026] wl_ops_bss_info_changed: BSS idle: true (implement)
[74058.455046] cfg80211: All devices are disconnected, going to restore regulatory settings
[74058.455055] cfg80211: Restoring regulatory settings
[74058.455064] cfg80211: Calling CRDA to update world regulatory domain
[74058.455069] wl_ops_bss_info_changed: BSS idle: false (implement)
[74058.460281] cfg80211: Updating information on frequency 2412 MHz for a 20 MHz width channel with regulatory rule:
[74058.460291] cfg80211: 2402000 KHz - 2472000 KHz @  KHz), (300 mBi, 2700 mBm)
[74058.460297] cfg80211: Updating information on frequency 2417 MHz for a 20 MHz width channel with regulatory rule:
[74058.460305] cfg80211: 2402000 KHz - 2472000 KHz @  KHz), (300 mBi, 2700 mBm)
[74058.460311] cfg80211: Updating information on frequency 2422 MHz for a 20 MHz width channel with regulatory rule:
[74058.460319] cfg80211: 2402000 KHz - 2472000 KHz @  KHz), (300 mBi, 2700 mBm)
[74058.460325] cfg80211: Updating information on frequency 2427 MHz for a 20 MHz width channel with regulatory rule:
[74058.460330] cfg80211: 2402000 KHz - 2472000 KHz @  KHz), (300 mBi, 2700 mBm)
[74058.460334] cfg80211: Updating information on frequency 2432 MHz for a 20 MHz width channel with regulatory rule:
[74058.460339] cfg80211: 2402000 KHz - 2472000 KHz @  KHz), (300 mBi, 2700 mBm)
[74058.460344] cfg80211: Updating information on frequency 2437 MHz for a 20 MHz width channel with regulatory rule:
[74058.460349] cfg80211: 2402000 KHz - 2472000 KHz @  KHz), (300 mBi, 2700 mBm)
[74058.460353] cfg80211: Updating information on frequency 2442 MHz for a 20 MHz width channel with regulatory rule:
[74058.460358] cfg80211: 2402000 KHz - 2472000 KHz @  KHz), (300 mBi, 2700 mBm)
[74058.460363] cfg80211: Updating information on frequency 2447 MHz for a 20 MHz width channel with regulatory rule:
[74058.460368] cfg80211: 2402000 KHz - 2472000 KHz @  KHz), (300 mBi, 2700 mBm)
[74058.460372] cfg80211: Updating information on frequency 2452 MHz for a 20 MHz width channel with regulatory rule:
[74058.460377] cfg80211: 2402000 KHz - 2472000 KHz @  KHz), (300 mBi, 2700 mBm)
[74058.460382] cfg80211: Updating information on frequency 2457 MHz for a 20 MHz width channel with regulatory rule:
[74058.460387] cfg80211: 2402000 KHz - 2472000 KHz @  KHz), (300 mBi, 2700 mBm)
[74058.460391] cfg80211: Updating information on frequency 2462 MHz for a 20 MHz width channel with regulatory rule:
[74058.460396] cfg80211: 2402000 KHz - 2472000 KHz @  KHz), (300 mBi, 2700 mBm)
[74058.460400] cfg80211: Disabling freq 2467 MHz
[74058.460403] cfg80211: Disabling freq 2472 MHz
[74058.460405] cfg80211: Disabling freq 2484 MHz
[74058.460410] cfg80211: World regulatory domain updated:
[74058.460413] cfg80211:     (start_freq - end_freq @ bandwidth), (max_antenna_gain, max_eirp)
[74058.460418] cfg80211:     (2402000 KHz - 2472000 KHz @ 40000 KHz), (300 mBi, 2000 mBm)
[74058.460423] cfg80211:     (2457000 KHz - 2482000 KHz @ 20000 KHz), (300 mBi, 2000 mBm)
[74058.460427] cfg80211:     (2474000 KHz - 2494000 KHz @ 20000 KHz), (300 mBi, 2000 mBm)
[74058.460432] cfg80211:     (5170000 KHz - 5250000 KHz @ 40000 KHz), (300 mBi, 2000 mBm)
[74058.460437] cfg80211:     (5735000 KHz - 5835000 KHz @ 40000 KHz), (300 mBi, 2000 mBm)
[74058.464926] wl_ops_bss_info_changed: BSS idle: true (implement)
[74059.892010] PM: Syncing filesystems ... done.
[74059.909543] PM: Preparing system for mem sleep
[74060.072757] Freezing user space processes ... (elapsed 0.01 seconds) done.
[74060.084607] Freezing remaining freezable tasks ... (elapsed 0.01 seconds) done.
[74060.095548] PM: Entering mem sleep
[74060.095712] Suspending console(s) (use no_console_suspend to debug)
[74060.107943] sd 0:0:0:0: [sda] Synchronizing SCSI cache
[74060.108024] sd 0:0:0:0: [sda] Stopping disk
[74060.147028] HDA Intel 0000:01:00.1: PCI INT B disabled
[74060.147031] brcmsmac 0000:03:00.0: PCI INT A disabled
[74060.147064] ACPI handle has no context!
[74060.157421] ehci_hcd 0000:00:1d.0: PCI INT A disabled
[74060.157444] ehci_hcd 0000:00:1a.0: PCI INT A disabled
[74060.248878] HDA Intel 0000:00:1b.0: PCI INT A disabled
[74062.612741] PM: suspend of devices complete after 2512.037 msecs
[74062.612949] r8169 0000:02:00.0: PME# enabled
[74062.621666] r8169 0000:02:00.0: wake-up capability enabled by ACPI
[74062.654658] PM: late suspend of devices complete after 42.007 msecs
[74062.654817] ACPI: Preparing to enter system sleep state S3
[74062.700627] PM: Saving platform NVS memory
[74062.704367] Disabling non-boot CPUs ...
[74062.706846] CPU 1 is now offline
[74062.724771] CPU 2 is now offline
[74062.734603] CPU 3 is now offline
[74062.734969] Extended CMOS year: 2000
[74062.735165] ACPI: Low-level resume complete
[74062.735220] PM: Restoring platform NVS memory
[74062.735780] Extended CMOS year: 2000
[74062.735802] Enabling non-boot CPUs ...
[74062.735923] Booting Node 0 Processor 1 APIC 0x1
[74062.735924] smpboot cpu 1: start_ip = 98000
[74062.826473] CPU1 is up
[74062.826637] Booting Node 0 Processor 2 APIC 0x4
[74062.826641] smpboot cpu 2: start_ip = 98000
[74062.826826] Switched to NOHz mode on CPU #1
[74062.917217] CPU2 is up
[74062.917382] Booting Node 0 Processor 3 APIC 0x5
[74062.917386] smpboot cpu 3: start_ip = 98000
[74062.917580] Switched to NOHz mode on CPU #2
[74063.008091] CPU3 is up
[74063.009302] Switched to NOHz mode on CPU #3
[74063.009672] ACPI: Waking up from system sleep state S3
[74063.090894] pcieport 0000:00:01.0: restoring config space at offset 0x1 (was 0x100007, writing 0x100407)
[74063.090915] i915 0000:00:02.0: restoring config space at offset 0x1 (was 0x900007, writing 0x900407)
[74063.090974] ehci_hcd 0000:00:1a.0: restoring config space at offset 0x1 (was 0x2900006, writing 0x2900002)
[74063.091009] HDA Intel 0000:00:1b.0: restoring config space at offset 0x1 (was 0x100006, writing 0x100002)
[74063.091117] ehci_hcd 0000:00:1d.0: restoring config space at offset 0x1 (was 0x2900006, writing 0x2900002)
[74063.091140] pci 0000:00:1e.0: restoring config space at offset 0xa (was 0xffffffff, writing 0x0)
[74063.091213] ahci 0000:00:1f.2: restoring config space at offset 0x1 (was 0x2b00007, writing 0x2b00407)
[74063.091336] HDA Intel 0000:01:00.1: restoring config space at offset 0x1 (was 0x100007, writing 0x100003)
[74063.091389] r8169 0000:02:00.0: restoring config space at offset 0x1 (was 0x100007, writing 0x100407)
[74063.091477] brcmsmac 0000:03:00.0: restoring config space at offset 0xf (was 0x100, writing 0x10a)
[74063.091496] brcmsmac 0000:03:00.0: restoring config space at offset 0x4 (was 0x4, writing 0xc2400004)
[74063.091502] brcmsmac 0000:03:00.0: restoring config space at offset 0x3 (was 0x0, writing 0x10)
[74063.091508] brcmsmac 0000:03:00.0: restoring config space at offset 0x1 (was 0x100000, writing 0x100006)
[74063.091655] PM: early resume of devices complete after 0.826 msecs
[74063.091803] i915 0000:00:02.0: setting latency timer to 64
[74063.091883] HDA Intel 0000:01:00.1: PCI INT B -> GSI 17 (level, low) -> IRQ 17
[74063.091888] ehci_hcd 0000:00:1a.0: PCI INT A -> GSI 16 (level, low) -> IRQ 16
[74063.091890] HDA Intel 0000:01:00.1: setting latency timer to 64
[74063.091895] ehci_hcd 0000:00:1a.0: setting latency timer to 64
[74063.091938] HDA Intel 0000:01:00.1: irq 46 for MSI/MSI-X
[74063.091945] HDA Intel 0000:00:1b.0: PCI INT A -> GSI 22 (level, low) -> IRQ 22
[74063.091953] HDA Intel 0000:00:1b.0: setting latency timer to 64
[74063.091987] HDA Intel 0000:00:1b.0: irq 47 for MSI/MSI-X
[74063.091990] ehci_hcd 0000:00:1d.0: PCI INT A -> GSI 20 (level, low) -> IRQ 20
[74063.091996] ehci_hcd 0000:00:1d.0: setting latency timer to 64
[74063.092023] pci 0000:00:1e.0: setting latency timer to 64
[74063.092088] ahci 0000:00:1f.2: setting latency timer to 64
[74063.092096] brcmsmac 0000:03:00.0: PCI INT A -> GSI 17 (level, low) -> IRQ 17
[74063.092107] brcmsmac 0000:03:00.0: setting latency timer to 64
[74063.102150] sd 0:0:0:0: [sda] Starting disk
[74063.105668] r8169 0000:02:00.0: wake-up capability disabled by ACPI
[74063.105674] r8169 0000:02:00.0: PME# disabled
[74063.322691] usb 1-1.4: reset full speed USB device number 3 using ehci_hcd
[74063.406321] ata2: SATA link up 1.5 Gbps (SStatus 113 SControl 300)
[74063.410296] ata5: SATA link down (SStatus 0 SControl 300)
[74063.440225] ata2.00: configured for UDMA/100
[74063.480281] usb 2-1.3: reset full speed USB device number 3 using ehci_hcd
[74063.566915] btusb 2-1.3:1.0: no reset_resume for driver btusb?
[74063.566921] btusb 2-1.3:1.1: no reset_resume for driver btusb?
[74063.637853] usb 2-1.6: reset high speed USB device number 5 using ehci_hcd
[74064.566218] hci_cmd_timer: hci0 command tx timeout
[74065.849747] ata1: SATA link up 3.0 Gbps (SStatus 123 SControl 300)
[74065.861688] ata1.00: configured for UDMA/133
[74066.466771] PM: resume of devices complete after 3384.208 msecs
[74066.467065] PM: Finishing wakeup.
[74066.467067] Restarting tasks ... done.
[74066.475211] video LNXVIDEO:00: Restoring backlight state
[74066.475339] video LNXVIDEO:01: Restoring backlight state
[74066.740330] wl_ops_bss_info_changed: use_cts_prot: false (implement)
[74066.740334] wl_ops_bss_info_changed: short preamble: false (implement)
[74066.740349] wl_ops_config: change monitor mode: false (implement)
[74066.740350] wl_ops_config: change power-save mode: false (implement)
[74066.742592] wl_ops_bss_info_changed: qos enabled: false (implement)
[74066.743416] wl_ops_bss_info_changed: BSS idle: false (implement)
[74066.743435] ADDRCONF(NETDEV_UP): wlan0: link is not ready
[74066.833025] wl_ops_bss_info_changed: BSS idle: true (implement)
[74066.833049] wl_ops_bss_info_changed: BSS idle: false (implement)
[74066.922738] wl_ops_bss_info_changed: BSS idle: true (implement)
[74067.470305] hci_cmd_timer: hci0 command tx timeout
[74071.913773] wl_ops_bss_info_changed: BSS idle: false (implement)
[74072.813906] wl_ops_bss_info_changed: BSS idle: true (implement)
[74072.813930] wl_ops_bss_info_changed: BSS idle: false (implement)
[74072.813990] wlan0: deauthenticating from 00:1e:2a:00:2d:fe by local choice (reason=3)
[74072.903591] wlan0: authenticate with 00:1e:2a:00:2d:fe (try 1)
[74072.913250] wlan0: authenticated
[74072.913271] wl_ops_bss_info_changed: BSS idle: true (implement)
[74072.913304] wl_ops_bss_info_changed: BSS idle: false (implement)
[74072.913312] wlan0: associate with 00:1e:2a:00:2d:fe (try 1)
[74072.916142] wlan0: RX AssocResp from 00:1e:2a:00:2d:fe (capab=0x411 status=0 aid=1)
[74072.916147] wlan0: associated
[74072.917091] wl_ops_bss_info_changed: qos enabled: true (implement)
[74072.917096] brcmsmac: wl_ops_bss_info_changed: associated
[74072.917100] wl_ops_bss_info_changed: use_cts_prot: true (implement)
[74072.917103] wl_ops_bss_info_changed: short preamble: true (implement)
[74072.917111] wl_ops_bss_info_changed: Need to change Basic Rates: 0xf (implement)
[74072.917118] wl_ops_bss_info_changed: arp filtering: enabled true, count 0 (implement)
[74072.918403] ADDRCONF(NETDEV_CHANGE): wlan0: link becomes ready
[74073.806196] wl_ops_bss_info_changed: arp filtering: enabled true, count 1 (implement)