Bug 99627 - Improve resume time
Summary: Improve resume time
Status: CLOSED NOTABUG
Alias: None
Product: DRI
Classification: Unclassified
Component: DRM/Intel (show other bugs)
Version: DRI git
Hardware: Other All
: medium normal
Assignee: Intel GFX Bugs mailing list
QA Contact: Intel GFX Bugs mailing list
URL:
Whiteboard:
Keywords:
Depends on:
Blocks:
 
Reported: 2017-02-01 14:46 UTC by Paul Menzel
Modified: 2017-02-27 16:19 UTC (History)
3 users (show)

See Also:
i915 platform: KBL
i915 features: power/suspend-resume

Attachments
HTML output of `analyze_suspend.py` (349.71 KB, text/plain)
2017-02-02 15:46 UTC, Paul Menzel 		no flags Details
HTML output of `analyze_suspend.py -config config/suspend-callgraph.cfg -filter i915` (3.47 MB, text/html)
2017-02-24 16:45 UTC, Paul Menzel 		no flags Details
View All

Description Paul Menzel 2017-02-01 14:46:12 UTC 
On the Kaby Lake laptop TUXEDO Book BU1406 with Ubuntu 16.04, and Linux 4.10-rc6+, AnalyzeSuspend v4.5 shows that the i915 module takes 46 ms to resume.

```
i915 @ 0000:00:02.0 {i915} async_device (Total Suspend: 35.237 ms Total Resume: 46.429 ms)
```

To improve the user experience, and keeping in mind that most firmware takes quite long already, it’s essential to optimize each component.

10 ms are used solely in the “resume early” phase. Could this phase be moved into the “resume” phase?

Are there other ways to optimize the resume?

PS: I know, other components take much longer, and I’ll report these too. But every component needs to be optimized to compete with Apple macOS on Apple devices.

