[bug report] NVMe/IB: WARNING: possible circular locking dependency detected on target after connect

Yi Zhang yi.zhang at redhat.com
Sun Feb 20 22:09:08 PST 2022


Hello
The below WARNING was triggered on the target side after a connection
on  5.17.0-rc3, here is the full log, let me if you need any tests for
it, thanks

HW:
# lspci | grep -i mel
04:00.0 Infiniband controller: Mellanox Technologies MT27700 Family [ConnectX-4]
04:00.1 Infiniband controller: Mellanox Technologies MT27700 Family [ConnectX-4]

dmesg:
[  514.481280] null_blk: module loaded
[  523.597381] nvmet: adding nsid 1 to subsystem testnqn
[  523.612212] nvmet_rdma: enabling port 2 (172.31.0.202:4420)
[  525.520199] mlx5_ib0.8008: multicast join failed for
ff12:401b:8008:0000:0000:0000:ffff:ffff, status -22
[  526.543740] mlx5_ib0.8016: multicast join failed for
ff12:401b:8016:0000:0000:0000:ffff:ffff, status -22

[  540.633829] ======================================================
[  540.640765] WARNING: possible circular locking dependency detected
[  540.647709] 5.17.0-rc3.rc3.debug #3 Tainted: G S
[  540.655117] ------------------------------------------------------
[  540.662753] kworker/10:3/1152 is trying to acquire lock:
[  540.669414] ffff88810005c548 ((wq_completion)events){+.+.}-{0:0},
at: flush_workqueue+0xe6/0x1400
[  540.680127]
               but task is already holding lock:
[  540.688047] ffff8883914483e0
(&id_priv->handler_mutex/1){+.+.}-{3:3}, at:
cma_ib_req_handler+0x1709/0x4a60 [rdma_cm]
[  540.700602]
               which lock already depends on the new lock.

[  540.712121]
               the existing dependency chain (in reverse order) is:
[  540.722123]
               -> #10 (&id_priv->handler_mutex/1){+.+.}-{3:3}:
[  540.731728]        lock_acquire+0x1d2/0x5a0
[  540.737298]        __mutex_lock+0x155/0x15f0
[  540.742975]        cma_ib_req_handler+0x1709/0x4a60 [rdma_cm]
[  540.750330]        cm_process_work+0x47/0x190 [ib_cm]
[  540.756928]        cm_req_handler+0x2235/0x6fd0 [ib_cm]
[  540.763727]        cm_work_handler+0x1acf/0x4a30 [ib_cm]
[  540.770637]        process_one_work+0x97e/0x1700
[  540.776770]        worker_thread+0x87/0xb30
[  540.782429]        kthread+0x29d/0x340
[  540.787609]        ret_from_fork+0x22/0x30
[  540.793186]
               -> #9 (&id_priv->handler_mutex){+.+.}-{3:3}:
[  540.802794]        lock_acquire+0x1d2/0x5a0
[  540.808510]        __mutex_lock+0x155/0x15f0
[  540.814331]        cma_ib_req_handler+0xf86/0x4a60 [rdma_cm]
[  540.821736]        cm_process_work+0x47/0x190 [ib_cm]
[  540.828477]        cm_req_handler+0x2235/0x6fd0 [ib_cm]
[  540.835424]        cm_work_handler+0x1acf/0x4a30 [ib_cm]
[  540.842485]        process_one_work+0x97e/0x1700
[  540.848768]        worker_thread+0x87/0xb30
[  540.854575]        kthread+0x29d/0x340
[  540.859903]        ret_from_fork+0x22/0x30
[  540.865628]
               -> #8 ((work_completion)(&(&work->work)->work)){+.+.}-{0:0}:
[  540.877103]        lock_acquire+0x1d2/0x5a0
[  540.882984]        process_one_work+0x8dd/0x1700
[  540.889364]        worker_thread+0x87/0xb30
[  540.895267]        kthread+0x29d/0x340
[  540.900688]        ret_from_fork+0x22/0x30
[  540.906509]
               -> #7 ((wq_completion)ib_cm){+.+.}-{0:0}:
[  540.916268]        lock_acquire+0x1d2/0x5a0
[  540.922155]        flush_workqueue+0x109/0x1400
[  540.928418]        cm_remove_one+0x31d/0x560 [ib_cm]
[  540.935164]        remove_client_context+0xa9/0xf0 [ib_core]
[  540.942712]        disable_device+0x12d/0x210 [ib_core]
[  540.949754]        __ib_unregister_device+0x80/0x160 [ib_core]
[  540.957456]        ib_unregister_device+0x21/0x30 [ib_core]
[  540.964844]        __mlx5_ib_remove+0x88/0xe0 [mlx5_ib]
[  540.971848]        auxiliary_bus_remove+0x55/0x80
[  540.978213]        device_release_driver_internal+0x1e5/0x4a0
[  540.985713]        bus_remove_device+0x2a9/0x570
[  540.991936]        device_del+0x54a/0xd10
[  540.997483]        mlx5_rescan_drivers_locked+0x1d4/0x830 [mlx5_core]
[  541.005879]        mlx5_lag_remove_devices+0xcb/0x110 [mlx5_core]
[  541.013867]        mlx5_do_bond_work+0x83c/0xf00 [mlx5_core]
[  541.021361]        process_one_work+0x97e/0x1700
[  541.027611]        worker_thread+0x87/0xb30
[  541.033361]        kthread+0x29d/0x340
[  541.038627]        ret_from_fork+0x22/0x30
[  541.044272]
               -> #6 (&device->unregistration_lock){+.+.}-{3:3}:
[  541.054465]        lock_acquire+0x1d2/0x5a0
[  541.060212]        __mutex_lock+0x155/0x15f0
[  541.066050]        __ib_unregister_device+0x24/0x160 [ib_core]
[  541.073675]        ib_unregister_device+0x21/0x30 [ib_core]
[  541.081015]        __mlx5_ib_remove+0x88/0xe0 [mlx5_ib]
[  541.087966]        auxiliary_bus_remove+0x55/0x80
[  541.094325]        device_release_driver_internal+0x1e5/0x4a0
[  541.101856]        bus_remove_device+0x2a9/0x570
[  541.108117]        device_del+0x54a/0xd10
[  541.113701]        mlx5_rescan_drivers_locked+0x1d4/0x830 [mlx5_core]
[  541.122096]        mlx5_lag_remove_devices+0xcb/0x110 [mlx5_core]
[  541.130104]        mlx5_do_bond_work+0x83c/0xf00 [mlx5_core]
[  541.137619]        process_one_work+0x97e/0x1700
[  541.143899]        worker_thread+0x87/0xb30
[  541.149689]        kthread+0x29d/0x340
[  541.154988]        ret_from_fork+0x22/0x30
[  541.160678]
               -> #5 (&esw->mode_lock_key#2){+.+.}-{3:3}:
[  541.170295]        lock_acquire+0x1d2/0x5a0
[  541.176080]        down_write+0x9e/0x3d0
[  541.181554]        mlx5_do_bond_work+0x15e/0xf00 [mlx5_core]
[  541.189061]        process_one_work+0x97e/0x1700
[  541.195329]        worker_thread+0x87/0xb30
[  541.201111]        kthread+0x29d/0x340
[  541.206407]        ret_from_fork+0x22/0x30
[  541.212091]
               -> #4 (&esw->mode_lock_key){+.+.}-{3:3}:
[  541.221482]        lock_acquire+0x1d2/0x5a0
[  541.227261]        down_write+0x9e/0x3d0
[  541.232734]        mlx5_do_bond_work+0x129/0xf00 [mlx5_core]
[  541.240242]        process_one_work+0x97e/0x1700
[  541.246503]        worker_thread+0x87/0xb30
[  541.252268]        kthread+0x29d/0x340
[  541.257537]        ret_from_fork+0x22/0x30
[  541.263177]
               -> #3 (mlx5_intf_mutex){+.+.}-{3:3}:
[  541.272098]        lock_acquire+0x1d2/0x5a0
[  541.277828]        __mutex_lock+0x155/0x15f0
[  541.283653]        mlx5_lag_add_mdev+0x36/0x610 [mlx5_core]
[  541.291011]        mlx5_load+0x1b6/0x240 [mlx5_core]
[  541.297671]        mlx5_init_one+0x337/0x470 [mlx5_core]
[  541.304713]        probe_one+0x412/0x5f0 [mlx5_core]
[  541.311366]        local_pci_probe+0xde/0x170
[  541.317274]        work_for_cpu_fn+0x51/0xa0
[  541.323084]        process_one_work+0x97e/0x1700
[  541.329286]        worker_thread+0x538/0xb30
[  541.335100]        kthread+0x29d/0x340
[  541.340309]        ret_from_fork+0x22/0x30
[  541.345905]
               -> #2 (&dev->intf_state_mutex){+.+.}-{3:3}:
[  541.355423]        lock_acquire+0x1d2/0x5a0
[  541.361115]        __mutex_lock+0x155/0x15f0
[  541.366885]        mlx5_init_one+0x2e/0x470 [mlx5_core]
[  541.373799]        probe_one+0x412/0x5f0 [mlx5_core]
[  541.380421]        local_pci_probe+0xde/0x170
[  541.386286]        work_for_cpu_fn+0x51/0xa0
[  541.392052]        process_one_work+0x97e/0x1700
[  541.398195]        worker_thread+0x538/0xb30
[  541.403930]        kthread+0x29d/0x340
[  541.409083]        ret_from_fork+0x22/0x30
[  541.414615]
               -> #1 ((work_completion)(&wfc.work)){+.+.}-{0:0}:
[  541.424600]        lock_acquire+0x1d2/0x5a0
[  541.430253]        process_one_work+0x8dd/0x1700
[  541.436396]        worker_thread+0x87/0xb30
[  541.442049]        kthread+0x29d/0x340
[  541.447204]        ret_from_fork+0x22/0x30
[  541.452748]
               -> #0 ((wq_completion)events){+.+.}-{0:0}:
[  541.462048]        check_prevs_add+0x3fd/0x2480
[  541.468075]        __lock_acquire+0x2402/0x2fa0
[  541.474100]        lock_acquire+0x1d2/0x5a0
[  541.479739]        flush_workqueue+0x109/0x1400
[  541.485770]        nvmet_rdma_queue_connect+0x1c79/0x2610 [nvmet_rdma]
[  541.494059]        cma_cm_event_handler+0xf2/0x530 [rdma_cm]
[  541.501382]        cma_ib_req_handler+0x1a76/0x4a60 [rdma_cm]
[  541.508809]        cm_process_work+0x47/0x190 [ib_cm]
[  541.515456]        cm_req_handler+0x2235/0x6fd0 [ib_cm]
[  541.522294]        cm_work_handler+0x1acf/0x4a30 [ib_cm]
[  541.529225]        process_one_work+0x97e/0x1700
[  541.535380]        worker_thread+0x87/0xb30
[  541.541050]        kthread+0x29d/0x340
[  541.546235]        ret_from_fork+0x22/0x30
[  541.551807]
               other info that might help us debug this:

[  541.563694] Chain exists of:
                 (wq_completion)events --> &id_priv->handler_mutex -->
&id_priv->handler_mutex/1

[  541.581095]  Possible unsafe locking scenario:

[  541.589747]        CPU0                    CPU1
[  541.595828]        ----                    ----
[  541.601891]   lock(&id_priv->handler_mutex/1);
[  541.607873]                                lock(&id_priv->handler_mutex);
[  541.616508]                                lock(&id_priv->handler_mutex/1);
[  541.625321]   lock((wq_completion)events);
[  541.630935]
                *** DEADLOCK ***

[  541.640567] 4 locks held by kworker/10:3/1152:
[  541.646535]  #0: ffff8891339a0548
((wq_completion)ib_cm){+.+.}-{0:0}, at: process_one_work+0x857/0x1700
[  541.658114]  #1: ffff88832ebcfe08
((work_completion)(&(&work->work)->work)){+.+.}-{0:0}, at:
process_one_work+0x88b/0x1700
[  541.671586]  #2: ffff8884081a53e0
(&id_priv->handler_mutex){+.+.}-{3:3}, at:
cma_ib_req_handler+0xf86/0x4a60 [rdma_cm]
[  541.684712]  #3: ffff8883914483e0
(&id_priv->handler_mutex/1){+.+.}-{3:3}, at:
cma_ib_req_handler+0x1709/0x4a60 [rdma_cm]
[  541.698155]
               stack backtrace:
[  541.705358] CPU: 10 PID: 1152 Comm: kworker/10:3 Tainted: G S
         5.17.0-rc3.rc3.debug #3
