`nvme_disable_ctrl()` takes 411 ms on a Dell XPS 13 with SK hynix PC300 NVMEe

Paul Menzel pmenzel at molgen.mpg.de
Tue Apr 30 21:29:12 PDT 2024 

Dear Linux folks,


On the Dell XPS 13 9360 with a PC300 NVMe SK hynix 512GB

     $ sudo dmesg | grep -e "DMI:" -e "Linux version" -e microcode
     [    0.000000] Linux version 6.9.0-rc6-00046-g18daea77cca6 
(build at bohemianrhapsody.molgen.mpg.de) (gcc (Debian 13.2.0-23) 13.2.0, 
GNU ld (GNU Binutils for Debian) 2.42) #127 SMP PREEMPT_DYNAMIC Tue Apr 
30 21:55:07 CEST 2024
     [    0.000000] DMI: Dell Inc. XPS 13 9360/0596KF, BIOS 2.21.0 
06/02/2022
     [    0.370665] microcode: Current revision: 0x000000f4
     [    0.370667] microcode: Updated early from: 0x000000f0
     [  794.810669] Calling microcode_bsp_resume+0x0/0xd0
     [  989.533146] Calling microcode_bsp_resume+0x0/0xd0

     $ lsblk -N
     NAME    TYPE MODEL                     SERIAL                 REV 
TRAN   RQ-SIZE  MQ
     nvme0n1 disk PC300 NVMe SK hynix 512GB FS6BN01071010B54P 20004A00 
nvme      1023   4
     $ sudo nvme list
     Node                  Generic               SN 
Model                                    Namespace  Usage 
       Format           FW Rev
     --------------------- --------------------- -------------------- 
---------------------------------------- ---------- 
-------------------------- ---------------- --------
     /dev/nvme0n1          /dev/ng0n1            FS6BN01071010B54P 
PC300 NVMe SK hynix 512GB                0x1        512.11  GB / 512.11 
GB    512   B +  0 B   20004A00

benchmarking suspend and resume with `sudo ./analyze_suspend.py -f` [1], 
`nvme_disable_ctrl()` takes 400 ms:

       988.751855 |   2)  kworker-4882  |               | 
nvme_disable_ctrl [nvme_core]() {
     […]
       989.162790 |   2)  kworker-4882  |   410934.5 us |          } /* 
nvme_disable_ctrl [nvme_core] */

Could a warning be logged, when this takes more than 50 ms with a hint 
that the disk vendor should improve their firmware?


