Hang at NVME Host caused by Controller reset

kernel hang observed on NVME Host(TCP) while running iozone with link toggle:

[ +42.773018] INFO: task kworker/u24:5:1243 blocked for more than 122 seconds.
[ +0.000124] Not tainted 5.8.0-rc4ekr+ #19
[ +0.000105] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.

[  +0.000164] kworker/u24:5   D12600  1243      2 0x00004000
[  +0.000114] Workqueue: nvme-reset-wq nvme_reset_ctrl_work [nvme_tcp]
[  +0.000109] Call Trace:
[  +0.000105]  __schedule+0x270/0x5d0
[  +0.000105]  schedule+0x45/0xb0
[  +0.000125]  blk_mq_freeze_queue_wait+0x41/0xa0
[  +0.000122]  ? wait_woken+0x80/0x80
[  +0.000116]  blk_mq_update_nr_hw_queues+0x8a/0x380
[  +0.000109]  nvme_tcp_setup_ctrl+0x345/0x510 [nvme_tcp]
[  +0.000108]  nvme_reset_ctrl_work+0x45/0x60 [nvme_tcp]
[  +0.000135]  process_one_work+0x149/0x380
[  +0.000107]  worker_thread+0x1ae/0x3a0
[  +0.000107]  ? process_one_work+0x380/0x380
[  +0.000108]  kthread+0xf7/0x130
[  +0.000135]  ? kthread_bind+0x10/0x10
[  +0.000121]  ret_from_fork+0x22/0x30
[  +0.000134] INFO: task bash:6000 blocked for more than 122 seconds.
[  +0.000122]       Not tainted 5.8.0-rc4ekr+ #19
[  +0.000109] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs"
disables this message.
[  +0.000195] bash            D14232  6000   5967 0x00000080
[  +0.000115] Call Trace:
[  +0.000106]  __schedule+0x270/0x5d0
[  +0.000138]  ? terminate_walk+0x8a/0x90
[  +0.000123]  schedule+0x45/0xb0
[  +0.000108]  schedule_timeout+0x1d6/0x290
[  +0.000121]  wait_for_completion+0x82/0xe0
[  +0.000120]  __flush_work.isra.37+0x10c/0x180
[  +0.000115]  ? flush_workqueue_prep_pwqs+0x110/0x110
[  +0.000119]  nvme_reset_ctrl_sync+0x1c/0x30 [nvme_core]
[  +0.000110]  nvme_sysfs_reset+0xd/0x20 [nvme_core]
[  +0.000137]  kernfs_fop_write+0x10a/0x1a0
[  +0.000124]  vfs_write+0xa8/0x1a0
[  +0.000122]  ksys_write+0x50/0xc0
[  +0.000117]  do_syscall_64+0x3e/0x70
[  +0.000108]  entry_SYSCALL_64_after_hwframe+0x44/0xa9
[  +0.000111] RIP: 0033:0x7f4ed689dc60
[  +0.000107] Code: Bad RIP value.
[  +0.000105] RSP: 002b:00007ffe636b6fe8 EFLAGS: 00000246 ORIG_RAX:

0000000000000001
[ +0.000188] RAX: ffffffffffffffda RBX: 0000000000000002 RCX:
00007f4ed689dc60
----

This issue got uncovered after commit fe35ec58f0d3, which does freeze-queue operation if set->nr_maps is greater than '1'(all nvmef trasnports sets nr_maps to '2' by default).

Issue will not occur with multipath enabled.
Issue observed with RDMA transports also.

Steps to reproduce:
nvme connect -t tcp -a 102.1.1.6 -s 4420 -n nvme-ram0 -i 1

Run below each while loop in different terminals parallelly, to reprodue instantaneously.
while [ 1 ]; do echo 1 > /sys/block/nvme0n1/device/reset_controller; done
while [ 1 ]; do nvme write-zeroes /dev/nvme0n1 -s 1 -c 1; done

My understanding is: while performing reset-controller, nvme-write task tries to submit IO/blk_queue_enter, but fails at blk_mq_run_hw_queue() after seeing blk_queue_quiesced.
And never succeeded to blk_queue_exit, may be due to out-of-sync percpu counter operations(q_usage_counter), causing this hang at freeze_queue.