[  541.716799] Hardware name: Dell Inc. PowerEdge R430/03XKDV, BIOS
1.6.2 01/08/2016
[  541.726409] Workqueue: ib_cm cm_work_handler [ib_cm]
[  541.733209] Call Trace:
[  541.737175]  <TASK>
[  541.740741]  dump_stack_lvl+0x44/0x57
[  541.746073]  check_noncircular+0x280/0x320
[  541.751889]  ? lock_chain_count+0x20/0x20
[  541.757611]  ? print_circular_bug.isra.47+0x430/0x430
[  541.764505]  ? mark_lock.part.52+0x107/0x1210
[  541.770616]  ? mark_lock.part.52+0x107/0x1210
[  541.776715]  ? lock_chain_count+0x20/0x20
[  541.782423]  ? lock_chain_count+0x20/0x20
[  541.788118]  check_prevs_add+0x3fd/0x2480
[  541.793800]  ? sched_clock_cpu+0x15/0x200
[  541.799470]  ? check_irq_usage+0xb50/0xb50
[  541.805226]  ? lockdep_lock+0xcb/0x1c0
[  541.810587]  ? static_obj+0xc0/0xc0
[  541.815649]  ? sched_clock_cpu+0x15/0x200
[  541.821295]  __lock_acquire+0x2402/0x2fa0
[  541.826930]  ? rcu_read_lock_bh_held+0xc0/0xc0
[  541.833061]  lock_acquire+0x1d2/0x5a0
[  541.838316]  ? flush_workqueue+0xe6/0x1400
[  541.844066]  ? rcu_read_unlock+0x50/0x50
[  541.849618]  ? lockdep_init_map_type+0x2f8/0x7f0
[  541.855950]  ? lockdep_init_map_type+0x2f8/0x7f0
[  541.862267]  flush_workqueue+0x109/0x1400
[  541.867898]  ? flush_workqueue+0xe6/0x1400
[  541.873610]  ? rdma_create_qp+0x423/0x6d0 [rdma_cm]
[  541.880188]  ? nvmet_rdma_create_queue_ib+0x7e1/0xa90 [nvmet_rdma]
[  541.888236]  ? check_flush_dependency+0x410/0x410
[  541.894638]  ? _raw_spin_unlock_irqrestore+0x3b/0x50
[  541.901348]  ? nvmet_rdma_queue_connect+0x1c79/0x2610 [nvmet_rdma]
[  541.909442]  nvmet_rdma_queue_connect+0x1c79/0x2610 [nvmet_rdma]
[  541.917357]  ? nvmet_rdma_alloc_cmds+0xd80/0xd80 [nvmet_rdma]
[  541.924970]  ? sched_clock_cpu+0x15/0x200
[  541.930652]  ? find_held_lock+0x3a/0x1c0
[  541.936219]  ? lock_release+0x42f/0xc90
[  541.941685]  ? lock_downgrade+0x6b0/0x6b0
[  541.947350]  ? lock_is_held_type+0xd9/0x130
[  541.953219]  ? rcu_read_lock_sched_held+0xaf/0xe0
[  541.959673]  ? rdma_find_gid+0x3d0/0x3d0 [ib_core]
[  541.966219]  ? rcu_read_lock_bh_held+0xc0/0xc0
[  541.972318]  ? lock_is_held_type+0xd9/0x130
[  541.978088]  cma_cm_event_handler+0xf2/0x530 [rdma_cm]
[  541.984922]  cma_ib_req_handler+0x1a76/0x4a60 [rdma_cm]
[  541.991815]  ? stack_trace_save+0x8a/0xb0
[  541.997355]  ? addr_handler+0x2a0/0x2a0 [rdma_cm]
[  542.003658]  ? alloc_list_entry+0x156/0x2c0
[  542.009343]  ? mark_lock.part.52+0x107/0x1210
[  542.015202]  ? lock_is_held_type+0xd9/0x130
[  542.020871]  ? cm_process_work+0x47/0x190 [ib_cm]
[  542.027130]  cm_process_work+0x47/0x190 [ib_cm]
[  542.033200]  ? _raw_spin_unlock+0x29/0x40
[  542.038683]  cm_req_handler+0x2235/0x6fd0 [ib_cm]
[  542.044947]  ? check_irq_usage+0xb50/0xb50
[  542.050528]  ? lockdep_lock+0xcb/0x1c0
[  542.055716]  ? cm_rep_handler+0x2440/0x2440 [ib_cm]
[  542.062199]  cm_work_handler+0x1acf/0x4a30 [ib_cm]
[  542.068590]  ? lock_is_held_type+0xd9/0x130
[  542.074307]  ? cm_req_handler+0x6fd0/0x6fd0 [ib_cm]
[  542.080815]  ? rcu_read_lock_sched_held+0xaf/0xe0
[  542.087126]  ? rcu_read_lock_bh_held+0xc0/0xc0
[  542.093144]  process_one_work+0x97e/0x1700
[  542.098777]  ? pwq_dec_nr_in_flight+0x270/0x270
[  542.104902]  worker_thread+0x87/0xb30
[  542.110056]  ? __kthread_parkme+0xc3/0x1d0
[  542.115698]  ? process_one_work+0x1700/0x1700
[  542.121627]  kthread+0x29d/0x340
[  542.126279]  ? kthread_complete_and_exit+0x20/0x20
[  542.132702]  ret_from_fork+0x22/0x30
[  542.137771]  </TASK>
[  542.192405] nvmet: creating nvm controller 1 for subsystem testnqn
for NQN nqn.2014-08.org.nvmexpress:uuid:4c4c4544-0056-4c10-8058-b7c04f383432.
[  546.991610] DMA-API: dma_debug_entry pool grown to 2162688 (3300%)

-- 
Best Regards,
  Yi Zhang




More information about the Linux-nvme mailing list