Messages in this thread | | | From | Kalle Valo <> | Subject | Re: [regression] suspend stress test stalls within 30 minutes | Date | Fri, 17 May 2024 21:37:44 +0300 |
| |
Dave Hansen <dave.hansen@intel.com> writes:
> On 5/17/24 10:15, Kalle Valo wrote: >> Borislav Petkov <bp@alien8.de> writes: >>> There might be some #GP or so in the logs in case we've managed to f*ck >>> up microcode application which emulates that IBRS MSR bit and the >>> actual toggling or so when suspending... >> So the weird part is that when the bug happens (ie. suspend stalls) I >> can access the box normally using ssh and I don't see anything special >> in dmesg. Below is a full copy of dmesg output after the suspend >> stalled. Do note that I copied this dmesg before I updated microcode so >> it will still show the old microcode version. >> >> Let me know if you need more info. > > Kalle, could you remind us what we're seeing here? Does this show 30 > working rtcwake tests followed by a failure at "rtcwake test 31" where > the system failed to suspend?
Correct. So basically what I do is that I start the nuc box, ssh into it and run:
sudo su for i in {1..400}; do echo "rtcwake test $i" > /dev/kmsg; rtcwake -m mem -s 10; sleep 10; done
Here's the start of first loop:
[ 54.945105] rtcwake test 1 [ 55.162603] PM: suspend entry (deep) [ 55.168875] Filesystems sync: 0.006 seconds [ 55.182427] Freezing user space processes [ 55.191498] Freezing user space processes completed (elapsed 0.008 seconds) [ 55.191711] OOM killer disabled. [ 55.191805] Freezing remaining freezable tasks [ 55.193507] Freezing remaining freezable tasks completed (elapsed 0.001 seconds) [ 55.194056] printk: Suspending console(s) (use no_console_suspend to debug) [ 55.244962] e1000e: EEE TX LPI TIMER: 00000011
Now I leave the box to run it's test. I come back later to see that the for loop has stalled and the box is not going into suspend gain. I ssh into the machine and see this in dmesg:
[ 449.061525] rtcwake test 31 [ 449.176854] PM: suspend entry (deep) [ 449.179072] Filesystems sync: 0.002 seconds [ 632.961545] loop0: detected capacity change from 0 to 8 [ 637.003835] gpu-manager (6735) used greatest stack depth: 23808 bytes left [ 738.799026] kworker/dying (87) used greatest stack depth: 23488 bytes left [ 932.951032] loop0: detected capacity change from 0 to 8 [ 1232.962610] loop0: detected capacity change from 0 to 8
The system tried go into suspend but after the "Filesystems sync:" message nothing happened for 10 minutes. I assume loop0 messages are from some Ubuntu daemon, maybe snapd or similar. I have seen them always, they are not specific to this issue.
And now comes the really strange part: if I run 'shutdown -h now' the suspend continues apparently normally. Afterwards I checked from /var/log/kern.log and didn't see any errors:
May 17 13:34:38 nuc2 kernel: [ 449.176854] PM: suspend entry (deep) May 17 13:34:38 nuc2 kernel: [ 449.179072] Filesystems sync: 0.002 seconds May 17 13:37:42 nuc2 kernel: [ 632.961545] loop0: detected capacity change from 0 to 8 May 17 13:37:46 nuc2 kernel: [ 637.003835] gpu-manager (6735) used greatest stack depth: 23808 bytes left May 17 13:39:28 nuc2 kernel: [ 738.799026] kworker/dying (87) used greatest stack depth: 23488 bytes left May 17 13:42:42 nuc2 kernel: [ 932.951032] loop0: detected capacity change from 0 to 8 May 17 13:47:42 nuc2 kernel: [ 1232.962610] loop0: detected capacity change from 0 to 8 May 17 13:52:45 nuc2 kernel: [ 1527.307800] Freezing user space processes May 17 13:52:45 nuc2 kernel: [ 1527.334585] Freezing user space processes completed (elapsed 0.024 seconds) May 17 13:52:45 nuc2 kernel: [ 1527.336094] OOM killer disabled. May 17 13:52:45 nuc2 kernel: [ 1527.337562] Freezing remaining freezable tasks May 17 13:52:45 nuc2 kernel: [ 1527.340324] Freezing remaining freezable tasks completed (elapsed 0.001 seconds) May 17 13:52:45 nuc2 kernel: [ 1527.342596] printk: Suspending console(s) (use no_console_suspend to debug) May 17 13:52:45 nuc2 kernel: [ 1527.380121] e1000e: EEE TX LPI TIMER: 00000011 May 17 13:52:45 nuc2 kernel: [ 1527.474981] ACPI: EC: interrupt blocked May 17 13:52:45 nuc2 kernel: [ 1527.540696] ACPI: PM: Preparing to enter system sleep state S3 May 17 13:52:45 nuc2 kernel: [ 1527.567302] ACPI: EC: event blocked May 17 13:52:45 nuc2 kernel: [ 1527.567307] ACPI: EC: EC stopped May 17 13:52:45 nuc2 kernel: [ 1527.567311] ACPI: PM: Saving platform NVS memory May 17 13:52:45 nuc2 kernel: [ 1527.567412] Disabling non-boot CPUs ...
While writing this email I found another way to continue the suspend after a stall: terminate rtcwake with CTRL-C in the ssh session running the for loop. That explains why 'sudo shutdown -h now' makes the suspend go forward, it most likely kills the stalled rtcwake process.
| |