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

[Paul Menzel]

Dear Keith,


Thank you for your quick reply.

Am 02.05.24 um 00:03 schrieb Keith Busch:
> On Wed, May 01, 2024 at 10:58:05PM +0200, Paul Menzel wrote:
>> Am 01.05.24 um 09:58 schrieb Keith Busch:
>>> Exactly. Unless the device reports a lower D3 entry latency, then this
>>> sounds like everything is working-as-designed.
>>
>> Maybe according to the spec, but I have a hard time to believe, that disks
>> should take longer to shut down than coreboot to initialize a mainboard.
> 
> That doesn't seem too hard to believe to me. A safe shutdown can often
> take a while time for an SSD. I've seen other implementations orders of
> magnitude worse than what you're showing.

But why? Due to physics or due to “slow” firmware?

> You could do an unsafe shutdown instead, but the device will just
> take even more time to enable on its next power-on.

Indeed, that is does not sound good.

>> In the end, in my opinion, users cannot make an informed decision, if these
>> things are hidden. If it would be visible somehow in the logs - maybe not
>> warning but info level - then even not so technical users could inform
>> themselves and factor this in their buying decision.
> 
> What good is it to advertise a shutdown time when vendors are clearly
> unreliable at reporting an accurate value? If you need to see the driver
> report it from emperical testing, then you've already bought the device,
> right?
> 
>>> You can check your device's advertised shutdown time (assuming your
>>> device is nvme0):
>>>
>>>     nvme id-ctrl /dev/nvme0 | grep rtd3e
>>>
>>> The value is reported in microseconds. If it shows 0, then the device
>>> doesn't report an expected shutdown time.
>>
>> Thank you for sharing. It´s 60 ms:

I added some debug prints:

```
diff --git a/drivers/nvme/host/core.c b/drivers/nvme/host/core.c
index 27281a9a8951..76857d5e8a1a 100644
--- a/drivers/nvme/host/core.c
+++ b/drivers/nvme/host/core.c
@@ -2335,6 +2335,10 @@ int nvme_disable_ctrl(struct nvme_ctrl *ctrl, 
bool shutdown)
  {
         int ret;

+       dev_err(ctrl->device,
+                       "XXX Enter nvme_disable_ctrl with shutdown %s\n",
+                       shutdown ? "yes" : "no");
+
         ctrl->ctrl_config &= ~NVME_CC_SHN_MASK;
         if (shutdown)
                 ctrl->ctrl_config |= NVME_CC_SHN_NORMAL;
@@ -2346,14 +2350,24 @@ int nvme_disable_ctrl(struct nvme_ctrl *ctrl, 
bool shutdown)
                 return ret;

         if (shutdown) {
-               return nvme_wait_ready(ctrl, NVME_CSTS_SHST_MASK,
+               dev_err(ctrl->device,
+                               "XXX before nvme_wait_ready, 
shutdown_timeout %u\n", ctrl->shutdown_timeout);
+               ret = nvme_wait_ready(ctrl, NVME_CSTS_SHST_MASK,
                                        NVME_CSTS_SHST_CMPLT,
                                        ctrl->shutdown_timeout, "shutdown");
+               dev_err(ctrl->device,
+                               "XXX after nvme_wait_ready\n");
+               return ret;
         }
         if (ctrl->quirks & NVME_QUIRK_DELAY_BEFORE_CHK_RDY)
                 msleep(NVME_QUIRK_DELAY_AMOUNT);
-       return nvme_wait_ready(ctrl, NVME_CSTS_RDY, 0,
+       dev_err(ctrl->device,
+                       "XXX before nvme_wait_ready, shutdown_timeout 
%u\n", (NVME_CAP_TIMEOUT(ctrl->cap) + 1) / 2);
+       ret = nvme_wait_ready(ctrl, NVME_CSTS_RDY, 0,
                                (NVME_CAP_TIMEOUT(ctrl->cap) + 1) / 2, 
"reset");
+       dev_err(ctrl->device,
+                       "XXX after nvme_wait_ready\n");
+       return ret;
  }
  EXPORT_SYMBOL_GPL(nvme_disable_ctrl);
```

and got for “cold boot” and from ACPI S3 suspend and resume:

```
[    0.955837] nvme nvme0: XXX Enter nvme_disable_ctrl with shutdown no
[    0.955898] nvme nvme0: XXX before nvme_wait_ready, shutdown_timeout 128
[    0.961861] nvme nvme0: XXX after nvme_wait_ready
[    1.637251] device-mapper: core: CONFIG_IMA_DISABLE_HTABLE is 
disabled. Duplicate IMA measurements will not be recorded in the IMA log.
[   27.785752] wmi_bus wmi_bus-PNP0C14:01: [Firmware Bug]: WQBC data 
block query control method not found
[   29.811581] Bluetooth: hci0: HCI Enhanced Setup Synchronous 
Connection command is advertised, but not supported.
[   62.697526] nvme nvme0: XXX Enter nvme_disable_ctrl with shutdown yes
[   62.697538] nvme nvme0: XXX before nvme_wait_ready, shutdown_timeout 5
[   63.110008] nvme nvme0: XXX after nvme_wait_ready
[   63.308385] nvme nvme0: XXX Enter nvme_disable_ctrl with shutdown no
[   63.308394] nvme nvme0: XXX before nvme_wait_ready, shutdown_timeout 128
[   63.308399] nvme nvme0: XXX after nvme_wait_ready
```

So this confirms the ftrace findings. Excuse my ignorance, so the 
time-out is in seconds? And how does this relate to the rtd3e value (410 
ms ≠ 60 ms ≠ 5 s(?)?


Kind regards,

Paul