Hi all,

I'm running a small converged Ceph cluster (mons, OSDs, mds on the same
3 hosts, one of which is also a CephFS client). I noticed that sometimes
the CephFS client seems to deadlock. There are other CephFS clients on
the network, but they generally don't collide in file/dir accesses much
with the local client.

I found this old thread that describes a similar situation:

https://www.mail-archive.com/search?l=ceph-us...@lists.ceph.com&q=subject:%22Re%5C%3A+%5C%5Bceph%5C-users%5C%5D+co%5C-located+cephfs+client+deadlock%22&o=newest&f=1

The kernel version is 6.14.6 for the main hosts, 6.14.8 for a few other
unrelated clients, and 6.3.2 for one older client. Ceph version is
19.2.2. Ceph status was clean and dmesg didn't show any warnings around
the time of the hang, other than a few of these (which I always get and
seem to be related to SELinux attributes, but appear to be harmless):

[3447915.841214] ceph: [667e28f4-8964-454b-b777-03ce12b67742 6505232]:
sync 00000000f6e49a9a 100033726fb.152 during filling trace
[3447915.851171] SELinux: inode_doinit_use_xattr:  getxattr returned 16
for dev=ceph ino=1099565573883

Restarting the mds (letting it failover to the standby-replay mds) did
not help the situation, but after finding the above thread I noticed
that all the requests were stuck on the same OSD:

> root@flamingo:~ -# cat /sys/kernel/debug/ceph/*/osdc
> REQUESTS 17 homeless 0
> 46841260        osd17   14.2ab058d9     14.19s0 [17,18,15,6,7,4,3,0,1]/17     
>   [17,18,15,6,7,4,3,0,1]/17       e25593  10002e55314.0000003c    0x400014    
>     1       read
> 46841268        osd17   14.571aa108     14.8s0  [17,16,15,0,1,2,4,5,7]/17     
>   [17,16,15,0,1,2,4,5,7]/17       e25593  100030edef7.00000039    0x400014    
>     1       read
> 46841311        osd17   14.7b4e2d92     14.12s0 [17,16,15,6,7,4,2,1,3]/17     
>   [17,16,15,6,7,4,2,1,3]/17       e25593  1000318f566.00000179    0x400014    
>     1       read
> 46841323        osd17   14.deec222d     14.2ds0 [17,16,18,4,7,5,2,1,0]/17     
>   [17,16,18,4,7,5,2,1,0]/17       e25593  100030edf00.00000028    0x400014    
>     1       read
> 46841334        osd17   14.eb940708     14.8s0  [17,16,15,0,1,2,4,5,7]/17     
>   [17,16,15,0,1,2,4,5,7]/17       e25593  10003042460.000001c8    0x400014    
>     1       read
> 46841336        osd17   14.93065908     14.8s0  [17,16,15,0,1,2,4,5,7]/17     
>   [17,16,15,0,1,2,4,5,7]/17       e25593  1000318f566.00000181    0x400014    
>     1       read
> 46841350        osd17   14.3e9eeaa5     14.25s0 [17,18,15,2,0,1,7,6,4]/17     
>   [17,18,15,2,0,1,7,6,4]/17       e25593  10003498f94.00000000    0x400024    
>     1       write
> 46841359        osd17   14.5120499      14.19s0 [17,18,15,6,7,4,3,0,1]/17     
>   [17,18,15,6,7,4,3,0,1]/17       e25593  10002e53590.00000000    0x400014    
>     1       read
> 46841367        osd17   14.25e874a5     14.25s0 [17,18,15,2,0,1,7,6,4]/17     
>   [17,18,15,2,0,1,7,6,4]/17       e25593  1000318f566.00000196    0x400014    
>     1       read
> 46841376        osd17   14.cd26e465     14.25s0 [17,18,15,2,0,1,7,6,4]/17     
>   [17,18,15,2,0,1,7,6,4]/17       e25593  1000318f566.00000199    0x400014    
>     1       read
> 46841405        osd17   14.855295f5     14.35s0 [17,18,15,3,0,2,4,7,5]/17     
>   [17,18,15,3,0,2,4,7,5]/17       e25593  1000318f566.000001a7    0x400014    
>     1       read
> 46841421        osd17   14.57d5ef2c     14.2cs0 [17,18,16,1,3,2,4,6,5]/17     
>   [17,18,16,1,3,2,4,6,5]/17       e25593  10002fe07b1.00000008    0x400014    
>     1       read
> 46841424        osd17   14.ea554059     14.19s0 [17,18,15,6,7,4,3,0,1]/17     
>   [17,18,15,6,7,4,3,0,1]/17       e25593  1000318f566.000001ac    0x400014    
>     1       read
> 46841429        osd17   14.fa91b525     14.25s0 [17,18,15,2,0,1,7,6,4]/17     
>   [17,18,15,2,0,1,7,6,4]/17       e25593  100030916b5.0000004f    0x400014    
>     1       read
> 46841447        osd17   14.88f24788     14.8s0  [17,16,15,0,1,2,4,5,7]/17     
>   [17,16,15,0,1,2,4,5,7]/17       e25593  100032d95c7.00000011    0x400014    
>     1       read
> 46841468        osd17   12.159b3dd2     12.12   [17,5,2]/17     [17,5,2]/17   
>   e25593  10003307266.00000013    0x400014        1       read
> 46841496        osd17   12.a08092d2     12.12   [17,5,2]/17     [17,5,2]/17   
>   e25593  10003493c3f.00000050    0x400014        1       read
> LINGER REQUESTS
> BACKOFFS

