Sometime fwts reports suspend duration is 0 on Ubuntu Core

[Robert Liu]

System: Intel June Canyon Pentium
OS: Ubuntu Core 18
FWTS: V18.11.00 (snap version)
Command: sudo fwts s3 --s3-device-check --s3-device-check-delay=10 --s3-sleep-delay=20 --s3-multiple=30 --log-level=all --stdout-summary -r /var/snap/fwts/common/result-$(date +"%s").log --log-format="%date %time [ %field] (%owner): " -w 200 --pm-method logind -j /snap/fwts/current/share/fwts

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-sleep[5009]: Suspending system...
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] PMActionFailedPreS3: Test 1, pm-action failed before trying to put the system in the requested power saving state.
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.

[Robert Liu (robertliu)]

Some possible fixes:
1. use other pm method instead of logind. Confirm that sysfs works
2. add a hook in /lib/systemd/system-sleep to delay the logind
3. change the duration computing logic as the attachment.

[Alex Hung (alexhung)]

@robertliu,

Please generate and sign a git patch and send it (with git send-email) to <email address hidden> for review

[Alex Hung (alexhung)]

Patch was submitted (http://patchwork.ozlabs.org/patch/1024334/)