Thanks,
Krishna.

Sagi,
With the given patch, I am no more seeing the freeze_queue_wait hang issue, but I am seeing another hang issue:

Quoted 3 lines · Krishnamraju Eraparaju

Sagi,
With the given patch, I am no more seeing the freeze_queue_wait hang issue, but I am seeing another hang issue:

The trace suggest that you are not running with multipath right?

I think you need the patch:
[PATCH] nvme-fabrics: allow to queue requests for live queues

You can find it in linux-nvme

Sagi,

Yes, Multipath is disabled.

This time, with "nvme-fabrics: allow to queue requests for live queues" patch applied, I see hang only at blk_queue_enter():

[Jul28 17:25] INFO: task nvme:21119 blocked for more than 122 seconds.
[ +0.000061] Not tainted 5.8.0-rc7ekr+ #2
[ +0.000052] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.

[  +0.000059] nvme            D14392 21119   2456 0x00004000
[  +0.000059] Call Trace:
[  +0.000110]  __schedule+0x32b/0x670
[  +0.000108]  schedule+0x45/0xb0
[  +0.000107]  blk_queue_enter+0x1e9/0x250
[  +0.000109]  ? wait_woken+0x70/0x70
[  +0.000110]  blk_mq_alloc_request+0x53/0xc0
[  +0.000111]  nvme_alloc_request+0x61/0x70 [nvme_core]
[  +0.000121]  nvme_submit_user_cmd+0x50/0x310 [nvme_core]
[  +0.000118]  nvme_user_cmd+0x12e/0x1c0 [nvme_core]
[  +0.000163]  ? _copy_to_user+0x22/0x30
[  +0.000113]  blkdev_ioctl+0x100/0x250
[  +0.000115]  block_ioctl+0x34/0x40
[  +0.000110]  ksys_ioctl+0x82/0xc0
[  +0.000109]  __x64_sys_ioctl+0x11/0x20
[  +0.000109]  do_syscall_64+0x3e/0x70
[  +0.000120]  entry_SYSCALL_64_after_hwframe+0x44/0xa9
[  +0.000112] RIP: 0033:0x7fbe9cdbb67b
[  +0.000110] Code: Bad RIP value.
[  +0.000124] RSP: 002b:00007ffd61ff5778 EFLAGS: 00000246 ORIG_RAX:

0000000000000010
[ +0.000170] RAX: ffffffffffffffda RBX: 0000000000000003 RCX:
00007fbe9cdbb67b
[ +0.000114] RDX: 00007ffd61ff5780 RSI: 00000000c0484e43 RDI:
0000000000000003
[ +0.000113] RBP: 0000000000000000 R08: 0000000000000001 R09:
0000000000000000
[ +0.000115] R10: 0000000000000000 R11: 0000000000000246 R12:
00007ffd61ff7219
[ +0.000123] R13: 0000000000000006 R14: 00007ffd61ff5e30 R15:
000055e09c1854a0
[ +0.000115] Kernel panic - not syncing: hung_task: blocked tasks

You could easily reproduce this by running below, parallelly, for 10min:
while [ 1 ]; do nvme write-zeroes /dev/nvme0n1 -s 1 -c 1; done while [ 1 ]; do echo 1 > /sys/block/nvme0n1/device/reset_controller;
done
while [ 1 ]; do ifconfig enp2s0f4 down; sleep 24; ifconfig enp2s0f4 up;
sleep 28; done

Not sure using nvme-write this way is valid or not..

Quoted 3 lines

This time, with "nvme-fabrics: allow to queue requests for live queues" patch applied, I see hang only at blk_queue_enter():

Interesting, does the reset loop hang? or is it able to make forward progress?

Quoted 6 lines

Quoted 3 lines

This time, with "nvme-fabrics: allow to queue requests for live queues" patch applied, I see hang only at blk_queue_enter():

Interesting, does the reset loop hang? or is it able to make forward progress?