```
# suspend-013117-192126 helmuth-N24-25BU mem 4.10.0-rc6+
# fwsuspend 0 fwresume 1272626
[ 3546.667116] PM: Syncing filesystems ... done.
[ 3546.671334] PM: Preparing system for sleep (mem)
[ 3546.673034] Freezing user space processes ... (elapsed 0.002 seconds) done.
[ 3546.675386] Freezing remaining freezable tasks ... (elapsed 0.001 seconds) done.
[ 3546.676722] PM: Suspending system (mem)
[ 3546.676809] Suspending console(s) (use no_console_suspend to debug)
[ 3546.678548] calling  rfkill1+ @ 4446, parent: phy0
[ 3546.678554] call rfkill1+ returned 0 after 3 usecs
[ 3546.678562] calling  phy0-led+ @ 4446, parent: 0000:02:00.0
[ 3546.678566] call phy0-led+ returned 0 after 2 usecs
[ 3546.678572] calling  phy0+ @ 4450, parent: 0000:02:00.0
[ 3546.678574] calling  input20+ @ 4446, parent: 1-6:1.0
[ 3546.678579] call input20+ returned 0 after 2 usecs
[ 3546.678583] calling  rfkill0+ @ 4446, parent: hci0
[ 3546.678587] wlp2s0: deauthenticating from 6c:f3:7f:10:ae:10 by local choice (Reason: 3=DEAUTH_LEAVING)
[ 3546.678589] call rfkill0+ returned 0 after 1 usecs
[ 3546.678603] calling  coretemp.0+ @ 4446, parent: platform
[ 3546.678607] call coretemp.0+ returned 0 after 2 usecs
[ 3546.678611] calling  input19+ @ 4446, parent: card0
[ 3546.678614] call input19+ returned 0 after 1 usecs
[ 3546.678617] calling  input18+ @ 4446, parent: card0
[ 3546.678620] call input18+ returned 0 after 1 usecs
[ 3546.678623] calling  input17+ @ 4446, parent: card0
[ 3546.678625] call input17+ returned 0 after 1 usecs
[ 3546.678628] calling  input16+ @ 4446, parent: card0
[ 3546.678631] call input16+ returned 0 after 1 usecs
[ 3546.678634] calling  input15+ @ 4446, parent: card0
[ 3546.678636] call input15+ returned 0 after 1 usecs
[ 3546.678654] calling  snd-soc-dummy+ @ 4446, parent: platform
[ 3546.678657] call snd-soc-dummy+ returned 0 after 1 usecs
[ 3546.678660] calling  input4::scrolllock+ @ 4446, parent: input4
[ 3546.678664] call input4::scrolllock+ returned 0 after 1 usecs
[ 3546.678667] calling  hdaudioC0D2+ @ 4331, parent: 0000:00:1f.3
[ 3546.678669] calling  hdaudioC0D0+ @ 3660, parent: 0000:00:1f.3
[ 3546.678671] calling  input4::capslock+ @ 4446, parent: input4
[ 3546.678674] call input4::capslock+ returned 0 after 1 usecs
[ 3546.678677] call hdaudioC0D0+ returned 0 after 4 usecs
[ 3546.678678] call hdaudioC0D2+ returned 0 after 6 usecs
[ 3546.678680] calling  input4::numlock+ @ 4446, parent: input4
[ 3546.678684] call input4::numlock+ returned 0 after 1 usecs
[ 3546.678699] calling  regulatory.0+ @ 4446, parent: platform
[ 3546.678703] call regulatory.0+ returned 0 after 1 usecs
[ 3546.678708] calling  tuxedo::airplane+ @ 4446, parent: tuxedo_wmi
[ 3546.678711] call tuxedo::airplane+ returned 0 after 1 usecs
[ 3546.678714] calling  input14+ @ 4446, parent: tuxedo_wmi
[ 3546.678717] call input14+ returned 0 after 2 usecs
[ 3546.678720] calling  tuxedo_wmi+ @ 4446, parent: platform
[ 3546.678723] call tuxedo_wmi+ returned 0 after 1 usecs
[ 3546.678729] calling  input11+ @ 4446, parent: serio2
[ 3546.678732] call input11+ returned 0 after 1 usecs
[ 3546.678775] calling  1-6+ @ 4331, parent: usb1
[ 3546.678782] call 1-6+ returned 0 after 4 usecs
[ 3546.678790] calling  input10+ @ 4446, parent: LNXVIDEO:00
[ 3546.678796] calling  1-5+ @ 3660, parent: usb1
[ 3546.678799] call input10+ returned 0 after 3 usecs
[ 3546.678869] calling  intel_backlight+ @ 4446, parent: card0-eDP-1
[ 3546.678876] call intel_backlight+ returned 0 after 3 usecs
[ 3546.678897] calling  rtsx_pci_ms.0+ @ 4446, parent: 0000:03:00.0
[ 3546.678964] call rtsx_pci_ms.0+ returned 0 after 63 usecs
[ 3546.678968] calling  rtsx_pci_sdmmc.0+ @ 4446, parent: 0000:03:00.0
[ 3546.678972] call rtsx_pci_sdmmc.0+ returned 0 after 2 usecs
[ 3546.678995] calling  host1+ @ 3553, parent: ata2
[ 3546.679001] call host1+ returned 0 after 4 usecs
[ 3546.679005] calling  host0+ @ 4451, parent: ata1
[ 3546.679009] calling  ata2+ @ 3553, parent: 0000:00:17.0
[ 3546.679012] calling  microcode+ @ 4446, parent: platform
[ 3546.679013] call host0+ returned 0 after 5 usecs
[ 3546.679017] call microcode+ returned 0 after 3 usecs
[ 3546.679020] calling  ata1+ @ 4451, parent: 0000:00:17.0
[ 3546.679031] calling  input4+ @ 4446, parent: serio0
[ 3546.679036] call input4+ returned 0 after 3 usecs
[ 3546.679041] calling  rtc0+ @ 4446, parent: 00:01
[ 3546.679043] call ata2+ returned 0 after 30 usecs
[ 3546.679045] call rtc0+ returned 0 after 2 usecs
[ 3546.679055] calling  serio4+ @ 4446, parent: i8042
[ 3546.679059] call serio4+ returned 0 after 2 usecs
[ 3546.679062] calling  serio3+ @ 4446, parent: i8042
[ 3546.679064] call serio3+ returned 0 after 1 usecs
[ 3546.679067] calling  serio2+ @ 4446, parent: i8042
[ 3546.679822] call ata1+ returned 0 after 779 usecs
[ 3546.703048] call phy0+ returned 0 after 23896 usecs
[ 3546.721151] call serio2+ returned 0 after 41091 usecs
[ 3546.721160] calling  serio1+ @ 4446, parent: i8042
[ 3546.721165] call serio1+ returned 0 after 3 usecs
[ 3546.721168] calling  serio0+ @ 4446, parent: i8042
[ 3546.721712] call serio0+ returned 0 after 525 usecs
[ 3546.721722] calling  i8042+ @ 4446, parent: platform
[ 3547.265137] call i8042+ returned 0 after 530679 usecs
[ 3547.265157] calling  Fixed MDIO bus.0+ @ 4446, parent: platform
[ 3547.265158] call Fixed MDIO bus.0+ returned 0 after 0 usecs
[ 3547.265193] calling  usb3+ @ 3553, parent: 0000:01:00.0
[ 3547.265196] calling  serial8250+ @ 4446, parent: platform
[ 3547.265197] call serial8250+ returned 0 after 1 usecs
[ 3547.265201] calling  input3+ @ 4446, parent: LNXPWRBN:00
[ 3547.265203] call input3+ returned 0 after 0 usecs
[ 3547.265204] calling  input2+ @ 4446, parent: PNP0C0D:00
[ 3547.265205] call input2+ returned 0 after 0 usecs
[ 3547.265206] calling  input1+ @ 4446, parent: PNP0C0E:00
[ 3547.265207] call input1+ returned 0 after 0 usecs
[ 3547.265207] calling  usb4+ @ 4331, parent: 0000:01:00.0
[ 3547.265208] calling  input0+ @ 4446, parent: PNP0C0C:00
[ 3547.265209] call input0+ returned 0 after 0 usecs
[ 3547.265217] calling  alarmtimer+ @ 4446, parent: platform
[ 3547.265219] call alarmtimer+ returned 0 after 0 usecs
[ 3547.265220] calling  usb2+ @ 4451, parent: 0000:00:14.0
[ 3547.265221] calling  platform-framebuffer.0+ @ 4446, parent: platform
[ 3547.265222] call platform-framebuffer.0+ returned 0 after 0 usecs
[ 3547.265223] calling  pcspkr+ @ 4446, parent: platform
[ 3547.265223] call pcspkr+ returned 0 after 0 usecs
[ 3547.265248] calling  00:08+ @ 4446, parent: pnp0
[ 3547.265249] call 00:08+ returned 0 after 0 usecs
[ 3547.265250] calling  00:07+ @ 4446, parent: pnp0
[ 3547.265250] call 00:07+ returned 0 after 0 usecs
[ 3547.265251] calling  00:06+ @ 4446, parent: pnp0
[ 3547.265252] call 00:06+ returned 0 after 0 usecs
[ 3547.265252] calling  00:05+ @ 4446, parent: pnp0
[ 3547.265253] call 00:05+ returned 0 after 0 usecs
[ 3547.265254] calling  00:04+ @ 4446, parent: pnp0
[ 3547.265255] call 00:04+ returned 0 after 0 usecs
[ 3547.265255] calling  00:03+ @ 4446, parent: pnp0
[ 3547.265256] call 00:03+ returned 0 after 0 usecs
[ 3547.265256] calling  00:02+ @ 4446, parent: pnp0
[ 3547.265257] call 00:02+ returned 0 after 0 usecs
[ 3547.265258] calling  00:01+ @ 4446, parent: pnp0
[ 3547.265266] call usb2+ returned 0 after 44 usecs
[ 3547.265320] call 00:01+ returned 0 after 60 usecs
[ 3547.265321] calling  00:00+ @ 4446, parent: pnp0
[ 3547.265321] call 00:00+ returned 0 after 0 usecs
[ 3547.265324] calling  LNXPWRBN:00+ @ 4446, parent: LNXSYSTM:00
[ 3547.265325] call LNXPWRBN:00+ returned 0 after 0 usecs
[ 3547.265326] calling  PNP0C14:00+ @ 4446, parent: platform
[ 3547.265326] call PNP0C14:00+ returned 0 after 0 usecs
[ 3547.265327] calling  PNP0C0A:00+ @ 4446, parent: platform
[ 3547.265328] call PNP0C0A:00+ returned 0 after 0 usecs
[ 3547.265329] calling  ACPI0003:00+ @ 4446, parent: platform
[ 3547.265329] call ACPI0003:00+ returned 0 after 0 usecs
[ 3547.265330] calling  PNP0C0D:00+ @ 4446, parent: platform
[ 3547.265330] call PNP0C0D:00+ returned 0 after 0 usecs
[ 3547.265331] calling  PNP0C0E:00+ @ 4446, parent: platform
[ 3547.265332] call PNP0C0E:00+ returned 0 after 0 usecs
[ 3547.265332] calling  PNP0C0C:00+ @ 4446, parent: platform
[ 3547.265333] call PNP0C0C:00+ returned 0 after 0 usecs
[ 3547.265333] calling  INT0E0C:00+ @ 4446, parent: platform
[ 3547.265334] call INT0E0C:00+ returned 0 after 0 usecs
[ 3547.265335] calling  ACPI000C:00+ @ 4446, parent: platform
[ 3547.265335] call ACPI000C:00+ returned 0 after 0 usecs
[ 3547.265336] calling  PNP0C09:00+ @ 4446, parent: 0000:00:1f.0
[ 3547.265337] call PNP0C09:00+ returned 0 after 0 usecs
[ 3547.265337] calling  PNP0103:00+ @ 4446, parent: 0000:00:1f.0
[ 3547.265338] call PNP0103:00+ returned 0 after 0 usecs
[ 3547.265338] calling  INT0800:00+ @ 4446, parent: 0000:00:1f.0
[ 3547.265339] call INT0800:00+ returned 0 after 0 usecs
[ 3547.265348] calling  LNXTHERM:00+ @ 4446, parent: LNXSYBUS:01
[ 3547.265350] call LNXTHERM:00+ returned 0 after 1 usecs
[ 3547.265353] calling  PNP0C0D:00+ @ 4446, parent: LNXSYBUS:00
[ 3547.265354] call PNP0C0D:00+ returned 0 after 0 usecs
[ 3547.265355] calling  PNP0C0E:00+ @ 4446, parent: LNXSYBUS:00
[ 3547.265355] call PNP0C0E:00+ returned 0 after 0 usecs
[ 3547.265356] calling  PNP0C0C:00+ @ 4446, parent: LNXSYBUS:00
[ 3547.265356] call PNP0C0C:00+ returned 0 after 0 usecs
[ 3547.265375] calling  0000:04:00.0+ @ 4451, parent: 0000:00:1d.0
[ 3547.265395] calling  0000:03:00.1+ @ 4454, parent: 0000:00:1c.5
[ 3547.265397] calling  0000:03:00.0+ @ 4452, parent: 0000:00:1c.5
[ 3547.265408] calling  PNP0C09:00+ @ 4446, parent: device:20
[ 3547.265409] ACPI : EC: event blocked
[ 3547.265533] calling  0000:02:00.0+ @ 4455, parent: 0000:00:1c.2
[ 3547.265535] call 0000:02:00.0+ returned 0 after 1 usecs
[ 3547.265553] calling  0000:00:1f.4+ @ 4456, parent: pci0000:00
[ 3547.265554] call 0000:00:1f.4+ returned 0 after 0 usecs
[ 3547.265556] calling  0000:00:1f.3+ @ 4456, parent: pci0000:00
[ 3547.265568] calling  0000:00:1f.2+ @ 4457, parent: pci0000:00
[ 3547.265573] call 0000:00:1f.2+ returned 0 after 4 usecs
[ 3547.265575] calling  0000:00:1f.0+ @ 4457, parent: pci0000:00
[ 3547.265576] call 0000:00:1f.0+ returned 0 after 0 usecs
[ 3547.265593] calling  0000:00:1c.2+ @ 4459, parent: pci0000:00
[ 3547.265595] call 0000:00:1c.2+ returned 0 after 1 usecs
[ 3547.265604] calling  0000:00:17.0+ @ 4460, parent: pci0000:00
[ 3547.265636] calling  0000:00:16.0+ @ 4461, parent: pci0000:00
[ 3547.265646] call 0000:00:17.0+ returned 0 after 41 usecs
[ 3547.265691] calling  0000:00:14.2+ @ 4460, parent: pci0000:00
[ 3547.265693] call 0000:00:14.2+ returned 0 after 1 usecs
[ 3547.265694] call 0000:03:00.1+ returned 0 after 291 usecs
[ 3547.265695] calling  0000:00:08.0+ @ 4454, parent: pci0000:00
[ 3547.265696] call 0000:00:08.0+ returned 0 after 0 usecs
[ 3547.265697] calling  0000:00:02.0+ @ 4454, parent: pci0000:00
[ 3547.265969] calling  0000:00:00.0+ @ 4462, parent: pci0000:00
[ 3547.265970] call 0000:00:00.0+ returned 0 after 0 usecs
[ 3547.266639] call 0000:00:1f.3+ returned 0 after 1057 usecs
[ 3547.276776] call 0000:00:16.0+ returned 0 after 10879 usecs
[ 3547.282637] call 0000:00:02.0+ returned 0 after 16541 usecs
[ 3547.283291] call 0000:03:00.0+ returned 0 after 17472 usecs
[ 3547.283295] calling  0000:00:1c.5+ @ 4458, parent: pci0000:00
[ 3547.283297] call 0000:00:1c.5+ returned 0 after 1 usecs
[ 3547.306347] call usb3+ returned 0 after 40187 usecs
[ 3547.306457] call usb4+ returned 0 after 40282 usecs
[ 3547.306463] calling  0000:01:00.0+ @ 4455, parent: 0000:00:1c.0
[ 3547.307337] call 0000:01:00.0+ returned 0 after 853 usecs
[ 3547.307362] calling  0000:00:1c.0+ @ 4459, parent: pci0000:00
[ 3547.307366] call 0000:00:1c.0+ returned 0 after 2 usecs
[ 3547.344164] call 1-5+ returned 0 after 649772 usecs
[ 3547.344180] calling  usb1+ @ 4450, parent: 0000:00:14.0
[ 3547.344355] call usb1+ returned 0 after 169 usecs
[ 3547.344405] calling  0000:00:14.0+ @ 4460, parent: pci0000:00
[ 3547.344507] call 0000:00:14.0+ returned 0 after 98 usecs
[ 3547.371418] call 0000:04:00.0+ returned 0 after 103555 usecs
[ 3547.371434] calling  0000:00:1d.0+ @ 4457, parent: pci0000:00
[ 3547.371443] call 0000:00:1d.0+ returned 0 after 6 usecs
[ 3547.472115] call PNP0C09:00+ returned 0 after 201857 usecs
[ 3547.472212] calling  reg-dummy+ @ 4446, parent: platform
[ 3547.472218] call reg-dummy+ returned 0 after 3 usecs
[ 3547.472484] PM: suspend of devices complete after 793.976 msecs
[ 3547.473105] calling  0000:00:02.0+ @ 4460, parent: pci0000:00
[ 3547.491412] call 0000:00:02.0+ returned 0 after 17870 usecs
[ 3547.491481] PM: late suspend of devices complete after 18.989 msecs
[ 3547.492295] calling  0000:04:00.0+ @ 4451, parent: 0000:00:1d.0
[ 3547.492298] calling  0000:03:00.1+ @ 4457, parent: 0000:00:1c.5
[ 3547.492315] calling  0000:03:00.0+ @ 4460, parent: 0000:00:1c.5
[ 3547.492326] call 0000:03:00.0+ returned 0 after 8 usecs
[ 3547.492333] calling  0000:02:00.0+ @ 4460, parent: 0000:00:1c.2
[ 3547.492462] calling  PNP0C09:00+ @ 4446, parent: device:20
[ 3547.492466] ACPI : EC: interrupt blocked
[ 3547.492474] call PNP0C09:00+ returned 0 after 9 usecs
[ 3547.492931] pcieport 0000:00:1c.5: System wakeup enabled by ACPI
[ 3547.492963] calling  0000:01:00.0+ @ 4462, parent: 0000:00:1c.0
[ 3547.492972] calling  0000:00:1f.4+ @ 4450, parent: pci0000:00
[ 3547.492980] calling  0000:00:1f.3+ @ 3660, parent: pci0000:00
[ 3547.492988] calling  0000:00:1f.2+ @ 4459, parent: pci0000:00
[ 3547.493145] call 0000:00:1f.4+ returned 0 after 165 usecs
[ 3547.493154] calling  0000:00:1f.0+ @ 4450, parent: pci0000:00
[ 3547.493166] call 0000:00:1f.2+ returned 0 after 171 usecs
[ 3547.493249] calling  0000:00:17.0+ @ 4458, parent: pci0000:00
[ 3547.493257] call 0000:00:1f.0+ returned 0 after 97 usecs
[ 3547.493259] calling  0000:00:16.0+ @ 4452, parent: pci0000:00
[ 3547.493264] calling  0000:00:14.2+ @ 4450, parent: pci0000:00
[ 3547.493280] xhci_hcd 0000:01:00.0: System wakeup enabled by ACPI
[ 3547.493432] calling  0000:00:14.0+ @ 4454, parent: pci0000:00
[ 3547.493439] calling  0000:00:08.0+ @ 4456, parent: pci0000:00
[ 3547.493457] calling  0000:00:02.0+ @ 4461, parent: pci0000:00
[ 3547.493462] call 0000:00:02.0+ returned 0 after 3 usecs
[ 3547.493464] calling  0000:00:00.0+ @ 4464, parent: pci0000:00
[ 3547.493633] call 0000:00:08.0+ returned 0 after 187 usecs
[ 3547.493637] call 0000:00:00.0+ returned 0 after 167 usecs
[ 3547.493778] xhci_hcd 0000:00:14.0: System wakeup enabled by ACPI
[ 3547.511247] call 0000:00:14.2+ returned 0 after 17559 usecs
[ 3547.511288] call 0000:01:00.0+ returned 0 after 17893 usecs
[ 3547.511299] calling  0000:00:1c.0+ @ 3553, parent: pci0000:00
[ 3547.511305] call 0000:02:00.0+ returned 0 after 18525 usecs
[ 3547.511308] call 0000:00:17.0+ returned 0 after 17633 usecs
[ 3547.511318] calling  0000:00:1c.2+ @ 4331, parent: pci0000:00
[ 3547.511360] call 0000:04:00.0+ returned 0 after 18616 usecs
[ 3547.511368] calling  0000:00:1d.0+ @ 4459, parent: pci0000:00
[ 3547.511648] call 0000:03:00.1+ returned 0 after 18894 usecs
[ 3547.511652] call 0000:00:16.0+ returned 0 after 17960 usecs
[ 3547.511656] calling  0000:00:1c.5+ @ 4455, parent: pci0000:00
[ 3547.512407] call 0000:00:1f.3+ returned 0 after 18968 usecs
[ 3547.531222] call 0000:00:1c.5+ returned 0 after 19104 usecs
[ 3547.531224] call 0000:00:1c.2+ returned 0 after 19436 usecs
[ 3547.531232] call 0000:00:1c.0+ returned 0 after 19463 usecs
[ 3547.531234] call 0000:00:1d.0+ returned 0 after 19397 usecs
[ 3547.531401] call 0000:00:14.0+ returned 0 after 37078 usecs
[ 3547.531426] PM: noirq suspend of devices complete after 39.936 msecs
[ 3547.532473] ACPI: Preparing to enter system sleep state S3
[ 3547.534638] ACPI : EC: EC stopped
[ 3547.534639] PM: Saving platform NVS memory
[ 3547.534706] Disabling non-boot CPUs ...
[ 3547.535508] Broke affinity for irq 128
[ 3547.536593] smpboot: CPU 1 is now offline
[ 3547.564768] Broke affinity for irq 122
[ 3547.564781] Broke affinity for irq 125
[ 3547.564786] Broke affinity for irq 126
[ 3547.564794] Broke affinity for irq 128
[ 3547.564808] Broke affinity for irq 132
[ 3547.564814] Broke affinity for irq 137
[ 3547.566928] smpboot: CPU 2 is now offline
[ 3547.588529] Broke affinity for irq 1
[ 3547.588535] Broke affinity for irq 8
[ 3547.588539] Broke affinity for irq 9
[ 3547.588543] Broke affinity for irq 12
[ 3547.588554] Broke affinity for irq 122
[ 3547.588559] Broke affinity for irq 123
[ 3547.588563] Broke affinity for irq 124
[ 3547.588567] Broke affinity for irq 125
[ 3547.588570] Broke affinity for irq 126
[ 3547.588575] Broke affinity for irq 127
[ 3547.588579] Broke affinity for irq 128
[ 3547.588587] Broke affinity for irq 131
[ 3547.588591] Broke affinity for irq 132
[ 3547.588597] Broke affinity for irq 137
[ 3547.589644] smpboot: CPU 3 is now offline
[ 3547.607905] PM: Calling kvm_suspend+0x0/0x30 [kvm]
[ 3547.607912] PM: Calling mce_syscore_suspend+0x0/0x20
[ 3547.607919] PM: Calling ledtrig_cpu_syscore_suspend+0x0/0x20
[ 3547.607925] PM: Calling timekeeping_suspend+0x0/0x2a0
[ 3547.608028] PM: Calling irq_gc_suspend+0x0/0x70
[ 3547.608032] PM: Calling save_ioapic_entries+0x0/0x90
[ 3547.609235] PM: Calling i8259A_suspend+0x0/0x30
[ 3547.609247] PM: Calling fw_suspend+0x0/0x20
[ 3547.609252] PM: Calling acpi_save_bm_rld+0x0/0x1e
[ 3547.609262] PM: Calling lapic_suspend+0x0/0x1d0
[1266874881.041473] [Firmware Bug]: TSC ADJUST differs: CPU0 0 --> -89978441. Restoring
[ 3547.611146] ACPI: Low-level resume complete
[ 3547.611251] ACPI : EC: EC started
[ 3547.611251] PM: Restoring platform NVS memory
[ 3547.611282] PM: Calling bsp_resume+0x0/0x20
[ 3547.611284] PM: Calling lapic_resume+0x0/0x2a0
[ 3547.611312] PM: Calling acpi_restore_bm_rld+0x0/0x5c
[ 3547.611315] PM: Calling irqrouter_resume+0x0/0x3d
[ 3547.611317] PM: Calling i8259A_resume+0x0/0x30
[ 3547.611481] PM: Calling i8237A_resume+0x0/0x90
[ 3547.611610] PM: Calling ioapic_resume+0x0/0xa0
[ 3547.611852] PM: Calling irq_gc_resume+0x0/0x60
[ 3547.611854] PM: Calling irq_pm_syscore_resume+0x0/0x20
[ 3547.611865] PM: Calling timekeeping_resume+0x0/0x1d0
[ 3547.611979] Suspended for 13.352 seconds
[ 3547.611990] PM: Calling ledtrig_cpu_syscore_resume+0x0/0x20
[ 3547.611992] PM: Calling mce_syscore_resume+0x0/0x30
[ 3547.612008] PM: Calling mc_bp_resume+0x0/0x50
[ 3547.612021] PM: Calling kvm_resume+0x0/0x40 [kvm]
[ 3547.612032] Enabling non-boot CPUs ...
[ 3547.623366] x86: Booting SMP configuration:
[ 3547.623367] smpboot: Booting Node 0 Processor 1 APIC 0x2
[ 3547.623688] [Firmware Bug]: TSC ADJUST differs: Reference CPU0: -352922557 CPU1: 0
[ 3547.623794]  cache: parent cpu1 should not be sleeping
[ 3547.623924] CPU1 is up
[ 3547.635596] smpboot: Booting Node 0 Processor 2 APIC 0x1
[ 3547.636395] [Firmware Bug]: TSC ADJUST differs: Reference CPU0: -352922557 CPU2: 0
[ 3547.636641]  cache: parent cpu2 should not be sleeping
[ 3547.636979] CPU2 is up
[ 3547.651676] smpboot: Booting Node 0 Processor 3 APIC 0x3
[ 3547.652595] [Firmware Bug]: TSC ADJUST differs: Reference CPU0: -352922557 CPU3: 0
[ 3547.652848]  cache: parent cpu3 should not be sleeping
[ 3547.653230] CPU3 is up
[ 3547.661639] ACPI: Waking up from system sleep state S3
[ 3547.670853] calling  0000:00:00.0+ @ 4454, parent: pci0000:00
[ 3547.670860] calling  0000:00:02.0+ @ 4459, parent: pci0000:00
[ 3547.670877] calling  0000:00:08.0+ @ 3553, parent: pci0000:00
[ 3547.670892] call 0000:00:00.0+ returned 0 after 35 usecs
[ 3547.670895] calling  0000:00:14.0+ @ 4454, parent: pci0000:00
[ 3547.670913] call 0000:00:08.0+ returned 0 after 33 usecs
[ 3547.670917] calling  0000:00:14.2+ @ 3553, parent: pci0000:00
[ 3547.670928] calling  0000:00:16.0+ @ 4455, parent: pci0000:00
[ 3547.670935] calling  0000:00:17.0+ @ 4331, parent: pci0000:00
[ 3547.670949] calling  0000:00:1c.0+ @ 3660, parent: pci0000:00
[ 3547.670959] calling  0000:00:1c.2+ @ 4452, parent: pci0000:00
[ 3547.670966] calling  0000:00:1c.5+ @ 4457, parent: pci0000:00
[ 3547.670976] calling  0000:00:1d.0+ @ 4460, parent: pci0000:00
[ 3547.670987] calling  0000:00:1f.2+ @ 4451, parent: pci0000:00
[ 3547.670999] calling  0000:00:1f.3+ @ 4458, parent: pci0000:00
[ 3547.671008] calling  0000:00:1f.4+ @ 4450, parent: pci0000:00
[ 3547.671034] call 0000:00:1f.2+ returned 0 after 44 usecs
[ 3547.671039] calling  0000:00:1f.0+ @ 4462, parent: pci0000:00
[ 3547.671060] calling  PNP0C09:00+ @ 4446, parent: device:20
[ 3547.671063] ACPI : EC: interrupt unblocked
[ 3547.671065] call PNP0C09:00+ returned 0 after 3 usecs
[ 3547.671117] call 0000:00:1f.4+ returned 0 after 104 usecs
[ 3547.671127] call 0000:00:1f.0+ returned 0 after 84 usecs
[ 3547.671235] calling  i8042+ @ 4446, parent: platform
[ 3547.671240] call i8042+ returned 0 after 2 usecs
[ 3547.687318] call 0000:00:16.0+ returned 0 after 16003 usecs
[ 3547.687443] call 0000:00:1c.5+ returned 0 after 16088 usecs
[ 3547.687446] call 0000:00:1d.0+ returned 0 after 16082 usecs
[ 3547.687454] call 0000:00:1c.2+ returned 0 after 16107 usecs
[ 3547.687458] call 0000:00:14.2+ returned 0 after 16153 usecs
[ 3547.687609] call 0000:00:17.0+ returned 0 after 16282 usecs
[ 3547.687617] calling  0000:04:00.0+ @ 4462, parent: 0000:00:1d.0
[ 3547.687629] calling  0000:02:00.0+ @ 4450, parent: 0000:00:1c.2
[ 3547.687632] calling  0000:03:00.1+ @ 4463, parent: 0000:00:1c.5
[ 3547.687676] call 0000:00:1c.0+ returned 0 after 16333 usecs
[ 3547.687677] call 0000:00:02.0+ returned 0 after 16420 usecs
[ 3547.687682] calling  0000:01:00.0+ @ 4451, parent: 0000:00:1c.0
[ 3547.687684] calling  0000:03:00.0+ @ 4464, parent: 0000:00:1c.5
[ 3547.691248] call 0000:00:1f.3+ returned 0 after 19773 usecs
[ 3547.708155] call 0000:02:00.0+ returned 0 after 20043 usecs
[ 3547.708184] xhci_hcd 0000:01:00.0: System wakeup disabled by ACPI
[ 3547.708188] call 0000:03:00.1+ returned 0 after 20072 usecs
[ 3547.708199] call 0000:01:00.0+ returned 0 after 20034 usecs
[ 3547.708207] call 0000:03:00.0+ returned 0 after 20040 usecs
[ 3547.708265] call 0000:04:00.0+ returned 0 after 20163 usecs
[ 3547.715281] xhci_hcd 0000:00:14.0: System wakeup disabled by ACPI
[ 3547.715286] call 0000:00:14.0+ returned 0 after 43349 usecs
[ 3547.715366] PM: noirq resume of devices complete after 44.580 msecs
[ 3547.715447] calling  0000:00:02.0+ @ 4483, parent: pci0000:00
[ 3547.726301] call 0000:00:02.0+ returned 0 after 10598 usecs
[ 3547.726378] PM: early resume of devices complete after 10.964 msecs
[ 3547.726415] calling  0000:00:00.0+ @ 4483, parent: pci0000:00
[ 3547.726419] call 0000:00:00.0+ returned 0 after 2 usecs
[ 3547.726425] calling  0000:00:08.0+ @ 4483, parent: pci0000:00
[ 3547.726428] calling  0000:00:02.0+ @ 4501, parent: pci0000:00
[ 3547.726429] call 0000:00:08.0+ returned 0 after 1 usecs
[ 3547.726431] calling  0000:00:14.0+ @ 4485, parent: pci0000:00
[ 3547.726432] calling  0000:00:14.2+ @ 4483, parent: pci0000:00
[ 3547.726435] call 0000:00:14.2+ returned 0 after 2 usecs
[ 3547.726438] calling  0000:00:16.0+ @ 4483, parent: pci0000:00
[ 3547.726544] calling  reg-dummy+ @ 4446, parent: platform
[ 3547.726548] call reg-dummy+ returned 0 after 2 usecs
[ 3547.726567] calling  PNP0C09:00+ @ 4446, parent: device:20
[ 3547.726569] ACPI : EC: event unblocked
[ 3547.726591] call PNP0C09:00+ returned 0 after 21 usecs
[ 3547.726625] calling  PNP0C0C:00+ @ 4446, parent: LNXSYBUS:00
[ 3547.726628] call PNP0C0C:00+ returned 0 after 1 usecs
[ 3547.726629] calling  PNP0C0E:00+ @ 4446, parent: LNXSYBUS:00
[ 3547.726631] call PNP0C0E:00+ returned 0 after 0 usecs
[ 3547.726633] calling  PNP0C0D:00+ @ 4446, parent: LNXSYBUS:00
[ 3547.726677] call 0000:00:14.0+ returned 0 after 238 usecs
[ 3547.726684] calling  0000:00:17.0+ @ 4485, parent: pci0000:00
[ 3547.726710] ACPI : button: The lid device is not compliant to SW_LID.
[ 3547.726713] call 0000:00:17.0+ returned 0 after 26 usecs
[ 3547.726714] calling  0000:00:1c.0+ @ 4482, parent: pci0000:00
[ 3547.726715] calling  0000:00:1c.2+ @ 4485, parent: pci0000:00
[ 3547.726717] call PNP0C0D:00+ returned 0 after 79 usecs
[ 3547.726719] call 0000:00:1c.0+ returned 0 after 3 usecs
[ 3547.726720] call 0000:00:1c.2+ returned 0 after 2 usecs
[ 3547.726722] calling  ACPI0003:00+ @ 4446, parent: LNXSYBUS:00
[ 3547.726723] calling  0000:00:1c.5+ @ 4482, parent: pci0000:00
[ 3547.726724] calling  0000:00:1d.0+ @ 4485, parent: pci0000:00
[ 3547.726727] call 0000:00:1c.5+ returned 0 after 2 usecs
[ 3547.726728] call 0000:00:1d.0+ returned 0 after 1 usecs
[ 3547.726729] calling  0000:00:1f.0+ @ 4482, parent: pci0000:00
[ 3547.726730] calling  0000:00:1f.2+ @ 4485, parent: pci0000:00
[ 3547.726732] call 0000:00:1f.0+ returned 0 after 2 usecs
[ 3547.726734] calling  0000:00:1f.3+ @ 4482, parent: pci0000:00
[ 3547.726738] call 0000:00:1f.2+ returned 0 after 6 usecs
[ 3547.726740] calling  0000:00:1f.4+ @ 4485, parent: pci0000:00
[ 3547.726744] call 0000:00:1f.4+ returned 0 after 1 usecs
[ 3547.726746] calling  0000:01:00.0+ @ 4485, parent: 0000:00:1c.0
[ 3547.726754] calling  0000:02:00.0+ @ 4484, parent: 0000:00:1c.2
[ 3547.726775] call 0000:02:00.0+ returned 0 after 19 usecs
[ 3547.726777] calling  0000:03:00.0+ @ 4484, parent: 0000:00:1c.5
[ 3547.727024] calling  0000:03:00.1+ @ 4499, parent: 0000:00:1c.5
[ 3547.727038] calling  0000:04:00.0+ @ 4480, parent: 0000:00:1d.0
[ 3547.727045] call 0000:04:00.0+ returned 0 after 5 usecs
[ 3547.727049] calling  usb1+ @ 4480, parent: 0000:00:14.0
[ 3547.727075] call 0000:03:00.0+ returned 0 after 289 usecs
[ 3547.727147] calling  usb2+ @ 4468, parent: 0000:00:14.0
[ 3547.727237] call usb2+ returned 0 after 76 usecs
[ 3547.727303] calling  ata1+ @ 4462, parent: 0000:00:17.0
[ 3547.727310] call ata1+ returned 0 after 6 usecs
[ 3547.727312] calling  ata2+ @ 4462, parent: 0000:00:17.0
[ 3547.727318] call ata2+ returned 0 after 4 usecs
[ 3547.727320] calling  host0+ @ 4462, parent: ata1
[ 3547.727324] call host0+ returned 0 after 3 usecs
[ 3547.727327] calling  host1+ @ 4462, parent: ata2
[ 3547.727329] call host1+ returned 0 after 1 usecs
[ 3547.727424] calling  phy0+ @ 4488, parent: 0000:02:00.0
[ 3547.727508] pcieport 0000:00:1c.5: System wakeup disabled by ACPI
[ 3547.729553] iwlwifi 0000:02:00.0: L1 Enabled - LTR Disabled
[ 3547.729708] call 0000:01:00.0+ returned 0 after 2891 usecs
[ 3547.729724] calling  usb4+ @ 4498, parent: 0000:01:00.0
[ 3547.729730] calling  usb3+ @ 4468, parent: 0000:01:00.0
[ 3547.729777] call usb4+ returned 0 after 50 usecs
[ 3547.729801] call usb3+ returned 0 after 67 usecs
[ 3547.730189] iwlwifi 0000:02:00.0: L1 Enabled - LTR Disabled
[ 3547.735240] call ACPI0003:00+ returned 0 after 8315 usecs
[ 3547.735244] calling  PNP0C0A:00+ @ 4446, parent: LNXSYBUS:00
[ 3547.735759] call PNP0C0A:00+ returned 0 after 500 usecs
[ 3547.735764] calling  LNXTHERM:00+ @ 4446, parent: LNXSYBUS:01
[ 3547.735771] call LNXTHERM:00+ returned 0 after 5 usecs
[ 3547.735784] calling  INT0800:00+ @ 4446, parent: 0000:00:1f.0
[ 3547.735786] call INT0800:00+ returned 0 after 1 usecs
[ 3547.735788] calling  PNP0103:00+ @ 4446, parent: 0000:00:1f.0
[ 3547.735789] call PNP0103:00+ returned 0 after 0 usecs
[ 3547.735791] calling  PNP0C09:00+ @ 4446, parent: 0000:00:1f.0
[ 3547.735792] call PNP0C09:00+ returned 0 after 0 usecs
[ 3547.735794] calling  ACPI000C:00+ @ 4446, parent: platform
[ 3547.735796] call ACPI000C:00+ returned 0 after 1 usecs
[ 3547.735797] calling  INT0E0C:00+ @ 4446, parent: platform
[ 3547.735799] call INT0E0C:00+ returned 0 after 0 usecs
[ 3547.735800] calling  PNP0C0C:00+ @ 4446, parent: platform
[ 3547.735801] call PNP0C0C:00+ returned 0 after 0 usecs
[ 3547.735802] calling  PNP0C0E:00+ @ 4446, parent: platform
[ 3547.735804] call PNP0C0E:00+ returned 0 after 0 usecs
[ 3547.735805] calling  PNP0C0D:00+ @ 4446, parent: platform
[ 3547.735807] call PNP0C0D:00+ returned 0 after 0 usecs
[ 3547.735808] calling  ACPI0003:00+ @ 4446, parent: platform
[ 3547.735810] call ACPI0003:00+ returned 0 after 0 usecs
[ 3547.735811] calling  PNP0C0A:00+ @ 4446, parent: platform
[ 3547.735813] call PNP0C0A:00+ returned 0 after 0 usecs
[ 3547.735814] calling  PNP0C14:00+ @ 4446, parent: platform
[ 3547.735815] call PNP0C14:00+ returned 0 after 0 usecs
[ 3547.735817] calling  LNXPWRBN:00+ @ 4446, parent: LNXSYSTM:00
[ 3547.735819] call LNXPWRBN:00+ returned 0 after 1 usecs
[ 3547.735822] calling  00:00+ @ 4446, parent: pnp0
[ 3547.735825] call 00:00+ returned 0 after 2 usecs
[ 3547.735827] calling  00:01+ @ 4446, parent: pnp0
[ 3547.735830] rtc_cmos 00:01: System wakeup disabled by ACPI
[ 3547.736062] call 00:01+ returned 0 after 228 usecs
[ 3547.736063] calling  00:02+ @ 4446, parent: pnp0
[ 3547.736065] call 00:02+ returned 0 after 0 usecs
[ 3547.736066] calling  00:03+ @ 4446, parent: pnp0
[ 3547.736068] call 00:03+ returned 0 after 1 usecs
[ 3547.736069] calling  00:04+ @ 4446, parent: pnp0
[ 3547.736071] call 00:04+ returned 0 after 0 usecs
[ 3547.736072] calling  00:05+ @ 4446, parent: pnp0
[ 3547.736074] call 00:05+ returned 0 after 0 usecs
[ 3547.736075] calling  00:06+ @ 4446, parent: pnp0
[ 3547.736077] call 00:06+ returned 0 after 0 usecs
[ 3547.736078] calling  00:07+ @ 4446, parent: pnp0
[ 3547.736079] call 00:07+ returned 0 after 0 usecs
[ 3547.736080] calling  00:08+ @ 4446, parent: pnp0
[ 3547.736082] call 00:08+ returned 0 after 0 usecs
[ 3547.736105] calling  pcspkr+ @ 4446, parent: platform
[ 3547.736107] call pcspkr+ returned 0 after 1 usecs
[ 3547.736108] calling  platform-framebuffer.0+ @ 4446, parent: platform
[ 3547.736111] call platform-framebuffer.0+ returned 0 after 1 usecs
[ 3547.736113] calling  alarmtimer+ @ 4446, parent: platform
[ 3547.736116] call alarmtimer+ returned 0 after 1 usecs
[ 3547.736122] calling  input0+ @ 4446, parent: PNP0C0C:00
[ 3547.736125] call input0+ returned 0 after 1 usecs
[ 3547.736126] calling  input1+ @ 4446, parent: PNP0C0E:00
[ 3547.736128] call input1+ returned 0 after 0 usecs
[ 3547.736129] calling  input2+ @ 4446, parent: PNP0C0D:00
[ 3547.736131] call input2+ returned 0 after 0 usecs
[ 3547.736132] calling  input3+ @ 4446, parent: LNXPWRBN:00
[ 3547.736134] call input3+ returned 0 after 1 usecs
[ 3547.736137] calling  serial8250+ @ 4446, parent: platform
[ 3547.736140] call serial8250+ returned 0 after 2 usecs
[ 3547.736167] calling  Fixed MDIO bus.0+ @ 4446, parent: platform
[ 3547.736169] call Fixed MDIO bus.0+ returned 0 after 1 usecs
[ 3547.736175] calling  i8042+ @ 4446, parent: platform
[ 3547.740255] call 0000:00:1f.3+ returned 0 after 13200 usecs
[ 3547.740268] calling  hdaudioC0D0+ @ 4490, parent: 0000:00:1f.3
[ 3547.740270] calling  hdaudioC0D2+ @ 4489, parent: 0000:00:1f.3
[ 3547.740274] call hdaudioC0D0+ returned 0 after 4 usecs
[ 3547.740275] call hdaudioC0D2+ returned 0 after 3 usecs
[ 3547.740835] call i8042+ returned 0 after 4549 usecs
[ 3547.740836] calling  serio0+ @ 4446, parent: i8042
[ 3547.740842] call serio0+ returned 0 after 4 usecs
[ 3547.740914] calling  serio1+ @ 4446, parent: i8042
[ 3547.740917] call serio1+ returned 0 after 2 usecs
[ 3547.740921] calling  serio2+ @ 4446, parent: i8042
[ 3547.740923] call serio2+ returned 0 after 1 usecs
[ 3547.740925] calling  serio3+ @ 4446, parent: i8042
[ 3547.740926] call serio3+ returned 0 after 1 usecs
[ 3547.740928] calling  serio4+ @ 4446, parent: i8042
[ 3547.740929] call serio4+ returned 0 after 0 usecs
[ 3547.740933] calling  rtc0+ @ 4446, parent: 00:01
[ 3547.740935] call rtc0+ returned 0 after 1 usecs
[ 3547.740937] calling  input4+ @ 4446, parent: serio0
[ 3547.740942] call input4+ returned 0 after 4 usecs
[ 3547.740947] calling  microcode+ @ 4446, parent: platform
[ 3547.740949] call microcode+ returned 0 after 1 usecs
[ 3547.740958] calling  rtsx_pci_sdmmc.0+ @ 4446, parent: 0000:03:00.0
[ 3547.740961] call rtsx_pci_sdmmc.0+ returned 0 after 1 usecs
[ 3547.740962] calling  rtsx_pci_ms.0+ @ 4446, parent: 0000:03:00.0
[ 3547.740968] call rtsx_pci_ms.0+ returned 0 after 4 usecs
[ 3547.741245] [drm] GuC firmware load skipped
[ 3547.743403] call 0000:03:00.1+ returned 0 after 15991 usecs
[ 3547.744203] call 0000:00:16.0+ returned 0 after 17344 usecs
[ 3547.745200] call 0000:00:02.0+ returned 0 after 18329 usecs
[ 3547.745215] calling  intel_backlight+ @ 4446, parent: card0-eDP-1
[ 3547.745220] call intel_backlight+ returned 0 after 3 usecs
[ 3547.745225] calling  input10+ @ 4446, parent: LNXVIDEO:00
[ 3547.745228] call input10+ returned 0 after 1 usecs
[ 3547.745237] calling  input11+ @ 4446, parent: serio2
[ 3547.745239] call input11+ returned 0 after 1 usecs
[ 3547.745242] calling  tuxedo_wmi+ @ 4446, parent: platform
[ 3547.745579] r8169 0000:03:00.1 enp3s0f1: link down
[ 3547.754194] call tuxedo_wmi+ returned 0 after 8737 usecs
[ 3547.754199] calling  input14+ @ 4446, parent: tuxedo_wmi
[ 3547.754203] call input14+ returned 0 after 3 usecs
[ 3547.754206] calling  tuxedo::airplane+ @ 4446, parent: tuxedo_wmi
[ 3547.754208] call tuxedo::airplane+ returned 0 after 1 usecs
[ 3547.754211] calling  regulatory.0+ @ 4446, parent: platform
[ 3547.754213] call regulatory.0+ returned 0 after 1 usecs
[ 3547.754217] calling  input4::numlock+ @ 4446, parent: input4
[ 3547.754219] call input4::numlock+ returned 0 after 1 usecs
[ 3547.754221] calling  input4::capslock+ @ 4446, parent: input4
[ 3547.754223] call input4::capslock+ returned 0 after 1 usecs
[ 3547.754224] calling  input4::scrolllock+ @ 4446, parent: input4
[ 3547.754226] call input4::scrolllock+ returned 0 after 1 usecs
[ 3547.754228] calling  snd-soc-dummy+ @ 4446, parent: platform
[ 3547.754230] call snd-soc-dummy+ returned 0 after 1 usecs
[ 3547.754237] calling  input15+ @ 4446, parent: card0
[ 3547.754239] call input15+ returned 0 after 1 usecs
[ 3547.754241] calling  input16+ @ 4446, parent: card0
[ 3547.754243] call input16+ returned 0 after 0 usecs
[ 3547.754244] calling  input17+ @ 4446, parent: card0
[ 3547.754246] call input17+ returned 0 after 0 usecs
[ 3547.754248] calling  input18+ @ 4446, parent: card0
[ 3547.754249] call input18+ returned 0 after 0 usecs
[ 3547.754251] calling  input19+ @ 4446, parent: card0
[ 3547.754253] call input19+ returned 0 after 0 usecs
[ 3547.754255] calling  coretemp.0+ @ 4446, parent: platform
[ 3547.754258] call coretemp.0+ returned 0 after 1 usecs
[ 3547.792347] xhci_hcd 0000:00:14.0: port 4 resume PLC timeout
[ 3547.857223] iwlwifi 0000:02:00.0: L1 Enabled - LTR Disabled
[ 3547.857497] iwlwifi 0000:02:00.0: L1 Enabled - LTR Disabled
[ 3547.911173] call usb1+ returned 0 after 179806 usecs
[ 3547.911186] calling  1-6+ @ 4492, parent: usb1
[ 3547.911209] calling  1-5+ @ 4462, parent: usb1
[ 3547.936674] call phy0+ returned 0 after 204318 usecs
[ 3548.031354] usb 1-6: reset high-speed USB device number 3 using xhci_hcd
[ 3548.042131] ata1: SATA link down (SStatus 4 SControl 300)
[ 3548.213440] call 1-6+ returned 0 after 295168 usecs
[ 3548.291400] usb 1-5: reset full-speed USB device number 2 using xhci_hcd
[ 3548.484800] call 1-5+ returned 0 after 560147 usecs
[ 3548.484882] calling  input20+ @ 4446, parent: 1-6:1.0
[ 3548.484884] call input20+ returned 0 after 2 usecs
[ 3548.484886] calling  phy0-led+ @ 4446, parent: 0000:02:00.0
[ 3548.484887] call phy0-led+ returned 0 after 0 usecs
[ 3548.484888] calling  rfkill1+ @ 4446, parent: phy0
[ 3548.484889] call rfkill1+ returned 0 after 1 usecs
[ 3548.484892] PM: resume of devices complete after 758.513 msecs
[ 3548.485011] usb 1-5:1.0: rebind failed: -517
[ 3548.485012] usb 1-5:1.1: rebind failed: -517
[ 3548.485490] PM: Finishing wakeup.
[ 3548.485492] Restarting tasks ... done.
[ 3548.500534] [drm] RC6 on
[ 3548.902701] psmouse serio2: synaptics: queried max coordinates: x [..5718], y [..4908]
```
Comment 1 Paul Menzel 2017-02-01 14:48:04 UTC 
Here is the used graphics controller.

