Speed up suspend/resume for FreeBSD

Since I took my laptop (Thinkpad X220) from the shelf, hacked it, and installed FreeBSD 14.2 and Coreboot on it — I found that suspend/resume times are longer than before. When I was using this laptop with FreeBSD 11 and proprietary BIOS — it was suspending slightly faster. And resuming almost immediately — I was able to open the lid and the computer become usable immediately.

Things changed when I started to use this laptop with FreeBSD 14.2 and Coreboot — the resume process takes near a minute or more. I thought that the Coreboot is to blame for this.

After some time I've installed Libreboot, based on the Coreboot, and the problem with long resume time still persisted. So, I starting to think that these opensource software somehow are to blame for long resume time.

One day, the @libreleah (lead Libreboot developer) helped me with my problem (https://mas.to/@libreleah/114930689192089022). It turned out that Libreboot stores the debug log and timestamps in memory and with cbmem utility I can access it.

So, with doas cbmem -t1 I got this table:

22 entries total: 0:1st timestamp 694 (0) 11:start of bootblock 73,218 (72,524) 12:end of bootblock 74,119 (901) 13:starting to load romstage 74,119 (0) 14:finished loading romstage 74,784 (664) 1:start of romstage 74,849 (65) 2:before RAM initialization 77,035 (2,185) 3:after RAM initialization 131,185 (54,150) 4:end of romstage 136,623 (5,438) 100:start of postcar 138,149 (1,525) 101:end of postcar 138,149 (0) 8:starting to load ramstage 138,150 (0) 15:starting LZMA decompress (ignore for x86) 138,158 (8) 16:finished LZMA decompress (ignore for x86) 176,308 (38,149) 9:finished loading ramstage 176,486 (177) 10:start of ramstage 176,562 (76) 30:device enumeration 176,573 (11) 31:<unknown> 176,578 (4) 40:device configuration 183,496 (6,918) 50:device enable 187,102 (3,606) 60:device initialization 187,457 (355) 70:device setup done 247,559 (60,101) 98:ACPI wake jump 247,617 (58) Total Time: 246,915

I didn't found any information about measurement units for these numbers. So, I assumed that there are microseconds, since Libreboot boots extremely fast — since press to power button it loads immediately and passing the control to the payload (SeaBIOS).

This table was acquired after suspend/resume cycle, so it is related to the Libreboot activity during resume.

And it shows that Libreboot is not the source of the long resume times!

After this discovery I started to study the FreeBSD dmesg log after suspend/resume cycle. First, I enabled the timestamps for kernel log with this line in the /boot/loader.conf:

kern.msgbuf_show_timestamp=2

According to the man 8 dmesg:

If set to 0, no timetamps are added. If set to 1, then a 1-second granularity timestamp will be added to most lines in the message buffer. If set to 2, then a microsecond granularity timestamp will be added. This may also be set as a bootloader(8) tunable. The timestamps are placed at the start of most lines that the kernel generates. Some multi-line messages will have only the first line tagged with a timestamp.

With this setting, I got the next dmesg lines for suspend:

[58.431192] acpi_lid0: Lid closed [61.793763] wlan0: link state changed to UP [61.793838] wlan0: 2 link states coalesced [61.793848] wlan0: link state changed to UP [63.340099] battery1: battery initialization failed, giving up [68.431390] acpi0: suspend request timed out, forcing sleep now [69.191132] uhub3: at usbus3, port 1, addr 1 (disconnected) [69.191160] ugen3.2: <vendor 0x8087 product 0x0024> at usbus3 (disconnected) [69.191170] uhub6: at uhub3, port 1, addr 2 (disconnected) [69.244325] ugen3.3: <vendor 0x8087 product 0x0a2b> at usbus3 (disconnected) [69.244336] ubt0: at uhub6, port 3, addr 3 (disconnected) [69.354402] ubt0: detached [69.374292] uhub6: detached [69.394299] uhub3: detached [69.413706] uhub0: at usbus2, port 1, addr 1 (disconnected) [69.413724] ugen2.2: <vendor 0x0424 product 0x2514> at usbus2 (disconnected) [69.413732] uhub4: at uhub0, port 4, addr 1 (disconnected) [69.434299] ugen2.3: <Logitech USB Trackball> at usbus2 (disconnected) [69.434306] ums0: at uhub4, port 4, addr 2 (disconnected) [69.454252] ums0: detached [69.474665] uhub4: detached [69.494650] uhub0: detached [69.534681] uhub1: at usbus1, port 1, addr 1 (disconnected) [69.534687] uhub1: detached [69.574549] wlan0: link state changed to DOWN [69.634591] uhub2: at usbus0, port 1, addr 1 (disconnected) [69.634614] ugen0.2: <vendor 0x8087 product 0x0024> at usbus0 (disconnected) [69.634623] uhub5: at uhub2, port 1, addr 2 (disconnected) [69.694315] ugen0.3: <AGAN X230> at usbus0 (disconnected) [69.694325] uhid0: at uhub5, port 1, addr 3 (disconnected) [69.714328] uhid0: detached [69.734300] ugen0.4: <UPEK Biometric Coprocessor> at usbus0 (disconnected) [69.754304] ugen0.5: <Chicony Electronics Co., Ltd. Integrated Camera> at usbus0 (disconnected) [69.814293] uhub5: detached [69.834291] uhub2: detached [70.188163] vgapci0: child drmn0 requested pci_set_powerstate [73.112055] acpi0: cleared fixed power button status [73.115446] vgapci0: child drmn0 requested pci_set_powerstate [73.115451] vgapci0: child drmn0 requested pci_enable_io [73.115454] vgapci0: child drmn0 requested pci_enable_io [73.366940] uhub0 on usbus1 [73.366948] uhub0: <(0x1912) XHCI root HUB, class 9/0, rev 3.00/1.00, addr 1> on usbus1 [73.367041] uhub1 on usbus2 [73.367047] uhub1: <(0x1033) XHCI root HUB, class 9/0, rev 3.00/1.00, addr 1> on usbus2 [73.466755] acpi_tz0: switched from NONE to _AC0: 128.1C [73.779239] uhub1: 4 ports with 4 removable, self powered [73.779279] uhub0: 4 ports with 4 removable, self powered [74.232159] ugen2.2: <vendor 0x0424 product 0x2514> at usbus2 [74.232319] uhub2 on uhub1 [74.232325] uhub2: <vendor 0x0424 product 0x2514, class 9/0, rev 2.00/0.00, addr 1> on usbus2 [74.232971] uhub2: MTT enabled [74.974239] uhub2: 4 ports with 4 removable, self powered [75.434134] ugen2.3: <Logitech USB Trackball> at usbus2 [75.441205] ums0 on uhub2 [75.441211] ums0: <Logitech USB Trackball, class 0/0, rev 1.10/14.00, addr 2> on usbus2 [75.445507] ums0: 5 buttons and [XY] coordinates ID=0 [77.676786] em0: link state changed to DOWN [77.676827] lagg0: link state changed to DOWN

So, with my old configuration the suspend takes near 77.68 - 58.43 = 19.25 seconds.

And the lines for resume:

[83.322494] acpi_tz0: temperature 128.1C: decreasing clock speed from 1600 MHz to 800 MHz [83.956774] acpi_tz0: switched from _AC0 to NONE: 55.1C [91.656767] em0: link state changed to UP [91.656782] lagg0: link state changed to UP [94.816837] battery0: battery initialization start [94.816880] battery1: battery initialization start [94.846957] uhub3 on usbus3 [94.847022] uhub4 on usbus0 [94.847029] uhub4: <Intel EHCI root HUB, class 9/0, rev 2.00/1.00, addr 1> on usbus0 [94.847033] uhub3: <Intel EHCI root HUB, class 9/0, rev 2.00/1.00, addr 1> on usbus3 [95.746981] acpi_tz0: temperature 58.1C: resuming previous clock speed (1600 MHz) [96.234309] battery0: rev = ffff [96.234314] battery0: units = 1 [96.234317] battery0: dcap = 7326 [96.234320] battery0: lfcap = 4538 [96.234324] battery0: btech = 1 [96.234335] battery0: dvol = 11100 [96.234337] battery0: wcap = 226 [96.234339] battery0: lcap = 200 [96.234341] battery0: gra1 = 1 [96.234342] battery0: gra2 = 1 [96.234347] battery0: battery initialization done, tried 1 times [96.346113] uhub3: 3 ports with 3 removable, self powered [96.346147] uhub4: 3 ports with 3 removable, self powered [97.038680] ugen3.2: <vendor 0x8087 product 0x0024> at usbus3 [97.038911] uhub5 on uhub3 [97.038921] uhub5: <vendor 0x8087 product 0x0024, class 9/0, rev 2.00/0.00, addr 2> on usbus3 [97.058393] ugen0.2: <vendor 0x8087 product 0x0024> at usbus0 [97.058624] uhub6 on uhub4 [97.058630] uhub6: <vendor 0x8087 product 0x0024, class 9/0, rev 2.00/0.00, addr 2> on usbus0 [98.064311] uhub6: 6 ports with 6 removable, self powered [98.304314] uhub5: 8 ports with 8 removable, self powered [98.541038] ugen0.3: <AGAN X230> at usbus0 [98.544217] uhid0 on uhub6 [98.544228] uhid0: <AGAN X230, class 0/0, rev 1.10/0.00, addr 3> on usbus0 [98.769771] ugen3.3: <vendor 0x8087 product 0x0a2b> at usbus3 [98.981171] ugen0.4: <UPEK Biometric Coprocessor> at usbus0 [99.248246] Jul 28 15:57:08 freebsd wpa_supplicant[20391]: ioctl[SIOCS80211, op=20, val=0, arg_len=7]: Can't assign requested address [99.445559] ugen0.5: <Chicony Electronics Co., Ltd. Integrated Camera> at usbus0 [99.775758] iwm0: dumping device error log [99.776015] iwm0: Start Error Log Dump: [99.776018] iwm0: Status: 0x83, count: 6 [99.776021] iwm0: 0x00003073 | ADVANCED_SYSASSERT [99.776024] iwm0: 000002F0 | trm_hw_status0 [99.776026] iwm0: 00000000 | trm_hw_status1 [99.776028] iwm0: 0000E9C8 | branchlink2 [99.776030] iwm0: 0002843C | interruptlink1 [99.776032] iwm0: 00000000 | interruptlink2 [99.776034] iwm0: 00000000 | data1 [99.776036] iwm0: 00000001 | data2 [99.776038] iwm0: DEADBEEF | data3 [99.776041] iwm0: 0000180E | beacon time [99.776043] iwm0: 049FF7F2 | tsf low [99.776044] iwm0: 00000005 | tsf hi [99.776046] iwm0: 00000000 | time gp1 [99.776048] iwm0: 019091A1 | time gp2 [99.776050] iwm0: 00000000 | uCode revision type [99.776053] iwm0: 00000016 | uCode version major [99.776056] iwm0: 00058404 | uCode version minor [99.776059] iwm0: 00000201 | hw version [99.776062] iwm0: 0080FF0F | board version [99.776064] iwm0: 09480029 | hcmd [99.776067] iwm0: 00022000 | isr0 [99.776068] iwm0: 00000000 | isr1 [99.776070] iwm0: 08005802 | isr2 [99.776072] iwm0: 404000C2 | isr3 [99.776073] iwm0: 00000000 | isr4 [99.776075] iwm0: 00800110 | last cmd Id [99.776077] iwm0: 00000000 | wait_event [99.776078] iwm0: 000000C0 | l2p_control [99.776080] iwm0: 00000020 | l2p_duration [99.776082] iwm0: 00000000 | l2p_mhvalid [99.776084] iwm0: 00000000 | l2p_addr_match [99.776086] iwm0: 0000000D | lmpm_pmg_sel [99.776088] iwm0: 03071928 | timestamp [99.776090] iwm0: 00008898 | flow_handler [99.776185] iwm0: Start UMAC Error Log Dump: [99.776187] iwm0: Status: 0x83, count: 7 [99.776189] iwm0: 0x00000070 | ADVANCED_SYSASSERT [99.776191] iwm0: 0x00000000 | umac branchlink1 [99.776193] iwm0: 0xC008383C | umac branchlink2 [99.776195] iwm0: 0xC008166C | umac interruptlink1 [99.776198] iwm0: 0xC008166C | umac interruptlink2 [99.776200] iwm0: 0x00000800 | umac data1 [99.776202] iwm0: 0xC008166C | umac data2 [99.776203] iwm0: 0xDEADBEEF | umac data3 [99.776205] iwm0: 0x00000016 | umac major [99.776207] iwm0: 0x00058404 | umac minor [99.776209] iwm0: 0xC0886280 | frame pointer [99.776211] iwm0: 0xC0886280 | stack pointer [99.776213] iwm0: 0x09480029 | last host cmd [99.776215] iwm0: 0x00000000 | isr status reg [99.776217] iwm0: driver status: [99.776219] iwm0: tx ring 0: qid=0 cur=4 queued=0 [99.776222] iwm0: tx ring 1: qid=1 cur=0 queued=0 [99.776224] iwm0: tx ring 2: qid=2 cur=0 queued=0 [99.776227] iwm0: tx ring 3: qid=3 cur=0 queued=0 [99.776229] iwm0: tx ring 4: qid=4 cur=0 queued=0 [99.776232] iwm0: tx ring 5: qid=5 cur=0 queued=0 [99.776234] iwm0: tx ring 6: qid=6 cur=0 queued=0 [99.776237] iwm0: tx ring 7: qid=7 cur=0 queued=0 [99.776240] iwm0: tx ring 8: qid=8 cur=0 queued=0 [99.776242] iwm0: tx ring 9: qid=9 cur=73 queued=0 [99.776245] iwm0: tx ring 10: qid=10 cur=0 queued=0 [99.776248] iwm0: tx ring 11: qid=11 cur=0 queued=0 [99.776250] iwm0: tx ring 12: qid=12 cur=0 queued=0 [99.776253] iwm0: tx ring 13: qid=13 cur=0 queued=0 [99.776255] iwm0: tx ring 14: qid=14 cur=0 queued=0 [99.776258] iwm0: tx ring 15: qid=15 cur=0 queued=0 [99.776261] iwm0: tx ring 16: qid=16 cur=0 queued=0 [99.776263] iwm0: tx ring 17: qid=17 cur=0 queued=0 [99.776266] iwm0: tx ring 18: qid=18 cur=0 queued=0 [99.776268] iwm0: tx ring 19: qid=19 cur=0 queued=0 [99.776271] iwm0: tx ring 20: qid=20 cur=0 queued=0 [99.776273] iwm0: tx ring 21: qid=21 cur=0 queued=0 [99.776276] iwm0: tx ring 22: qid=22 cur=0 queued=0 [99.776278] iwm0: tx ring 23: qid=23 cur=0 queued=0 [99.776281] iwm0: tx ring 24: qid=24 cur=0 queued=0 [99.776283] iwm0: tx ring 25: qid=25 cur=0 queued=0 [99.776286] iwm0: tx ring 26: qid=26 cur=0 queued=0 [99.776288] iwm0: tx ring 27: qid=27 cur=0 queued=0 [99.776291] iwm0: tx ring 28: qid=28 cur=0 queued=0 [99.776293] iwm0: tx ring 29: qid=29 cur=0 queued=0 [99.776296] iwm0: tx ring 30: qid=30 cur=0 queued=0 [99.776298] iwm0: rx ring: cur=143 [99.776300] iwm0: 802.11 state 5 [99.776302] iwm0: iwm_intr: controller panicked, iv_state = 5; restarting [101.237688] ubt0 on uhub5 [101.237699] ubt0: <vendor 0x8087 product 0x0a2b, class 224/1, rev 2.00/0.01, addr 3> on usbus3 [101.333474] Jul 28 15:57:10 freebsd webcamd[86185]: webcamd: Cannot find USB device [101.407337] Jul 28 15:57:10 freebsd webcamd[98635]: Webcamd is already running for ugen0.5.0 [104.431745] Jul 28 15:57:13 freebsd wpa_supplicant[20391]: ioctl[SIOCS80211, op=20, val=0, arg_len=7]: Can't assign requested address [104.526921] wlan0: link state changed to UP [104.526948] wlan0: 2 link states coalesced [104.526951] wlan0: link state changed to UP [104.742868] iwm0: code ce, frame 1/153 b800002c unhandled [104.963470] iwm0: dumping device error log [104.963652] iwm0: Start Error Log Dump: [104.963654] iwm0: Status: 0x3, count: 6 [104.963657] iwm0: 0x00003073 | ADVANCED_SYSASSERT [104.963660] iwm0: 000002F0 | trm_hw_status0 [104.963662] iwm0: 00000000 | trm_hw_status1 [104.963664] iwm0: 0000E9C8 | branchlink2 [104.963666] iwm0: 0002843C | interruptlink1 [104.963668] iwm0: 00000000 | interruptlink2 [104.963670] iwm0: 00000000 | data1 [104.963671] iwm0: 00000001 | data2 [104.963673] iwm0: DEADBEEF | data3 [104.963675] iwm0: 00009EFC | beacon time [104.963677] iwm0: 04EF2115 | tsf low [104.963679] iwm0: 00000005 | tsf hi [104.963680] iwm0: 00000000 | time gp1 [104.963682] iwm0: 0035118B | time gp2 [104.963684] iwm0: 00000000 | uCode revision type [104.963686] iwm0: 00000016 | uCode version major [104.963688] iwm0: 00058404 | uCode version minor [104.963690] iwm0: 00000201 | hw version [104.963692] iwm0: 0080FF0F | board version [104.963694] iwm0: 09480029 | hcmd [104.963696] iwm0: 00022000 | isr0 [104.963698] iwm0: 00000000 | isr1 [104.963700] iwm0: 08001802 | isr2 [104.963701] iwm0: 404000C2 | isr3 [104.963703] iwm0: 00000000 | isr4 [104.963704] iwm0: 00800110 | last cmd Id [104.963706] iwm0: 00000000 | wait_event [104.963708] iwm0: 000002D0 | l2p_control [104.963710] iwm0: 00000020 | l2p_duration [104.963712] iwm0: 00000000 | l2p_mhvalid [104.963714] iwm0: 00000020 | l2p_addr_match [104.963716] iwm0: 0000000D | lmpm_pmg_sel [104.963718] iwm0: 03071928 | timestamp [104.963719] iwm0: 00008898 | flow_handler [104.963788] iwm0: Start UMAC Error Log Dump: [104.963790] iwm0: Status: 0x3, count: 7 [104.963792] iwm0: 0x00000070 | ADVANCED_SYSASSERT [104.963794] iwm0: 0x00000000 | umac branchlink1 [104.963796] iwm0: 0xC008383C | umac branchlink2 [104.963798] iwm0: 0xC008166C | umac interruptlink1 [104.963801] iwm0: 0xC008166C | umac interruptlink2 [104.963803] iwm0: 0x00000800 | umac data1 [104.963805] iwm0: 0xC008166C | umac data2 [104.963807] iwm0: 0xDEADBEEF | umac data3 [104.963809] iwm0: 0x00000016 | umac major [104.963810] iwm0: 0x00058404 | umac minor [104.963812] iwm0: 0xC0886280 | frame pointer [104.963814] iwm0: 0xC0886280 | stack pointer [104.963816] iwm0: 0x09480029 | last host cmd [104.963818] iwm0: 0x00000000 | isr status reg [104.963820] iwm0: driver status: [104.963823] iwm0: tx ring 0: qid=0 cur=4 queued=0 [104.963825] iwm0: tx ring 1: qid=1 cur=0 queued=0 [104.963828] iwm0: tx ring 2: qid=2 cur=0 queued=0 [104.963830] iwm0: tx ring 3: qid=3 cur=0 queued=0 [104.963833] iwm0: tx ring 4: qid=4 cur=0 queued=0 [104.963835] iwm0: tx ring 5: qid=5 cur=0 queued=0 [104.963838] iwm0: tx ring 6: qid=6 cur=0 queued=0 [104.963841] iwm0: tx ring 7: qid=7 cur=0 queued=0 [104.963843] iwm0: tx ring 8: qid=8 cur=0 queued=0 [104.963846] iwm0: tx ring 9: qid=9 cur=73 queued=1 [104.963849] iwm0: tx ring 10: qid=10 cur=0 queued=0 [104.963851] iwm0: tx ring 11: qid=11 cur=0 queued=0 [104.963854] iwm0: tx ring 12: qid=12 cur=0 queued=0 [104.963857] iwm0: tx ring 13: qid=13 cur=0 queued=0 [104.963859] iwm0: tx ring 14: qid=14 cur=0 queued=0 [104.963862] iwm0: tx ring 15: qid=15 cur=0 queued=0 [104.963864] iwm0: tx ring 16: qid=16 cur=0 queued=0 [104.963867] iwm0: tx ring 17: qid=17 cur=0 queued=0 [104.963870] iwm0: tx ring 18: qid=18 cur=0 queued=0 [104.963872] iwm0: tx ring 19: qid=19 cur=0 queued=0 [104.963875] iwm0: tx ring 20: qid=20 cur=0 queued=0 [104.963878] iwm0: tx ring 21: qid=21 cur=0 queued=0 [104.963881] iwm0: tx ring 22: qid=22 cur=0 queued=0 [104.963883] iwm0: tx ring 23: qid=23 cur=0 queued=0 [104.963886] iwm0: tx ring 24: qid=24 cur=0 queued=0 [104.963888] iwm0: tx ring 25: qid=25 cur=0 queued=0 [104.963891] iwm0: tx ring 26: qid=26 cur=0 queued=0 [104.963893] iwm0: tx ring 27: qid=27 cur=0 queued=0 [104.963896] iwm0: tx ring 28: qid=28 cur=0 queued=0 [104.963898] iwm0: tx ring 29: qid=29 cur=0 queued=0 [104.963901] iwm0: tx ring 30: qid=30 cur=0 queued=0 [104.963903] iwm0: rx ring: cur=141 [104.963905] iwm0: 802.11 state 5 [104.963907] iwm0: iwm_intr: controller panicked, iv_state = 5; restarting [105.956818] wlan0: link state changed to DOWN [109.167505] wlan0: link state changed to UP [109.452608] iwm0: code ce, frame 1/179 b800002c unhandled [109.675168] iwm0: dumping device error log [109.675339] iwm0: Start Error Log Dump: [109.675341] iwm0: Status: 0x3, count: 6 [109.675344] iwm0: 0x00003073 | ADVANCED_SYSASSERT [109.675347] iwm0: 000002F0 | trm_hw_status0 [109.675349] iwm0: 00000000 | trm_hw_status1 [109.675351] iwm0: 0000E9C8 | branchlink2 [109.675353] iwm0: 0002843C | interruptlink1 [109.675355] iwm0: 00000000 | interruptlink2 [109.675357] iwm0: 00000000 | data1 [109.675359] iwm0: 00000001 | data2 [109.675360] iwm0: DEADBEEF | data3 [109.675362] iwm0: 00009972 | beacon time [109.675364] iwm0: 053706A7 | tsf low [109.675366] iwm0: 00000005 | tsf hi [109.675368] iwm0: 00000000 | time gp1 [109.675369] iwm0: 003588AB | time gp2 [109.675371] iwm0: 00000000 | uCode revision type [109.675373] iwm0: 00000016 | uCode version major [109.675375] iwm0: 00058404 | uCode version minor [109.675377] iwm0: 00000201 | hw version [109.675379] iwm0: 0080FF0F | board version [109.675381] iwm0: 09480029 | hcmd [109.675383] iwm0: 00022000 | isr0 [109.675385] iwm0: 10000000 | isr1 [109.675386] iwm0: 08001802 | isr2 [109.675388] iwm0: 404000C0 | isr3 [109.675389] iwm0: 00000000 | isr4 [109.675391] iwm0: 00800110 | last cmd Id [109.675393] iwm0: 00000000 | wait_event [109.675394] iwm0: 000000C0 | l2p_control [109.675396] iwm0: 00000020 | l2p_duration [109.675398] iwm0: 00000000 | l2p_mhvalid [109.675400] iwm0: 00000000 | l2p_addr_match [109.675402] iwm0: 0000000D | lmpm_pmg_sel [109.675404] iwm0: 03071928 | timestamp [109.675406] iwm0: 00008898 | flow_handler [109.675475] iwm0: Start UMAC Error Log Dump: [109.675477] iwm0: Status: 0x3, count: 7 [109.675479] iwm0: 0x00000070 | ADVANCED_SYSASSERT [109.675482] iwm0: 0x00000000 | umac branchlink1 [109.675484] iwm0: 0xC008383C | umac branchlink2 [109.675486] iwm0: 0xC008166C | umac interruptlink1 [109.675488] iwm0: 0xC008166C | umac interruptlink2 [109.675490] iwm0: 0x00000800 | umac data1 [109.675492] iwm0: 0xC008166C | umac data2 [109.675494] iwm0: 0xDEADBEEF | umac data3 [109.675496] iwm0: 0x00000016 | umac major [109.675498] iwm0: 0x00058404 | umac minor [109.675500] iwm0: 0xC0886280 | frame pointer [109.675502] iwm0: 0xC0886280 | stack pointer [109.675504] iwm0: 0x09480029 | last host cmd [109.675506] iwm0: 0x00000000 | isr status reg [109.675508] iwm0: driver status: [109.675510] iwm0: tx ring 0: qid=0 cur=4 queued=0 [109.675513] iwm0: tx ring 1: qid=1 cur=0 queued=0 [109.675515] iwm0: tx ring 2: qid=2 cur=0 queued=0 [109.675518] iwm0: tx ring 3: qid=3 cur=0 queued=0 [109.675520] iwm0: tx ring 4: qid=4 cur=0 queued=0 [109.675523] iwm0: tx ring 5: qid=5 cur=0 queued=0 [109.675525] iwm0: tx ring 6: qid=6 cur=0 queued=0 [109.675528] iwm0: tx ring 7: qid=7 cur=0 queued=0 [109.675531] iwm0: tx ring 8: qid=8 cur=0 queued=0 [109.675533] iwm0: tx ring 9: qid=9 cur=73 queued=1 [109.675536] iwm0: tx ring 10: qid=10 cur=0 queued=0 [109.675538] iwm0: tx ring 11: qid=11 cur=0 queued=0 [109.675541] iwm0: tx ring 12: qid=12 cur=0 queued=0 [109.675544] iwm0: tx ring 13: qid=13 cur=0 queued=0 [109.675547] iwm0: tx ring 14: qid=14 cur=0 queued=0 [109.675549] iwm0: tx ring 15: qid=15 cur=0 queued=0 [109.675552] iwm0: tx ring 16: qid=16 cur=0 queued=0 [109.675555] iwm0: tx ring 17: qid=17 cur=0 queued=0 [109.675557] iwm0: tx ring 18: qid=18 cur=0 queued=0 [109.675560] iwm0: tx ring 19: qid=19 cur=0 queued=0 [109.675562] iwm0: tx ring 20: qid=20 cur=0 queued=0 [109.675565] iwm0: tx ring 21: qid=21 cur=0 queued=0 [109.675567] iwm0: tx ring 22: qid=22 cur=0 queued=0 [109.675570] iwm0: tx ring 23: qid=23 cur=0 queued=0 [109.675573] iwm0: tx ring 24: qid=24 cur=0 queued=0 [109.675575] iwm0: tx ring 25: qid=25 cur=0 queued=0 [109.675578] iwm0: tx ring 26: qid=26 cur=0 queued=0 [109.675580] iwm0: tx ring 27: qid=27 cur=0 queued=0 [109.675583] iwm0: tx ring 28: qid=28 cur=0 queued=0 [109.675586] iwm0: tx ring 29: qid=29 cur=0 queued=0 [109.675588] iwm0: tx ring 30: qid=30 cur=0 queued=0 [109.675590] iwm0: rx ring: cur=139 [109.675592] iwm0: 802.11 state 5 [109.675595] iwm0: iwm_intr: controller panicked, iv_state = 5; restarting [110.722578] wlan0: link state changed to DOWN [113.921614] wlan0: link state changed to UP [114.203390] iwm0: code ce, frame 1/85 b800002c unhandled [124.431988] wlan0: link state changed to DOWN [124.551094] wlan0: link state changed to UP [135.048478] wlan0: link state changed to DOWN [135.165593] wlan0: link state changed to UP [156.288696] battery1: battery initialization failed, giving up

The resume takes near: 156.29 - 83.32 = 72.97 seconds.

Removing non-existent battery

Replacing iwm driver with iwlwifi

Turning off unnecessary USB devices

After all these changes and reboot, the log for suspend started to look like this:

[869.263458] acpi_lid0: Lid closed [873.064223] uhub3: at usbus0, port 1, addr 1 (disconnected) [873.064250] ugen0.2: <vendor 0x8087 product 0x0024> at usbus0 (disconnected) [873.064261] uhub6: at uhub3, port 1, addr 2 (disconnected) [873.064275] uhub0: at usbus1, port 1, addr 1 (disconnected) [873.064284] uhub0: detached [873.064370] uhub1: at usbus3, port 1, addr 1 (disconnected) [873.064395] ugen3.2: <vendor 0x8087 product 0x0024> at usbus3 (disconnected) [873.064406] uhub5: at uhub1, port 1, addr 2 (disconnected) [873.064428] uhub2: at usbus2, port 1, addr 1 (disconnected) [873.064445] ugen2.2: <vendor 0x0424 product 0x2514> at usbus2 (disconnected) [873.064451] uhub4: at uhub2, port 4, addr 1 (disconnected) [873.083752] ugen2.3: <Logitech USB Trackball> at usbus2 (disconnected) [873.083759] ums0: at uhub4, port 4, addr 2 (disconnected) [873.130146] vgapci0: child drmn0 requested pci_set_powerstate [874.462359] acpi0: cleared fixed power button status [874.465674] vgapci0: child drmn0 requested pci_set_powerstate [874.465679] vgapci0: child drmn0 requested pci_enable_io [874.465683] vgapci0: child drmn0 requested pci_enable_io [874.495321] ums0: detached [874.507165] ugen3.3: <vendor 0x8087 product 0x0a2b> at usbus3 (disconnected) [874.507240] ugen0.3: <AGAN X230> at usbus0 (disconnected) [874.507246] uhid0: at uhub6, port 1, addr 3 (disconnected) [874.527727] uhub5: detached [874.527833] uhid0: detached [874.547719] uhub1: detached [874.547796] ugen0.4: <UPEK Biometric Coprocessor> at usbus0 (disconnected) [874.567762] ugen0.5: <Chicony Electronics Co., Ltd. Integrated Camera> at usbus0 (disconnected) [874.587126] uhub6: detached [874.607103] uhub3: detached [874.607110] acpi_tz0: switched from NONE to _AC0: 128.1C [874.647204] uhub0 on usbus1 [874.647210] uhub0: <(0x1912) XHCI root HUB, class 9/0, rev 3.00/1.00, addr 1> on usbus1 [874.687042] xhci1: Resetting controller [874.912798] uhub4: detached [875.067049] uhub0: 4 ports with 4 removable, self powered [875.332794] uhub2: detached [875.407768] uhub1 on usbus2 [875.407773] uhub1: <(0x1033) XHCI root HUB, class 9/0, rev 3.00/1.00, addr 1> on usbus2 [875.829528] uhub1: 4 ports with 4 removable, self powered [875.829546] uhub1: at usbus2, port 1, addr 1 (disconnected) [875.829557] uhub1: detached [875.907776] uhub1 on usbus2 [875.907781] uhub1: <(0x1033) XHCI root HUB, class 9/0, rev 3.00/1.00, addr 1> on usbus2 [876.317035] uhub1: 4 ports with 4 removable, self powered [876.772401] ugen2.2: <vendor 0x0424 product 0x2514> at usbus2 [876.772533] uhub2 on uhub1 [876.772539] uhub2: <vendor 0x0424 product 0x2514, class 9/0, rev 2.00/0.00, addr 1> on usbus2 [876.773101] uhub2: MTT enabled [877.514530] uhub2: 4 ports with 4 removable, self powered [877.955021] ugen2.3: <Logitech USB Trackball> at usbus2 [877.962031] ums0 on uhub2 [877.962047] ums0: <Logitech USB Trackball, class 0/0, rev 1.10/14.00, addr 2> on usbus2 [877.966407] ums0: 5 buttons and [XY] coordinates ID=0 [878.947083] em0: link state changed to DOWN [878.947125] lagg0: link state changed to DOWN

And the lines for resume:

[892.927133] em0: link state changed to UP [892.927163] lagg0: link state changed to UP [894.817215] acpi_tz0: temperature 52.1C: resuming previous clock speed (2000 MHz) [896.161189] battery0: battery initialization start [896.187244] uhub3 on usbus0 [896.187252] uhub3: <Intel EHCI root HUB, class 9/0, rev 2.00/1.00, addr 1> on usbus0 [896.187324] uhub4 on usbus3 [896.187331] uhub4: <Intel EHCI root HUB, class 9/0, rev 2.00/1.00, addr 1> on usbus3 [897.733354] uhub4: 3 ports with 3 removable, self powered [897.763355] uhub3: 3 ports with 3 removable, self powered [897.857187] battery0: rev = ffff [897.857192] battery0: units = 1 [897.857195] battery0: dcap = 7326 [897.857199] battery0: lfcap = 4538 [897.857202] battery0: btech = 1 [897.857205] battery0: dvol = 11100 [897.857208] battery0: wcap = 226 [897.857212] battery0: lcap = 200 [897.857215] battery0: gra1 = 1 [897.857218] battery0: gra2 = 1 [897.857222] battery0: battery initialization done, tried 1 times [898.429058] ugen3.2: <vendor 0x8087 product 0x0024> at usbus3 [898.429234] uhub5 on uhub4 [898.429241] uhub5: <vendor 0x8087 product 0x0024, class 9/0, rev 2.00/0.00, addr 2> on usbus3 [898.459030] ugen0.2: <vendor 0x8087 product 0x0024> at usbus0 [898.459154] uhub6 on uhub3 [898.459159] uhub6: <vendor 0x8087 product 0x0024, class 9/0, rev 2.00/0.00, addr 2> on usbus0 [899.464604] uhub6: 6 ports with 6 removable, self powered [899.694605] uhub5: 8 ports with 8 removable, self powered [899.931834] ugen0.3: <AGAN X230> at usbus0 [899.935129] uhid0 on uhub6 [899.935137] uhid0: <AGAN X230, class 0/0, rev 1.10/0.00, addr 3> on usbus0 [900.160017] ugen3.3: <vendor 0x8087 product 0x0a2b> at usbus3 [900.390259] ugen0.4: <UPEK Biometric Coprocessor> at usbus0 [900.894470] ugen0.5: <Chicony Electronics Co., Ltd. Integrated Camera> at usbus0

Time for suspend: 878.95 - 869.26 = 9.69 seconds (was 19.25 seconds).

Time for resume: 900.89 - 892.93 = 7.96 seconds (was 72.97 seconds). There are some problems with iwlwifi driver, like with iwm driver, but at least it doesn't take so much time during resume, like the old driver.