Bug 1195025 - kernel takes 10 seconds to configure for UDMA/133 after resume from suspend to ram
kernel takes 10 seconds to configure for UDMA/133 after resume from suspend t...
Status: NEW
Classification: openSUSE
Product: openSUSE Tumbleweed
Classification: openSUSE
Component: Kernel
Current
Other Other
: P2 - High : Normal (vote)
: ---
Assigned To: openSUSE Kernel Bugs
E-mail List
:
Depends on:
Blocks:
  Show dependency treegraph
 
Reported: 2022-01-22 18:04 UTC by Karl Mistelberger
Modified: 2022-05-04 06:42 UTC (History)
3 users (show)

See Also:
Found By: ---
Services Priority:
Business Priority:
Blocker: ---
Marketing QA Status: ---
IT Deployment: ---
tiwai: needinfo? (karl.mistelberger)


Attachments
journal -b output (289.70 KB, text/plain)
2022-02-17 12:35 UTC, Karl Mistelberger
Details
Show delay 13096s - 13110s (358.06 KB, text/plain)
2022-02-17 15:13 UTC, Karl Mistelberger
Details

Note You need to log in before you can comment on or make changes to this bug.
Description Karl Mistelberger 2022-01-22 18:04:01 UTC
For several years resume from suspend to RAM was fast. Now the service waits annoying 10 seconds for the disk spinning up:

[ 8574.889875] systemd[1]: Starting System Suspend... 
[ 8574.923429] systemd-sleep[12971]: INFO: Skip running /usr/lib/systemd/system-sleep/grub2.sleep for suspend 
[ 8574.926813] systemd-sleep[12969]: Entering sleep state 'suspend'... 
...
[ 8587.351247] systemd-sleep[13033]: INFO: Skip running /usr/lib/systemd/system-sleep/grub2.sleep for suspend 
[ 8587.355285] systemd[1]: systemd-suspend.service: Deactivated successfully. 
[ 8587.355340] systemd[1]: Finished System Suspend.
Comment 1 Franck Bui 2022-02-17 11:55:41 UTC
Can you see anything relevant in the journal ?

Does this also happen if you suspend your system with "echo mem >/sys/power/state" ?
Comment 2 Karl Mistelberger 2022-02-17 12:35:44 UTC
Created attachment 856252 [details]
journal -b  output

