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

[Paul Menzel]

[add forgotten reply to questions in second paragraph]

Am 02.05.24 um 08:04 schrieb 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?

Linux time stamps would be reliable, and showing if vendors lie is a 
good thing, because then people can support vendors not lying.

>> If you need to see the driver report it from emperical testing,
>> then you've already bought the device, right?

Not necessarily, as logs from other systems can be accessed in databases 
like the Hardware for Linux database [1] and the uploaded log messages [2].

>>>> 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


[1]: https://linux-hardware.org/
[2]: https://github.com/linuxhw/Dmesg