[1]: https://github.com/intel/pm-graph
-------------- next part --------------
# suspend-050124-050530 abreu mem 6.9.0-rc6-00046-g18daea77cca6
# sysinfo | man:Dell Inc. | plat:XPS 13 9360 | cpu:Intel(R) Core(TM) i7-7500U CPU @ 2.70GHz | bios:2.21.0 | biosdate:06/02/2022 | numcpu:4 | memsz:15934724 | memfr:6457120 | os:Debian GNU/Linux trixie/sid
# command | analyze_suspend.py -f
# fwsuspend 0 fwresume 1069300
[  988.543689] PM: suspend entry (deep)
[  988.550787] Filesystems sync: 0.007 seconds
[  988.556348] Freezing user space processes
[  988.596014] Freezing user space processes completed (elapsed 0.039 seconds)
[  988.596052] OOM killer disabled.
[  988.596080] Freezing remaining freezable tasks
[  988.601766] Freezing remaining freezable tasks completed (elapsed 0.005 seconds)
[  988.601900] printk: Suspending console(s) (use no_console_suspend to debug)
[  988.621780] wlp58s0: deauthenticating from 88:71:b1:81:93:1b by local choice (Reason: 3=DEAUTH_LEAVING)
[  989.169191] PM: suspend of devices complete after 548.040 msecs
[  989.169222] PM: start suspend of devices complete after 567.175 msecs
[  989.216983] PM: late suspend of devices complete after 47.748 msecs
[  989.228745] ACPI: EC: interrupt blocked
[  989.306218] PM: noirq suspend of devices complete after 88.059 msecs
[  989.306260] ACPI: PM: Preparing to enter system sleep state S3
[  989.503508] ACPI: EC: event blocked
[  989.503526] ACPI: EC: EC stopped
[  989.503543] ACPI: PM: Saving platform NVS memory
[  989.505256] Disabling non-boot CPUs ...
[  989.507688] smpboot: CPU 1 is now offline
[  989.515131] smpboot: CPU 2 is now offline
[  989.519983] smpboot: CPU 3 is now offline
[  989.522691] Checking wakeup interrupts
[  989.522731] Calling kvm_suspend+0x0/0x40 [kvm]
[  989.522833] Calling intel_epb_save+0x0/0x30
[  989.522861] Calling mce_syscore_suspend+0x0/0x20
[  989.522886] Calling ledtrig_cpu_syscore_suspend+0x0/0x20
[  989.522915] Calling timekeeping_suspend+0x0/0x2f0
[  989.523082] Calling save_ioapic_entries+0x0/0xd0
[  989.524373] Calling i8259A_suspend+0x0/0x30
[  989.524405] Calling fw_suspend+0x0/0x20
[  989.524429] Calling acpi_save_bm_rld+0x0/0x30
[  989.524463] Calling lapic_suspend+0x0/0x160
[  989.529976] ACPI: PM: Low-level resume complete
[  989.530034] ACPI: EC: EC started
[  989.530038] ACPI: PM: Restoring platform NVS memory
[  989.531228] Calling init_counter_refs+0x0/0x40
[  989.531252] Calling lapic_resume+0x0/0x220
[  989.531319] Calling acpi_restore_bm_rld+0x0/0x70
[  989.531346] Calling irqrouter_resume+0x0/0x50
[  989.531367] Calling i8259A_resume+0x0/0x40
[  989.531557] Calling ioapic_resume+0x0/0xc0
[  989.531819] Calling irq_pm_syscore_resume+0x0/0x20
[  989.532855] Calling timekeeping_resume+0x0/0x1e0
[  989.533008] Timekeeping suspended for 14.174 seconds
[  989.533058] Calling ledtrig_cpu_syscore_resume+0x0/0x20
[  989.533082] Calling mce_syscore_resume+0x0/0x30
[  989.533125] Calling intel_epb_restore+0x0/0x90
[  989.533146] Calling microcode_bsp_resume+0x0/0xd0
[  989.533168] Calling kvm_resume+0x0/0x60 [kvm]
[  989.533255] PM: Triggering wakeup from IRQ 51
[  989.533299] Enabling non-boot CPUs ...
[  989.533554] smpboot: Booting Node 0 Processor 1 APIC 0x2
[  989.535107] CPU1 is up
[  989.535355] smpboot: Booting Node 0 Processor 2 APIC 0x1
[  989.537199] CPU2 is up
[  989.537443] smpboot: Booting Node 0 Processor 3 APIC 0x3
[  989.539014] CPU3 is up
[  989.545084] ACPI: PM: Waking up from system sleep state S3
[  990.591691] ACPI: EC: interrupt unblocked
[  990.623101] PM: noirq resume of devices complete after 31.933 msecs
[  990.624873] PM: early resume of devices complete after 1.517 msecs
[  990.625382] ACPI: EC: event unblocked
[  990.641114] nvme nvme0: 4/0/0 default/read/poll queues
[  990.658018] i915 0000:00:02.0: [drm] [ENCODER:94:DDI A/PHY A] is disabled/in DSI mode with an ungated DDI clock, gate it
[  990.669995] i915 0000:00:02.0: [drm] [ENCODER:102:DDI B/PHY B] is disabled/in DSI mode with an ungated DDI clock, gate it
[  990.773737] i915 0000:00:02.0: [drm] [ENCODER:113:DDI C/PHY C] is disabled/in DSI mode with an ungated DDI clock, gate it
[  990.902881] usb 1-4: reset full-speed USB device number 3 using xhci_hcd
[  991.034511] ACPI Debug:  "iGfx Supported Functions Bitmap "
[  991.190678] usb 1-5: reset high-speed USB device number 4 using xhci_hcd
[  991.467237] usb 1-3: reset full-speed USB device number 2 using xhci_hcd
[  991.617916] PM: resume of devices complete after 993.226 msecs
[  991.650442] OOM killer enabled.
[  991.650470] Restarting tasks ... done.
[  991.694503] random: crng reseeded on system resumption
[  991.846758] mei_hdcp 0000:00:16.0-b638ab7e-94e2-4ea2-a552-d1c54b627f04: bound 0000:00:02.0 (ops i915_hdcp_ops [i915])
[  991.925783] wlp58s0: authenticate with 88:71:b1:81:93:1a (local address=9c:b6:d0:d1:6a:b1)
[  991.925800] wlp58s0: send auth to 88:71:b1:81:93:1a (try 1/3)
[  991.930114] wlp58s0: authenticated
[  991.933812] wlp58s0: associate with 88:71:b1:81:93:1a (try 1/3)
[  991.970406] wlp58s0: RX AssocResp from 88:71:b1:81:93:1a (capab=0x1431 status=0 aid=1)
[  991.979423] wlp58s0: associated
[  991.979652] wlp58s0: Limiting TX power to 20 (20 - 0) dBm as advertised by 88:71:b1:81:93:1a
[  993.200241] PM: suspend exit
[  993.200929] Bluetooth: hci0: using rampatch file: qca/rampatch_usb_00000302.bin
[  993.200940] Bluetooth: hci0: QCA: patch rome 0x302 build 0x3e8, firmware rome 0x302 build 0x111
[  993.564671] Bluetooth: hci0: using NVM file: qca/nvm_usb_00000302.bin
[  993.591246] Bluetooth: hci0: HCI Enhanced Setup Synchronous Connection command is advertised, but not supported.
-------------- next part --------------
A non-text attachment was scrubbed...
Name: abreu_mem_ftrace.txt.7z
Type: application/x-7z-compressed
Size: 433371 bytes
Desc: not available
URL: <http://lists.infradead.org/pipermail/linux-nvme/attachments/20240501/47f64c84/attachment-0001.bin>

More information about the Linux-nvme mailing list