parallel nvme format

Niklas Cassel
2023-12-14T13:58:32Z

Hello guys,

We have observed the following on linux stable v6.6.x.

(We tried to backport commit 839a40d1e730 ("nvme: fix deadlock between reset
and scan"), but it didn't fix the problem.)

What happens is that we are formatting 8 different namespaces in parallel.

[Wed Nov 29 16:43:56 2023] INFO: task nvme:18411 blocked for more than 120 seconds.
[Wed Nov 29 16:43:56 2023] Not tainted 6.6.2 #1
[Wed Nov 29 16:43:56 2023] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs"
+disables this message.
[Wed Nov 29 16:43:56 2023] task:nvme state:D stack:0 pid:18411
+ppid:18405 flags:0x00004000
[Wed Nov 29 16:43:56 2023] Call Trace:
[Wed Nov 29 16:43:56 2023] <TASK>
[Wed Nov 29 16:43:56 2023] __schedule+0x34a/0xef0
[Wed Nov 29 16:43:56 2023] ? preempt_count_add+0x7c/0xc0
[Wed Nov 29 16:43:56 2023] ? _raw_spin_lock_irqsave+0x29/0x60
[Wed Nov 29 16:43:56 2023] schedule+0x6b/0xf0
[Wed Nov 29 16:43:56 2023] schedule_timeout+0x233/0x290
[Wed Nov 29 16:43:56 2023] ? __timer_delete_sync+0x31/0x50
[Wed Nov 29 16:43:56 2023] ? schedule_timeout+0x1a3/0x290
[Wed Nov 29 16:43:56 2023] wait_for_completion+0x8b/0x140
[Wed Nov 29 16:43:56 2023] __flush_work+0x139/0x240
[Wed Nov 29 16:43:56 2023] ? __pfx_wq_barrier_func+0x10/0x10
[Wed Nov 29 16:43:56 2023] flush_work+0x10/0x20
[Wed Nov 29 16:43:56 2023] nvme_passthru_end+0x60/0x170 [nvme_core]
[Wed Nov 29 16:43:56 2023] nvme_submit_user_cmd+0x162/0x170 [nvme_core]
[Wed Nov 29 16:43:56 2023] nvme_user_cmd.constprop.0+0x156/0x1d0 [nvme_core]
[Wed Nov 29 16:43:56 2023] nvme_dev_ioctl+0x12c/0x2a0 [nvme_core]
[Wed Nov 29 16:43:56 2023] __x64_sys_ioctl+0x95/0xd0
[Wed Nov 29 16:43:56 2023] do_syscall_64+0x38/0x90
[Wed Nov 29 16:43:56 2023] entry_SYSCALL_64_after_hwframe+0x6e/0xd8

flush_work() waits for more that 120 seconds on scan_work getting completed,
but even after 120 seconds, scan_work hasn't completed.

Inspecting nvme_scan_work(), the only thing that can cause it to not return
after 120 seconds, is if it is waiting on mutex_lock() to get the scan mutex.

What appears to be happening is:

format command #1 completes and calls nvme_passthru_end(),
nvme_passthru_end() calls:

mutex_unlock(&ctrl->scan_lock);
...
nvme_queue_scan(ctrl);
flush_work(&ctrl->scan_work);

Directly after format command #1 unlocks the mutex,
format command #2 will get the mutex in nvme_passthru_start().

Format command #2 will release the mutex in nvme_passthru_end(),
but only after the format command has completed.

The default timeout for the nvme format command via nvme-cli is 600 seconds,
so it is easy to imagine that the format command will take longer than 120
seconds.

So the scan work at the end of format command #1 will eventually get to run,
but only after the second nvme format command has completed.
(nvme_queue_scan() will finally be able to get the mutex, once
nvme_passthru_end() for the second format command has released the mutex.)

I don't think that formatting multiple namespaces in parallel is an
unreasonable thing to do, so I do not think that we should scare our
users with "hung task timeouts".

My first though was that perhaps we could do something like:

diff --git a/drivers/nvme/host/core.c b/drivers/nvme/host/core.c
index 46a4c9c5ea96..811d40cf23f6 100644
--- a/drivers/nvme/host/core.c
+++ b/drivers/nvme/host/core.c
@@ -1113,6 +1113,7 @@ u32 nvme_passthru_start(struct nvme_ctrl *ctrl, struct nvme_ns *ns, u8 opcode)
* effects say only one namespace is affected.
*/
if (effects & NVME_CMD_EFFECTS_CSE_MASK) {
+ flush_work(&ctrl->scan_work);
mutex_lock(&ctrl->scan_lock);
mutex_lock(&ctrl->subsys->lock);
nvme_mpath_start_freeze(ctrl->subsys);

But that will not work, because it will still have a race window between the
time nvme_passthru_end() has unlocked the mutex, and before
nvme_passthru_end() has queued the scan work.

I guess, in the case that nvme_passthru_end() has to perform a scan, we want
to unlock the scan mutex after nvme_passthru_end() has performed the scan,
but right now nvme_queue_scan() will acquire the mutex (and is running on the
workqueue)...

Thoughts?

Kind regards,
Niklas