Re: [regression] suspend stress test stalls within 30 minutes

[Pawan Gupta]

On Fri, May 17, 2024 at 08:41:41PM +0300, Kalle Valo wrote:
> There is no special workload when I reproduce the bug. This NUC box is
> one of our test setups which I use to test ath11k and ath12k wireless
> drivers, but when I'm debugging this suspend issue none of the wireless
> drivers are not even loaded. I don't normally have a display connected
> to the box but I do run netconsole, although I just verified that I see
> the bug if I remove netconsole configuration from cmdline.
> 
> The distro is Ubuntu 20.04.6 LTS. Oh, but I do have installed a WCN6855
> PCI module to the box so that I can test ath11k. That can of course make
> a difference. And maybe also BIOS settings?
> 
> I think is easiest if I try get more info about with my box first, it
> might be quite challenging for you to reproduce it.

When I enable ftrace I see similar behavior where the system fails to
suspend. I am not fully sure if I have reproduced the same issue, but the
symptoms do look similar. The test setup is undergoing some maintenance by
the lab people, so I my debugging is paused for now. I will resume
debugging once I get the setup back.

Below is how I reproduced it fairly quickly:

# trace-cmd start -p function -e power -e msr
# cat /sys/kernel/debug/tracing/trace_pipe > trace.log &
# for i in {1..400}; do echo "rtcwake test $i" > /dev/kmsg; rtcwake -m mem -s 10; sleep 10; done

Cmdline: BOOT_IMAGE=/boot/vmlinuz-6.9.0-rc7-test+ root=UUID=77593d83-f3ee-4a03-8f8d-12344ec878ec ro console=tty1 console=ttyS0 no_console_suspend ignore_loglevel sysrq_always_enabled systemd.unit=multi-user.target

Last kernel logs:

[...]
rtcwake test 1
PM: suspend entry (deep)
Filesystems sync: 0.000 seconds
Freezing user space processes
Freezing user space processes completed (elapsed 0.001 seconds)
OOM killer disabled.
Freezing remaining freezable tasks
Freezing remaining freezable tasks completed (elapsed 0.001 seconds)
e1000e: EEE TX LPI TIMER: 00000011
sd 2:0:0:0: [sda] Synchronizing SCSI cache
ata3.00: Entering standby power mode
ACPI: EC: interrupt blocked
ACPI: PM: Preparing to enter system sleep state S3
ACPI: EC: event blocked
ACPI: EC: EC stopped
ACPI: PM: Saving platform NVS memory
Disabling non-boot CPUs ...
smpboot: CPU 1 is now offline
smpboot: CPU 2 is now offline
smpboot: CPU 3 is now offline
smpboot: CPU 4 is now offline
smpboot: CPU 5 is now offline
smpboot: CPU 6 is now offline
smpboot: CPU 7 is now offline
ACPI: PM: Low-level resume complete
ACPI: EC: EC started
ACPI: PM: Restoring platform NVS memory
Enabling non-boot CPUs ...
smpboot: Booting Node 0 Processor 1 APIC 0x2
CPU1 is up
smpboot: Booting Node 0 Processor 2 APIC 0x4
CPU2 is up
smpboot: Booting Node 0 Processor 3 APIC 0x6
CPU3 is up
smpboot: Booting Node 0 Processor 4 APIC 0x1
CPU4 is up
smpboot: Booting Node 0 Processor 5 APIC 0x3
CPU5 is up
smpboot: Booting Node 0 Processor 6 APIC 0x5
CPU6 is up
smpboot: Booting Node 0 Processor 7 APIC 0x7
CPU7 is up
ACPI: PM: Waking up from system sleep state S3
ACPI: button: The lid device is not compliant to SW_LID.
ACPI: EC: interrupt unblocked
sunrisepoint-pinctrl INT345D:00: restored pin 103 padcfg0 0x000000
sunrisepoint-pinctrl INT345D:00: restored pin 103 padcfg1 0x00001f
sunrisepoint-pinctrl INT345D:00: restored pin 118 padcfg0 0x000000
sunrisepoint-pinctrl INT345D:00: restored pin 118 padcfg1 0x00002e
ACPI: EC: event unblocked
i915 0000:00:02.0: [drm] [ENCODER:94:DDI B/PHY B] is disabled/in DSI mode with an ungated DDI clock, gate it
i915 0000:00:02.0: [drm] [ENCODER:111:DDI C/PHY C] is disabled/in DSI mode with an ungated DDI clock, gate it
i915 0000:00:02.0: [drm] [ENCODER:115:DDI D/PHY D] is disabled/in DSI mode with an ungated DDI clock, gate it
serial 00:07: activated
ata3: SATA link up 6.0 Gbps (SStatus 133 SControl 300)
ata4: SATA link down (SStatus 4 SControl 300)
sd 2:0:0:0: [sda] Starting disk
ata3.00: configured for UDMA/133
mei_hdcp 0000:00:16.0-b638ab7e-94e2-4ea2-a552-d1c54b627f04: bound 0000:00:02.0 (ops i915_hdcp_ops)
OOM killer enabled.
Restarting tasks ... done.
random: crng reseeded on system resumption
atkbd serio0: Failed to deactivate keyboard on isa0060/serio0
PM: suspend exit
atkbd serio0: Failed to enable keyboard on isa0060/serio0
e1000e 0000:00:1f.6 enp0s31f6: NIC Link is Up 1000 Mbps Full Duplex, Flow Control: None
rtcwake test 2