Restarting that OSD fixed it. Looking at the OSD log at the exact time
of the hang (determined by other logs), I see this:

> 2025-07-18T06:39:06.992+0900 fffeed21bf00  0 
> bluestore(/var/lib/ceph/osd/ceph-17) log_latency_fn slow operation observed 
> for _remove, latency = 5.162732124s, lat = 5s cid =12.3_head oid 
> =#12:c0ccf68d:::1000336b41c.0000009d:13d#
> 2025-07-18T06:39:06.992+0900 fffeed21bf00  0 
> bluestore(/var/lib/ceph/osd/ceph-17) log_latency slow operation observed for 
> submit_transact, latency = 5.167396545s
> 2025-07-18T06:39:06.993+0900 fffef837bf00  0 
> bluestore(/var/lib/ceph/osd/ceph-17) log_latency_fn slow operation observed 
> for _txc_committed_kv, latency = 5.168415070s, txc = 0xaaabe3f57000
> 2025-07-18T06:39:14.834+0900 fffeeca0bf00  0 
> bluestore(/var/lib/ceph/osd/ceph-17) log_latency_fn slow operation observed 
> for _remove, latency = 5.340788364s, lat = 5s cid =12.14_head oid 
> =#12:28e0c837:::10003307273.00000024:13d#
> 2025-07-18T06:39:14.835+0900 fffeeca0bf00  0 
> bluestore(/var/lib/ceph/osd/ceph-17) log_latency slow operation observed for 
> submit_transact, latency = 5.342024803s
> 2025-07-18T06:39:14.843+0900 fffef837bf00  0 
> bluestore(/var/lib/ceph/osd/ceph-17) log_latency_fn slow operation observed 
> for _txc_committed_kv, latency = 5.349779129s, txc = 0xaaac19c75b00
> 2025-07-18T06:40:37.552+0900 fffeeb9ebf00  0 
> bluestore(/var/lib/ceph/osd/ceph-17) log_latency_fn slow operation observed 
> for _remove, latency = 5.124079704s, lat = 5s cid =12.c_head oid 
> =#12:340862a9:::100033073f1.0000002c:13d#
> 2025-07-18T06:40:37.560+0900 fffeeb9ebf00  0 
> bluestore(/var/lib/ceph/osd/ceph-17) log_latency slow operation observed for 
> submit_transact, latency = 5.132128239s
> 2025-07-18T06:40:37.568+0900 fffef837bf00  0 
> bluestore(/var/lib/ceph/osd/ceph-17) log_latency_fn slow operation observed 
> for _txc_committed_kv, latency = 5.140548706s, txc = 0xaaabf25b8000
> 2025-07-18T06:40:59.228+0900 fffeec1fbf00  0 
> bluestore(/var/lib/ceph/osd/ceph-17) log_latency_fn slow operation observed 
> for _remove, latency = 5.677710056s, lat = 5s cid =12.2_head oid 
> =#12:40b82ac1:::1000348d274.00000008:13d#
> 2025-07-18T06:40:59.229+0900 fffeec1fbf00  0 
> bluestore(/var/lib/ceph/osd/ceph-17) log_latency slow operation observed for 
> submit_transact, latency = 5.679266453s
> 2025-07-18T06:40:59.232+0900 fffef837bf00  0 
> bluestore(/var/lib/ceph/osd/ceph-17) log_latency_fn slow operation observed 
> for _txc_committed_kv, latency = 5.682381630s, txc = 0xaaac34479500
> 2025-07-18T06:41:01.799+0900 fffeeb9ebf00  0 
> bluestore(/var/lib/ceph/osd/ceph-17) log_latency_fn slow operation observed 
> for _remove, latency = 5.117489815s, lat = 5s cid =12.c_head oid 
> =#12:340e7251:::10003307273.00000027:13d#
> 2025-07-18T06:41:01.799+0900 fffeeb9ebf00  0 
> bluestore(/var/lib/ceph/osd/ceph-17) log_latency slow operation observed for 
> submit_transact, latency = 5.118617058s
> 2025-07-18T06:41:01.804+0900 fffef837bf00  0 
> bluestore(/var/lib/ceph/osd/ceph-17) log_latency_fn slow operation observed 
> for _txc_committed_kv, latency = 5.123104095s, txc = 0xaaabbf99de00
> 2025-07-18T06:42:28.863+0900 fffeec1fbf00  0 
> bluestore(/var/lib/ceph/osd/ceph-17) log_latency_fn slow operation observed 
> for _remove, latency = 5.191506386s, lat = 5s cid =12.3_head oid 
> =#12:c2349a5a:::1000336b418.000000f0:13d#
> 2025-07-18T06:42:28.863+0900 fffeec1fbf00  0 
> bluestore(/var/lib/ceph/osd/ceph-17) log_latency slow operation observed for 
> submit_transact, latency = 5.192711353s
> 2025-07-18T06:42:28.864+0900 fffef837bf00  0 
> bluestore(/var/lib/ceph/osd/ceph-17) log_latency_fn slow operation observed 
> for _txc_committed_kv, latency = 5.193384171s, txc = 0xaaabd1e51e00
> 2025-07-18T06:42:34.152+0900 fffeeca0bf00  0 
> bluestore(/var/lib/ceph/osd/ceph-17) log_latency_fn slow operation observed 
> for _remove, latency = 5.287574291s, lat = 5s cid =12.3_head oid 
> =#12:c2bf668a:::10003307273.0000007b:13d#
> 2025-07-18T06:42:34.154+0900 fffeeca0bf00  0 
> bluestore(/var/lib/ceph/osd/ceph-17) log_latency slow operation observed for 
> submit_transact, latency = 5.289901257s
> 2025-07-18T06:42:34.156+0900 fffef837bf00  0 
> bluestore(/var/lib/ceph/osd/ceph-17) log_latency_fn slow operation observed 
> for _txc_committed_kv, latency = 5.291684628s, txc = 0xaaabf9f90c00
> 2025-07-18T06:42:40.801+0900 ffff014cbf00 -1 osd.17 25584 get_health_metrics 
> reporting 1 slow ops, oldest is osd_op(client.6505232.0:46841429 14.25s0 
> 14.fa91b525 (undecoded) ondisk+read+known_if_redirected e25584)
> 2025-07-18T06:42:40.801+0900 ffff014cbf00  0 log_channel(cluster) log [WRN] : 
> 1 slow requests (by type [ 'queued for pg' : 1 ] most affected pool [ 
> 'cephfs2_data_hec5.4' : 1 ])
[ repeats ... ]
> 2025-07-18T06:44:15.954+0900 ffff014cbf00 -1 osd.17 25584 get_health_metrics 
> reporting 1 slow ops, oldest is osd_op(client.6505232.0:46841429 14.25s0 
> 14.fa91b525 (undecoded) ondisk+read+known_if_redirected e25584)
> 2025-07-18T06:44:15.954+0900 ffff014cbf00  0 log_channel(cluster) log [WRN] : 
> 1 slow requests (by type [ 'queued for pg' : 1 ] most affected pool [ 
> 'cephfs2_data_hec5.4' : 1 ])
> 2025-07-18T06:44:27.591+0900 fffeeca0bf00  0 
> bluestore(/var/lib/ceph/osd/ceph-17) log_latency_fn slow operation observed 
> for _remove, latency = 5.561402321s, lat = 5s cid =12.0_head oid 
> =#12:064b3406:::1000348bd03.0000004a:13d#
> 2025-07-18T06:44:27.594+0900 fffeeca0bf00  0 
> bluestore(/var/lib/ceph/osd/ceph-17) log_latency slow operation observed for 
> submit_transact, latency = 5.565083027s
> 2025-07-18T06:44:27.595+0900 fffef837bf00  0 
> bluestore(/var/lib/ceph/osd/ceph-17) log_latency_fn slow operation observed 
> for _txc_committed_kv, latency = 5.565894604s, txc = 0xaaabe0e98c00
> 2025-07-18T06:44:29.442+0900 ffff014cbf00 -1 osd.17 25584 get_health_metrics 
> reporting 1 slow ops, oldest is osd_op(client.6505232.0:46841429 14.25s0 
> 14.fa91b525 (undecoded) ondisk+read+known_if_redirected e25584)
> 2025-07-18T06:44:29.442+0900 ffff014cbf00  0 log_channel(cluster) log [WRN] : 
> 1 slow requests (by type [ 'queued for pg' : 1 ] most affected pool [ 
> 'cephfs2_data_hec5.4' : 1 ])
[ repeats ... ]
> 2025-07-18T06:44:32.362+0900 ffff014cbf00 -1 osd.17 25584 get_health_metrics 
> reporting 2 slow ops, oldest is osd_op(client.6505232.0:46841429 14.25s0 
> 14.fa91b525 (undecoded) ondisk+read+known_if_redirected e25584)
> 2025-07-18T06:44:32.362+0900 ffff014cbf00  0 log_channel(cluster) log [WRN] : 
> 2 slow requests (by type [ 'queued for pg' : 1 'started' : 1 ] most affected 
> pool [ 'cephfs2_data_hr3' : 1 ])
> 2025-07-18T06:44:33.314+0900 ffff014cbf00 -1 osd.17 25584 get_health_metrics 
> reporting 2 slow ops, oldest is osd_op(client.6505232.0:46841429 14.25s0 
> 14.fa91b525 (undecoded) ondisk+read+known_if_redirected e25584)
> 2025-07-18T06:44:33.314+0900 ffff014cbf00  0 log_channel(cluster) log [WRN] : 
> 2 slow requests (by type [ 'queued for pg' : 1 'started' : 1 ] most affected 
> pool [ 'cephfs2_data_hr3' : 1 ])
> 2025-07-18T06:44:34.328+0900 ffff014cbf00 -1 osd.17 25584 get_health_metrics 
> reporting 2 slow ops, oldest is osd_op(client.6505232.0:46841429 14.25s0 
> 14.fa91b525 (undecoded) ondisk+read+known_if_redirected e25584)
> 2025-07-18T06:44:34.328+0900 ffff014cbf00  0 log_channel(cluster) log [WRN] : 
> 2 slow requests (by type [ 'queued for pg' : 1 'started' : 1 ] most affected 
> pool [ 'cephfs2_data_hr3' : 1 ])
> 2025-07-18T06:44:38.361+0900 ffff014cbf00 -1 osd.17 25584 get_health_metrics 
> reporting 2 slow ops, oldest is osd_op(client.6505232.0:46841376 14.25s0 
> 14.cd26e465 (undecoded) ondisk+read+known_if_redirected e25584)
> 2025-07-18T06:44:38.361+0900 ffff014cbf00  0 log_channel(cluster) log [WRN] : 
> 2 slow requests (by type [ 'queued for pg' : 2 ] most affected pool [ 
> 'cephfs2_data_hec5.4' : 2 ])
> 2025-07-18T06:44:39.369+0900 ffff014cbf00 -1 osd.17 25584 get_health_metrics 
> reporting 2 slow ops, oldest is osd_op(client.6505232.0:46841376 14.25s0 
> 14.cd26e465 (undecoded) ondisk+read+known_if_redirected e25584)
> 2025-07-18T06:44:39.369+0900 ffff014cbf00  0 log_channel(cluster) log [WRN] : 
> 2 slow requests (by type [ 'queued for pg' : 2 ] most affected pool [ 
> 'cephfs2_data_hec5.4' : 2 ])
> 2025-07-18T06:44:40.356+0900 ffff014cbf00 -1 osd.17 25584 get_health_metrics 
> reporting 5 slow ops, oldest is osd_op(client.6505232.0:46841260 14.19s0 
> 14.2ab058d9 (undecoded) ondisk+read+known_if_redirected e25583)
> 2025-07-18T06:44:40.356+0900 ffff014cbf00  0 log_channel(cluster) log [WRN] : 
> 5 slow requests (by type [ 'queued for pg' : 5 ] most affected pool [ 
> 'cephfs2_data_hec5.4' : 5 ])
> 2025-07-18T06:44:41.324+0900 ffff014cbf00 -1 osd.17 25584 get_health_metrics 
> reporting 1 slow ops, oldest is osd_op(client.6505232.0:46841429 14.25s0 
> 14.fa91b525 (undecoded) ondisk+read+known_if_redirected e25584)
> 2025-07-18T06:44:41.324+0900 ffff014cbf00  0 log_channel(cluster) log [WRN] : 
> 1 slow requests (by type [ 'queued for pg' : 1 ] most affected pool [ 
> 'cephfs2_data_hec5.4' : 1 ])
[ repeats ... ]
> 2025-07-18T06:45:14.197+0900 ffff014cbf00 -1 osd.17 25584 get_health_metrics 
> reporting 1 slow ops, oldest is osd_op(client.6505232.0:46841429 14.25s0 
> 14.fa91b525 (undecoded) ondisk+read+known_if_redirected e25584)
> 2025-07-18T06:45:14.197+0900 ffff014cbf00  0 log_channel(cluster) log [WRN] : 
> 1 slow requests (by type [ 'queued for pg' : 1 ] most affected pool [ 
> 'cephfs2_data_hec5.4' : 1 ])
> 2025-07-18T06:45:15.825+0900 fffeec1fbf00  0 
> bluestore(/var/lib/ceph/osd/ceph-17) log_latency_fn slow operation observed 
> for _remove, latency = 5.245476246s, lat = 5s cid =12.b_head oid 
> =#12:d12c2386:::1000336b41a.00000095:13d#
> 2025-07-18T06:45:15.826+0900 fffeec1fbf00  0 
> bluestore(/var/lib/ceph/osd/ceph-17) log_latency slow operation observed for 
> submit_transact, latency = 5.247073650s
> 2025-07-18T06:45:15.831+0900 fffef837bf00  0 
> bluestore(/var/lib/ceph/osd/ceph-17) log_latency_fn slow operation observed 
> for _txc_committed_kv, latency = 5.252201080s, txc = 0xaaabd1e50c00
> 2025-07-18T06:45:19.037+0900 ffff014cbf00 -1 osd.17 25584 get_health_metrics 
> reporting 1 slow ops, oldest is osd_op(client.6505232.0:46841429 14.25s0 
> 14.fa91b525 (undecoded) ondisk+read+known_if_redirected e25584)
> 2025-07-18T06:45:19.037+0900 ffff014cbf00  0 log_channel(cluster) log [WRN] : 
> 1 slow requests (by type [ 'queued for pg' : 1 ] most affected pool [ 
> 'cephfs2_data_hec5.4' : 1 ])
> 2025-07-18T06:45:20.056+0900 ffff014cbf00 -1 osd.17 25584 get_health_metrics 
> reporting 1 slow ops, oldest is osd_op(client.6505232.0:46841429 14.25s0 
> 14.fa91b525 (undecoded) ondisk+read+known_if_redirected e25584)
> 2025-07-18T06:45:20.056+0900 ffff014cbf00  0 log_channel(cluster) log [WRN] : 
> 1 slow requests (by type [ 'queued for pg' : 1 ] most affected pool [ 
> 'cephfs2_data_hec5.4' : 1 ])
> 2025-07-18T06:45:21.010+0900 ffff014cbf00 -1 osd.17 25584 get_health_metrics 
> reporting 1 slow ops, oldest is osd_op(client.6505232.0:46841429 14.25s0 
> 14.fa91b525 (undecoded) ondisk+read+known_if_redirected e25584)
> 2025-07-18T06:45:21.010+0900 ffff014cbf00  0 log_channel(cluster) log [WRN] : 
> 1 slow requests (by type [ 'queued for pg' : 1 ] most affected pool [ 
> 'cephfs2_data_hec5.4' : 1 ])
> 2025-07-18T06:45:21.963+0900 ffff014cbf00 -1 osd.17 25584 get_health_metrics 
> reporting 1 slow ops, oldest is osd_op(client.6505232.0:46841429 14.25s0 
> 14.fa91b525 (undecoded) ondisk+read+known_if_redirected e25584)
> 2025-07-18T06:45:21.963+0900 ffff014cbf00  0 log_channel(cluster) log [WRN] : 
> 1 slow requests (by type [ 'queued for pg' : 1 ] most affected pool [ 
> 'cephfs2_data_hec5.4' : 1 ])
> 2025-07-18T06:45:22.973+0900 ffff014cbf00 -1 osd.17 25584 get_health_metrics 
> reporting 2 slow ops, oldest is osd_op(client.6505232.0:46841376 14.25s0 
> 14.cd26e465 (undecoded) ondisk+read+known_if_redirected e25584)
> 2025-07-18T06:45:22.973+0900 ffff014cbf00  0 log_channel(cluster) log [WRN] : 
> 2 slow requests (by type [ 'queued for pg' : 2 ] most affected pool [ 
> 'cephfs2_data_hec5.4' : 2 ])
> 2025-07-18T06:45:23.958+0900 ffff014cbf00 -1 osd.17 25584 get_health_metrics 
> reporting 2 slow ops, oldest is osd_op(client.6505232.0:46841376 14.25s0 
> 14.cd26e465 (undecoded) ondisk+read+known_if_redirected e25584)
> 2025-07-18T06:45:23.958+0900 ffff014cbf00  0 log_channel(cluster) log [WRN] : 
> 2 slow requests (by type [ 'queued for pg' : 2 ] most affected pool [ 
> 'cephfs2_data_hec5.4' : 2 ])
> 2025-07-18T06:45:32.861+0900 ffff014cbf00 -1 osd.17 25584 get_health_metrics 
> reporting 1 slow ops, oldest is osd_op(client.6505232.0:46841429 14.25s0 
> 14.fa91b525 (undecoded) ondisk+read+known_if_redirected e25584)
[ repeats ... ]
> 2025-07-18T06:49:20.553+0900 ffff014cbf00  0 log_channel(cluster) log [WRN] : 
> 1 slow requests (by type [ 'queued for pg' : 1 ] most affected pool [ 
> 'cephfs2_data_hec5.4' : 1 ])
> 2025-07-18T06:49:21.547+0900 ffff014cbf00 -1 osd.17 25584 get_health_metrics 
> reporting 1 slow ops, oldest is osd_op(client.6505232.0:46841429 14.25s0 
> 14.fa91b525 (undecoded) ondisk+read+known_if_redirected e25584)
> 2025-07-18T06:49:21.547+0900 ffff014cbf00  0 log_channel(cluster) log [WRN] : 
> 1 slow requests (by type [ 'queued for pg' : 1 ] most affected pool [ 
> 'cephfs2_data_hec5.4' : 1 ])
> 2025-07-18T06:49:22.596+0900 ffff014cbf00 -1 osd.17 25584 get_health_metrics 
> reporting 1 slow ops, oldest is osd_op(client.6505232.0:46841429 14.25s0 
> 14.fa91b525 (undecoded) ondisk+read+known_if_redirected e25584)
> 2025-07-18T06:49:22.596+0900 ffff014cbf00  0 log_channel(cluster) log [WRN] : 
> 1 slow requests (by type [ 'queued for pg' : 1 ] most affected pool [ 
> 'cephfs2_data_hec5.4' : 1 ])
> 2025-07-18T06:49:48.204+0900 fffeec1fbf00  0 
> bluestore(/var/lib/ceph/osd/ceph-17) log_latency_fn slow operation observed 
> for _remove, latency = 5.027801514s, lat = 5s cid =12.1a_head oid 
> =#12:5b980d7b:::100033073d8.0000002a:13d#
> 2025-07-18T06:49:48.205+0900 fffeec1fbf00  0 
> bluestore(/var/lib/ceph/osd/ceph-17) log_latency slow operation observed for 
> submit_transact, latency = 5.031510353s
> 2025-07-18T06:49:48.214+0900 fffef837bf00  0 
> bluestore(/var/lib/ceph/osd/ceph-17) log_latency_fn slow operation observed 
> for _txc_committed_kv, latency = 5.040008068s, txc = 0xaaabe5c0cf00

