Ceph » bluestore

Hey @Adam Kupczyk can you take a look?

/a/skanta-2024-09-27_06:56:34-rados-wip-bharath14-testing-2024-09-26-2119-squid-distro-default-smithi/7921642

/a/yuriw-2024-10-16_22:34:49-rados-wip-yuri10-testing-2024-10-15-1007-distro-default-smithi/7952544/

/a/yuriw-2024-10-23_23:17:32-rados-wip-yuri13-testing-2024-10-23-0743-distro-default-smithi/7963642

/a/yuriw-2024-10-16_14:57:58-rados-wip-yuri2-testing-2024-10-15-0703-distro-default-smithi/7950897

/a/yuriw-2024-11-21_15:33:29-rados-wip-yuri2-testing-2024-11-15-0902-distro-default-smithi/8003584

/a/yuriw-2024-12-24_16:11:09-rados-squid-release-distro-default-smithi/8051547

/a/yuriw-2024-12-18_15:56:21-rados-wip-yuri6-testing-2024-12-17-1653-distro-default-smithi/8043285

/a/skanta-2025-03-01_01:42:21-rados-wip-bharath3-testing-2025-03-01-0356-distro-default-smithi/8162109

/a/yuriw-2025-02-26_00:53:37-rados-wip-yuri2-testing-2025-02-25-1331-squid-distro-default-smithi/8153350

/a/skanta-2025-03-04_03:23:08-rados-wip-bharath4-testing-2025-03-03-0448-distro-default-smithi/8168969
/a/skanta-2025-03-04_03:23:08-rados-wip-bharath4-testing-2025-03-03-0448-distro-default-smithi/8168891

/a/skanta-2025-03-02_12:28:27-rados-wip-bharath8-testing-2025-03-02-0552-distro-default-smithi/8164424

/a/skanta-2025-02-18_22:53:18-rados-wip-bharath2-testing-2025-02-18-1645-squid-distro-default-smithi/
5 jobs: ['8138146', '8138310', '8138388', '8138295', '8138376']

/a/yuriw-2025-02-27_21:53:52-rados-wip-yuri3-testing-2025-02-27-0658-distro-default-smithi/8159362

/a/skanta-2025-03-12_23:26:26-rados-wip-bharath4-testing-2025-03-12-0528-distro-default-smithi/8185358/

/a/yuriw-2025-03-14_20:32:49-rados-wip-yuri7-testing-2025-03-11-0847-distro-default-smithi/8190469

/a/yuriw-2025-03-14_20:21:57-rados-wip-yuri13-testing-2025-03-14-0922-distro-default-smithi/8190103

/a/yuriw-2025-03-20_14:48:30-rados-wip-yuri3-testing-2025-03-18-0732-distro-default-smithi/8199766

/a/skanta-2025-03-23_11:08:44-rados-wip-bharath15-testing-2025-03-22-1514-distro-default-smithi/8204178

/a/yuriw-2025-03-21_20:27:12-rados-wip-yuri2-testing-2025-03-21-0820-distro-default-smithi/8202099

/a/skanta-2025-03-27_08:02:07-rados-wip-bharath10-testing-2025-03-27-0430-distro-default-smithi/8212800

/a/yuriw-2025-03-29_14:10:41-rados-wip-yuri11-testing-2025-03-28-1517-squid-distro-default-smithi/8215730

/a/skanta-2025-04-04_06:10:17-rados-wip-bharath10-testing-2025-04-03-2112-distro-default-smithi/8223620

/a/yuriw-2025-04-07_23:32:09-rados-wip-yuri13-testing-2025-04-07-1144-distro-default-smithi/8229091
/a/yuriw-2025-04-07_23:32:09-rados-wip-yuri13-testing-2025-04-07-1144-distro-default-smithi/8229404

/a/skanta-2025-04-05_15:49:33-rados-wip-bharath8-testing-2025-04-05-1439-distro-default-smithi/8225363

