lkml.org 
[lkml]   [2024]   [May]   [17]   [last100]   RSS Feed
Views: [wrap][no wrap]   [headers]  [forward] 
 
Messages in this thread
/
From
SubjectRe: [regression] suspend stress test stalls within 30 minutes
Date
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.

\
 
 \ /
  Last update: 2024-05-27 18:30    [W:0.088 / U:0.888 seconds]
©2003-2020 Jasper Spaans|hosted at Digital Ocean and TransIP|Read the blog|Advertise on this site