Note that osd17 is on a different host (but some of the shards of the
affected PGs are on the same host).

After this 10-minute period, the logs are clean. So it kind of looks
like one op (46841429) above was a slow op for about 10 minutes, but
then it stopped being considered slow by the OSD, yet the kernel client
never considered the op completed and it got stuck there?

Other ops from that client are also mentioned, and this doesn't seem
right to me. Op 46841429 is the first one to become "slow", but then
other ops like 46841376 are reported as the "oldest" op, and then it
goes back to 46841429. Unless this is about different phases for the
same op, it doesn't make sense to me that a younger op could be reported
as slow, then an older op, then back to a younger op. If the older op is
older, it should always be reported as slow first, right?

I checked all the other OSD logs and there's nothing interesting other
than a couple other OSDs that also got slow ops at around the same time
(but much shorter duration).

Grafana stats show a snaptrim operation started at exactly that time and
lasted 10 minutes. The CPU logs show that this did repro the CPU
usage/page cache thrashing anomaly I previously mentioned on the list
(high sys >> user CPU usage), but this time the thrashing only lasted 10
minutes, so I would say this is unlikely to be directly caused by that
bug, though it could be that the high load triggering slow ops in
general then tickled another bug causing the ops to get stuck.

Happy to help debug this if it happens again if anyone has pointers (I
think this might not be the first time, but it's the first time I found
that thread and learned about this issue specifically, and the debug
file to check the culprit OSD).

- Hector
_______________________________________________
ceph-users mailing list -- ceph-users@ceph.io
To unsubscribe send an email to ceph-users-le...@ceph.io

Reply via email to