Looks like the freeze depth is messed up with the timeout handler. We shouldn't call nvme_tcp_teardown_io_queues in the timeout handler because it messes with the freeze depth, causing the unfreeze to not wake the waiter (blk_queue_enter). We should simply stop the queue and complete the I/O, and the condition was wrong too, because we need to do it only for the connect command (which cannot reset the timer). So we should check for reserved in the timeout handler.

Can you please try this patch?

--

drivers/nvme/host/tcp.c +1 -3

index 62fbaecdc960..c3288dd2c92f 100644
@@ -464,6 +464,7 @@ static void nvme_tcp_error_recovery(struct
 nvme_ctrl *ctrl)
        if (!nvme_change_ctrl_state(ctrl, NVME_CTRL_RESETTING))
                return;
 
+       dev_warn(ctrl->device, "starting error recovery\n");
        queue_work(nvme_reset_wq, &to_tcp_ctrl(ctrl)->err_work);
 }

@@ -2156,33 +2157,37 @@ nvme_tcp_timeout(struct request *rq, bool reserved)
        struct nvme_tcp_ctrl *ctrl = req->queue->ctrl;
        struct nvme_tcp_cmd_pdu *pdu = req->pdu;
 
-       /*
-        * Restart the timer if a controller reset is already scheduled. Any
-        * timed out commands would be handled before entering the

connecting

drivers/nvme/host/tcp.c +2 -7

-        * state.
-        */
-       if (ctrl->ctrl.state == NVME_CTRL_RESETTING)
-               return BLK_EH_RESET_TIMER;
-
        dev_warn(ctrl->ctrl.device,
                "queue %d: timeout request %#x type %d\n",
                nvme_tcp_queue_id(req->queue), rq->tag, pdu->hdr.type);
 
-       if (ctrl->ctrl.state != NVME_CTRL_LIVE) {
+       switch (ctrl->ctrl.state) {
+       case NVME_CTRL_RESETTING:
                /*
-                * Teardown immediately if controller times out

while starting

drivers/nvme/host/tcp.c +0 -2

-                * or we are already started error recovery. all outstanding
-                * requests are completed on shutdown, so we return

BLK_EH_DONE.
+ * Restart the timer if a controller reset is
already scheduled.
+ * Any timed out commands would be handled before
entering the

drivers/nvme/host/tcp.c +6 -4

+                * connecting state.
                 */
-               flush_work(&ctrl->err_work);
-               nvme_tcp_teardown_io_queues(&ctrl->ctrl, false);
-               nvme_tcp_teardown_admin_queue(&ctrl->ctrl, false);
-               return BLK_EH_DONE;
+               return BLK_EH_RESET_TIMER;
+       case NVME_CTRL_CONNECTING:
+               if (reserved) {
+                       /*
+                        * stop queue immediately if controller

times out while connecting
+ * or we are already started error recovery.
all outstanding
+ * requests are completed on shutdown, so we
return BLK_EH_DONE.

drivers/nvme/host/tcp.c +2 -0

+                        */
+                       nvme_tcp_stop_queue(&ctrl->ctrl,

nvme_tcp_queue_id(req->queue));

drivers/nvme/host/tcp.c +9 -4

+                       nvme_req(rq)->flags |= NVME_REQ_CANCELLED;
+                       nvme_req(rq)->status = NVME_SC_HOST_ABORTED_CMD;
+                       blk_mq_complete_request(rq);
+                       return BLK_EH_DONE;
+               }
+               /* fallthru */
+       default:
+       case NVME_CTRL_LIVE:
+               nvme_tcp_error_recovery(&ctrl->ctrl);
        }
 
-       dev_warn(ctrl->ctrl.device, "starting error recovery\n");
-       nvme_tcp_error_recovery(&ctrl->ctrl);
-
        return BLK_EH_RESET_TIMER;
 }
--

Quoted 15 lines

Quoted 6 lines

Quoted 3 lines

This time, with "nvme-fabrics: allow to queue requests for live queues" patch applied, I see hang only at blk_queue_enter():

Interesting, does the reset loop hang? or is it able to make forward progress?