```
$ lspci -v -nn -s 00:02.0
00:02.0 VGA compatible controller [0300]: Intel Corporation Device [8086:5916] (rev 02) (prog-if 00 [VGA controller])
	Subsystem: CLEVO/KAPOK Computer Device [1558:2410]
	Flags: bus master, fast devsel, latency 0, IRQ 130
	Memory at de000000 (64-bit, non-prefetchable) [size=16M]
	Memory at c0000000 (64-bit, prefetchable) [size=256M]
	I/O ports at f000 [size=64]
	[virtual] Expansion ROM at 000c0000 [disabled] [size=128K]
	Capabilities: <access denied>
	Kernel driver in use: i915
	Kernel modules: i915
```
Comment 2 Paul Menzel 2017-02-01 14:51:34 UTC 
User *Weine* in the IRC channel #intel-gfx@irc.freenode.net asked to look at the eDP panel timings.


```
$ sudo cat /sys/kernel/debug/dri/0/eDP-1/i915_panel_timings
Panel power up delay: 200
Panel power down delay: 50
Backlight on delay: 20
Backlight off delay: 230
```
Comment 3 Paul Menzel 2017-02-02 15:45:39 UTC 
```
$ lspci -nn -v -s 0:02.0
00:02.0 VGA compatible controller [0300]: Intel Corporation Device [8086:5916] (rev 02) (prog-if 00 [VGA controller])
	Subsystem: Dell Device [1028:075b]
	Flags: bus master, fast devsel, latency 0, IRQ 285
	Memory at db000000 (64-bit, non-prefetchable) [size=16M]
	Memory at 90000000 (64-bit, prefetchable) [size=256M]
	I/O ports at f000 [size=64]
	[virtual] Expansion ROM at 000c0000 [disabled] [size=128K]
	Capabilities: <access denied>
	Kernel driver in use: i915
	Kernel modules: i915
```
Comment 4 Paul Menzel 2017-02-02 15:46:30 UTC 
Created attachment 129297 [details]
HTML output of `analyze_suspend.py`
Comment 5 Paul Menzel 2017-02-02 15:53:01 UTC 
Please ignore comment #3 and comment #4, meant for bug #99650 [1].