/a/lflores-2025-04-14_14:00:23-rados-wip-lflores-testing-2-2025-04-11-1133-distro-default-smithi/8239441

Looks like at least some of the above failures are bound to embedded OSD benchmarking (apparently called by mclock scheduler) as slow ops are reported immediated after that, e.g.

2025-04-14T17:18:46.932+0000 5ef1940 1 osd.8 0 bench count 12288000 bsize 4 KiB
...
2025-04-14T17:18:53.294+0000 1e5fe640 0 bluestore(/var/lib/ceph/osd/ceph-8) log_latency slow operation observed for kv_sync, latency = 5.239987850s

Please note the timestamps delta and latency reported in "slow operation observed" line.
Indeed apart from writing benchmark data itself this procedure writes out ~400MB data to disk as a prefill stuff. Likely this stalls BlueStore on weak teuthology nodes.
https://github.com/ceph/ceph/pull/62866 hopefully provides a bit better visibility to the case by addinig more verbose logging to the benchmarking method.

/a/lflores-2025-04-15_00:57:49-rados-wip-lflores-testing-5-2025-04-14-1635-distro-default-gibba/8241200

/a/skanta-2025-05-28_00:49:22-rados-wip-bharath8-testing-2025-05-27-1740-distro-default-smithi/8299240

/a/skanta-2025-06-07_04:15:58-rados-wip-bharath8-testing-2025-06-02-1508-distro-default-smithi/8312612/

Seen on tentacle:
/a/yuriw-2025-07-01_21:01:48-rados-wip-yuri11-testing-2025-07-01-1146-tentacle-distro-default-smithi/8365756

Confirmed that osd_mclock_skip_benchmark is set to true and so the 'osd bench' on start-up is not the reason
for the slow op alert.

During the course of the test, the slow op appears to be triggered due to stalled aio as shown below: But the
OSD's threadpool worker threads were already reporting heartbeat timeouts, the first instances of which is
shown below:

2025-07-02T03:25:34.642+0000 7fabe3d85640  1 -- [v2:172.21.15.84:6804/1741798596,v1:172.21.15.84:6805/1741798596] <== osd.2 172.21.15.151:0/3437529257 168 ==== osd_ping(ping e144 up_from 9 ping_stamp 2025-07-02T03:25:34.645126+0000/526.835571289s send_stamp 526.835571289s delta_ub -0.244257003s) ==== 2033+0+0 (crc 0 0 0) 0x560397e31500 con 0x560391b63400
2025-07-02T03:25:34.642+0000 7fabe3d85640 20 osd.0 144 handle_osd_ping new stamps hbstamp(osd.2 up_from 9 peer_clock_delta [-0.245183900s,-0.244257003s])
2025-07-02T03:25:34.642+0000 7fabe3584640  1 -- [v2:172.21.15.84:6806/1741798596,v1:172.21.15.84:6807/1741798596] <== osd.2 172.21.15.151:0/3437529257 168 ==== osd_ping(ping e144 up_from 9 ping_stamp 2025-07-02T03:25:34.645126+0000/526.835571289s send_stamp 526.835571289s delta_ub -0.244257003s) ==== 2033+0+0 (crc 0 0 0) 0x560390e44e00 con 0x5603905b4000
2025-07-02T03:25:34.642+0000 7fabe3d85640  1 heartbeat_map is_healthy 'OSD::osd_op_tp thread 0x7fabbf050640' had timed out after 15.000000954s
2025-07-02T03:25:34.642+0000 7fabe3d85640  1 heartbeat_map is_healthy 'OSD::osd_op_tp thread 0x7fabc0052640' had timed out after 15.000000954s
2025-07-02T03:25:34.642+0000 7fabe3d85640  1 heartbeat_map is_healthy 'OSD::osd_op_tp thread 0x7fabc0853640' had timed out after 15.000000954s
2025-07-02T03:25:34.642+0000 7fabe3d85640  1 heartbeat_map is_healthy 'OSD::osd_op_tp thread 0x7fabc1855640' had timed out after 15.000000954s
2025-07-02T03:25:34.642+0000 7fabe3d85640  1 heartbeat_map is_healthy 'OSD::osd_op_tp thread 0x7fabc2857640' had timed out after 15.000000954s
2025-07-02T03:25:34.642+0000 7fabe3d85640  1 heartbeat_map is_healthy 'OSD::osd_op_tp thread 0x7fabc3058640' had timed out after 15.000000954s
2025-07-02T03:25:34.642+0000 7fabe3d85640  1 heartbeat_map is_healthy 'OSD::osd_op_tp thread 0x7fabc3859640' had timed out after 15.000000954s
2025-07-02T03:25:34.642+0000 7fabe3d85640  1 heartbeat_map is_healthy 'OSD::osd_op_tp thread 0x7fabc405a640' had timed out after 15.000000954s
2025-07-02T03:25:34.642+0000 7fabe3d85640  1 heartbeat_map is_healthy 'OSD::osd_op_tp thread 0x7fabc505c640' had timed out after 15.000000954s
2025-07-02T03:25:34.642+0000 7fabe3d85640  1 heartbeat_map is_healthy 'OSD::osd_op_tp thread 0x7fabc585d640' had timed out after 15.000000954s
2025-07-02T03:25:34.642+0000 7fabe3d85640  1 heartbeat_map is_healthy 'OSD::osd_op_tp thread 0x7fabc685f640' had timed out after 15.000000954s
2025-07-02T03:25:34.642+0000 7fabe3d85640 10 osd.0 144 internal heartbeat not healthy, dropping ping request

