You are not logged in.

Pages: 1

#1 2021-08-16 10:13:58

freaxtux
Member
Registered: 2012-07-17
Posts: 37

[Solved]Resuming from suspend takes 1min, dmesg shows kernel warning

[Subject edit Aug 28: "dmesg reports NVMe controller errors" -> "dmesg shows kernel warning". See 1st reply for the update]

uname -a: Linux (HOSTNAME) 5.13.10-arch1-1 #1 SMP PREEMPT Thu, 12 Aug 2021 21:59:14 +0000 x86_64 GNU/Linux
System: ASUS q407iq
CPU: Ryzen 4500U
GPU: integrated AMD graphics and discrete NVIDIA MX350. No `xf86-video-*` package installed, let alone any Optimus setup
(I didn't realize I never installed any. I guess unaccelerated video performance is still good enough o_O)
NVMe: HFM256GDJTNG-8310A by SK Hynix

dmesg log:

[  944.203299] PM: suspend entry (s2idle)
[  944.217835] Filesystems sync: 0.014 seconds
[  944.219491] Freezing user space processes ... (elapsed 0.002 seconds) done.
[  944.221563] OOM killer disabled.
[  944.221565] Freezing remaining freezable tasks ... (elapsed 0.001 seconds) done.
[  944.222922] printk: Suspending console(s) (use no_console_suspend to debug)
[  944.357903] ACPI: EC: interrupt blocked
[  960.202202] ACPI: EC: interrupt unblocked
[  960.645848] pci 0000:00:00.2: can't derive routing for PCI INT A
[  960.645855] pci 0000:00:00.2: PCI INT A: no GSI
[  960.647481] [drm] PCIE GART of 1024M enabled.
[  960.647484] [drm] PTB located at 0x000000F400900000
[  960.647500] amdgpu 0000:04:00.0: amdgpu: SMU is resuming...
[  960.648306] amdgpu 0000:04:00.0: amdgpu: dpm has been disabled
[  960.649320] amdgpu 0000:04:00.0: amdgpu: SMU is resumed successfully!
[  960.650217] [drm] DMUB hardware initialized: version=0x01010014
[  960.724389] [drm] VCN decode and encode initialized successfully(under DPG Mode).
[  960.724434] [drm] JPEG decode initialized successfully.
[  960.724444] amdgpu 0000:04:00.0: amdgpu: ring gfx uses VM inv eng 0 on hub 0
[  960.724447] amdgpu 0000:04:00.0: amdgpu: ring comp_1.0.0 uses VM inv eng 1 on hub 0
[  960.724448] amdgpu 0000:04:00.0: amdgpu: ring comp_1.1.0 uses VM inv eng 4 on hub 0
[  960.724448] amdgpu 0000:04:00.0: amdgpu: ring comp_1.2.0 uses VM inv eng 5 on hub 0
[  960.724450] amdgpu 0000:04:00.0: amdgpu: ring comp_1.3.0 uses VM inv eng 6 on hub 0
[  960.724450] amdgpu 0000:04:00.0: amdgpu: ring comp_1.0.1 uses VM inv eng 7 on hub 0
[  960.724451] amdgpu 0000:04:00.0: amdgpu: ring comp_1.1.1 uses VM inv eng 8 on hub 0
[  960.724452] amdgpu 0000:04:00.0: amdgpu: ring comp_1.2.1 uses VM inv eng 9 on hub 0
[  960.724453] amdgpu 0000:04:00.0: amdgpu: ring comp_1.3.1 uses VM inv eng 10 on hub 0
[  960.724454] amdgpu 0000:04:00.0: amdgpu: ring kiq_2.1.0 uses VM inv eng 11 on hub 0
[  960.724454] amdgpu 0000:04:00.0: amdgpu: ring sdma0 uses VM inv eng 0 on hub 1
[  960.724455] amdgpu 0000:04:00.0: amdgpu: ring vcn_dec uses VM inv eng 1 on hub 1
[  960.724456] amdgpu 0000:04:00.0: amdgpu: ring vcn_enc0 uses VM inv eng 4 on hub 1
[  960.724457] amdgpu 0000:04:00.0: amdgpu: ring vcn_enc1 uses VM inv eng 5 on hub 1
[  960.724457] amdgpu 0000:04:00.0: amdgpu: ring jpeg_dec uses VM inv eng 6 on hub 1
[  960.961368] ata2: SATA link down (SStatus 0 SControl 300)
[  960.962097] ata1: SATA link down (SStatus 0 SControl 300)
[  960.967129] r8152 2-1.1:1.0 enp4s0f3u1u1: carrier on
[ 1000.470566] nvme nvme0: I/O 1004 QID 5 timeout, aborting
[ 1000.470593] nvme nvme0: I/O 1005 QID 5 timeout, aborting
[ 1000.470600] nvme nvme0: I/O 1006 QID 5 timeout, aborting
[ 1000.470604] nvme nvme0: I/O 1007 QID 5 timeout, aborting
[ 1020.737234] nvme nvme0: I/O 19 QID 0 timeout, reset controller
[ 1020.737994] nvme nvme0: Abort status: 0x371
[ 1020.737999] nvme nvme0: Abort status: 0x371
[ 1020.738001] nvme nvme0: Abort status: 0x371
[ 1020.738003] nvme nvme0: Abort status: 0x371
[ 1020.738056] PM: dpm_run_callback(): pci_pm_resume+0x0/0xe0 returns -16
[ 1020.738078] nvme 0000:03:00.0: PM: failed to resume async: error -16
[ 1020.738747] OOM killer enabled.
[ 1020.738751] Restarting tasks ... done.
[ 1020.741091] thermal thermal_zone1: failed to read out thermal zone (-61)
[ 1020.749891] PM: suspend exit
[ 1020.752338] audit: type=1130 audit(1629105455.546:194): pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=systemd-suspend comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
[ 1020.752343] audit: type=1131 audit(1629105455.546:195): pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=systemd-suspend comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
[ 1020.752338] audit: type=1130 audit(1629105455.546:194): pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=systemd-suspend comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
[ 1020.752343] audit: type=1131 audit(1629105455.546:195): pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=systemd-suspend comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
[ 1020.772421] nvme nvme0: 16/0/0 default/read/poll queues

Lines of significance:
Suspend started @ [  944.203299] PM: suspend entry (s2idle)
Power button pressed ~16s later @ [  960.202202] ACPI: EC: interrupt unblocked
NVMe timeout reported @ [ 1000.470566] nvme nvme0: I/O 1004 QID 5 timeout, aborting
NVMe controller reset @ [ 1020.737234] nvme nvme0: I/O 19 QID 0 timeout, reset controller

At first I thought key input was not getting registered, and now I am concerned if this is stressing NVMe and/or NVMe is dying : (
Any insights or solutions appreciated.

Last edited by freaxtux (2021-09-11 05:03:02)

Offline

#2 2021-08-28 10:36:58

freaxtux
Member
Registered: 2012-07-17
Posts: 37

Re: [Solved]Resuming from suspend takes 1min, dmesg shows kernel warning

Problem still present almost 2 weeks later.

Linux kernel updated from 5.13.10 to 5.13.13-arch1-1
xf86-video-amdgpu installed.
Mainboard firmware updated from 302 to 303

The SSD, often dubbed as PG501, has 80001C00 firmware, and doesn't have firmware update available from Asus.
Tried to apply 80003C00 firmware from HP and Dell, but both updaters refused to work on my system
(Windows executables, each reporting "... I/O device error ... [0x45D]" and "Unsupported model name").

[   48.837002] PM: suspend entry (s2idle)
[   48.848630] Filesystems sync: 0.011 seconds
[   48.850110] Freezing user space processes ... (elapsed 0.002 seconds) done.
[   48.852134] OOM killer disabled.
[   48.852135] Freezing remaining freezable tasks ... (elapsed 0.000 seconds) done.
[   48.852945] printk: Suspending console(s) (use no_console_suspend to debug)
[   49.012257] ACPI: EC: interrupt blocked
[   64.501368] ACPI: EC: interrupt unblocked
[   64.926679] ------------[ cut here ]------------
[   64.926683] WARNING: CPU: 2 PID: 1276 at kernel/irq/chip.c:210 irq_startup+0x10d/0x130
[   64.926697] Modules linked in: rtsx_usb_sdmmc hid_logitech_hidpp mmc_core rtsx_usb_ms memstick r8153_ecm cdc_ether usbnet uas r8152 usb_storage mii rtsx_usb ftdi_sio hid_logitech_dj btusb btrtl btbcm btintel bluetooth usbhid uvcvideo j
oydev ecdh_generic mousedev videobuf2_vmalloc intel_rapl_msr ecc videobuf2_memops videobuf2_v4l2 videobuf2_common asus_nb_wmi videodev asus_wmi hid_multitouch sparse_keymap wmi_bmof intel_rapl_common mc edac_mce_amd kvm_amd kvm irqbypass 
crct10dif_pclmul crc32_pclmul ghash_clmulni_intel aesni_intel crypto_simd cryptd rapl pcspkr iwlmvm snd_hda_codec_realtek snd_hda_codec_generic ledtrig_audio snd_hda_codec_hdmi mac80211 snd_hda_intel snd_intel_dspcfg snd_intel_sdw_acpi am
dgpu libarc4 snd_hda_codec nouveau iwlwifi snd_hda_core snd_hwdep snd_pcm gpu_sched k10temp mxm_wmi i2c_algo_bit drm_ttm_helper sp5100_tco snd_rn_pci_acp3x vfat ttm i2c_piix4 fat snd_pci_acp3x snd_timer ccp cfg80211 drm_kms_helper snd sou
ndcore cec syscopyarea sysfillrect tpm_crb sysimgblt
[   64.926793]  rfkill fb_sys_fops mac_hid wmi tpm_tis tpm_tis_core tpm video i2c_hid_acpi i2c_hid amd_pmc rng_core acpi_cpufreq pinctrl_amd sg drm crypto_user acpi_call(OE) fuse agpgart bpf_preload ip_tables x_tables ext4 crc32c_generic crc16 mbcache jbd2 serio_raw atkbd libps2 i8042 xhci_pci crc32c_intel xhci_pci_renesas serio
[   64.926831] CPU: 2 PID: 1276 Comm: systemd-sleep Tainted: G           OE     5.13.13-arch1-1 #1
[   64.926836] Hardware name: ASUSTeK COMPUTER INC. ZenBook UX434IQ_Q407IQ/UX434IQ, BIOS UX434IQ_Q407IQ.303 03/10/2021
[   64.926838] RIP: 0010:irq_startup+0x10d/0x130
[   64.926844] Code: f6 4c 89 e7 e8 e4 40 00 00 85 c0 75 2b 4c 89 e7 31 d2 4c 89 ee e8 23 c3 ff ff 48 89 ef e8 8b fe ff ff 41 89 c4 e9 25 ff ff ff <0f> 0b e9 63 ff ff ff e8 47 c8 ff ff eb 97 0f 0b e9 55 ff ff ff 66
[   64.926847] RSP: 0018:ffffb9944348bcb8 EFLAGS: 00010002
[   64.926851] RAX: 0000000000000140 RBX: 0000000000000001 RCX: 0000000000000140
[   64.926853] RDX: 0000000000000004 RSI: ffffffffae9f7920 RDI: ffff9b70835ebc18
[   64.926855] RBP: ffff9b70835ebc00 R08: 0000000000000000 R09: 0000000000000000
[   64.926857] R10: 0000000000000140 R11: 0000000000000000 R12: 0000000000000001
[   64.926859] R13: ffff9b70835ebc18 R14: ffff9b70835ebce4 R15: 0000000000000000
[   64.926861] FS:  00007f4d7cf0ba40(0000) GS:ffff9b71a7680000(0000) knlGS:0000000000000000
[   64.926864] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[   64.926866] CR2: 00007f715c06b09c CR3: 0000000104272000 CR4: 0000000000350ee0
[   64.926869] Call Trace:
[   64.926875]  resume_irqs+0xc7/0x110
[   64.926881]  dpm_resume_noirq+0xf/0x20
[   64.926889]  suspend_devices_and_enter+0x32c/0x7f0
[   64.926896]  pm_suspend.cold+0x329/0x374
[   64.926901]  state_store+0x71/0xd0
[   64.926908]  kernfs_fop_write_iter+0x11c/0x1b0
[   64.926914]  new_sync_write+0x159/0x1f0
[   64.926921]  vfs_write+0x1db/0x270
[   64.926926]  ksys_write+0x67/0xe0
[   64.926929]  do_syscall_64+0x61/0x80
[   64.926936]  ? exc_page_fault+0x78/0x180
[   64.926940]  entry_SYSCALL_64_after_hwframe+0x44/0xae
[   64.926947] RIP: 0033:0x7f4d7d8c5907
[   64.926951] Code: 0d 00 f7 d8 64 89 02 48 c7 c0 ff ff ff ff eb b7 0f 1f 00 f3 0f 1e fa 64 8b 04 25 18 00 00 00 85 c0 75 10 b8 01 00 00 00 0f 05 <48> 3d 00 f0 ff ff 77 51 c3 48 83 ec 28 48 89 54 24 18 48 89 74 24
[   64.926954] RSP: 002b:00007ffe4755a918 EFLAGS: 00000246 ORIG_RAX: 0000000000000001
[   64.926957] RAX: ffffffffffffffda RBX: 0000000000000004 RCX: 00007f4d7d8c5907
[   64.926959] RDX: 0000000000000004 RSI: 00007ffe4755aa00 RDI: 0000000000000004
[   64.926961] RBP: 00007ffe4755aa00 R08: 000055e5e7574180 R09: 00007f4d7d95b4e0
[   64.926963] R10: 00007f4d7d95b3e0 R11: 0000000000000246 R12: 0000000000000004
[   64.926964] R13: 000055e5e75703c0 R14: 0000000000000004 R15: 00007f4d7d997700
[   64.926968] ---[ end trace c1af87a183fe7161 ]---
[   64.928559] pci 0000:00:00.2: can't derive routing for PCI INT A
[   64.928566] pci 0000:00:00.2: PCI INT A: no GSI
[   64.931156] [drm] PCIE GART of 1024M enabled.
[   64.931162] [drm] PTB located at 0x000000F400900000
[   64.931180] amdgpu 0000:04:00.0: amdgpu: SMU is resuming...
[   64.931534] amdgpu 0000:04:00.0: amdgpu: dpm has been disabled
[   64.932538] amdgpu 0000:04:00.0: amdgpu: SMU is resumed successfully!
[   64.933441] [drm] DMUB hardware initialized: version=0x01010019
[   65.007408] [drm] VCN decode and encode initialized successfully(under DPG Mode).
[   65.007609] [drm] JPEG decode initialized successfully.
[   65.007724] amdgpu 0000:04:00.0: amdgpu: ring gfx uses VM inv eng 0 on hub 0
[   65.007728] amdgpu 0000:04:00.0: amdgpu: ring comp_1.0.0 uses VM inv eng 1 on hub 0
[   65.007730] amdgpu 0000:04:00.0: amdgpu: ring comp_1.1.0 uses VM inv eng 4 on hub 0
[   65.007732] amdgpu 0000:04:00.0: amdgpu: ring comp_1.2.0 uses VM inv eng 5 on hub 0
[   65.007733] amdgpu 0000:04:00.0: amdgpu: ring comp_1.3.0 uses VM inv eng 6 on hub 0
[   65.007735] amdgpu 0000:04:00.0: amdgpu: ring comp_1.0.1 uses VM inv eng 7 on hub 0
[   65.007736] amdgpu 0000:04:00.0: amdgpu: ring comp_1.1.1 uses VM inv eng 8 on hub 0
[   65.007738] amdgpu 0000:04:00.0: amdgpu: ring comp_1.2.1 uses VM inv eng 9 on hub 0
[   65.007739] amdgpu 0000:04:00.0: amdgpu: ring comp_1.3.1 uses VM inv eng 10 on hub 0
[   65.007742] amdgpu 0000:04:00.0: amdgpu: ring kiq_2.1.0 uses VM inv eng 11 on hub 0
[   65.007743] amdgpu 0000:04:00.0: amdgpu: ring sdma0 uses VM inv eng 0 on hub 1
[   65.007745] amdgpu 0000:04:00.0: amdgpu: ring vcn_dec uses VM inv eng 1 on hub 1
[   65.007746] amdgpu 0000:04:00.0: amdgpu: ring vcn_enc0 uses VM inv eng 4 on hub 1
[   65.007748] amdgpu 0000:04:00.0: amdgpu: ring vcn_enc1 uses VM inv eng 5 on hub 1
[   65.007749] amdgpu 0000:04:00.0: amdgpu: ring jpeg_dec uses VM inv eng 6 on hub 1
[   65.246223] ata2: SATA link down (SStatus 0 SControl 300)
[   65.247083] ata1: SATA link down (SStatus 0 SControl 300)
[  126.079971] nvme nvme0: I/O 961 QID 3 timeout, aborting
[  126.079972] nvme nvme0: I/O 14 QID 0 timeout, reset controller
[  126.079993] nvme nvme0: I/O 962 QID 3 timeout, aborting
[  126.079998] nvme nvme0: I/O 963 QID 3 timeout, aborting
[  126.080017] nvme nvme0: I/O 964 QID 3 timeout, aborting
[  126.080684] PM: dpm_run_callback(): pci_pm_resume+0x0/0xe0 returns -16
[  126.080700] nvme nvme0: Abort status: 0x371
[  126.080710] nvme 0000:03:00.0: PM: failed to resume async: error -16
[  126.080712] nvme nvme0: Abort status: 0x371
[  126.080715] nvme nvme0: Abort status: 0x371
[  126.080716] nvme nvme0: Abort status: 0x371
[  126.081246] OOM killer enabled.
[  126.081250] Restarting tasks ... done.
[  126.087966] audit: type=1131 audit(1630131923.583:112): pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=NetworkManager-dispatcher comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
[  126.088090] PM: suspend exit
[  126.088805] audit: type=1131 audit(1630131923.583:113): pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=geoclue comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
[  126.089551] audit: type=1130 audit(1630131923.583:114): pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=systemd-suspend comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
[  126.089559] audit: type=1131 audit(1630131923.583:115): pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=systemd-suspend comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
[  126.120288] nvme nvme0: 16/0/0 default/read/poll queues
[  126.121378] IPv6: ADDRCONF(NETDEV_CHANGE): enp4s0f3u1u1: link becomes ready
[  126.121581] r8152 2-1.1:1.0 enp4s0f3u1u1: carrier on
[  126.198361] audit: type=1130 audit(1630131923.693:116): pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=NetworkManager-dispatcher comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
[  126.776237] nouveau 0000:01:00.0: bus: MMIO read of 00000000 FAULT at 6013d4 [ PRIVRING ]

Notable lines:
Suspend started @ [   48.837002] PM: suspend entry (s2idle)
Suspend ended ~16s later @ [   64.501368] ACPI: EC: interrupt unblocked
Kernel shows warning with call trace now @ from [   64.926679] ------------[ cut here ]------------ to [   64.926968] ---[ end trace c1af87a183fe7161 ]---
NVMe timeout reported @ [  126.079971] nvme nvme0: I/O 961 QID 3 timeout, aborting
NVMe controller reset @ [  126.079972] nvme nvme0: I/O 14 QID 0 timeout, reset controller

Offline

#3 2021-08-28 13:01:29

seth
Member
Registered: 2012-09-03
Posts: 51,826

Re: [Solved]Resuming from suspend takes 1min, dmesg shows kernel warning

Renoir?
https://lore.kernel.org/linux-acpi/CAJZ … gmail.com/

How to upload text · How to boot w/o GUI · Disable Windows Fast-Start! · Fix your xinitrc

Offline

#4 2021-08-28 15:19:19

freaxtux
Member
Registered: 2012-07-17
Posts: 37

Re: [Solved]Resuming from suspend takes 1min, dmesg shows kernel warning

seth wrote:

Huh, that indeed seems to be the case. Thank you.
Looks like I'll have to wait until kernel v5.14 (before and after)

I'll try to remember and test when it arrives, and mark solved once I verify it

Last edited by freaxtux (2021-08-28 15:21:56)

Offline

#5 2021-09-11 05:07:34

freaxtux
Member
Registered: 2012-07-17
Posts: 37

Re: [Solved]Resuming from suspend takes 1min, dmesg shows kernel warning

Kernel updated to 5.14.2
I just tested and the system wakes up right away. Thanks :)

Offline

Pages: 1

Board footer

Powered by FluxBB