No delay upon running "echo mem >/sys/power/state", see attached journal.txt
Comment 3 Karl Mistelberger 2022-02-17 12:44:08 UTC
(In reply to Franck Bui from comment #1)
> Can you see anything relevant in the journal ?
Nope:
erlangen:~ # journalctl -b -o short-monotonic -u systemd-suspend.service -p debug 
[13947.866387] erlangen systemd[1]: Starting System Suspend...
[13947.883695] erlangen systemd-sleep[13738]: INFO: Skip running /usr/lib/systemd/system-sleep/grub2.sleep for suspend
[13947.885116] erlangen systemd-sleep[13736]: Entering sleep state 'suspend'...
[13960.779300] erlangen systemd-sleep[13845]: INFO: Skip running /usr/lib/systemd/system-sleep/grub2.sleep for suspend
[13960.780172] erlangen systemd[1]: systemd-suspend.service: Deactivated successfully.
[13960.780451] erlangen systemd[1]: Finished System Suspend.
[13960.780707] erlangen systemd[1]: systemd-suspend.service: Consumed 1.190s CPU time.
erlangen:~ #
Comment 4 Franck Bui 2022-02-17 14:29:55 UTC
(In reply to Karl Mistelberger from comment #3)
> (In reply to Franck Bui from comment #1)
> > Can you see anything relevant in the journal ?
> Nope:
> erlangen:~ # journalctl -b -o short-monotonic -u systemd-suspend.service -p
> debug 

Can you attach the complete output of "journalctl -b -oshort-monotonic" showing the delay of 10 seconds ?
Comment 5 Karl Mistelberger 2022-02-17 15:13:40 UTC
Created attachment 856262 [details]
Show delay 13096s - 13110s
Comment 6 Karl Mistelberger 2022-03-15 04:22:03 UTC
Evidence for 10 seconds delay. ata3.00 and ata5.00 are ready immediately at 57.4 seconds. ata4.00 lags more than 10 seconds.

erlangen:~ # journalctl -b -g ata..00 -o short-monotonic 
[    0.642425] erlangen kernel: ata4.00: ATA-9: WDC WD40EZRX-22SPEB0, 80.00A80, max UDMA/133
[    0.642793] erlangen kernel: ata4.00: 7814037168 sectors, multi 16: LBA48 NCQ (depth 32), AA
[    0.643364] erlangen kernel: ata3.00: ATA-10: CT2000BX500SSD1, M6CR030, max UDMA/133
[    0.643594] erlangen kernel: ata4.00: configured for UDMA/133
[    0.645211] erlangen kernel: ata3.00: 3907029168 sectors, multi 1: LBA48 NCQ (depth 32), AA
[    0.651638] erlangen kernel: ata3.00: Features: Dev-Sleep
[    0.655759] erlangen kernel: ata5.00: ATAPI: PIONEER DVD-RW  DVR-221, 1.00, max UDMA/100
[    0.664148] erlangen kernel: ata3.00: configured for UDMA/133
[    0.671389] erlangen kernel: ata5.00: configured for UDMA/100
[   57.418345] erlangen kernel: ata3.00: configured for UDMA/133
[   57.436200] erlangen kernel: ata5.00: configured for UDMA/100
[   68.109170] erlangen kernel: ata4.00: configured for UDMA/133
erlangen:~ #
Comment 7 Takashi Iwai 2022-04-20 15:49:10 UTC
(In reply to Karl Mistelberger from comment #0)
> For several years resume from suspend to RAM was fast. Now the service waits
> annoying 10 seconds for the disk spinning up:

So this sounds like a regression.  Since when does this problem appear?  You can try older kernels and see which kernel works or not -- narrowing down the regression range would be helpful.

Also, what I don't understand is:

(In reply to Karl Mistelberger from comment #2)
> Created attachment 856252 [details]
> journal -b  output
> 
> No delay upon running "echo mem >/sys/power/state", see attached journal.txt

You mean there is no delay if you suspend directly with sysfs as the above?
And, the problem is triggered via "systemctl suspend"?
Comment 8 Karl Mistelberger 2022-05-04 06:42:55 UTC
(In reply to Takashi Iwai from comment #7)
> (In reply to Karl Mistelberger from comment #0)
> > For several years resume from suspend to RAM was fast. Now the service waits
> > annoying 10 seconds for the disk spinning up:
> 
> So this sounds like a regression.  Since when does this problem appear?  You
> can try older kernels and see which kernel works or not -- narrowing down
> the regression range would be helpful.
> 
> Also, what I don't understand is:
> 
> (In reply to Karl Mistelberger from comment #2)
> > Created attachment 856252 [details]
> > journal -b  output
> > 
> > No delay upon running "echo mem >/sys/power/state", see attached journal.txt
> 
> You mean there is no delay if you suspend directly with sysfs as the above?
> And, the problem is triggered via "systemctl suspend"?

Double checked: No delay when drive is disabled. Delay occurs with "echo mem >/sys/power/state" and with "systemctl start systemd-suspend.service":
 
[    1.149886] kernel: ata1.00: ATA-9: WDC WD40EZRX-22SPEB0, 80.00A80, max UDMA/133
[    1.150116] kernel: ata1.00: 7814037168 sectors, multi 16: LBA48 NCQ (depth 32), AA
[    1.150706] kernel: ata1.00: configured for UDMA/133
[    1.947055] kernel: ata3.00: ATA-10: CT2000BX500SSD1, M6CR030, max UDMA/133
[    1.948957] kernel: ata3.00: 3907029168 sectors, multi 1: LBA48 NCQ (depth 32), AA
[    1.955404] kernel: ata3.00: Features: Dev-Sleep
[    1.967804] kernel: ata3.00: configured for UDMA/133
[    2.775433] kernel: ata5.00: ATAPI: PIONEER DVD-RW  DVR-221, 1.00, max UDMA/100
[    2.793114] kernel: ata5.00: configured for UDMA/100
[    5.335929] kernel: ata1.00: disable device
[ 2388.911053] kernel: ata3.00: configured for UDMA/133
[ 2388.928912] kernel: ata5.00: configured for UDMA/100
[ 2434.490356] kernel: ata1.00: ATA-9: WDC WD40EZRX-22SPEB0, 80.00A80, max UDMA/133
[ 2434.491012] kernel: ata1.00: 7814037168 sectors, multi 0: LBA48 NCQ (depth 32), AA
[ 2434.491738] kernel: ata1.00: configured for UDMA/133
[ 2451.124166] kernel: ata3.00: configured for UDMA/133
[ 2451.142077] kernel: ata5.00: configured for UDMA/100
[ 2461.089442] kernel: ata1.00: configured for UDMA/133
[ 2630.673831] kernel: ata3.00: configured for UDMA/133
[ 2630.691728] kernel: ata5.00: configured for UDMA/100
[ 2641.412946] kernel: ata1.00: configured for UDMA/133