....

2025-07-02T03:25:43.818+0000 7fabd7b74640 -1 bdev(0x56038f9c1c00 /var/lib/ceph/osd/ceph-0/block) debug_aio_unlink stalled aio 0x5603939c6b10 since 2025-07-02T03:25:17.473823+0000, timeout is 5s
2025-07-02T03:25:43.826+0000 7fabd7b74640 10 bluestore(/var/lib/ceph/osd/ceph-0) _txc_state_proc txc 0x560395bd2600 aio_wait
2025-07-02T03:25:43.826+0000 7fabc2857640  0 bluestore(/var/lib/ceph/osd/ceph-0) log_latency slow operation observed for submit_transact, latency = 26.359331131s
2025-07-02T03:25:43.826+0000 7fabd7b74640  0 bluestore(/var/lib/ceph/osd/ceph-0) _txc_state_proc slow aio_wait, txc = 0x560395bd2600, latency = 26.357818604s
2025-07-02T03:25:43.826+0000 7fabd7b74640 20 bluestore(/var/lib/ceph/osd/ceph-0) _txc_finish_io 0x560395bd2600
2025-07-02T03:25:43.826+0000 7fabc2857640 10 osd.0 144 dequeue_op osd_repop(client.6276.0:2017 9.8 e144/141 9:1ecb4df2:::benchmark_data_smithi084_18396_object2016:head v 144'129, pct=144'128) v3 finish
2025-07-02T03:25:43.826+0000 7fabc2857640  1 heartbeat_map reset_timeout 'OSD::osd_op_tp thread 0x7fabc2857640' had timed out after 15.000000954s

/a/skanta-2025-07-03_10:29:59-rados-wip-bharath5-testing-2025-06-30-2106-distro-default-smithi/8368515

Shraddha Agrawal wrote in #note-39:

/a/skanta-2025-07-03_10:29:59-rados-wip-bharath5-testing-2025-06-30-2106-distro-default-smithi/8368515

