nvme_tcp: nvme connect failed after execute stress-ng: unshare
Yi Zhang
yi.zhang at redhat.com
Wed Oct 28 08:19:08 EDT 2020
On 9/15/20 9:40 AM, Yi Zhang wrote:
> Hi Sagi
>
> On 9/15/20 7:50 AM, Sagi Grimberg wrote:
>>
>>> Hello
>>>
>>> Recently I found nvme-tcp connecting always failed[1] after execute
>>> stress-ng:unshare[2], by bisecting I finally found it was introduced
>>> with commit[3], the connecting works well after revert it.
>>> I'm not sure whether it's one test case issue or kernel issue, could
>>> anyone help check it.
>>
>> Is this failure persistent or transient?
>>
> It's persistent, and most of recent CKI job with 5.8 stable kernel
> also showed this failure.
>
Found "WARNING: possible circular locking" with latest 5.10.0-rc1
[ 230.353213] run blktests nvme/003 at 2020-10-28 07:41:08
[ 230.666092] loop: module loaded
[ 230.870124] nvmet: adding nsid 1 to subsystem blktests-subsystem-1
[ 230.902252] nvmet_tcp: enabling port 0 (127.0.0.1:4420)
[ 246.097201] nvmet: ctrl 1 keep-alive timer (15 seconds) expired!
[ 246.104886] nvmet: ctrl 1 fatal error occurred!
[ 246.113796] ======================================================
[ 246.120042] WARNING: possible circular locking dependency detected
[ 246.126288] 5.10.0-rc1 #1 Not tainted
[ 246.129987] ------------------------------------------------------
[ 246.136231] kworker/0:2/251 is trying to acquire lock:
[ 246.141423] ffff00012ec0b830
((work_completion)(&queue->io_work)){+.+.}-{0:0}, at:
__flush_work+0x48/0x4f0
[ 246.151202]
but task is already holding lock:
[ 246.157095] ffff8000147e3dd8
((work_completion)(&queue->release_work)){+.+.}-{0:0}, at:
process_one_work+0x1bc/0x670
[ 246.167743]
which lock already depends on the new lock.
[ 246.176007]
the existing dependency chain (in reverse order) is:
[ 246.183569]
-> #2 ((work_completion)(&queue->release_work)){+.+.}-{0:0}:
[ 246.191849] validate_chain+0x5f0/0xa00
[ 246.196251] __lock_acquire+0x3b0/0xb70
[ 246.200652] lock_acquire+0x104/0x428
[ 246.204878] process_one_work+0x21c/0x670
[ 246.209456] worker_thread+0x54/0x408
[ 246.213684] kthread+0x11c/0x148
[ 246.217473] ret_from_fork+0x10/0x18
[ 246.221611]
-> #1 ((wq_completion)events){+.+.}-{0:0}:
[ 246.228602] validate_chain+0x5f0/0xa00
[ 246.233005] __lock_acquire+0x3b0/0xb70
[ 246.237407] lock_acquire+0x104/0x428
[ 246.241634] flush_workqueue+0x8c/0x4a8
[ 246.246041] nvmet_tcp_install_queue+0x100/0x110 [nvmet_tcp]
[ 246.252309] nvmet_install_queue+0xc4/0x150 [nvmet]
[ 246.257775] nvmet_execute_admin_connect+0xf4/0x1e0 [nvmet]
[ 246.263935] nvmet_tcp_io_work+0x8dc/0x970 [nvmet_tcp]
[ 246.269654] process_one_work+0x268/0x670
[ 246.274231] worker_thread+0x54/0x408
[ 246.278458] kthread+0x11c/0x148
[ 246.282246] ret_from_fork+0x10/0x18
[ 246.288493]
-> #0 ((work_completion)(&queue->io_work)){+.+.}-{0:0}:
[ 246.300559] check_noncircular+0x100/0x128
[ 246.307367] check_prev_add+0xa4/0x668
[ 246.313777] validate_chain+0x5f0/0xa00
[ 246.320230] __lock_acquire+0x3b0/0xb70
[ 246.326652] lock_acquire+0x104/0x428
[ 246.332879] __flush_work+0x70/0x4f0
[ 246.338994] flush_work+0x1c/0x28
[ 246.344833] nvmet_tcp_release_queue_work+0xd0/0x230 [nvmet_tcp]
[ 246.353405] process_one_work+0x268/0x670
[ 246.359955] worker_thread+0x54/0x408
[ 246.366131] kthread+0x11c/0x148
[ 246.371843] ret_from_fork+0x10/0x18
[ 246.377876]
other info that might help us debug this:
[ 246.391416] Chain exists of:
(work_completion)(&queue->io_work) -->
(wq_completion)events --> (work_completion)(&queue->release_work)
[ 246.411895] Possible unsafe locking scenario:
[ 246.421363] CPU0 CPU1
[ 246.427687] ---- ----
[ 246.433978] lock((work_completion)(&queue->release_work));
[ 246.441413] lock((wq_completion)events);
[ 246.449816] lock((work_completion)(&queue->release_work));
[ 246.459780] lock((work_completion)(&queue->io_work));
[ 246.466808]
*** DEADLOCK ***
[ 246.478008] 2 locks held by kworker/0:2/251:
[ 246.484053] #0: ffff000100051b38
((wq_completion)events){+.+.}-{0:0}, at: process_one_work+0x1bc/0x670
[ 246.495355] #1: ffff8000147e3dd8
((work_completion)(&queue->release_work)){+.+.}-{0:0}, at:
process_one_work+0x1bc/0x670
[ 246.508301]
stack backtrace:
[ 246.516512] CPU: 0 PID: 251 Comm: kworker/0:2 Not tainted 5.10.0-rc1 #1
[ 246.525121] Hardware name: GIGABYTE R120-T32-00/MT30-GS1-00, BIOS F02
08/06/2019
[ 246.534560] Workqueue: events nvmet_tcp_release_queue_work [nvmet_tcp]
[ 246.543156] Call trace:
[ 246.547634] dump_backtrace+0x0/0x1c8
[ 246.553325] show_stack+0x20/0x70
[ 246.558653] dump_stack+0xf8/0x164
[ 246.564043] print_circular_bug.isra.0+0x234/0x290
[ 246.570834] check_noncircular+0x100/0x128
[ 246.576931] check_prev_add+0xa4/0x668
[ 246.582676] validate_chain+0x5f0/0xa00
[ 246.588512] __lock_acquire+0x3b0/0xb70
[ 246.594346] lock_acquire+0x104/0x428
[ 246.599986] __flush_work+0x70/0x4f0
[ 246.605506] flush_work+0x1c/0x28
[ 246.610765] nvmet_tcp_release_queue_work+0xd0/0x230 [nvmet_tcp]
[ 246.618768] process_one_work+0x268/0x670
[ 246.624777] worker_thread+0x54/0x408
[ 246.630438] kthread+0x11c/0x148
[ 246.635661] ret_from_fork+0x10/0x18
[ 295.375201] nvme nvme0: queue 0: timeout request 0x0 type 4
[ 295.383074] nvme nvme0: Connect command failed, error wo/DNR bit: 881
[ 295.391912] nvme nvme0: failed to connect queue: 0 ret=881
[ 479.792299] nvmet: creating controller 1 for subsystem
nqn.2014-08.org.nvmexpress.discovery for NQN
nqn.2014-08.org.nvmexpress:uuid:0e657e35bc5f402480543a94c7a292ed.
>>>
>>> [1]
>>> # sh test.sh
>>> + ./stress-ng/stress-ng --unshare 0 --timeout 5 --log-file unshare.log
>>> stress-ng: info: [355534] dispatching hogs: 32 unshare
>>> stress-ng: info: [355534] successful run completed in 5.04s
>>> + modprobe null-blk nr-devices=1
>>> + modprobe nvmet-tcp
>>> + modprobe nvme-tcp
>>> + nvmetcli restore tcp.json
>>> + nvme connect -t tcp -n nqn.2014-08.org.nvmexpress.discovery -a
>>> 127.0.0.1 -s 4420
>>> Failed to write to /dev/nvme-fabrics: Input/output error
>>>
>>> # dmesg | tail -9
>>> [ 700.012299] null_blk: module loaded
>>> [ 700.073415] nvmet: adding nsid 1 to subsystem blktests-subsystem-1
>>> [ 700.073923] nvmet_tcp: enabling port 0 (127.0.0.1:4420)
>>> [ 715.291020] nvmet: ctrl 1 keep-alive timer (15 seconds) expired!
>>> [ 715.297031] nvmet: ctrl 1 fatal error occurred!
>>> [ 749.939898] nvmet: creating controller 1 for subsystem
>>> nqn.2014-08.org.nvmexpress.discovery for NQN
>>> nqn.2014-08.org.nvmexpress:uuid:e405e6bb-8e28-4a73-b338-3fddb5746b8c.
>>> [ 763.417376] nvme nvme0: queue 0: timeout request 0x0 type 4
>>> [ 763.422979] nvme nvme0: Connect command failed, error wo/DNR bit:
>>> 881
>>> [ 763.429419] nvme nvme0: failed to connect queue: 0 ret=881
>>>
>>> # uname -r
>>> 5.9.0-rc4
>>>
>>>
>>> [2] stress-ng: unshare case
>>> https://github.com/ColinIanKing/stress-ng.git
>>> https://github.com/ColinIanKing/stress-ng/blob/master/stress-unshare.c
>>>
>>>
>>> [3]
>>> commit e1eb26fa62d04ec0955432be1aa8722a97cb52e7
>>> Author: Giuseppe Scrivano <gscrivan at redhat.com>
>>> Date: Sun Jun 7 21:40:10 2020 -0700
>>>
>>> ipc/namespace.c: use a work queue to free_ipc
>>> the reason is to avoid a delay caused by the
>>> synchronize_rcu() call in
>>> kern_umount() when the mqueue mount is freed.
More information about the Linux-nvme
mailing list