Bugzilla – Bug 1195025
kernel takes 10 seconds to configure for UDMA/133 after resume from suspend to ram
Last modified: 2022-05-04 06:42:55 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.
Can you see anything relevant in the journal ? Does this also happen if you suspend your system with "echo mem >/sys/power/state" ?
Created attachment 856252 [details] journal -b output No delay upon running "echo mem >/sys/power/state", see attached journal.txt
(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:~ #
(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 ?
Created attachment 856262 [details] Show delay 13096s - 13110s
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:~ #
(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"?
(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