This time we've got some gap in OSD.9 log output which looks like OSD stuck for ~50 sec. With debug_bluestore level set to 20 it looks pretty unrealistic we have no output for that long unless the OSD process was stalled by some external means..
2025-07-03T11:27:13.381+0000 9e8d640 20 osd.9 128 get_con_osd_cluster to osd.8 from_epoch 128
2025-07-03T11:27:13.381+0000 9e8d640 20 osd.9 128 get_nextmap_reserved map_reservations: {128=2}
2025-07-03T11:27:13.381+0000 9e8d640 20 osd.9 128 release_map epoch: 128
2025-07-03T11:27:13.370+0000 2d2be640 10 osd.9 128 maybe_share_map: con v2:172.21.15.46:6813/3671089128 our osdmap epoch of 128 is not newer than session's projected_epoch of 128
2025-07-03T11:28:02.939+0000 27ab3640 15 osd.9 128 enqueue_peering_evt 23.7 epoch_sent: 126 epoch_requested: 126 RenewLease
2025-07-03T11:28:02.939+0000 27ab3640 20 osd.9 op_wq(7) _enqueue OpSchedulerItem(23.7 PGPeeringEvent(epoch_sent: 126 epoch_requested: 126 RenewLease) class_id 2 prio 255 cost 10 e126)
2025-07-03T11:28:02.939+0000 27ab3640 15 osd.9 128 enqueue_peering_evt 23.11 epoch_sent: 126 epoch_requested: 126 RenewLease


/a/yuriw-2025-07-07_23:26:39-rados-wip-yuri3-testing-2025-07-07-1323-squid-distro-default-smithi/8375006

/a/skanta-2025-07-27_15:49:52-rados-wip-bharath9-testing-2025-07-26-0628-distro-default-smithi/8410723

Igor Fedotov wrote in #note-40:

Shraddha Agrawal wrote in #note-39:

/a/skanta-2025-07-03_10:29:59-rados-wip-bharath5-testing-2025-06-30-2106-distro-default-smithi/8368515

This time we've got some gap in OSD.9 log output which looks like OSD stuck for ~50 sec. With debug_bluestore level set to 20 it looks pretty unrealistic we have no output for that long unless the OSD process was stalled by some external means..
2025-07-03T11:27:13.381+0000 9e8d640 20 osd.9 128 get_con_osd_cluster to osd.8 from_epoch 128
2025-07-03T11:27:13.381+0000 9e8d640 20 osd.9 128 get_nextmap_reserved map_reservations: {128=2}
2025-07-03T11:27:13.381+0000 9e8d640 20 osd.9 128 release_map epoch: 128
2025-07-03T11:27:13.370+0000 2d2be640 10 osd.9 128 maybe_share_map: con v2:172.21.15.46:6813/3671089128 our osdmap epoch of 128 is not newer than session's projected_epoch of 128
2025-07-03T11:28:02.939+0000 27ab3640 15 osd.9 128 enqueue_peering_evt 23.7 epoch_sent: 126 epoch_requested: 126 RenewLease
2025-07-03T11:28:02.939+0000 27ab3640 20 osd.9 op_wq(7) _enqueue OpSchedulerItem(23.7 PGPeeringEvent(epoch_sent: 126 epoch_requested: 126 RenewLease) class_id 2 prio 255 cost 10 e126)
2025-07-03T11:28:02.939+0000 27ab3640 15 osd.9 128 enqueue_peering_evt 23.11 epoch_sent: 126 epoch_requested: 126 RenewLease


@Ilya Dryomov what info are we missing here, if any?

squid -
https://pulpito.ceph.com/hyelloji-2025-08-11_06:39:02-fs-wip-hemanth2-testing-2025-08-01-0731-squid-distro-default-smithi/8435861/

/a/skanta-2025-08-05_03:51:26-rados-wip-bharath9-testing-2025-08-05-0506-distro-default-smithi/8424386

Laura Flores wrote in #note-45:

/a/skanta-2025-08-05_03:51:26-rados-wip-bharath9-testing-2025-08-05-0506-distro-default-smithi/8424386

