Sometime fwts reports suspend duration is 0 on Ubuntu Core
Affects | Status | Importance | Assigned to | Milestone | |
---|---|---|---|---|---|
Firmware Test Suite |
Fix Released
|
Undecided
|
Unassigned |
Bug Description
System: Intel June Canyon Pentium
OS: Ubuntu Core 18
FWTS: V18.11.00 (snap version)
Command: sudo fwts s3 --s3-device-check --s3-device-
When using FWTS to run S3 stress tests, FWTS sometimes reports the duration is 0. After cross checking fwts result log and journalctl log, I found that the fwts klog message of suspend was printed at the the same time of resume one. Then I guess it could be a timing issue. fwts klog is not fast enough before the system suspended.
klog
Dec 19 02:07:07 localhost systemd[1]: Reached target Sleep.
Dec 19 02:07:07 localhost systemd[1]: Starting Suspend...
Dec 19 02:07:07 localhost systemd-
Dec 19 02:07:07 localhost kernel: PM: suspend entry (deep)
Dec 19 02:07:28 localhost kernel: PM: Syncing filesystems ... done.
Dec 19 02:07:28 localhost kernel: PM: Preparing system for sleep (deep)
Dec 19 02:07:28 localhost kernel: Freezing user space processes ... (elapsed 0.001 seconds) done.
Dec 19 02:07:28 localhost kernel: OOM killer disabled.
Dec 19 02:07:28 localhost kernel: Freezing remaining freezable tasks ... (elapsed 0.000 seconds) done.
Dec 19 02:07:28 localhost kernel: PM: Suspending system (deep)
Dec 19 02:07:28 localhost kernel: Suspending console(s) (use no_console_suspend to debug)
Dec 19 02:07:28 localhost kernel: wlan0: deauthenticating from a4:56:30:cc:0f:30 by local choice (Reason: 3=DEAUTH_LEAVING)
Dec 19 02:07:28 localhost kernel: sd 0:0:0:0: [sda] Synchronizing SCSI cache
Dec 19 02:07:28 localhost kernel: sd 0:0:0:0: [sda] Stopping disk
Dec 19 02:07:28 localhost kernel: PM: suspend of devices complete after 164.182 msecs
Dec 19 02:07:28 localhost kernel: PM: late suspend of devices complete after 19.677 msecs
Dec 19 02:07:28 localhost kernel: ACPI: EC: interrupt blocked
Dec 19 02:07:28 localhost kernel: PM: noirq suspend of devices complete after 39.706 msecs
Dec 19 02:07:28 localhost kernel: ACPI: Preparing to enter system sleep state S3
Dec 19 02:07:28 localhost kernel: ACPI: EC: event blocked
Dec 19 02:07:28 localhost kernel: ACPI: EC: EC stopped
Dec 19 02:07:28 localhost kernel: PM: Saving platform NVS memory
Dec 19 02:07:28 localhost kernel: Disabling non-boot CPUs ...
Dec 19 02:07:28 localhost kernel: smpboot: CPU 1 is now offline
Dec 19 02:07:28 localhost kernel: smpboot: CPU 2 is now offline
Dec 19 02:07:28 localhost kernel: smpboot: CPU 3 is now offline
Dec 19 02:07:28 localhost kernel: ACPI: Low-level resume complete
Dec 19 02:07:28 localhost kernel: ACPI: EC: EC started
Dec 19 02:07:28 localhost kernel: PM: Restoring platform NVS memory
Dec 19 02:07:28 localhost kernel: PM: Timekeeping suspended for 20.348 seconds
Dec 19 02:07:28 localhost kernel: Enabling non-boot CPUs ...
Dec 19 02:07:28 localhost kernel: x86: Booting SMP configuration:
Dec 19 02:07:28 localhost kernel: smpboot: Booting Node 0 Processor 1 APIC 0x2
Dec 19 02:07:28 localhost kernel: x86/cpu: Activated the Intel User Mode Instruction Prevention (UMIP) CPU feature
Dec 19 02:07:28 localhost kernel: cache: parent cpu1 should not be sleeping
Dec 19 02:07:28 localhost kernel: CPU1 is up
Dec 19 02:07:28 localhost kernel: smpboot: Booting Node 0 Processor 2 APIC 0x4
Dec 19 02:07:28 localhost kernel: x86/cpu: Activated the Intel User Mode Instruction Prevention (UMIP) CPU feature
Dec 19 02:07:28 localhost kernel: cache: parent cpu2 should not be sleeping
Dec 19 02:07:28 localhost kernel: CPU2 is up
Dec 19 02:07:28 localhost kernel: smpboot: Booting Node 0 Processor 3 APIC 0x6
Dec 19 02:07:28 localhost kernel: x86/cpu: Activated the Intel User Mode Instruction Prevention (UMIP) CPU feature
Dec 19 02:07:28 localhost kernel: cache: parent cpu3 should not be sleeping
Dec 19 02:07:28 localhost kernel: CPU3 is up
Dec 19 02:07:28 localhost kernel: ACPI: Waking up from system sleep state S3
Dec 19 02:07:28 localhost kernel: ACPI: EC: interrupt unblocked
Dec 19 02:07:28 localhost kernel: PM: noirq resume of devices complete after 39.457 msecs
Dec 19 02:07:28 localhost kernel: PM: early resume of devices complete after 4.528 msecs
Dec 19 02:07:28 localhost kernel: ACPI: EC: event unblocked
Dec 19 02:07:28 localhost kernel: sd 0:0:0:0: [sda] Starting disk
Dec 19 02:07:28 localhost kernel: r8169 0000:02:00.0 eth0: link down
Dec 19 02:07:28 localhost kernel: iwlwifi 0000:00:0c.0: Conflict between TLV & NVM regarding enabling LAR (TLV = enabled NVM =disabled)
Dec 19 02:07:28 localhost kernel: PM: resume of devices complete after 182.297 msecs
Dec 19 02:07:28 localhost kernel: acpi LNXPOWER:06: Turning OFF
Dec 19 02:07:28 localhost kernel: acpi LNXPOWER:05: Turning OFF
Dec 19 02:07:28 localhost kernel: acpi LNXPOWER:04: Turning OFF
Dec 19 02:07:28 localhost kernel: acpi LNXPOWER:03: Turning OFF
Dec 19 02:07:28 localhost kernel: acpi LNXPOWER:02: Turning OFF
Dec 19 02:07:28 localhost kernel: acpi LNXPOWER:01: Turning OFF
Dec 19 02:07:28 localhost kernel: acpi LNXPOWER:00: Turning OFF
Dec 19 02:07:28 localhost kernel: PM: Finishing wakeup.
Dec 19 02:07:28 localhost kernel: OOM killer enabled.
Dec 19 02:07:28 localhost kernel: Restarting tasks ... done.
## fwts klog - suspend
Dec 19 02:07:28 localhost fwts: Starting fwts suspend
Dec 19 02:07:28 localhost fwts: Suspend
Dec 19 02:07:28 localhost kernel: video LNXVIDEO:00: Restoring backlight state
Dec 19 02:07:28 localhost kernel: PM: suspend exit
## fwts klog - resume
Dec 19 02:07:28 localhost fwts: FWTS_RESUME
Dec 19 02:07:28 localhost fwts: Finished fwts resume
result log
19/12/18 02:07:07 [ INF ] (s3 ): S3 cycle 11 of 30
19/12/18 02:07:07 [ INF ] (s3 ): Using logind as the default power method.
19/12/18 02:07:07 [ INF ] (s3 ): Requesting Suspend action
19/12/18 02:07:28 [ INF ] (s3 ): Skipping the minimum delay (0) and using a 3 seconds delay instead
19/12/18 02:07:31 [ INF ] (s3 ): S3 duration = 0.
19/12/18 02:07:31 [ INF ] (s3 ): pm-action returned 1 after 0 seconds.
19/12/18 02:07:41 [ FAL ] (s3 ): FAILED [MEDIUM] ShortSuspend: Test 1, Unexpected: S3 slept for 0 seconds, less than the expected 20 seconds.
19/12/18 02:07:41 [ FAL ] (s3 ): FAILED [HIGH] PMActionFailedP
19/12/18 02:07:41 [ INF ] (s3 ): Suspend/Resume Timings:
19/12/18 02:07:41 [ INF ] (s3 ): Could not determine time to suspend.
19/12/18 02:07:41 [ INF ] (s3 ): Resume: 0.249 seconds.
Changed in fwts: | |
status: | Fix Committed → Fix Released |
Some possible fixes: system- sleep to delay the logind
1. use other pm method instead of logind. Confirm that sysfs works
2. add a hook in /lib/systemd/
3. change the duration computing logic as the attachment.