Looks like the freeze depth is messed up with the timeout handler. We shouldn't call nvme_tcp_teardown_io_queues in the timeout handler because it messes with the freeze depth, causing the unfreeze to not wake the waiter (blk_queue_enter). We should simply stop the queue and complete the I/O, and the condition was wrong too, because we need to do it only for the connect command (which cannot reset the timer). So we should check for reserved in the timeout handler.

Quoted 1 line

Can you please try this patch?

Even with this patch I see hangs, as shown below:

Quoted 15 lines

Quoted 15 lines

Quoted 15 lines

Quoted 6 lines

Quoted 3 lines

This time, with "nvme-fabrics: allow to queue requests for live queues" patch applied, I see hang only at blk_queue_enter():

Interesting, does the reset loop hang? or is it able to make forward progress?

Looks like the freeze depth is messed up with the timeout handler. We shouldn't call nvme_tcp_teardown_io_queues in the timeout handler because it messes with the freeze depth, causing the unfreeze to not wake the waiter (blk_queue_enter). We should simply stop the queue and complete the I/O, and the condition was wrong too, because we need to do it only for the connect command (which cannot reset the timer). So we should check for reserved in the timeout handler.

Quoted 8 lines

Quoted 2 lines

Quoted 1 line

Can you please try this patch?

Even with this patch I see hangs, as shown below:

While it's omitted from the log you provided, its possible that we just reset the timer for timed out admin commands which makes the error recovery flow stuck.

Can you please try this:

Sagi,

Now the below malloc failure at Target is causing blk_queue_enter/wait_event hang at Host.

[  +0.000004] Workqueue: nvmet_tcp_wq nvmet_tcp_io_work [nvmet_tcp]
[  +0.000001] Call Trace:
[  +0.000007]  dump_stack+0x57/0x6b
[  +0.000005]  warn_alloc+0xf7/0x160
[  +0.000003]  __alloc_pages_slowpath.constprop.123+0x831/0x9f0
[  +0.000001]  __alloc_pages_nodemask+0x2cd/0x300
[  +0.000004]  kmalloc_order+0x1d/0x90
[  +0.000002]  kmalloc_order_trace+0x1d/0xb0
[  +0.000002]  nvmet_tcp_install_queue+0x3f/0xd0 [nvmet_tcp]
[  +0.000004]  nvmet_install_queue+0x86/0x120 [nvmet]
[  +0.000001]  nvmet_execute_io_connect+0xf4/0x1b0 [nvmet]
[  +0.000002]  nvmet_tcp_io_work+0xa46/0xadb [nvmet_tcp]
[  +0.000002]  process_one_work+0x149/0x380
[  +0.000002]  worker_thread+0x41/0x3a0

This malloc failure may be expected as I am running reset controller script in a loop without any sleep(It took more than 4 hours to hit this malloc failure on my target machine). But I think the hang issue at host needs to be addressed.

Host side dmesg:

[  +0.000198] nvme nvme1: creating 12 I/O queues.
[  +0.005365] nvme nvme1: Connect command failed, error wo/DNR bit: 6
[  +0.000165] nvme nvme1: failed to connect queue: 1 ret=6
[  +0.000418] nvme nvme1: Reconnecting in 10 seconds...

[ +35.705727] cxgb4 0000:02:00.4: Port 0 link down, reason: Link Down [ +0.615556] cxgb4 0000:02:00.4 enp2s0f4: link up, 40Gbps, full-duplex, Tx/Rx PAUSE [ +0.001146] IPv6: ADDRCONF(NETDEV_CHANGE): enp2s0f4: link becomes ready [Jul30 05:51] nvme nvme1: queue 0: timeout request 0x1 type 4

[  +0.000020] nvme nvme1: Connect command failed, error wo/DNR bit: -16388
[  +0.000170] nvme nvme1: failed to connect queue: 0 ret=-4
[  +0.000148] nvme nvme1: Failed reconnect attempt 2
[  +0.000001] nvme nvme1: Reconnecting in 10 seconds...
[ +13.311922] nvme nvme1: failed to connect socket: -110
[  +0.000125] nvme nvme1: Failed reconnect attempt 3
[  +0.000001] nvme nvme1: Reconnecting in 10 seconds...
[  +2.586017] cxgb4 0000:02:00.4: Port 0 link down, reason: Link Down
[  +0.557409] cxgb4 0000:02:00.4 enp2s0f4: link up, 40Gbps, full-duplex, Tx/Rx PAUSE
[  +0.001144] IPv6: ADDRCONF(NETDEV_CHANGE): enp2s0f4: link becomes ready

