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:

quoted

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:

_______________________________________________
Linux-nvme mailing list
Linux-nvme@lists.infradead.org
http://lists.infradead.org/mailman/listinfo/linux-nvme