[bug report] WARNING: possible circular locking dependency detected with blktests nvme-tcp nvme/013
Yi Zhang
yi.zhang at redhat.com
Thu Feb 10 21:38:40 PST 2022
On Wed, Sep 29, 2021 at 7:06 PM Sagi Grimberg <sagi at grimberg.me> wrote:
>
>
> > Hello
> >
> > Bellow warning was triggered with blktests nvme-tcp on latest
> > 5.15.0-rc3, pls help check it.
>
> Hey Yi, thanks for reporting..
>
> I'm trying to understand the circular locking here. I'm trying to
> understand if this is due to having an allocation in the
> network send path that may cause a circular dependency.
>
> >
Hi Sagi
This issue is still reproducible on the latest 5.17.0-rc3, fee free to
let me know if you need any testing for it. :)
[ 5960.130892] run blktests nvme/013 at 2022-02-11 00:31:51
[ 5960.456011] nvmet: adding nsid 1 to subsystem blktests-subsystem-1
[ 5960.483756] nvmet_tcp: enabling port 0 (127.0.0.1:4420)
[ 5960.511578] nvmet: creating nvm controller 1 for subsystem
blktests-subsystem-1 for NQN
nqn.2014-08.org.nvmexpress:uuid:4c4c4544-0035-4b10-8044-b9c04f463333.
[ 5960.515933] nvme nvme0: creating 32 I/O queues.
[ 5960.536234] nvme nvme0: mapped 32/0/0 default/read/poll queues.
[ 5960.551779] nvme nvme0: new ctrl: NQN "blktests-subsystem-1", addr
127.0.0.1:4420
[ 5961.788277] XFS (nvme0n1): Mounting V5 Filesystem
[ 5961.820057] XFS (nvme0n1): Ending clean mount
[ 5961.826643] xfs filesystem being mounted at /mnt/blktests supports
timestamps until 2038 (0x7fffffff)
[ 5966.115175] ======================================================
[ 5966.121352] WARNING: possible circular locking dependency detected
[ 5966.127533] 5.17.0-rc3 #2 Tainted: G S I
[ 5966.132585] ------------------------------------------------------
[ 5966.138763] fio/5034 is trying to acquire lock:
[ 5966.143295] ffff8882ad9158c0 (sk_lock-AF_INET){+.+.}-{0:0}, at:
tcp_sendpage+0x23/0x50
[ 5966.151218]
but task is already holding lock:
[ 5966.157050] ffff8881d51246b0 (&xfs_dir_ilock_class/5){+.+.}-{3:3},
at: xfs_ilock+0x166/0x4a0 [xfs]
[ 5966.166149]
which lock already depends on the new lock.
[ 5966.174321]
the existing dependency chain (in reverse order) is:
[ 5966.181801]
-> #3 (&xfs_dir_ilock_class/5){+.+.}-{3:3}:
[ 5966.188509] lock_acquire+0x1d2/0x5a0
[ 5966.192695] down_write_nested+0xa2/0x3b0
[ 5966.197227] xfs_ilock+0x166/0x4a0 [xfs]
[ 5966.201793] xfs_create+0x64b/0x12e0 [xfs]
[ 5966.206524] xfs_generic_create+0x25b/0x5a0 [xfs]
[ 5966.211863] lookup_open+0xea8/0x1850
[ 5966.216049] path_openat+0x705/0x2370
[ 5966.220235] do_filp_open+0x1a4/0x280
[ 5966.224421] do_sys_openat2+0x30d/0x670
[ 5966.228779] do_sys_open+0x8a/0xd0
[ 5966.232706] do_syscall_64+0x37/0x80
[ 5966.236805] entry_SYSCALL_64_after_hwframe+0x44/0xae
[ 5966.242379]
-> #2 (sb_internal){.+.+}-{0:0}:
[ 5966.248125] lock_acquire+0x1d2/0x5a0
[ 5966.252309] xfs_trans_alloc+0x3b1/0x980 [xfs]
[ 5966.257388] xfs_vn_update_time+0x201/0x610 [xfs]
[ 5966.262728] touch_atime+0x2fa/0x490
[ 5966.266824] xfs_file_mmap+0x244/0x2d0 [xfs]
[ 5966.271732] mmap_region+0x87f/0x11c0
[ 5966.275917] do_mmap+0x58c/0xc00
[ 5966.279670] vm_mmap_pgoff+0x178/0x220
[ 5966.283942] ksys_mmap_pgoff+0x2f3/0x470
[ 5966.288387] do_syscall_64+0x37/0x80
[ 5966.292488] entry_SYSCALL_64_after_hwframe+0x44/0xae
[ 5966.298060]
-> #1 (&mm->mmap_lock#2){++++}-{3:3}:
[ 5966.304246] lock_acquire+0x1d2/0x5a0
[ 5966.308433] __might_fault+0xe2/0x160
[ 5966.312617] _copy_from_user+0x20/0xd0
[ 5966.316893] copy_bpf_fprog_from_user+0x16f/0x1f0
[ 5966.322118] sock_setsockopt+0x663/0x25b0
[ 5966.326649] __sys_setsockopt+0x39e/0x4e0
[ 5966.331183] __x64_sys_setsockopt+0xba/0x150
[ 5966.335974] do_syscall_64+0x37/0x80
[ 5966.340074] entry_SYSCALL_64_after_hwframe+0x44/0xae
[ 5966.345647]
-> #0 (sk_lock-AF_INET){+.+.}-{0:0}:
[ 5966.351738] check_prevs_add+0x3fd/0x2480
[ 5966.356271] __lock_acquire+0x2402/0x2fa0
[ 5966.360803] lock_acquire+0x1d2/0x5a0
[ 5966.364990] lock_sock_nested+0x37/0xd0
[ 5966.369350] tcp_sendpage+0x23/0x50
[ 5966.373362] inet_sendpage+0xb3/0x130
[ 5966.377547] kernel_sendpage+0x1c0/0x2f0
[ 5966.381992] nvme_tcp_try_send+0x552/0x2250 [nvme_tcp]
[ 5966.387651] nvme_tcp_queue_rq+0xf3b/0x17b0 [nvme_tcp]
[ 5966.393312] __blk_mq_try_issue_directly+0x448/0x660
[ 5966.398797] blk_mq_plug_issue_direct.constprop.75+0x13a/0x210
[ 5966.405149] blk_mq_flush_plug_list+0x828/0xfd0
[ 5966.410201] blk_flush_plug+0x2b8/0x4c0
[ 5966.414561] blk_finish_plug+0x47/0x90
[ 5966.418834] _xfs_buf_ioapply+0x6ed/0xb70 [xfs]
[ 5966.423998] __xfs_buf_submit+0x228/0x650 [xfs]
[ 5966.429155] xfs_buf_read_map+0x365/0x970 [xfs]
[ 5966.434320] xfs_trans_read_buf_map+0x694/0x11b0 [xfs]
[ 5966.440101] xfs_btree_read_buf_block.constprop.28+0x1dc/0x340 [xfs]
[ 5966.447076] xfs_btree_lookup_get_block+0x1a6/0x630 [xfs]
[ 5966.453092] xfs_btree_lookup+0x39f/0xf20 [xfs]
[ 5966.458240] xfs_dialloc_ag_update_inobt+0x19d/0x4e0 [xfs]
[ 5966.464350] xfs_dialloc+0x8a7/0x11c0 [xfs]
[ 5966.469161] xfs_create+0xb85/0x12e0 [xfs]
[ 5966.473891] xfs_generic_create+0x25b/0x5a0 [xfs]
[ 5966.479228] lookup_open+0xea8/0x1850
[ 5966.483416] path_openat+0x705/0x2370
[ 5966.487601] do_filp_open+0x1a4/0x280
[ 5966.491787] do_sys_openat2+0x30d/0x670
[ 5966.496145] do_sys_open+0x8a/0xd0
[ 5966.500072] do_syscall_64+0x37/0x80
[ 5966.504172] entry_SYSCALL_64_after_hwframe+0x44/0xae
[ 5966.509742]
other info that might help us debug this:
[ 5966.517744] Chain exists of:
sk_lock-AF_INET --> sb_internal --> &xfs_dir_ilock_class/5
[ 5966.528784] Possible unsafe locking scenario:
[ 5966.534703] CPU0 CPU1
[ 5966.539235] ---- ----
[ 5966.543768] lock(&xfs_dir_ilock_class/5);
[ 5966.547954] lock(sb_internal);
[ 5966.553701] lock(&xfs_dir_ilock_class/5);
[ 5966.560397] lock(sk_lock-AF_INET);
[ 5966.563978]
*** DEADLOCK ***
[ 5966.569897] 6 locks held by fio/5034:
[ 5966.573562] #0: ffff88829c044470 (sb_writers#14){.+.+}-{0:0}, at:
path_openat+0x2182/0x2370
[ 5966.582004] #1: ffff8881d51248f0
(&inode->i_sb->s_type->i_mutex_dir_key){++++}-{3:3}, at:
path_openat+0x6f2/0x2370
[ 5966.592439] #2: ffff88829c044690 (sb_internal){.+.+}-{0:0}, at:
xfs_trans_alloc_icreate+0xa4/0x180 [xfs]
[ 5966.602118] #3: ffff8881d51246b0
(&xfs_dir_ilock_class/5){+.+.}-{3:3}, at: xfs_ilock+0x166/0x4a0 [xfs]
[ 5966.611626] #4: ffff88829c0154d0 (q->srcu){....}-{0:0}, at:
blk_mq_flush_plug_list+0x7d2/0xfd0
[ 5966.620327] #5: ffff888e2e7dbcd0 (&queue->send_mutex){+.+.}-{3:3},
at: nvme_tcp_queue_rq+0xef5/0x17b0 [nvme_tcp]
[ 5966.630588]
stack backtrace:
[ 5966.634948] CPU: 24 PID: 5034 Comm: fio Tainted: G S I
5.17.0-rc3 #2
[ 5966.642425] Hardware name: Dell Inc. PowerEdge R640/06NR82, BIOS
2.11.2 004/21/2021
[ 5966.650078] Call Trace:
[ 5966.652532] <TASK>
[ 5966.654637] dump_stack_lvl+0x44/0x57
[ 5966.658303] check_noncircular+0x280/0x320
[ 5966.662403] ? print_circular_bug.isra.47+0x430/0x430
[ 5966.667455] ? mark_lock.part.52+0x107/0x1210
[ 5966.671814] ? mark_lock.part.52+0x107/0x1210
[ 5966.676175] ? lock_chain_count+0x20/0x20
[ 5966.680186] check_prevs_add+0x3fd/0x2480
[ 5966.684202] ? check_irq_usage+0xb50/0xb50
[ 5966.688296] ? lockdep_lock+0xcb/0x1c0
[ 5966.692051] ? static_obj+0xc0/0xc0
[ 5966.695542] ? sched_clock_cpu+0x15/0x200
[ 5966.699555] __lock_acquire+0x2402/0x2fa0
[ 5966.703570] ? rcu_read_lock_bh_held+0xc0/0xc0
[ 5966.708012] lock_acquire+0x1d2/0x5a0
[ 5966.711679] ? tcp_sendpage+0x23/0x50
[ 5966.715347] ? rcu_read_unlock+0x50/0x50
[ 5966.719272] ? sched_clock_cpu+0x15/0x200
[ 5966.723284] lock_sock_nested+0x37/0xd0
[ 5966.727121] ? tcp_sendpage+0x23/0x50
[ 5966.730789] tcp_sendpage+0x23/0x50
[ 5966.734281] inet_sendpage+0xb3/0x130
[ 5966.737946] kernel_sendpage+0x1c0/0x2f0
[ 5966.741873] nvme_tcp_try_send+0x552/0x2250 [nvme_tcp]
[ 5966.747012] ? lock_is_held_type+0xd9/0x130
[ 5966.751199] ? nvme_tcp_try_send_ddgst+0x330/0x330 [nvme_tcp]
[ 5966.756944] ? ww_mutex_unlock+0x2f0/0x2f0
[ 5966.761044] ? __rq_qos_issue+0x4f/0x90
[ 5966.764885] nvme_tcp_queue_rq+0xf3b/0x17b0 [nvme_tcp]
[ 5966.770021] ? __lock_acquire+0xc31/0x2fa0
[ 5966.774120] __blk_mq_try_issue_directly+0x448/0x660
[ 5966.779086] ? __blk_mq_get_driver_tag+0xa70/0xa70
[ 5966.783877] ? rcu_read_lock_bh_held+0xc0/0xc0
[ 5966.788325] blk_mq_plug_issue_direct.constprop.75+0x13a/0x210
[ 5966.794158] ? blk_mq_requeue_work+0x6c0/0x6c0
[ 5966.798601] ? lock_is_held_type+0xd9/0x130
[ 5966.802789] blk_mq_flush_plug_list+0x828/0xfd0
[ 5966.807321] ? blk_mq_flush_plug_list+0x7d2/0xfd0
[ 5966.812028] ? submit_bio_noacct+0x31d/0x840
[ 5966.816299] ? blk_mq_insert_requests+0x590/0x590
[ 5966.821003] ? find_held_lock+0x3a/0x1c0
[ 5966.824932] blk_flush_plug+0x2b8/0x4c0
[ 5966.828771] ? blk_start_plug_nr_ios+0x270/0x270
[ 5966.833390] ? submit_bio_noacct+0x840/0x840
[ 5966.837663] blk_finish_plug+0x47/0x90
[ 5966.841413] _xfs_buf_ioapply+0x6ed/0xb70 [xfs]
[ 5966.846064] ? __xfs_buf_submit+0x134/0x650 [xfs]
[ 5966.850878] ? xfs_buf_get_map+0xbc0/0xbc0 [xfs]
[ 5966.855602] ? rcu_read_lock_bh_held+0xc0/0xc0
[ 5966.860049] __xfs_buf_submit+0x228/0x650 [xfs]
[ 5966.864693] xfs_buf_read_map+0x365/0x970 [xfs]
[ 5966.869338] ? xfs_btree_read_buf_block.constprop.28+0x1dc/0x340 [xfs]
[ 5966.875957] ? find_held_lock+0x3a/0x1c0
[ 5966.879885] ? _xfs_buf_read+0x110/0x110 [xfs]
[ 5966.884443] ? lock_release+0x42f/0xc90
[ 5966.888285] xfs_trans_read_buf_map+0x694/0x11b0 [xfs]
[ 5966.893542] ? xfs_btree_read_buf_block.constprop.28+0x1dc/0x340 [xfs]
[ 5966.900163] ? xfs_trans_getsb+0x690/0x690 [xfs]
[ 5966.904904] ? __kasan_slab_alloc+0x6d/0x90
[ 5966.909091] ? xfs_btree_ptr_to_daddr+0x24f/0x6b0 [xfs]
[ 5966.914422] xfs_btree_read_buf_block.constprop.28+0x1dc/0x340 [xfs]
[ 5966.920867] ? __kernel_text_address+0xe/0x30
[ 5966.925228] ? xfs_btree_readahead_ptr.constprop.27+0x1f0/0x1f0 [xfs]
[ 5966.931765] ? xfs_btree_ptr_to_daddr+0x24f/0x6b0 [xfs]
[ 5966.937083] xfs_btree_lookup_get_block+0x1a6/0x630 [xfs]
[ 5966.942586] ? filter_irq_stacks+0xa0/0xa0
[ 5966.946682] ? xfs_btree_get_leaf_keys+0xdf/0x480 [xfs]
[ 5966.952004] ? xfs_btree_dec_cursor+0xe0/0xe0 [xfs]
[ 5966.956979] ? kasan_save_stack+0x2b/0x40
[ 5966.960992] ? kasan_save_stack+0x1c/0x40
[ 5966.965005] ? __kasan_slab_alloc+0x6d/0x90
[ 5966.969189] ? kmem_cache_alloc+0x105/0x2d0
[ 5966.973377] ? xfs_inobt_init_common+0x6e/0x300 [xfs]
[ 5966.978531] ? xfs_inobt_init_cursor+0x4f/0x170 [xfs]
[ 5966.983688] ? xfs_dialloc+0x893/0x11c0 [xfs]
[ 5966.988144] ? xfs_create+0xb85/0x12e0 [xfs]
[ 5966.992529] ? xfs_generic_create+0x25b/0x5a0 [xfs]
[ 5966.997524] xfs_btree_lookup+0x39f/0xf20 [xfs]
[ 5967.002162] ? xfs_btree_overlapped_query_range+0xfd0/0xfd0 [xfs]
[ 5967.008355] ? find_held_lock+0x3a/0x1c0
[ 5967.012281] ? lock_downgrade+0x6b0/0x6b0
[ 5967.016294] ? lock_is_held_type+0xd9/0x130
[ 5967.020480] ? xfs_inobt_init_common+0x6e/0x300 [xfs]
[ 5967.025634] ? rcu_read_lock_sched_held+0xaf/0xe0
[ 5967.030340] ? rcu_read_lock_bh_held+0xc0/0xc0
[ 5967.034788] xfs_dialloc_ag_update_inobt+0x19d/0x4e0 [xfs]
[ 5967.040378] ? xfs_dialloc_ag_finobt_newino.isra.19+0x550/0x550 [xfs]
[ 5967.046919] ? xfs_inobt_init_common+0x203/0x300 [xfs]
[ 5967.052165] xfs_dialloc+0x8a7/0x11c0 [xfs]
[ 5967.056458] ? xfs_ialloc_pagi_init+0xc0/0xc0 [xfs]
[ 5967.061437] ? down_write_nested+0x185/0x3b0
[ 5967.065708] ? _down_write_nest_lock+0x3b0/0x3b0
[ 5967.070328] ? rcu_read_lock_bh_held+0xc0/0xc0
[ 5967.074771] ? xfs_trans_alloc_inode+0x2c0/0x2c0 [xfs]
[ 5967.080026] ? xfs_create+0x64b/0x12e0 [xfs]
[ 5967.084420] xfs_create+0xb85/0x12e0 [xfs]
[ 5967.088634] ? xfs_init_new_inode+0x18a0/0x18a0 [xfs]
[ 5967.093806] ? get_cached_acl+0x185/0x390
[ 5967.097817] ? rcu_read_lock_held+0xaf/0xc0
[ 5967.102003] ? rcu_read_lock_sched_held+0xe0/0xe0
[ 5967.106709] ? _raw_spin_unlock_irqrestore+0x30/0x50
[ 5967.111675] ? get_cached_acl+0x185/0x390
[ 5967.115686] ? get_cached_acl+0x272/0x390
[ 5967.119699] ? posix_acl_fix_xattr_userns+0x290/0x290
[ 5967.124756] ? get_acl+0x18/0x260
[ 5967.128082] xfs_generic_create+0x25b/0x5a0 [xfs]
[ 5967.132909] ? xfs_setup_iops+0x3b0/0x3b0 [xfs]
[ 5967.137553] ? may_create+0x2ef/0x370
[ 5967.141217] ? selinux_inode_init_security+0x730/0x730
[ 5967.146359] ? selinux_inode_permission+0x288/0x3b0
[ 5967.151238] ? selinux_sk_alloc_security+0x1d0/0x1d0
[ 5967.156202] ? from_kgid+0x83/0xc0
[ 5967.159610] lookup_open+0xea8/0x1850
[ 5967.163277] ? lock_acquired+0x262/0xb10
[ 5967.167198] ? lookup_positive_unlocked+0x70/0x70
[ 5967.171910] ? __mnt_want_write+0x15b/0x240
[ 5967.176101] path_openat+0x705/0x2370
[ 5967.179766] ? do_syscall_64+0x27/0x80
[ 5967.183521] ? filename_lookup.part.60+0x390/0x390
[ 5967.188312] ? lock_is_held_type+0xd9/0x130
[ 5967.192497] ? alloc_fd+0x234/0x570
[ 5967.195991] ? sched_clock_cpu+0x15/0x200
[ 5967.200002] do_filp_open+0x1a4/0x280
[ 5967.203668] ? lock_release+0x42f/0xc90
[ 5967.207508] ? may_open_dev+0xc0/0xc0
[ 5967.211177] ? do_raw_spin_unlock+0x54/0x230
[ 5967.215459] do_sys_openat2+0x30d/0x670
[ 5967.219302] ? file_open_root+0x200/0x200
[ 5967.223316] ? ktime_get_coarse_real_ts64+0x11c/0x160
[ 5967.228367] do_sys_open+0x8a/0xd0
[ 5967.231772] ? filp_open+0x50/0x50
[ 5967.235178] ? syscall_trace_enter.isra.15+0x190/0x270
[ 5967.240319] do_syscall_64+0x37/0x80
[ 5967.243896] entry_SYSCALL_64_after_hwframe+0x44/0xae
[ 5967.248948] RIP: 0033:0x7ff075c3f296
[ 5967.252527] Code: 89 54 24 08 e8 9b f4 ff ff 8b 74 24 0c 48 8b 3c
24 41 89 c0 44 8b 54 24 08 b8 01 01 00 00 89 f2 48 89 fe bf 9c ff ff
ff 0f 05 <48> 3d 00 f0 ff ff 77 30 44 89 c7 89 44 24 08 e8 c6 f4 ff ff
8b 44
[ 5967.271273] RSP: 002b:00007ffc916b0af0 EFLAGS: 00000293 ORIG_RAX:
0000000000000101
[ 5967.278839] RAX: ffffffffffffffda RBX: 0000000000000000 RCX: 00007ff075c3f296
[ 5967.285971] RDX: 0000000000000041 RSI: 00007ff0640ff290 RDI: 00000000ffffff9c
[ 5967.293103] RBP: 0000000000000000 R08: 0000000000000000 R09: 00007ff0754627e0
[ 5967.300235] R10: 00000000000001a4 R11: 0000000000000293 R12: 000000003b600000
[ 5967.307370] R13: 0000000000000000 R14: 00007ff0640ff110 R15: 00007ff00b494000
[ 5967.314507] </TASK>
[ 6105.703881] XFS (nvme0n1): Unmounting Filesystem
[ 6105.765404] nvme nvme0: Removing ctrl: NQN "blktests-subsystem-1"
--
Best Regards,
Yi Zhang
More information about the Linux-nvme
mailing list