[Jul30 05:52] cxgb4 0000:02:00.4: Port 0 link down, reason: Link Down [ +0.551397] cxgb4 0000:02:00.4 enp2s0f4: link up, 40Gbps, full-duplex, Tx/Rx PAUSE [ +0.001073] IPv6: ADDRCONF(NETDEV_CHANGE): enp2s0f4: link becomes ready [Jul30 05:53] INFO: task nvme:5944 blocked for more than 122 seconds.

[  +0.000125]       Not tainted 5.8.0-rc7ekr+ #2
[  +0.000111] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[  +0.000177] nvme            D14392  5944   2796 0x00004000
[  +0.000123] Call Trace:
[  +0.001375]  __schedule+0x32b/0x670
[  +0.000125]  schedule+0x45/0xb0
[  +0.000138]  blk_queue_enter+0x1e9/0x250
[  +0.000137]  ? wait_woken+0x70/0x70
[  +0.000116]  blk_mq_alloc_request+0x53/0xc0
[  +0.000122]  nvme_alloc_request+0x61/0x70 [nvme_core]
[  +0.000121]  nvme_submit_user_cmd+0x50/0x310 [nvme_core]
[  +0.000123]  nvme_user_cmd+0x12e/0x1c0 [nvme_core]
[  +0.000142]  ? _copy_to_user+0x22/0x30
[  +0.000135]  blkdev_ioctl+0x100/0x250
[  +0.000122]  block_ioctl+0x34/0x40
[  +0.000129]  ksys_ioctl+0x82/0xc0

Quoted 27 lines

Quoted 15 lines

Quoted 15 lines

Quoted 15 lines

Quoted 6 lines

Quoted 3 lines

This time, with "nvme-fabrics: allow to queue requests for live queues" patch applied, I see hang only at blk_queue_enter():

Interesting, does the reset loop hang? or is it able to make forward progress?

Looks like the freeze depth is messed up with the timeout handler. We shouldn't call nvme_tcp_teardown_io_queues in the timeout handler because it messes with the freeze depth, causing the unfreeze to not wake the waiter (blk_queue_enter). We should simply stop the queue and complete the I/O, and the condition was wrong too, because we need to do it only for the connect command (which cannot reset the timer). So we should check for reserved in the timeout handler.

Quoted 8 lines

Quoted 2 lines

Quoted 1 line

Can you please try this patch?

Even with this patch I see hangs, as shown below:

While it's omitted from the log you provided, its possible that we just reset the timer for timed out admin commands which makes the error recovery flow stuck.

Can you please try this:

Sagi,

Now the below malloc failure at Target is causing blk_queue_enter/wait_event hang at Host.

Quoted 15 lines

[  +0.000004] Workqueue: nvmet_tcp_wq nvmet_tcp_io_work [nvmet_tcp]
[  +0.000001] Call Trace:
[  +0.000007]  dump_stack+0x57/0x6b
[  +0.000005]  warn_alloc+0xf7/0x160
[  +0.000003]  __alloc_pages_slowpath.constprop.123+0x831/0x9f0
[  +0.000001]  __alloc_pages_nodemask+0x2cd/0x300
[  +0.000004]  kmalloc_order+0x1d/0x90
[  +0.000002]  kmalloc_order_trace+0x1d/0xb0
[  +0.000002]  nvmet_tcp_install_queue+0x3f/0xd0 [nvmet_tcp]
[  +0.000004]  nvmet_install_queue+0x86/0x120 [nvmet]
[  +0.000001]  nvmet_execute_io_connect+0xf4/0x1b0 [nvmet]
[  +0.000002]  nvmet_tcp_io_work+0xa46/0xadb [nvmet_tcp]
[  +0.000002]  process_one_work+0x149/0x380
[  +0.000002]  worker_thread+0x41/0x3a0