[1] https://bugs.freedesktop.org/show_bug.cgi?id=99650
Comment 6 David Weinehall 2017-02-07 12:38:13 UTC 
35ms suspend, 46ms resume are already quite respectable figures. This includes access to hardware, etc. I suspect this might also include loading the DMC firmware (unless you're running your system without DMC firmware, in which case it's likely to have non-functioning power management instead).
Comment 7 David Weinehall 2017-02-21 19:35:11 UTC 
If you want me to analyse this further, feel free to provide an analyse_suspend callgraph like the one in #99650.
Comment 8 Paul Menzel 2017-02-24 16:45:21 UTC 
Created attachment 129901 [details]
HTML output of `analyze_suspend.py -config config/suspend-callgraph.cfg -filter i915`

(In reply to David Weinehall from comment #7)
> If you want me to analyse this further, feel free to provide an
> analyse_suspend callgraph like the one in #99650.

Please find the output attached from a Linux kernel built from today’s latest commit from Linus’ master branch.

```
$ git describe --tag
v4.10-9579-gf1ef09f
```

The numbers are higher though.

> i915 @ 0000:00:02.0 {i915} async_device (Total Suspend: 331.893 ms Total Resume: 304.859 ms)
Comment 9 David Weinehall 2017-02-27 12:51:33 UTC 
One more thing that would be helpful is the output of:

cat /sys/kernel/debug/dri/0/eDP-1/i915_panel_timings

Looking at the suspend/resume log I make the following observations:

intel_edp_backlight_off() takes 238ms
intel_edp_panel_off() takes 52ms

332ms - 238ms - 52ms = 52ms, which is a totally reasonable suspend time.
(It should be noted here, and for the corresponding panel on/backlight on timeouts, that due to the potentially long waits we're doing ranged sleeps, not precise sleeps, meaning that these delays vary in length).

The 22ms in resume_noirq() is mostly spent in pci_power_up(), which is outside our control (it's part of the PCI subsystem; I'm no expert here, but I find it likely that the delays imposed here are mandated by specs).

The majority of the time spent in resume_early() is spent in intel_csr_load_program() loading the DMC firmware (necessary for deeper display power management). I should probably add some bad news here; it's likely that if you enable GuC submissions and also provide the HuC firmware you'll see further slowdowns, since those firmwares will also need loading.

I'm currently investigating the feasibility of loading these firmwares asynchronously, but that will only happen if we can guarantee that it doesn't introduce race conditions or unduly complicates the driver.

As for the intel_opregion_setup(), it seems that your BIOS is really slow. We're requesting BIOS data and polling for the data. On the test systems here the BIOS returns the relevant data within 1ms; on your machine it takes 18ms. I'd posit that this is a hardware issue, not a software issue.

intel_edp_panel_on() takes 201ms

This leaves us with:

274ms - 201ms - (18 - 1)ms = 57ms, which again is a perfectly cromulent figure.

So, nothing here stands out apart from the suspected BIOS read slowdown.

Use of freedesktop.org services, including Bugzilla, is subject to our Code of Conduct. How we collect and use information is described in our Privacy Policy.