Re: RE: [PATCH] Revert "ceph: when filling trace, call ceph_get_inode outside of mutexes"
From: Viacheslav Dubeyko
Date: Mon Apr 27 2026 - 15:56:40 EST
On Fri, 2026-04-24 at 18:54 +0000, 李磊 wrote:
>
> > 2026年4月25日 02:11，Viacheslav Dubeyko <Slava.Dubeyko@xxxxxxx> 写道：
> >
> > 安全提示：此邮件来自公司外部。除非您确认发件人身份可信且邮件内容不含可疑信息，否则请勿回复或转发邮件、点击邮件链接或打开附件。
> >
> >
> > On Thu, 2026-04-23 at 19:50 +0000, Viacheslav Dubeyko wrote:
> > > On Sat, 2026-04-18 at 12:12 +0800, Li Lei wrote:
> > > > This reverts commit bca9fc14c70fcbbebc84954cc39994e463fb9468.
> > > >
> > > > Deadlock detected between mdsc->snap_rwsem and the I_NEW bit in
> > > > handle_reply().
> > > >
> > > > - kworker/u113:1 (stat inode)
> > > > 1) Hold a inode with I_NEW set
> > > > 2) Request for mdsc->snap_rwsem
> > > > - kworker/u113:2 (readdir)
> > > > 1) Hold mdsc->snap_rwsem
> > > > 2) Wait for inode I_NEW flag to be cleared
> > > >
> > > > task:kworker/u113:1 state:D stack: 0 pid:34454 ppid: 2
> > > > flags:0x00004000
> > > > Workqueue: ceph-msgr ceph_con_workfn [libceph]
> > > > Call Trace:
> > > > __schedule+0x3a9/0x8d0
> > > > schedule+0x49/0xb0
> > > > rwsem_down_write_slowpath+0x30a/0x5e0
> > > > handle_reply+0x4d7/0x7f0 [ceph]
> > > > ? ceph_tcp_recvmsg+0x6f/0xa0 [libceph]
> > > > mds_dispatch+0x10a/0x690 [ceph]
> > > > ? calc_signature+0xdf/0x110 [libceph]
> > > > ? ceph_x_check_message_signature+0x58/0xc0 [libceph]
> > > > ceph_con_process_message+0x73/0x140 [libceph]
> > > > ceph_con_v1_try_read+0x2f2/0x860 [libceph]
> > > > ceph_con_workfn+0x31e/0x660 [libceph]
> > > > process_one_work+0x1cb/0x370
> > > > worker_thread+0x30/0x390
> > > > ? process_one_work+0x370/0x370
> > > > kthread+0x13e/0x160
> > > > ? set_kthread_struct+0x50/0x50
> > > > ret_from_fork+0x1f/0x30
> > > >
> > > > task:kworker/u113:2 state:D stack: 0 pid:54267 ppid: 2
> > > > flags:0x00004000
> > > > Workqueue: ceph-msgr ceph_con_workfn [libceph]
> > > > Call Trace:
> > > > __schedule+0x3a9/0x8d0
> > > > ? bit_wait_io+0x60/0x60
> > > > ? bit_wait_io+0x60/0x60
> > > > schedule+0x49/0xb0
> > > > bit_wait+0xd/0x60
> > > > __wait_on_bit+0x2a/0x90
> > > > ? ceph_force_reconnect+0x90/0x90 [ceph]
> > > > out_of_line_wait_on_bit+0x91/0xb0
> > > > ? bitmap_empty+0x20/0x20
> > > > ilookup5.part.29+0x69/0x90
> > > > ? ceph_force_reconnect+0x90/0x90 [ceph]
> > > > ? ceph_ino_compare+0x30/0x30 [ceph]
> > > > iget5_locked+0x26/0x90
> > > > ceph_get_inode+0x45/0x130 [ceph]
> > > > ceph_readdir_prepopulate+0x59f/0xca0 [ceph]
> > > > handle_reply+0x78d/0x7f0 [ceph]
> > > > ? ceph_tcp_recvmsg+0x6f/0xa0 [libceph]
> > > > mds_dispatch+0x10a/0x690 [ceph]
> > > > ? calc_signature+0xdf/0x110 [libceph]
> > > > ? ceph_x_check_message_signature+0x58/0xc0 [libceph]
> > > > ceph_con_process_message+0x73/0x140 [libceph]
> > > > ceph_con_v1_try_read+0x2f2/0x860 [libceph]
> > > > ceph_con_workfn+0x31e/0x660 [libceph]
> > > > process_one_work+0x1cb/0x370
> > > > worker_thread+0x30/0x390
> > > > ? process_one_work+0x370/0x370
> > > > kthread+0x13e/0x160
> > > > ? set_kthread_struct+0x50/0x50
> > > > ret_from_fork+0x1f/0x30
> > > >
> > > > It's rather rear to be caught, but here's Fast Reproduce Steps
> > > > (multiple mds is needed):
> > > > 1. Try to find 2 different directories (DIR_a DIR_b) in a cephfs cluster
> > > > and make sure they have different auth mds nodes. In this way, a client
> > > > may have chances to run handle_reply on different CPU for our test
> > > > (see step 5 and step 6).
> > > > 2. In DIR_b, create a hard link of DIR_a/FILE_a, namely FILE_b.
> > > > DIR_a/FILE_a and DIR_b/FILE_b have the same ino (123456 e.g)
> > > > 3. Save ino in code below, make it sleep for stat command.
> > > > ```
> > > > static void handle_reply(struct ceph_mds_session
> > > > *session, struct ceph_msg *msg)
> > > > goto out_err;
> > > > }
> > > > req->r_target_inode = in;
> > > > + if (in->i_ino == 123456) {
> > > > + pr_err("inode %lu found, ready to wait 10 seconds.\n",
> > > > + in->i_ino);
> > > > + msleep(10000);
> > > > + }
> > > > ```
> > > > 4. Execute echo 3 > /proc/sys/vm/drop_caches
> > > > 5. In a shell, do `cd DIR_a;stat DIR_a/FILE_a`, we suppose to be stuck on this shell
> > > > because of msleep() in handle_reply().
> > > > 6. In the other shell, do `cd DIR_b;ls DIR_b/` to trigger ceph_readdir_prepopulate()
> > > >
> > > > Repeat step 4-6, less than 10 times is enough to see the problem.
> > > >
> > > > It turns out that commit bca9fc14c70f ("ceph: when filling trace, call ceph_get_inode outside of mutexes")
> > > > moved ceph_inode_get outside snap_rmsem and made a chance for the deadlock of ceph_inode_get()
> > > > and snap_rwsem.
> > > >
> > > > After the following commit, original commit(bca9fc14c70f) can be reverted safely.
> > > > commit 6a92b08fdad2 ("ceph: don't take s_mutex or snap_rwsem in ceph_check_caps")
> > > >
> > > > Signed-off-by: Zhao Sun <sunzhao03@xxxxxxxxxxxx>
> > > > Signed-off-by: Li Lei <lilei24@xxxxxxxxxxxx>
> > > > ---
> > > > fs/ceph/inode.c | 26 ++++++++++++++++++++++----
> > > > fs/ceph/mds_client.c | 29 -----------------------------
> > > > 2 files changed, 22 insertions(+), 33 deletions(-)
> > > >
> > > > diff --git a/fs/ceph/inode.c b/fs/ceph/inode.c
> > > > index d99e12d..0c241a4 100644
> > > > --- a/fs/ceph/inode.c
> > > > +++ b/fs/ceph/inode.c
> > > > @@ -1667,10 +1667,28 @@ int ceph_fill_trace(struct super_block *sb, struct ceph_mds_request *req)
> > > > }
> > > >
> > > > if (rinfo->head->is_target) {
> > > > - /* Should be filled in by handle_reply */
> > > > - BUG_ON(!req->r_target_inode);
> > > > + in = xchg(&req->r_new_inode, NULL);
> > > > + tvino.ino = le64_to_cpu(rinfo->targeti.in->ino);
> > > > + tvino.snap = le64_to_cpu(rinfo->targeti.in->snapid);
> > > > +
> > > > + /*
> > > > + * If we ended up opening an existing inode, discard
> > > > + * r_new_inode
> > > > + */
> > > > + if (req->r_op == CEPH_MDS_OP_CREATE &&
> > > > + !req->r_reply_info.has_create_ino) {
> > > > + /* This should never happen on an async create */
> > > > + WARN_ON_ONCE(req->r_deleg_ino);
> > > > + iput(in);
> > > > + in = NULL;
> > > > + }
> > > > +
> > > > + in = ceph_get_inode(fsc->sb, tvino, in);
> > > > + if (IS_ERR(in)) {
> > > > + err = PTR_ERR(in);
> > > > + goto done;
> > > > + }
> > > >
> > > > - in = req->r_target_inode;
> > > > err = ceph_fill_inode(in, req->r_locked_page, &rinfo->targeti,
> > > > NULL, session,
> > > > (!test_bit(CEPH_MDS_R_ABORTED, &req->r_req_flags) &&
> > > > @@ -1680,13 +1698,13 @@ int ceph_fill_trace(struct super_block *sb, struct ceph_mds_request *req)
> > > > if (err < 0) {
> > > > pr_err_client(cl, "badness %p %llx.%llx\n", in,
> > > > ceph_vinop(in));
> > > > - req->r_target_inode = NULL;
> > > > if (inode_state_read_once(in) & I_NEW)
> > > > discard_new_inode(in);
> > > > else
> > > > iput(in);
> > > > goto done;
> > > > }
> > > > + req->r_target_inode = in;
> > > > if (inode_state_read_once(in) & I_NEW)
> > > > unlock_new_inode(in);
> > > > }
> > > > diff --git a/fs/ceph/mds_client.c b/fs/ceph/mds_client.c
> > > > index b174627..8a27775 100644
> > > > --- a/fs/ceph/mds_client.c
> > > > +++ b/fs/ceph/mds_client.c
> > > > @@ -3941,36 +3941,7 @@ static void handle_reply(struct ceph_mds_session *session, struct ceph_msg *msg)
> > > > session->s_con.peer_features);
> > > > mutex_unlock(&mdsc->mutex);
> > > >
> > > > - /* Must find target inode outside of mutexes to avoid deadlocks */
> > > > rinfo = &req->r_reply_info;
> > > > - if ((err >= 0) && rinfo->head->is_target) {
> > > > - struct inode *in = xchg(&req->r_new_inode, NULL);
> > > > - struct ceph_vino tvino = {
> > > > - .ino = le64_to_cpu(rinfo->targeti.in->ino),
> > > > - .snap = le64_to_cpu(rinfo->targeti.in->snapid)
> > > > - };
> > > > -
> > > > - /*
> > > > - * If we ended up opening an existing inode, discard
> > > > - * r_new_inode
> > > > - */
> > > > - if (req->r_op == CEPH_MDS_OP_CREATE &&
> > > > - !req->r_reply_info.has_create_ino) {
> > > > - /* This should never happen on an async create */
> > > > - WARN_ON_ONCE(req->r_deleg_ino);
> > > > - iput(in);
> > > > - in = NULL;
> > > > - }
> > > > -
> > > > - in = ceph_get_inode(mdsc->fsc->sb, tvino, in);
> > > > - if (IS_ERR(in)) {
> > > > - err = PTR_ERR(in);
> > > > - mutex_lock(&session->s_mutex);
> > > > - goto out_err;
> > > > - }
> > > > - req->r_target_inode = in;
> > > > - }
> > > > -
> > > > mutex_lock(&session->s_mutex);
> > > > if (err < 0) {
> > > > pr_err_client(cl, "got corrupt reply mds%d(tid:%lld)\n",
> > >
> > > Let me run xfstests for the patch to double check that nothing is broken.
> > >
> > >
> >
> > Unexpectedly, I have a crash on generic/701 with your patch applied. I am going
> > to re-run xfstests without your patch.
> >
> > generic/701 50s ... [failed, exit status 137]_check_dmesg: something found in
> > dmesg (see xfstests-dev/results//generic/701.dmesg)
> > - output mismatch (see xfstests-dev/results//generic/701.out.bad)
> > --- tests/generic/701.out 2026-04-01 19:47:53.878452478 -0700
> > +++ xfstests-dev/results//generic/701.out.bad 2026-04-24
> > 04:57:37.887700953 -0700
> > @@ -1,2 +1,3 @@
> > QA output created by 701
> > -Number of allocated blocks after truncate is in range
> > +pwrite: Permission denied
> > +./check: line 700: 311685 Killed systemd-run --quiet --
> > unit "${unit}" --scope "${cmd[@]}"
> > ...
> > (Run 'diff -u xfstests-dev/tests/generic/701.out xfstests-
> > dev/results//generic/701.out.bad' to see the entire diff)
> >
> > Apr 23 22:42:26 ssdfs-vm-test kernel: [29717.030383] ceph: [2bf3efd7-3e1c-453d-
> > 9665-3c75a0dc96dd 19499]: mds0 caps stale
> > Apr 23 22:43:18 ssdfs-vm-test kernel: [29733.938331] INFO: task
> > kworker/u32:0:241092 blocked for more than 122 seconds.
> > Apr 23 22:43:25 ssdfs-vm-test kernel: [29733.940727] Not tainted 7.0.0+ #9
> > Apr 23 22:43:25 ssdfs-vm-test kernel: [29733.941449] "echo 0 >
> > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
> > Apr 23 22:43:25 ssdfs-vm-test kernel: [29733.942756] task:kworker/u32:0
> > state:D stack:0 pid:241092 tgid:241092 ppid:2 task_flags:0x4208060
> > flags:0x00080000
> > Apr 23 22:43:26 ssdfs-vm-test kernel: [29733.942773] Workqueue: writeback
> > wb_workfn (flush-ceph-766)
> > Apr 23 22:43:26 ssdfs-vm-test kernel: [29733.942792] Call Trace:
> > Apr 23 22:43:26 ssdfs-vm-test kernel: [29733.942795] <TASK>
> > Apr 23 22:43:26 ssdfs-vm-test kernel: [29733.942803] __schedule+0x5b7/0x1fe0
> > Apr 23 22:43:26 ssdfs-vm-test kernel: [29733.942812] ? lock_acquire+0xc8/0x2f0
> > Apr 23 22:43:26 ssdfs-vm-test kernel: [29733.942819] ? schedule+0xb1/0x180
> > Apr 23 22:43:26 ssdfs-vm-test kernel: [29733.942823] ? find_held_lock+0x31/0x90
> > Apr 23 22:43:26 ssdfs-vm-test kernel: [29733.942829] ? schedule+0x10e/0x180
> > Apr 23 22:43:26 ssdfs-vm-test kernel: [29733.942834] ? lock_release+0xd9/0x300
> > Apr 23 22:43:26 ssdfs-vm-test kernel: [29733.942842] schedule+0x3a/0x180
> > Apr 23 22:43:26 ssdfs-vm-test kernel: [29733.942847]
> > schedule_preempt_disabled+0x15/0x30
> > Apr 23 22:43:26 ssdfs-vm-test kernel: [29733.942851] __mutex_lock+0x777/0x1220
> > Apr 23 22:43:26 ssdfs-vm-test kernel: [29733.942858] ? ceph_con_send+0x4c/0x250
> > Apr 23 22:43:26 ssdfs-vm-test kernel: [29733.942876]
> > mutex_lock_nested+0x1b/0x30
> > Apr 23 22:43:26 ssdfs-vm-test kernel: [29733.942881] ?
> > mutex_lock_nested+0x1b/0x30
> > Apr 23 22:43:26 ssdfs-vm-test kernel: [29733.943136] ceph_con_send+0x4c/0x250
> > Apr 23 22:43:26 ssdfs-vm-test kernel: [29733.943146] ? lock_acquire+0xc8/0x2f0
> > Apr 23 22:43:26 ssdfs-vm-test kernel: [29733.943158] send_request+0x7d0/0xcc0
> > Apr 23 22:43:26 ssdfs-vm-test kernel: [29733.943174] ?
> > do_raw_spin_unlock+0x4e/0xe0
> > Apr 23 22:43:26 ssdfs-vm-test kernel: [29733.943182] ?
> > _raw_spin_unlock+0x22/0x50
> > Apr 23 22:43:26 ssdfs-vm-test kernel: [29733.943222]
> > __submit_request+0x2a9/0x4c0
> > Apr 23 22:43:26 ssdfs-vm-test kernel: [29733.943236]
> > ceph_osdc_start_request+0x6c/0x90
> > Apr 23 22:43:26 ssdfs-vm-test kernel: [29733.943245]
> > ceph_writepages_start+0x101b/0x21e0
> > Apr 23 22:43:26 ssdfs-vm-test kernel: [29733.943254] ?
> > __lock_acquire+0x4a2/0x2650
> > Apr 23 22:43:26 ssdfs-vm-test kernel: [29733.943331] do_writepages+0xc2/0x170
> > Apr 23 22:43:26 ssdfs-vm-test kernel: [29733.943338] ? do_writepages+0xc2/0x170
> > Apr 23 22:43:26 ssdfs-vm-test kernel: [29733.943342] ? lock_release+0xd9/0x300
> > Apr 23 22:43:26 ssdfs-vm-test kernel: [29733.943347] ?
> > writeback_sb_inodes+0x1e7/0x900
> > Apr 23 22:43:26 ssdfs-vm-test kernel: [29733.943358]
> > __writeback_single_inode+0x5a/0x5e0
> > Apr 23 22:43:26 ssdfs-vm-test kernel: [29733.943365] ?
> > _raw_spin_unlock+0x22/0x50
> > Apr 23 22:43:26 ssdfs-vm-test kernel: [29733.943377]
> > writeback_sb_inodes+0x29f/0x900
> > Apr 23 22:43:26 ssdfs-vm-test kernel: [29733.943435]
> > __writeback_inodes_wb+0x54/0xf0
> > Apr 23 22:43:30 ssdfs-vm-test kernel: [29733.943448] wb_writeback+0x3df/0x470
> > Apr 23 22:43:30 ssdfs-vm-test kernel: [29733.943473] wb_workfn+0x364/0x520
> > Apr 23 22:43:30 ssdfs-vm-test kernel: [29733.943493]
> > process_one_work+0x22f/0x620
> > Apr 23 22:43:30 ssdfs-vm-test kernel: [29733.943515] worker_thread+0x1e2/0x400
> > Apr 23 22:43:30 ssdfs-vm-test kernel: [29733.943525] ?
> > __pfx_worker_thread+0x10/0x10
> > Apr 23 22:43:30 ssdfs-vm-test kernel: [29733.943532] kthread+0x109/0x140
> > Apr 23 22:43:30 ssdfs-vm-test kernel: [29733.943539] ? __pfx_kthread+0x10/0x10
> > Apr 23 22:43:30 ssdfs-vm-test kernel: [29733.943548] ret_from_fork+0x3e1/0x470
> > Apr 23 22:43:30 ssdfs-vm-test kernel: [29733.943556] ? __pfx_kthread+0x10/0x10
> > Apr 23 22:43:30 ssdfs-vm-test kernel: [29733.943561] ? __pfx_kthread+0x10/0x10
> > Apr 23 22:43:30 ssdfs-vm-test kernel: [29733.943568]
> > ret_from_fork_asm+0x1a/0x30
> > Apr 23 22:43:30 ssdfs-vm-test kernel: [29733.943595] </TASK>
> > Apr 23 22:43:30 ssdfs-vm-test kernel: [29733.943669] INFO: task
> > kworker/u32:0:241092 is blocked on a mutex likely owned by task
> > kworker/7:4:308292.
> > Apr 23 22:43:30 ssdfs-vm-test kernel: [29733.953769] task:kworker/7:4
> > state:R running task stack:0 pid:308292 tgid:308292 ppid:2
> > task_flags:0x4208860 flags:0x00080000
> > Apr 23 22:43:30 ssdfs-vm-test kernel: [29733.953786] Workqueue: ceph-msgr
> > ceph_con_workfn
> > Apr 23 22:43:30 ssdfs-vm-test kernel: [29733.953795] Call Trace:
> > Apr 23 22:43:30 ssdfs-vm-test kernel: [29733.953798] <TASK>
> > Apr 23 22:43:30 ssdfs-vm-test kernel: [29733.953805] __schedule+0x5b7/0x1fe0
> > Apr 23 22:43:30 ssdfs-vm-test kernel: [29733.953809] ?
> > irqentry_exit+0x299/0x740
> > Apr 23 22:43:30 ssdfs-vm-test kernel: [29733.953843] ?
> > sysvec_apic_timer_interrupt+0x54/0xd0
> > Apr 23 22:43:30 ssdfs-vm-test kernel: [29733.953858] preempt_schedule+0x4c/0x80
> > Apr 23 22:43:30 ssdfs-vm-test kernel: [29733.953862]
> > preempt_schedule_thunk+0x16/0x30
> > Apr 23 22:43:30 ssdfs-vm-test kernel: [29733.953874]
> > _raw_spin_unlock_irq+0x4f/0x70
> > Apr 23 22:43:30 ssdfs-vm-test kernel: [29733.953880] evict_folios+0x394/0xf00
> > Apr 23 22:43:30 ssdfs-vm-test kernel: [29733.953886] ?
> > hrtimer_start_range_ns+0x270/0x980
> > Apr 23 22:43:30 ssdfs-vm-test kernel: [29733.953904] ?
> > lock_is_held_type+0xaa/0x140
> > Apr 23 22:43:30 ssdfs-vm-test kernel: [29733.953916]
> > try_to_shrink_lruvec+0x1a9/0x3b0
> > Apr 23 22:43:30 ssdfs-vm-test kernel: [29733.953934] shrink_one+0xd1/0x1c0
> > Apr 23 22:43:30 ssdfs-vm-test kernel: [29733.953943] shrink_node+0xba8/0x13d0
> > Apr 23 22:43:30 ssdfs-vm-test kernel: [29733.953954] ? shrink_node+0xb7e/0x13d0
> > Apr 23 22:43:30 ssdfs-vm-test kernel: [29733.953969]
> > do_try_to_free_pages+0xc1/0x4f0
> > Apr 23 22:43:30 ssdfs-vm-test kernel: [29733.953974] ?
> > do_try_to_free_pages+0xc1/0x4f0
> > Apr 23 22:43:30 ssdfs-vm-test kernel: [29733.953984]
> > try_to_free_pages+0xe0/0x310
> > Apr 23 22:43:30 ssdfs-vm-test kernel: [29733.953989] ?
> > fs_reclaim_acquire+0x4f/0x100
> > Apr 23 22:43:30 ssdfs-vm-test kernel: [29733.954009]
> > __alloc_frozen_pages_noprof+0xd49/0x1830
> > Apr 23 22:43:30 ssdfs-vm-test kernel: [29733.954017] ?
> > ip_dst_mtu_maybe_forward.constprop.0+0x24/0x2a0
> > Apr 23 22:43:30 ssdfs-vm-test kernel: [29733.954034] ? lock_acquire+0xc8/0x2f0
> > Apr 23 22:43:30 ssdfs-vm-test kernel: [29733.954039] ?
> > __virt_addr_valid+0xf5/0x340
> > Apr 23 22:43:30 ssdfs-vm-test kernel: [29733.954053] ?
> > policy_nodemask+0x122/0x1d0
> > Apr 23 22:43:30 ssdfs-vm-test kernel: [29733.954064]
> > alloc_pages_mpol+0xba/0x1a0
> > Apr 23 22:43:30 ssdfs-vm-test kernel: [29733.954069] ?
> > _copy_from_iter+0x273/0x790
> > Apr 23 22:43:30 ssdfs-vm-test kernel: [29733.954080]
> > alloc_pages_noprof+0x59/0xe0
> > Apr 23 22:43:30 ssdfs-vm-test kernel: [29733.954087]
> > skb_page_frag_refill+0xc4/0xf0
> > Apr 23 22:43:30 ssdfs-vm-test kernel: [29733.954093]
> > sk_page_frag_refill+0x21/0xc0
> > Apr 23 22:43:30 ssdfs-vm-test kernel: [29733.954099]
> > tcp_sendmsg_locked+0x848/0x14e0
> > Apr 23 22:43:30 ssdfs-vm-test kernel: [29733.954122] tcp_sendmsg+0x30/0x60
> > Apr 23 22:43:30 ssdfs-vm-test kernel: [29733.954128] inet_sendmsg+0x46/0x90
> > Apr 23 22:43:30 ssdfs-vm-test kernel: [29733.954135] sock_sendmsg+0xf1/0x100
> > Apr 23 22:43:30 ssdfs-vm-test kernel: [29733.954142] ? kfree+0x3ab/0x560
> > Apr 23 22:43:30 ssdfs-vm-test kernel: [29733.954147] ?
> > __free_frozen_pages+0x6e0/0x730
> > Apr 23 22:43:30 ssdfs-vm-test kernel: [29733.954157] ? sg_free_table+0x39/0x90
> > Apr 23 22:43:30 ssdfs-vm-test kernel: [29733.954167] do_sendmsg+0x8d/0xe0
> > Apr 23 22:43:30 ssdfs-vm-test kernel: [29733.954197]
> > ceph_con_v2_try_write+0x99/0x560
> > Apr 23 22:43:30 ssdfs-vm-test kernel: [29733.954206]
> > ceph_con_workfn+0x17f/0x820
> > Apr 23 22:43:30 ssdfs-vm-test kernel: [29733.954215]
> > process_one_work+0x22f/0x620
> > Apr 23 22:43:30 ssdfs-vm-test kernel: [29733.954221] ?
> > process_one_work+0x254/0x620
> > Apr 23 22:43:30 ssdfs-vm-test kernel: [29733.954252] worker_thread+0x1e2/0x400
> > Apr 23 22:43:30 ssdfs-vm-test kernel: [29733.954260] ?
> > __pfx_worker_thread+0x10/0x10
> > Apr 23 22:43:30 ssdfs-vm-test kernel: [29733.954265] kthread+0x109/0x140
> > Apr 23 22:43:30 ssdfs-vm-test kernel: [29733.954271] ? __pfx_kthread+0x10/0x10
> > Apr 23 22:43:30 ssdfs-vm-test kernel: [29733.954278] ret_from_fork+0x3e1/0x470
> > Apr 23 22:43:30 ssdfs-vm-test kernel: [29733.954283] ? __pfx_kthread+0x10/0x10
> > Apr 23 22:43:30 ssdfs-vm-test kernel: [29733.954287] ? __pfx_kthread+0x10/0x10
> > Apr 23 22:43:30 ssdfs-vm-test kernel: [29733.954293]
> > ret_from_fork_asm+0x1a/0x30
> > Apr 23 22:43:30 ssdfs-vm-test kernel: [29733.954314] </TASK>
> > Apr 23 22:43:30 ssdfs-vm-test kernel: [29733.954321] INFO: task
> > kworker/7:2:299107 blocked for more than 122 seconds.
> > Apr 23 22:43:30 ssdfs-vm-test kernel: [29733.955829] Not tainted 7.0.0+ #9
> > Apr 23 22:43:30 ssdfs-vm-test kernel: [29733.959909] "echo 0 >
> > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
> > Apr 23 22:43:30 ssdfs-vm-test kernel: [29733.961590] task:kworker/7:2
> > state:D stack:0 pid:299107 tgid:299107 ppid:2 task_flags:0x4208060
> > flags:0x00080000
> > Apr 23 22:43:30 ssdfs-vm-test kernel: [29733.961598] Workqueue: events
> > delayed_work
> > Apr 23 22:43:30 ssdfs-vm-test kernel: [29733.961607] Call Trace:
> > Apr 23 22:43:30 ssdfs-vm-test kernel: [29733.961610] <TASK>
> > Apr 23 22:43:30 ssdfs-vm-test kernel: [29733.961618] __schedule+0x5b7/0x1fe0
> > Apr 23 22:43:30 ssdfs-vm-test kernel: [29733.961622] ?
> > mark_held_locks+0x46/0x90
> > Apr 23 22:43:30 ssdfs-vm-test kernel: [29733.961629] ? find_held_lock+0x31/0x90
> > Apr 23 22:43:30 ssdfs-vm-test kernel: [29733.961634] ? schedule+0x10e/0x180
> > Apr 23 22:43:30 ssdfs-vm-test kernel: [29733.961639] ? lock_release+0xd9/0x300
> > Apr 23 22:43:30 ssdfs-vm-test kernel: [29733.961649] schedule+0x3a/0x180
> > Apr 23 22:43:30 ssdfs-vm-test kernel: [29733.961653]
> > schedule_preempt_disabled+0x15/0x30
> > Apr 23 22:43:30 ssdfs-vm-test kernel: [29733.961658]
> > rwsem_down_read_slowpath+0x27b/0x6c0
> > Apr 23 22:43:30 ssdfs-vm-test kernel: [29733.961662] ?
> > ceph_send_cap_releases+0x4b/0x370
> > Apr 23 22:43:30 ssdfs-vm-test kernel: [29733.961672] ?
> > __queue_delayed_work+0x134/0x190
> > Apr 23 22:43:30 ssdfs-vm-test kernel: [29733.961682] down_read+0x7c/0x190
> > Apr 23 22:43:30 ssdfs-vm-test kernel: [29733.961687]
> > ceph_send_cap_releases+0x4b/0x370
> > Apr 23 22:43:30 ssdfs-vm-test kernel: [29733.961692] ?
> > ceph_con_send+0x1e8/0x250
> > Apr 23 22:43:30 ssdfs-vm-test kernel: [29733.961705] delayed_work+0x1d8/0x2b0
> > Apr 23 22:43:30 ssdfs-vm-test kernel: [29733.961715]
> > process_one_work+0x22f/0x620
> > Apr 23 22:43:30 ssdfs-vm-test kernel: [29733.961730] worker_thread+0x1e2/0x400
> > Apr 23 22:43:30 ssdfs-vm-test kernel: [29733.961738] ?
> > __pfx_worker_thread+0x10/0x10
> > Apr 23 22:43:30 ssdfs-vm-test kernel: [29733.961744] kthread+0x109/0x140
> > Apr 23 22:43:30 ssdfs-vm-test kernel: [29733.961749] ? __pfx_kthread+0x10/0x10
> > Apr 23 22:43:30 ssdfs-vm-test kernel: [29733.961756] ret_from_fork+0x3e1/0x470
> > Apr 23 22:43:30 ssdfs-vm-test kernel: [29733.961787] ? __pfx_kthread+0x10/0x10
> > Apr 23 22:43:30 ssdfs-vm-test kernel: [29733.961791] ? __pfx_kthread+0x10/0x10
> > Apr 23 22:43:30 ssdfs-vm-test kernel: [29733.961797]
> > ret_from_fork_asm+0x1a/0x30
> > Apr 23 22:43:30 ssdfs-vm-test kernel: [29733.961818] </TASK>
> > Apr 23 22:43:30 ssdfs-vm-test kernel: [29733.961851] INFO: task
> > kworker/7:2:299107 <reader> blocked on an rw-semaphore likely owned by task
> > kworker/u32:0:241092 <reader>
> > Apr 23 22:43:30 ssdfs-vm-test kernel: [29733.972571] INFO: task
> > kworker/7:5:309930 blocked for more than 122 seconds.
> > Apr 23 22:43:30 ssdfs-vm-test kernel: [29733.973737] Not tainted 7.0.0+ #9
> > Apr 23 22:43:30 ssdfs-vm-test kernel: [29733.974413] "echo 0 >
> > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
> > Apr 23 22:43:30 ssdfs-vm-test kernel: [29733.978473] task:kworker/7:5
> > state:D stack:0 pid:309930 tgid:309930 ppid:2 task_flags:0x4208060
> > flags:0x00080000
> > Apr 23 22:43:30 ssdfs-vm-test kernel: [29733.978479] Workqueue: events
> > handle_osds_timeout
> > Apr 23 22:43:30 ssdfs-vm-test kernel: [29733.978485] Call Trace:
> > Apr 23 22:43:30 ssdfs-vm-test kernel: [29733.978487] <TASK>
> > Apr 23 22:43:30 ssdfs-vm-test kernel: [29733.978493] __schedule+0x5b7/0x1fe0
> > Apr 23 22:43:30 ssdfs-vm-test kernel: [29733.978496] ?
> > mark_held_locks+0x46/0x90
> > Apr 23 22:43:30 ssdfs-vm-test kernel: [29733.978502] ? find_held_lock+0x31/0x90
> > Apr 23 22:43:30 ssdfs-vm-test kernel: [29733.978506] ? schedule+0x10e/0x180
> > Apr 23 22:43:30 ssdfs-vm-test kernel: [29733.978509] ? lock_release+0xd9/0x300
> > Apr 23 22:43:30 ssdfs-vm-test kernel: [29733.978537] schedule+0x3a/0x180
> > Apr 23 22:43:30 ssdfs-vm-test kernel: [29733.978540]
> > schedule_preempt_disabled+0x15/0x30
> > Apr 23 22:43:30 ssdfs-vm-test kernel: [29733.978543]
> > rwsem_down_write_slowpath+0x1f3/0x990
> > Apr 23 22:43:30 ssdfs-vm-test kernel: [29733.978547] ? lock_acquire+0xc8/0x2f0
> > Apr 23 22:43:30 ssdfs-vm-test kernel: [29733.978556] ?
> > process_one_work+0x1ef/0x620
> > Apr 23 22:43:30 ssdfs-vm-test kernel: [29733.978563] down_write+0xe4/0xf0
> > Apr 23 22:43:30 ssdfs-vm-test kernel: [29733.978567]
> > handle_osds_timeout+0x45/0x160
> > Apr 23 22:43:30 ssdfs-vm-test kernel: [29733.978573]
> > process_one_work+0x22f/0x620
> > Apr 23 22:43:30 ssdfs-vm-test kernel: [29733.978585] worker_thread+0x1e2/0x400
> > Apr 23 22:43:30 ssdfs-vm-test kernel: [29733.978591] ?
> > __pfx_worker_thread+0x10/0x10
> > Apr 23 22:43:30 ssdfs-vm-test kernel: [29733.978595] kthread+0x109/0x140
> > Apr 23 22:43:30 ssdfs-vm-test kernel: [29733.978599] ? __pfx_kthread+0x10/0x10
> > Apr 23 22:43:30 ssdfs-vm-test kernel: [29733.978604] ret_from_fork+0x3e1/0x470
> > Apr 23 22:43:30 ssdfs-vm-test kernel: [29733.978608] ? __pfx_kthread+0x10/0x10
> > Apr 23 22:43:30 ssdfs-vm-test kernel: [29733.978611] ? __pfx_kthread+0x10/0x10
> > Apr 23 22:43:30 ssdfs-vm-test kernel: [29733.978615]
> > ret_from_fork_asm+0x1a/0x30
> > Apr 23 22:43:30 ssdfs-vm-test kernel: [29733.978631] </TASK>
> > Apr 23 22:43:30 ssdfs-vm-test kernel: [29733.978653] INFO: task
> > kworker/7:5:309930 <writer> blocked on an rw-semaphore likely owned by task
> > kworker/u32:0:241092 <reader>
> >
> > I am not completely sure that your patch is responsible.
>
> Thanks for the double check and sorry for the inconvenience.
> I’ll recheck the patch and take more stress tests.
>
>
As far as I can see, I was able to reproduce the issue without your patch
applied. It looks like I was "lucky" to reproduce the issue. I need to take a
deeper look into the issue. But your patch is not responsible for the issue. Let
me spend some time to analyze the issue reason and environment.
Have you able to reproduce the issue on your side?
Thanks,
Slava.