OK, that is a new bug... Lets take care of that separately.

Quoted 4 lines

This malloc failure may be expected as I am running reset controller script in a loop without any sleep(It took more than 4 hours to hit this malloc failure on my target machine). But I think the hang issue at host needs to be addressed.

The I/O won't complete unless you disconnect from the controller, it shouldn't hang.

BTW, in order to handle a controller reset during I/O and when the target all of a sudden becomes unresponsive in the middle of the reset sequence, requires some more fixes, which I'll send out soon.

Quoted 27 lines

Host side dmesg:

[  +0.000198] nvme nvme1: creating 12 I/O queues.
[  +0.005365] nvme nvme1: Connect command failed, error wo/DNR bit: 6
[  +0.000165] nvme nvme1: failed to connect queue: 1 ret=6
[  +0.000418] nvme nvme1: Reconnecting in 10 seconds...

[ +35.705727] cxgb4 0000:02:00.4: Port 0 link down, reason: Link Down [ +0.615556] cxgb4 0000:02:00.4 enp2s0f4: link up, 40Gbps, full-duplex, Tx/Rx PAUSE [ +0.001146] IPv6: ADDRCONF(NETDEV_CHANGE): enp2s0f4: link becomes ready [Jul30 05:51] nvme nvme1: queue 0: timeout request 0x1 type 4

[  +0.000020] nvme nvme1: Connect command failed, error wo/DNR bit: -16388
[  +0.000170] nvme nvme1: failed to connect queue: 0 ret=-4
[  +0.000148] nvme nvme1: Failed reconnect attempt 2
[  +0.000001] nvme nvme1: Reconnecting in 10 seconds...
[ +13.311922] nvme nvme1: failed to connect socket: -110
[  +0.000125] nvme nvme1: Failed reconnect attempt 3
[  +0.000001] nvme nvme1: Reconnecting in 10 seconds...
[  +2.586017] cxgb4 0000:02:00.4: Port 0 link down, reason: Link Down
[  +0.557409] cxgb4 0000:02:00.4 enp2s0f4: link up, 40Gbps, full-duplex, Tx/Rx PAUSE
[  +0.001144] IPv6: ADDRCONF(NETDEV_CHANGE): enp2s0f4: link becomes ready

[Jul30 05:52] cxgb4 0000:02:00.4: Port 0 link down, reason: Link Down [ +0.551397] cxgb4 0000:02:00.4 enp2s0f4: link up, 40Gbps, full-duplex, Tx/Rx PAUSE [ +0.001073] IPv6: ADDRCONF(NETDEV_CHANGE): enp2s0f4: link becomes ready [Jul30 05:53] INFO: task nvme:5944 blocked for more than 122 seconds.

Quoted 16 lines

[  +0.000125]       Not tainted 5.8.0-rc7ekr+ #2
[  +0.000111] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[  +0.000177] nvme            D14392  5944   2796 0x00004000
[  +0.000123] Call Trace:
[  +0.001375]  __schedule+0x32b/0x670
[  +0.000125]  schedule+0x45/0xb0
[  +0.000138]  blk_queue_enter+0x1e9/0x250
[  +0.000137]  ? wait_woken+0x70/0x70
[  +0.000116]  blk_mq_alloc_request+0x53/0xc0
[  +0.000122]  nvme_alloc_request+0x61/0x70 [nvme_core]
[  +0.000121]  nvme_submit_user_cmd+0x50/0x310 [nvme_core]
[  +0.000123]  nvme_user_cmd+0x12e/0x1c0 [nvme_core]
[  +0.000142]  ? _copy_to_user+0x22/0x30
[  +0.000135]  blkdev_ioctl+0x100/0x250
[  +0.000122]  block_ioctl+0x34/0x40
[  +0.000129]  ksys_ioctl+0x82/0xc0

That is expected, without multipath, the I/O will not complete, and unless the target restores (or host disconnects), the I/O keeps waiting, that is the expected behavior.