Hi, We are having slow osd's... A hot topic to search on it... I've tried to dive as deep as I can, but I need to know which debug setting will help me to dive even deeper... Okay: situation: - After expansion lot's of backfill operations are running spread over the osd's. - max_backfills is set to 1 (meaning only 1 read and 1 write operation might take place at the same time for the backfill operation) - Disks are monitored and manual compaction is performed as soon as load goes over 80% - Requests thru RGW goes okay for some objects, and less okay for others. When it goes fine requests are returned within a few ms, other requests vary from a few ms to >10s. - Ceph version 14.2.11 - Erasure coding configured, 6-3 - Backfill is running at an incredible terrible pace. I assume it's all related Okay, what have I done to navigate down: 1. Removed 1 RGW from the load balancer to increase logging and dive into it 2. Using s3cmd to request the object teaches me that the delay is between the request from the RGW to the OSD and the response. 3. Investigating the osd using iostat doesn't reveal an issue. Load is very low. 3. Next I increased logging on the osd (debug_osd 20/20) and launched a request (debug setting has been immediately reversed)... 4. First you see that it is starting with the block for getting all available shards... so far so good 5. Next we will see multiple blocks like: 2020-11-19 11:53:21.938 7fe90f79c700 15 osd.156 45341 *enqueue_op* 0x559f94d43ce0 prio 127 cost 0 latency 0.000032 epoch 45341 *MOSDECSubOpRead*(1.1e2s0 45341/45313 ECSubRead(tid=191, to_read={1:47c1b09f:::44a57332-bad8-47b4-85d6-6d34be960d5f.51962.196_CT%2f20201001%2f82078cfd-a111-4b58-8b79-88a860915c56.PNG:head=0,28672,0}, subchunks={1:47c1b09f:::44a57332-bad8-47b4-85d6-6d34be960d5f.51962.196_CT%2f20201001%2f82078cfd-a111-4b58-8b79-88a860915c56.PNG:head=[0,1]}, attrs_to_read=)) v3 2020-11-19 11:53:21.938 7fe90678a700 10 osd.156 45341 *dequeue_op* 0x559f94d43ce0 prio 127 cost 0 latency 0.000135 *MOSDECSubOpRead*(1.1e2s0 45341/45313 ECSubRead(tid=191, to_read={1:47c1b09f:::44a57332-bad8-47b4-85d6-6d34be960d5f.51962.196_CT%2f20201001%2f82078cfd-a111-4b58-8b79-88a860915c56.PNG:head=0,28672,0}, subchunks={1:47c1b09f:::44a57332-bad8-47b4-85d6-6d34be960d5f.51962.196_CT%2f20201001%2f82078cfd-a111-4b58-8b79-88a860915c56.PNG:head=[0,1]}, attrs_to_read=)) v3 pg pg[1.1e2s0( v 45295'4373744 (34740'4370700,45295'4373744] local-lis/les=45313/45317 n=1842926 ec=5869/714 lis/c 45313/45313 les/c/f 45317/45322/0 45313/45313/45313) [156,64,146,256,98,67,46,31,100]p156(0) r=0 lpr=45313 crt=45295'4373744 lcod 0'0 mlcod 0'0 active+clean] 2020-11-19 11:53:21.938 7fe90678a700 20 osd.156 45341 share_map osd.156 v2: 192.168.34.57:6892/1464289 45341 2020-11-19 11:53:21.938 7fe90678a700 20 osd.156 45341 should_share_map osd.156 v2:192.168.34.57:6892/1464289 45341 2020-11-19 11:53:21.938 7fe90678a700 10 osd.156 pg_epoch: 45341 pg[1.1e2s0( v 45295'4373744 (34740'4370700,45295'4373744] local-lis/les=45313/45317 n=1842926 ec=5869/714 lis/c 45313/45313 les/c/f 45317/45322/0 45313/45313/45313) [156,64,146,256,98,67,46,31,100]p156(0) r=0 lpr=45313 crt=45295'4373744 lcod 0'0 mlcod 0'0 active+clean] _handle_message: MOSDECSubOpRead(1.1e2s0 45341/45313 ECSubRead(tid=191, to_read={1:47c1b09f:::44a57332-bad8-47b4-85d6-6d34be960d5f.51962.196_CT%2f20201001%2f82078cfd-a111-4b58-8b79-88a860915c56.PNG:head=0,28672,0}, subchunks={1:47c1b09f:::44a57332-bad8-47b4-85d6-6d34be960d5f.51962.196_CT%2f20201001%2f82078cfd-a111-4b58-8b79-88a860915c56.PNG:head=[0,1]}, attrs_to_read=)) v3 2020-11-19 11:53:21.938 7fe90678a700 20 osd.156 pg_epoch: 45341 pg[1.1e2s0( v 45295'4373744 (34740'4370700,45295'4373744] local-lis/les=45313/45317 n=1842926 ec=5869/714 lis/c 45313/45313 les/c/f 45317/45322/0 45313/45313/45313) [156,64,146,256,98,67,46,31,100]p156(0) r=0 lpr=45313 crt=45295'4373744 lcod 0'0 mlcod 0'0 active+clean] handle_sub_read read request=28672 r=28672 len=28672 2020-11-19 11:53:21.938 7fe90678a700 10 osd.156 pg_epoch: 45341 pg[1.1e2s0( v 45295'4373744 (34740'4370700,45295'4373744] local-lis/les=45313/45317 n=1842926 ec=5869/714 lis/c 45313/45313 les/c/f 45317/45322/0 45313/45313/45313) [156,64,146,256,98,67,46,31,100]p156(0) r=0 lpr=45313 crt=45295'4373744 lcod 0'0 mlcod 0'0 active+clean] get_hash_info: Getting attr on 1:47c1b09f:::44a57332-bad8-47b4-85d6-6d34be960d5f.51962.196_CT%2f20201001%2f82078cfd-a111-4b58-8b79-88a860915c56.PNG:head 2020-11-19 11:53:21.938 7fe90678a700 10 osd.156 pg_epoch: 45341 pg[1.1e2s0( v 45295'4373744 (34740'4370700,45295'4373744] local-lis/les=45313/45317 n=1842926 ec=5869/714 lis/c 45313/45313 les/c/f 45317/45322/0 45313/45313/45313) [156,64,146,256,98,67,46,31,100]p156(0) r=0 lpr=45313 crt=45295'4373744 lcod 0'0 mlcod 0'0 active+clean] get_hash_info: not in cache 1:47c1b09f:::44a57332-bad8-47b4-85d6-6d34be960d5f.51962.196_CT%2f20201001%2f82078cfd-a111-4b58-8b79-88a860915c56.PNG:head 2020-11-19 11:53:21.938 7fe90678a700 10 osd.156 pg_epoch: 45341 pg[1.1e2s0( v 45295'4373744 (34740'4370700,45295'4373744] local-lis/les=45313/45317 n=1842926 ec=5869/714 lis/c 45313/45313 les/c/f 45317/45322/0 45313/45313/45313) [156,64,146,256,98,67,46,31,100]p156(0) r=0 lpr=45313 crt=45295'4373744 lcod 0'0 mlcod 0'0 active+clean] get_hash_info: found on disk, size 28672 2020-11-19 11:53:21.938 7fe90678a700 20 osd.156 pg_epoch: 45341 pg[1.1e2s0( v 45295'4373744 (34740'4370700,45295'4373744] local-lis/les=45313/45317 n=1842926 ec=5869/714 lis/c 45313/45313 les/c/f 45317/45322/0 45313/45313/45313) [156,64,146,256,98,67,46,31,100]p156(0) r=0 lpr=45313 crt=45295'4373744 lcod 0'0 mlcod 0'0 active+clean] handle_sub_read: Checking hash of 1:47c1b09f:::44a57332-bad8-47b4-85d6-6d34be960d5f.51962.196_CT%2f20201001%2f82078cfd-a111-4b58-8b79-88a860915c56.PNG:head 2020-11-19 11:53:21.938 7fe90678a700 20 osd.156 45341 share_map_peer 0x559f71ee3400 don't know epoch, doing nothing 2020-11-19 11:53:21.938 7fe90678a700 10 osd.156 45341 dequeue_op 0x559f94d43ce0 finish .... This goes on... The latency is caused between such blocks. E.g.: Last line of a block of logging: ... 2020-11-19 11:53:*22.150* 7fe90678a700 10 osd.156 45341 dequeue_op 0x559f96a5f600 finish 2020-11-19 11:53:*22.150* 7fe90678a700 20 osd.156 op_wq(2) _process empty q, waiting ... Next block of logging: 2020-11-19 11:53:*27.089* 7fe925251700 15 osd.156 45341 enqueue_op 0x559f8f9618c0 prio 127 cost 0 latency 0.000019 epoch 45341 *MOSDECSubOpReadReply*(1.1e2s0 45341/45313 *ECSubReadReply*(tid=191, attrs_read=0)) v2 2020-11-19 11:53:27.089 7fe925251700 20 osd.156 op_wq(2) _enqueue OpQueueItem(1.1e2s0 PGOpItem(op=*MOSDECSubOpReadReply*(1.1e2s0 45341/45313 ECSubReadReply(tid=191, attrs_read=0)) v2) prio 127 cost 0 e45341) 2020-11-19 11:53:27.089 7fe90678a700 20 osd.156 op_wq(2) _process 1.1e2s0 to_process <> waiting <> waiting_peering {} 2020-11-19 11:53:27.089 7fe90678a700 20 osd.156 op_wq(2) _process OpQueueItem(1.1e2s0 PGOpItem(op=*MOSDECSubOpReadReply*(1.1e2s0 45341/45313 ECSubReadReply(tid=191, attrs_read=0)) v2) prio 127 cost 0 e45341) queued 2020-11-19 11:53:27.089 7fe90678a700 20 osd.156 op_wq(2) _process 1.1e2s0 to_process <OpQueueItem(1.1e2s0 PGOpItem(op=MOSDECSubOpReadReply(1.1e2s0 45341/45313 ECSubReadReply(tid=191, attrs_read=0)) v2) prio 127 cost 0 e45341)> waiting <> waiting_peering {} 2020-11-19 11:53:27.089 7fe90678a700 20 osd.156 op_wq(2) _process OpQueueItem(1.1e2s0 PGOpItem(op=*MOSDECSubOpReadReply*(1.1e2s0 45341/45313 *ECSubReadReply*(tid=191, attrs_read=0)) v2) prio 127 cost 0 e45341) pg 0x559f8b5e5000 2020-11-19 11:53:27.089 7fe90678a700 10 osd.156 45341 dequeue_op 0x559f8f9618c0 prio 127 cost 0 latency 0.000092 MOSDECSubOpReadReply(1.1e2s0 45341/45313 ECSubReadReply(tid=191, attrs_read=0)) v2 pg pg[1.1e2s0( v 45295'4373744 (34740'4370700,45295'4373744] local-lis/les=45313/45317 n=1842926 ec=5869/714 lis/c 45313/45313 les/c/f 45317/45322/0 45313/45313/45313) [156,64,146,256,98,67,46,31,100]p156(0) r=0 lpr=45313 crt=45295'4373744 lcod 0'0 mlcod 0'0 active+clean] Now my question is: What is triggering the enqueue_op? And what is triggering this operation ('cause it takes 5 seconds)? Which debug setting can help me find that out? Many thanks for the feedback, Kristof