Both OSDs .5 & .15 reported slow ops. At both OSDs slow ops had neem happening during initial OSD benchmarking. See log snippets below

from OSD.5 log:
2025-08-05T06:43:20.112+0000 5faea00 0 OSDBenchTest: OSD Bench Test Params: count: 12288000 Bytes block size: 4 KiB number of objects: 100 object size: 4 MiB
2025-08-05T06:43:20.119+0000 5faea00 0 OSDBenchTest: run_test: running osd bench with count: 12288000 Bytes bsize: 4 KiB onum: 100 osize: 4 MiB
...
2025-08-05T06:43:26.250+0000 1e2ac640 0 bluestore(/var/lib/ceph/osd/ceph-5) log_latency_fn slow operation observed for _txc_committed_kv, latency = 6.108261585s, txc = 0x162a5470, txc bytes = 4194525, txc ios = 65, txc cost = 4454525, txc onodes = 1, DB updates = 1, DB bytes = 1193, cost max = 71272407 on 2025-08-05T06:43:26.241087+0000, txc max = 16 on 2025-08-05T06:43:25.705120+0000
...
2025-08-05T06:43:54.253+0000 1e2ac640 0 bluestore(/var/lib/ceph/osd/ceph-5) log_latency_fn slow operation observed for _txc_committed_kv, latency = 5.026462078s, txc = 0x66e6f60, txc bytes = 4194526, txc ios = 65, txc cost = 4454526, txc onodes = 1, DB updates = 1, DB bytes = 1194, cost max = 71272416 on 2025-08-05T06:43:29.476188+0000, txc max = 16 on 2025-08-05T06:43:25.705120+0000
2025-08-05T06:43:54.281+0000 5faea00 0 OSDBenchTest: prefill_objects: Prefill took 34.16 secs.

For OSD.15
2025-08-05T06:43:19.033+0000 5faea00 0 OSDBenchTest: OSD Bench Test Params: count: 12288000 Bytes block size: 4 KiB number of objects: 100 object size: 4 MiB
2025-08-05T06:43:19.041+0000 5faea00 0 OSDBenchTest: run_test: running osd bench with count: 12288000 Bytes bsize: 4 KiB onum: 100 osize: 4 MiB
...
2025-08-05T06:43:25.681+0000 1deac640 0 bluestore(/var/lib/ceph/osd/ceph-15) log_latency_fn slow operation observed for txc_committed_kv, latency = 6.618067265s, txc = 0x162be060, txc bytes = 4194525, txc ios = 65, txc cost = 4454525, txc onodes = 1, DB updates = 1, DB bytes = 1193, cost max = 71272409 on 2025-08-05T06:43:25.680985+0000, txc max = 16 on 2025-08-05T06:43:24.512585+0000
...
2025-08-05T06:43:52.751+0000 1deac640 0 bluestore(/var/lib/ceph/osd/ceph-15) log_latency_fn slow operation observed for _txc_committed_kv, latency = 5.288516998s, txc = 0x31941b80, txc bytes = 4194526, txc ios = 65, txc cost = 4454526, txc onodes = 1, DB updates = 1, DB bytes = 1194, cost max = 71272416 on 2025-08-05T06:43:28.546180+0000, txc max = 17 on 2025-08-05T06:43:26.120335+0000
2025-08-05T06:43:52.784+0000 5faea00 0 OSDBenchTest: prefill_objects: Prefill took 33.74 secs.
...
2025-08-05T06:43:56.520+0000 5faea00 0 log_channel(cluster) log [WRN] : OSD bench result of 899.195348 IOPS is not within the threshold limit range of 1000.000000 IOPS and 80000.000000 IOPS for osd.15. IOPS capacity is unchanged at 21500.000000 IOPS. The recommendation is to establish the osd's IOPS capacity using other benchmark tools (e.g. Fio) and then override osd_mclock_max_capacity_iops[hdd|ssd].

