[PATCH 2/2] nvmet-tcp: Fix incorrect locking in state_change sk callback
Sagi Grimberg
sagi at grimberg.me
Thu Mar 25 22:39:55 GMT 2021
> Hi Sagi
> With the two patch, I reproduced another lock dependency issue, here is
Hey Yi,
This one is different, still the fixes for the other one are valid...
Will look into this one too...
> the full log:
>
> [ 143.310362] run blktests nvme/003 at 2021-03-23 21:52:15
> [ 143.927284] loop: module loaded
> [ 144.027532] nvmet: adding nsid 1 to subsystem blktests-subsystem-1
> [ 144.059070] nvmet_tcp: enabling port 0 (127.0.0.1:4420)
> [ 144.201559] nvmet: creating controller 1 for subsystem
> nqn.2014-08.org.nvmexpress.discovery for NQN
> nqn.2014-08.org.nvmexpress:uuid:e25db33098f14032b70b755db1976647.
> [ 144.211644] nvme nvme1: new ctrl: NQN
> "nqn.2014-08.org.nvmexpress.discovery", addr 127.0.0.1:4420
> [ 154.400575] nvme nvme1: Removing ctrl: NQN
> "nqn.2014-08.org.nvmexpress.discovery"
>
> [ 154.407970] ======================================================
> [ 154.414871] WARNING: possible circular locking dependency detected
> [ 154.421765] 5.12.0-rc3.fix+ #2 Not tainted
> [ 154.426340] ------------------------------------------------------
> [ 154.433232] kworker/7:2/260 is trying to acquire lock:
> [ 154.438972] ffff888288e92030
> ((work_completion)(&queue->io_work)){+.+.}-{0:0}, at:
> __flush_work+0x118/0x1a0
> [ 154.449882]
> but task is already holding lock:
> [ 154.456395] ffffc90002b57db0
> ((work_completion)(&queue->release_work)){+.+.}-{0:0}, at:
> process_one_work+0x7c1/0x1480
> [ 154.468263]
> which lock already depends on the new lock.
>
> [ 154.477393]
> the existing dependency chain (in reverse order) is:
> [ 154.485739]
> -> #2
> ((work_completion)(&queue->release_work)){+.+.}-{0:0}:
> [ 154.494884] __lock_acquire+0xb77/0x18d0
> [ 154.499853] lock_acquire+0x1ca/0x480
> [ 154.504528] process_one_work+0x813/0x1480
> [ 154.509688] worker_thread+0x590/0xf80
> [ 154.514458] kthread+0x368/0x440
> [ 154.518650] ret_from_fork+0x22/0x30
> [ 154.523232]
> -> #1 ((wq_completion)events){+.+.}-{0:0}:
> [ 154.530633] __lock_acquire+0xb77/0x18d0
> [ 154.535597] lock_acquire+0x1ca/0x480
> [ 154.540272] flush_workqueue+0x101/0x1250
> [ 154.545334] nvmet_tcp_install_queue+0x22c/0x2a0 [nvmet_tcp]
> [ 154.552242] nvmet_install_queue+0x2a3/0x360 [nvmet]
> [ 154.558387] nvmet_execute_admin_connect+0x321/0x420 [nvmet]
> [ 154.565305] nvmet_tcp_io_work+0xa04/0xcfb [nvmet_tcp]
> [ 154.571629] process_one_work+0x8b2/0x1480
> [ 154.576787] worker_thread+0x590/0xf80
> [ 154.581560] kthread+0x368/0x440
> [ 154.585749] ret_from_fork+0x22/0x30
> [ 154.590328]
> -> #0 ((work_completion)(&queue->io_work)){+.+.}-{0:0}:
> [ 154.598989] check_prev_add+0x15e/0x20f0
> [ 154.603953] validate_chain+0xec9/0x19c0
> [ 154.608918] __lock_acquire+0xb77/0x18d0
> [ 154.613883] lock_acquire+0x1ca/0x480
> [ 154.618556] __flush_work+0x139/0x1a0
> [ 154.623229] nvmet_tcp_release_queue_work+0x2e5/0xcb0 [nvmet_tcp]
> [ 154.630621] process_one_work+0x8b2/0x1480
> [ 154.635780] worker_thread+0x590/0xf80
> [ 154.640549] kthread+0x368/0x440
> [ 154.644741] ret_from_fork+0x22/0x30
> [ 154.649321]
> other info that might help us debug this:
>
> [ 154.658257] Chain exists of:
> (work_completion)(&queue->io_work) -->
> (wq_completion)events --> (work_completion)(&queue->release_work)
>
> [ 154.675070] Possible unsafe locking scenario:
>
> [ 154.681679] CPU0 CPU1
> [ 154.686728] ---- ----
> [ 154.691776] lock((work_completion)(&queue->release_work));
> [ 154.698102] lock((wq_completion)events);
> [ 154.705493] lock((work_completion)(&queue->release_work));
> [ 154.714631] lock((work_completion)(&queue->io_work));
> [ 154.720470]
> *** DEADLOCK ***
>
> [ 154.727080] 2 locks held by kworker/7:2/260:
> [ 154.731849] #0: ffff888100053148
> ((wq_completion)events){+.+.}-{0:0}, at: process_one_work+0x792/0x1480
> [ 154.742458] #1: ffffc90002b57db0
> ((work_completion)(&queue->release_work)){+.+.}-{0:0}, at:
> process_one_work+0x7c1/0x1480
> [ 154.754809]
> stack backtrace:
> [ 154.759674] CPU: 7 PID: 260 Comm: kworker/7:2 Not tainted
> 5.12.0-rc3.fix+ #2
> [ 154.767549] Hardware name: Dell Inc. PowerEdge
> R730xd/\xc9\xb2\xdePow, BIOS 2.12.1 12/04/2020
> [ 154.776197] Workqueue: events nvmet_tcp_release_queue_work [nvmet_tcp]
> [ 154.783497] Call Trace:
> [ 154.786231] dump_stack+0x93/0xc2
> [ 154.789942] check_noncircular+0x26a/0x310
> [ 154.794521] ? print_circular_bug+0x460/0x460
> [ 154.799391] ? deref_stack_reg+0x170/0x170
> [ 154.803967] ? alloc_chain_hlocks+0x1de/0x520
> [ 154.808843] check_prev_add+0x15e/0x20f0
> [ 154.813231] validate_chain+0xec9/0x19c0
> [ 154.817611] ? check_prev_add+0x20f0/0x20f0
> [ 154.822286] ? save_trace+0x88/0x5e0
> [ 154.826290] __lock_acquire+0xb77/0x18d0
> [ 154.830682] lock_acquire+0x1ca/0x480
> [ 154.834775] ? __flush_work+0x118/0x1a0
> [ 154.839066] ? rcu_read_unlock+0x40/0x40
> [ 154.843455] ? __lock_acquire+0xb77/0x18d0
> [ 154.848036] __flush_work+0x139/0x1a0
> [ 154.852120] ? __flush_work+0x118/0x1a0
> [ 154.856409] ? start_flush_work+0x810/0x810
> [ 154.861084] ? mark_lock+0xd3/0x1470
> [ 154.865082] ? mark_lock_irq+0x1d10/0x1d10
> [ 154.869662] ? lock_downgrade+0x100/0x100
> [ 154.874147] ? mark_held_locks+0xa5/0xe0
> [ 154.878522] ? sk_stream_wait_memory+0xe40/0xe40
> [ 154.883686] ? lockdep_hardirqs_on_prepare.part.0+0x198/0x340
> [ 154.890394] ? __local_bh_enable_ip+0xa2/0x100
> [ 154.895358] ? trace_hardirqs_on+0x1c/0x160
> [ 154.900034] ? sk_stream_wait_memory+0xe40/0xe40
> [ 154.905192] nvmet_tcp_release_queue_work+0x2e5/0xcb0 [nvmet_tcp]
> [ 154.911999] ? lock_is_held_type+0x9a/0x110
> [ 154.916676] process_one_work+0x8b2/0x1480
> [ 154.921255] ? pwq_dec_nr_in_flight+0x260/0x260
> [ 154.926315] ? __lock_contended+0x910/0x910
> [ 154.930990] ? worker_thread+0x150/0xf80
> [ 154.935374] worker_thread+0x590/0xf80
> [ 154.939564] ? __kthread_parkme+0xcb/0x1b0
> [ 154.944140] ? process_one_work+0x1480/0x1480
> [ 154.949007] kthread+0x368/0x440
> [ 154.952615] ? _raw_spin_unlock_irq+0x24/0x30
> [ 154.957482] ? __kthread_bind_mask+0x90/0x90
> [ 154.962255] ret_from_fork+0x22/0x30
>
>
> On 3/21/21 3:08 PM, Sagi Grimberg wrote:
>> We are not changing anything in the TCP connection state so
>> we should not take a write_lock but rather a read lock.
>>
>> This caused a deadlock when running nvmet-tcp and nvme-tcp
>> on the same system, where state_change callbacks on the
>> host and on the controller side have causal relationship
>> and made lockdep report on this with blktests:
>
More information about the Linux-nvme
mailing list