Laura Flores wrote in #note-45:

/a/skanta-2025-08-05_03:51:26-rados-wip-bharath9-testing-2025-08-05-0506-distro-default-smithi/8424386

@Laura Flores,
IIUC this was run against main branch containing fixes for both https://tracker.ceph.com/issues/71419 & https://tracker.ceph.com/issues/71168, right?

If so @Adam Kupczyk or @Sridhar Seshasayee might want to take a look

/a/yuriw-2025-09-12_19:42:42-rados-wip-yuri3-testing-2025-09-12-0906-distro-default-smithi/8496820

/a/yuriw-2025-09-10_23:52:16-rados-wip-yuri10-testing-2025-09-10-1231-squid-distro-default-smithi/8493657

/a/yuriw-2025-10-16_19:13:59-rados-tentacle-release-distro-default-smithi/8556619

/a/yuriw-2025-10-21_19:06:36-rados-wip-yuri2-testing-2025-10-21-0752-squid-distro-default-smithi/8562422
/a/yuriw-2025-10-21_19:06:36-rados-wip-yuri2-testing-2025-10-21-0752-squid-distro-default-smithi/8562582

/a/skanta-2025-11-01_01:12:28-rados-wip-bharath5-testing-2025-10-31-1454-distro-default-smithi/8578595
/a/skanta-2025-10-31_12:25:51-rados-wip-bharath5-testing-2025-10-31-1454-distro-default-smithi/8577854

/a/lflores-2025-11-19_18:47:12-rados-wip-lflores-testing-2-2025-11-19-1711-distro-default-smithi/8613459

Squid:
https://pulpito.ceph.com/jcollin-2025-10-02_03:29:56-fs-wip-jcollin-testing-20251001.014437-squid-distro-default-smithi/8530963

https://pulpito.ceph.com/skanta-2026-01-28_09:27:17-rados-wip-bharath2-testing-2026-01-27-0639-squid-distro-default-trial/22956

/a/skanta-2026-01-29_13:10:13-rados-wip-bharath6-testing-2026-01-29-0855-squid-distro-default-trial/
[25748, 25754, 25756, 25760, 25767, 25771]

/a/yuriw-2026-02-17_20:43:43-rados-wip-yuri6-testing-2026-02-17-1732-squid-distro-default-trial/
['53902', '53880', '53895', '53862', '53886', '53874', '53878', '53894', '53897']

/a/yuriw-2026-02-24_16:22:43-rados-wip-yuri6-testing-2026-02-22-1629-squid-distro-default-trial/68631
/a/yuriw-2026-02-24_16:22:43-rados-wip-yuri6-testing-2026-02-22-1629-squid-distro-default-trial/68651
/a/yuriw-2026-02-24_16:22:43-rados-wip-yuri6-testing-2026-02-22-1629-squid-distro-default-trial/68632
/a/yuriw-2026-02-24_16:22:43-rados-wip-yuri6-testing-2026-02-22-1629-squid-distro-default-trial/68639
/a/yuriw-2026-02-24_16:22:43-rados-wip-yuri6-testing-2026-02-22-1629-squid-distro-default-trial/68648
/a/yuriw-2026-02-24_16:22:43-rados-wip-yuri6-testing-2026-02-22-1629-squid-distro-default-trial/68641
/a/yuriw-2026-02-24_16:22:43-rados-wip-yuri6-testing-2026-02-22-1629-squid-distro-default-trial/68638

/a/yuriw-2026-02-26_01:51:16-rados-wip-yuri9-testing-2026-02-25-1600-squid-distro-default-trial/
['70984', '70895', '71075' ]

/a/yuriw-2026-02-26_16:03:22-rados-wip-yuri9-testing-2026-02-25-1600-squid-distro-default-trial/
['72550', '72535', '72560', '72546', '72544', '72536', '72556']