Actions
Bug #69439
closedradosbench-high-concurrency: trim_to <= peering_state.get_pg_committed_to()
% Done:
0%
Source:
Backport:
tentacle
Regression:
No
Severity:
3 - minor
Reviewed:
Affected Versions:
ceph-qa-suite:
Pull request ID:
Tags (freeform):
backport_processed
Merge Commit:
Fixed In:
v20.3.0-118-g76dcf47d1c
Released In:
Upkeep Timestamp:
2025-07-14T19:37:47+00:00
Description
This failure was noticed when testing: https://github.com/ceph/ceph-ci/commits/wip-matanb-crimson-testing-january-5/
short_pg_log was added to the suite not recently so it might be related to backfill
DEBUG 2025-01-06 12:31:20,866 [shard 1:main] osd - pg_epoch 22 pg[3.e( v 22'353 (22'347,22'353] local-lis/les=16/17 n=45 ec=16/16 lis/c=16/16 les/c/f=17/17/0 sis=16) [2,1,3] r=0 lpr=16 pct=22'348 lua=0'0 crt=22'353 lcod 22'348 mlcod 22'348 active+clean PG::submit_executer: DEBUG 2025-01-06 12:31:20,866 [shard 2:main] ms - [0x5110000e5b40 osd.2(cluster) v2:172.21.15.156:6803/2092494667 >> osd.1 v2:172.21.15.8:6803/2377743465] GOT AckFrame: seq=1602 DEBUG 2025-01-06 12:31:20,866 [shard 1:main] osd - pg_epoch 22 pg[3.e( v 22'353 (22'347,22'353] local-lis/les=16/17 n=45 ec=16/16 lis/c=16/16 les/c/f=17/17/0 sis=16) [2,1,3] r=0 lpr=16 pct=22'348 lua=0'0 crt=22'353 lcod 22'348 mlcod 22'348 active+clean PGScrubber::handle_event: handle_event: op_stats_t DEBUG 2025-01-06 12:31:20,866 [shard 1:main] osd - pg_epoch 22 pg[3.e( v 22'353 (22'347,22'353] local-lis/les=16/17 n=45 ec=16/16 lis/c=16/16 les/c/f=17/17/0 sis=16) [2,1,3] r=0 lpr=16 pct=22'348 lua=0'0 crt=22'353 lcod 22'348 mlcod 22'348 active+clean PeeringState::prepare_stats_for_publish reporting purged_snaps [] DEBUG 2025-01-06 12:31:20,866 [shard 1:main] osd - pg_epoch 22 pg[3.e( v 22'353 (22'347,22'353] local-lis/les=16/17 n=45 ec=16/16 lis/c=16/16 les/c/f=17/17/0 sis=16) [2,1,3] r=0 lpr=16 pct=22'348 lua=0'0 crt=22'353 lcod 22'348 mlcod 22'348 active+clean PeeringState::prepare_stats_for_publish publish_stats_to_osd 22:378 DEBUG 2025-01-06 12:31:20,866 [shard 1:main] osd - pg_epoch 22 pg[3.e( v 22'353 (22'347,22'353] local-lis/les=16/17 n=45 ec=16/16 lis/c=16/16 les/c/f=17/17/0 sis=16) [2,1,3] r=0 lpr=16 pct=22'348 lua=0'0 crt=22'353 lcod 22'348 mlcod 22'348 active+clean OpsExecuter::prepare_head_update: entry: 22'354 (22'353) modify 3:7046def4:::benchmark_data_smithi008_32746_object723:head by client.4235.0:5786 2025-01-06T12:31:20.794987+0000 0 ObjectCleanRegions clean_offsets: [(0, 8192), (16384, 18446744073709535231)], clean_omap: true, new_object: false DEBUG 2025-01-06 12:31:20,867 [shard 2:main] ms - [0x5110000e5b40 osd.2(cluster) v2:172.21.15.156:6803/2092494667 >> osd.1 v2:172.21.15.8:6803/2377743465] <== #1607,1602 === osd_repop_reply(client.4235.0:5784 3.e e22/16) v2 (113) DEBUG 2025-01-06 12:31:20,867 [shard 1:main] osd - pg_epoch 22 pg[3.e( v 22'353 (22'347,22'353] local-lis/les=16/17 n=45 ec=16/16 lis/c=16/16 les/c/f=17/17/0 sis=16) [2,1,3] r=0 lpr=16 pct=22'348 lua=0'0 crt=22'353 lcod 22'348 mlcod 22'348 active+clean PeeringState::calc_trim_to_aggressive limit = 22'348 DEBUG 2025-01-06 12:31:20,867 [shard 1:main] osd - pg_epoch 22 pg[3.e( v 22'353 (22'347,22'353] local-lis/les=16/17 n=45 ec=16/16 lis/c=16/16 les/c/f=17/17/0 sis=16) [2,1,3] r=0 lpr=16 pct=22'348 lua=0'0 crt=22'353 lcod 22'348 mlcod 22'348 active+clean PeeringState::calc_trim_to_aggressive approx pg log length = 6 DEBUG 2025-01-06 12:31:20,867 [shard 1:main] osd - pg_epoch 22 pg[3.e( v 22'353 (22'347,22'353] local-lis/les=16/17 n=45 ec=16/16 lis/c=16/16 les/c/f=17/17/0 sis=16) [2,1,3] r=0 lpr=16 pct=22'348 lua=0'0 crt=22'353 lcod 22'348 mlcod 22'348 active+clean PeeringState::calc_trim_to_aggressive num_to_trim = 4 DEBUG 2025-01-06 12:31:20,867 [shard 1:main] osd - pg_epoch 22 pg[3.e( v 22'353 (22'347,22'353] local-lis/les=16/17 n=45 ec=16/16 lis/c=16/16 les/c/f=17/17/0 sis=16) [2,1,3] r=0 lpr=16 pct=22'348 lua=0'0 crt=22'353 lcod 22'348 mlcod 22'348 active+clean PeeringState::calc_trim_to_aggressive pg_trim_to now 22'348 DEBUG 2025-01-06 12:31:20,867 [shard 1:main] osd - pg_epoch 22 pg[3.e( v 22'353 (22'347,22'353] local-lis/les=16/17 n=45 ec=16/16 lis/c=16/16 les/c/f=17/17/0 sis=16) [2,1,3] r=0 lpr=16 pct=22'348 lua=0'0 crt=22'353 lcod 22'348 mlcod 22'348 active+clean ReplicatedBackend::submit_transaction: object 3:7046def4:::benchmark_data_smithi008_32746_object723:head DEBUG 2025-01-06 12:31:20,867 [shard 1:main] osd - pg_epoch 22 pg[3.e( v 22'353 (22'347,22'353] local-lis/les=16/17 n=45 ec=16/16 lis/c=16/16 les/c/f=17/17/0 sis=16) [2,1,3] r=0 lpr=16 pct=22'348 lua=0'0 crt=22'353 lcod 22'348 mlcod 22'348 active+clean PG::update_snap_map: DEBUG 2025-01-06 12:31:20,867 [shard 1:main] osd - pg_epoch 22 pg[3.e( v 22'353 (22'347,22'353] local-lis/les=16/17 n=45 ec=16/16 lis/c=16/16 les/c/f=17/17/0 sis=16) [2,1,3] r=0 lpr=16 pct=22'348 lua=0'0 crt=22'353 lcod 22'348 mlcod 22'348 active+clean PG::log_operation: ERROR 2025-01-06 12:31:20,867 [shard 1:main] none - /home/jenkins-build/build/workspace/ceph-dev-new-build/ARCH/x86_64/AVAILABLE_ARCH/x86_64/AVAILABLE_DIST/centos9/DIST/centos9/MACHINE_SIZE/gigantic/release/19.3.0-6702-g438c8a71/rpm/el9/BUILD/ceph-19.3.0-6702-g438c8a71/src/crimson/osd/pg.cc:1300 : In function 'void crimson::osd::PG::log_operation(std::vector<pg_log_entry_t>&&, const eversion_t&, const eversion_t&, const eversion_t&, bool, ObjectStore::Transaction&, bool)', ceph_assert(%s) trim_to <= peering_state.get_pg_committed_to() Aborting on shard 1. Backtrace:
Files
Updated by Matan Breizman about 1 year ago
- Related to Bug #69412: crimson: sparse read omitted non-zero data ... added
Updated by Yingxin Cheng about 1 year ago
Updated by Xuehan Xu about 1 year ago · Edited
PeeringState::pg_trim_to first resolved to 22.349
DEBUG 2025-01-06 12:31:20,858 [shard 1:main] osd - pg_epoch 22 pg[3.e( v 22'352 (22'347,22'352] local-lis/les=16/17 n=45 ec=16/16 lis/c=16/16 les/c/f=17/17/0 sis=16) [2,1,3] r=0 lpr=16 pct=22'349 lua=0'0 crt=22'352 lcod 22'349 mlcod 22'349 active+clean PeeringState::calc_trim_to_aggressive limit = 22'349 DEBUG 2025-01-06 12:31:20,858 [shard 1:main] osd - pg_epoch 22 pg[3.e( v 22'352 (22'347,22'352] local-lis/les=16/17 n=45 ec=16/16 lis/c=16/16 les/c/f=17/17/0 sis=16) [2,1,3] r=0 lpr=16 pct=22'349 lua=0'0 crt=22'352 lcod 22'349 mlcod 22'349 active+clean PeeringState::calc_trim_to_aggressive approx pg log length = 5 DEBUG 2025-01-06 12:31:20,858 [shard 1:main] osd - pg_epoch 22 pg[3.e( v 22'352 (22'347,22'352] local-lis/les=16/17 n=45 ec=16/16 lis/c=16/16 les/c/f=17/17/0 sis=16) [2,1,3] r=0 lpr=16 pct=22'349 lua=0'0 crt=22'352 lcod 22'349 mlcod 22'349 active+clean PeeringState::calc_trim_to_aggressive num_to_trim = 3 DEBUG 2025-01-06 12:31:20,858 [shard 1:main] osd - pg_epoch 22 pg[3.e( v 22'352 (22'347,22'352] local-lis/les=16/17 n=45 ec=16/16 lis/c=16/16 les/c/f=17/17/0 sis=16) [2,1,3] r=0 lpr=16 pct=22'349 lua=0'0 crt=22'352 lcod 22'349 mlcod 22'349 active+clean PeeringState::calc_trim_to_aggressive pg_trim_to now 22'349
PeeringState::pg_trim_to later resolved to 22.348
DEBUG 2025-01-06 12:31:20,867 [shard 2:main] ms - [0x5110000e5b40 osd.2(cluster) v2:172.21.15.156:6803/2092494667 >> osd.1 v2:172.21.15.8:6803/2377743465] <== #1607,1602 === osd_repop_reply(client.4235.0:5784 3.e e22/16) v2 (113) DEBUG 2025-01-06 12:31:20,867 [shard 1:main] osd - pg_epoch 22 pg[3.e( v 22'353 (22'347,22'353] local-lis/les=16/17 n=45 ec=16/16 lis/c=16/16 les/c/f=17/17/0 sis=16) [2,1,3] r=0 lpr=16 pct=22'348 lua=0'0 crt=22'353 lcod 22'348 mlcod 22'348 active+clean PeeringState::calc_trim_to_aggressive limit = 22'348 DEBUG 2025-01-06 12:31:20,867 [shard 1:main] osd - pg_epoch 22 pg[3.e( v 22'353 (22'347,22'353] local-lis/les=16/17 n=45 ec=16/16 lis/c=16/16 les/c/f=17/17/0 sis=16) [2,1,3] r=0 lpr=16 pct=22'348 lua=0'0 crt=22'353 lcod 22'348 mlcod 22'348 active+clean PeeringState::calc_trim_to_aggressive approx pg log length = 6 DEBUG 2025-01-06 12:31:20,867 [shard 1:main] osd - pg_epoch 22 pg[3.e( v 22'353 (22'347,22'353] local-lis/les=16/17 n=45 ec=16/16 lis/c=16/16 les/c/f=17/17/0 sis=16) [2,1,3] r=0 lpr=16 pct=22'348 lua=0'0 crt=22'353 lcod 22'348 mlcod 22'348 active+clean PeeringState::calc_trim_to_aggressive num_to_trim = 4 DEBUG 2025-01-06 12:31:20,867 [shard 1:main] osd - pg_epoch 22 pg[3.e( v 22'353 (22'347,22'353] local-lis/les=16/17 n=45 ec=16/16 lis/c=16/16 les/c/f=17/17/0 sis=16) [2,1,3] r=0 lpr=16 pct=22'348 lua=0'0 crt=22'353 lcod 22'348 mlcod 22'348 active+clean PeeringState::calc_trim_to_aggressive pg_trim_to now 22'348
Updated by Xuehan Xu about 1 year ago
I think this issue is caused by not controlling the order of client requests' post on-disk processing:
The post on-disk processing for client.4235.0:5781 happens before client.4235.0:5780
DEBUG 2025-01-06 12:31:20,858 [shard 1:main] osd - pg_epoch 22 pg[3.e( v 22'352 (22'347,22'352] local-lis/les=16/17 n=44 ec=16/16 lis/c=16/16 les/c/f=17/17/0 sis=16) [2,1,3] r=0 lpr=16 pct=22'347 lua=0'0 crt=22'352 lcod 22'347 mlcod 22'347 active+clean PeeringState::update_peer_last_complete_ondisk updating peer_last_complete_ondisk of osd: 1 to: 22'349 DEBUG 2025-01-06 12:31:20,858 [shard 1:main] osd - pg_epoch 22 pg[3.e( v 22'352 (22'347,22'352] local-lis/les=16/17 n=44 ec=16/16 lis/c=16/16 les/c/f=17/17/0 sis=16) [2,1,3] r=0 lpr=16 pct=22'347 lua=0'0 crt=22'352 lcod 22'347 mlcod 22'347 active+clean PeeringState::update_peer_last_complete_ondisk updating peer_last_complete_ondisk of osd: 3 to: 22'349 ...... DEBUG 2025-01-06 12:31:20,860 [shard 1:main] osd - pg_epoch 22 pg[3.e( v 22'353 (22'347,22'353] local-lis/les=16/17 n=45 ec=16/16 lis/c=16/16 les/c/f=17/17/0 sis=16) [2,1,3] r=0 lpr=16 pct=22'349 lua=0'0 crt=22'353 lcod 22'349 mlcod 22'349 active+clean PeeringState::update_peer_last_complete_ondisk updating peer_last_complete_ondisk of osd: 1 to: 22'348 DEBUG 2025-01-06 12:31:20,860 [shard 1:main] osd - pg_epoch 22 pg[3.e( v 22'353 (22'347,22'353] local-lis/les=16/17 n=45 ec=16/16 lis/c=16/16 les/c/f=17/17/0 sis=16) [2,1,3] r=0 lpr=16 pct=22'349 lua=0'0 crt=22'353 lcod 22'349 mlcod 22'349 active+clean PeeringState::update_peer_last_complete_ondisk updating peer_last_complete_ondisk of osd: 3 to: 22'348
Updated by Matan Breizman about 1 year ago · Edited
- Status changed from New to In Progress
Updated by Matan Breizman about 1 year ago
- Pull request ID changed from 61381 to 62146
Updated by Matan Breizman about 1 year ago
Matan Breizman wrote in #note-9:
with 62146 merged:
http://qa-proxy.ceph.com/teuthology/matan-2025-03-10_08:59:19-crimson-rados-wip-matanb-crimson-only-testing-9-march-distro-crimson-smithi/8178298/teuthology.loglooking into this.
From osd.2 (shard1/pg5.a):
DEBUG 2025-03-10 09:52:04,730 [shard 1:main] osd - pg_epoch 43 pg[5.a( v 43'38 (43'33,43'38] local-lis/les=41/42 n=5 ec=41/41 lis/c=41/41 les/c/f=42/42/0 sis=41) [2,3,0] r=0 lpr=41 pct=43'36 lua=0'0 crt=43'38 lcod 43'35 mlcod 43'35 active+clean PeeringState::calc_trim_to_aggressive pg_trim_to now 43'36 ... DEBUG 2025-03-10 09:52:04,739 [shard 1:main] osd - pg_epoch 43 pg[5.a( v 43'39 (43'33,43'39] local-lis/les=41/42 n=5 ec=41/41 lis/c=41/41 les/c/f=42/42/0 sis=41) [2,3,0] r=0 lpr=41 pct=43'35 lua=0'0 crt=43'39 lcod 43'34 mlcod 43'34 active+clean PeeringState::calc_trim_to_aggressive pg_trim_to now 43'35
pct=43'36 is updated to pct=43'35 which will cause the assert of:
trim_to (43'36) <= peering_state.get_pg_committed_to() (43'35)
Updated by Matan Breizman about 1 year ago · Edited
- Subject changed from thrash/short_pg_log: trim_to <= peering_state.get_pg_committed_to() to radosbench-high-concurrency: trim_to <= peering_state.get_pg_committed_to()
Note, all the failures are from radosbench-high-concurrency (mostly with thrashers/simple hence not related to recovery, should make it easier to reproduce)
Updated by Matan Breizman about 1 year ago · Edited
- Assignee changed from Xuehan Xu to Matan Breizman
- Priority changed from Normal to High
- Pull request ID changed from 62146 to 62277
Changing to 62277 as the issue still appears.
For now there are only logs added in the PR to more easily spot the issue:
DEBUG 2025-03-16 10:20:55,445 [shard 1:main] osd - pg_epoch 62 pg[9.9( v 62'316 (62'296,62'316] local-lis/les=60/61 n=40 ec=60/60 lis/c=60/60 les/c/f=61/61/0 sis=60) [3,0,2] r=0 lpr=60 pct=62'309 lua=0'0 crt=62'316 lcod 62'308 mlcod 62'308 active+clean PG::complete_write: updating pct to: 62'308 updating lcod to: 62'307 DEBUG 2025-03-16 10:20:55,448 [shard 1:main] osd - pg_epoch 62 pg[9.9( v 62'316 (62'296,62'316] local-lis/les=60/61 n=40 ec=60/60 lis/c=60/60 les/c/f=61/61/0 sis=60) [3,0,2] r=0 lpr=60 pct=62'308 lua=0'0 crt=62'316 lcod 62'307 mlcod 62'307 active+clean PG::complete_write: updating pct to: 62'311 updating lcod to: 62'310 DEBUG 2025-03-16 10:20:55,453 [shard 1:main] osd - pg_epoch 62 pg[9.9( v 62'317 (62'296,62'317] local-lis/les=60/61 n=40 ec=60/60 lis/c=60/60 les/c/f=61/61/0 sis=60) [3,0,2] r=0 lpr=60 pct=62'311 lua=0'0 crt=62'317 lcod 62'310 mlcod 62'310 active+clean PG::complete_write: updating pct to: 62'312 updating lcod to: 62'311 DEBUG 2025-03-16 10:20:55,454 [shard 1:main] osd - pg_epoch 62 pg[9.9( v 62'317 (62'296,62'317] local-lis/les=60/61 n=40 ec=60/60 lis/c=60/60 les/c/f=61/61/0 sis=60) [3,0,2] r=0 lpr=60 pct=62'312 lua=0'0 crt=62'317 lcod 62'311 mlcod 62'311 active+clean PG::complete_write: updating pct to: 62'310 updating lcod to: 62'309
same goes for lcod:
DEBUG 2025-03-16 10:20:55,448 [shard 1:main] osd - pg_epoch 62 pg[9.9( v 62'316 (62'296,62'316] local-lis/les=60/61 n=40 ec=60/60 lis/c=60/60 les/c/f=61/61/0 sis=60) [3,0,2] r=0 lpr=60 pct=62'308 lua=0'0 crt=62'316 lcod 62'307 mlcod 62'307 active+clean ReplicatedBackend::got_rep_op_reply: got reply from 2 updating lcod to: 62'311 DEBUG 2025-03-16 10:20:55,448 [shard 1:main] osd - pg_epoch 62 pg[9.9( v 62'316 (62'296,62'316] local-lis/les=60/61 n=40 ec=60/60 lis/c=60/60 les/c/f=61/61/0 sis=60) [3,0,2] r=0 lpr=60 pct=62'308 lua=0'0 crt=62'316 lcod 62'307 mlcod 62'307 active+clean ReplicatedBackend::got_rep_op_reply: got reply from 2 updating lcod to: 62'311 DEBUG 2025-03-16 10:20:55,453 [shard 1:main] osd - pg_epoch 62 pg[9.9( v 62'317 (62'296,62'317] local-lis/les=60/61 n=40 ec=60/60 lis/c=60/60 les/c/f=61/61/0 sis=60) [3,0,2] r=0 lpr=60 pct=62'311 lua=0'0 crt=62'317 lcod 62'310 mlcod 62'310 active+clean ReplicatedBackend::got_rep_op_reply: got reply from 2 updating lcod to: 62'312 DEBUG 2025-03-16 10:20:55,454 [shard 1:main] osd - pg_epoch 62 pg[9.9( v 62'317 (62'296,62'317] local-lis/les=60/61 n=40 ec=60/60 lis/c=60/60 les/c/f=61/61/0 sis=60) [3,0,2] r=0 lpr=60 pct=62'312 lua=0'0 crt=62'317 lcod 62'311 mlcod 62'311 active+clean ReplicatedBackend::got_rep_op_reply: got reply from 2 updating lcod to: 62'310
We seem to handle a repop out of order, client.5896.0:4742 is handled after client.5896.0:4744
DEBUG 2025-03-16 10:20:55,448 [shard 1:main] osd - pg_epoch 62 pg[9.9( v 62'316 (62'296,62'316] local-lis/les=60/61 n=40 ec=60/60 lis/c=60/60 les/c/f=61/61/0 sis=60) [3,0,2] r=0 lpr=60 pct=62'308 lua=0'0 crt=62'316 lcod 62'307 mlcod 62'307 active+clean ReplicatedBackend::got_rep_op_reply: osd_repop_reply(client.5896.0:4743 9.9 e62/60 ondisk, result = 0) v2 DEBUG 2025-03-16 10:20:55,448 [shard 1:main] osd - pg_epoch 62 pg[9.9( v 62'316 (62'296,62'316] local-lis/les=60/61 n=40 ec=60/60 lis/c=60/60 les/c/f=61/61/0 sis=60) [3,0,2] r=0 lpr=60 pct=62'308 lua=0'0 crt=62'316 lcod 62'307 mlcod 62'307 active+clean ReplicatedBackend::got_rep_op_reply: got reply from 2 updating lcod to: 62'311 DEBUG 2025-03-16 10:20:55,448 [shard 1:main] osd - pg_epoch 62 pg[9.9( v 62'316 (62'296,62'316] local-lis/les=60/61 n=40 ec=60/60 lis/c=60/60 les/c/f=61/61/0 sis=60) [3,0,2] r=0 lpr=60 pct=62'308 lua=0'0 crt=62'316 lcod 62'307 mlcod 62'307 active+clean ReplicatedBackend::got_rep_op_reply: got reply from 2 updating lcod to: 62'311 DEBUG 2025-03-16 10:20:55,448 [shard 1:main] osd - pg_epoch 62 pg[9.9( v 62'316 (62'296,62'316] local-lis/les=60/61 n=40 ec=60/60 lis/c=60/60 les/c/f=61/61/0 sis=60) [3,0,2] r=0 lpr=60 pct=62'308 lua=0'0 crt=62'316 lcod 62'307 mlcod 62'307 active+clean ReplicatedBackend::got_rep_op_reply: all peers have acked, completing write DEBUG 2025-03-16 10:20:55,452 [shard 1:main] osd - pg_epoch 62 pg[9.9( v 62'317 (62'296,62'317] local-lis/les=60/61 n=40 ec=60/60 lis/c=60/60 les/c/f=61/61/0 sis=60) [3,0,2] r=0 lpr=60 pct=62'311 lua=0'0 crt=62'317 lcod 62'310 mlcod 62'310 active+clean ReplicatedBackend::got_rep_op_reply: osd_repop_reply(client.5896.0:4744 9.9 e62/60 ondisk, result = 0) v2 DEBUG 2025-03-16 10:20:55,453 [shard 1:main] osd - pg_epoch 62 pg[9.9( v 62'317 (62'296,62'317] local-lis/les=60/61 n=40 ec=60/60 lis/c=60/60 les/c/f=61/61/0 sis=60) [3,0,2] r=0 lpr=60 pct=62'311 lua=0'0 crt=62'317 lcod 62'310 mlcod 62'310 active+clean ReplicatedBackend::got_rep_op_reply: got reply from 2 updating lcod to: 62'312 DEBUG 2025-03-16 10:20:55,453 [shard 1:main] osd - pg_epoch 62 pg[9.9( v 62'317 (62'296,62'317] local-lis/les=60/61 n=40 ec=60/60 lis/c=60/60 les/c/f=61/61/0 sis=60) [3,0,2] r=0 lpr=60 pct=62'311 lua=0'0 crt=62'317 lcod 62'310 mlcod 62'310 active+clean ReplicatedBackend::got_rep_op_reply: got reply from 2 updating lcod to: 62'312 DEBUG 2025-03-16 10:20:55,453 [shard 1:main] osd - pg_epoch 62 pg[9.9( v 62'317 (62'296,62'317] local-lis/les=60/61 n=40 ec=60/60 lis/c=60/60 les/c/f=61/61/0 sis=60) [3,0,2] r=0 lpr=60 pct=62'311 lua=0'0 crt=62'317 lcod 62'310 mlcod 62'310 active+clean ReplicatedBackend::got_rep_op_reply: all peers have acked, completing write DEBUG 2025-03-16 10:20:55,454 [shard 1:main] osd - pg_epoch 62 pg[9.9( v 62'317 (62'296,62'317] local-lis/les=60/61 n=40 ec=60/60 lis/c=60/60 les/c/f=61/61/0 sis=60) [3,0,2] r=0 lpr=60 pct=62'312 lua=0'0 crt=62'317 lcod 62'311 mlcod 62'311 active+clean ReplicatedBackend::got_rep_op_reply: osd_repop_reply(client.5896.0:4742 9.9 e62/60 ondisk, result = 0) v2 DEBUG 2025-03-16 10:20:55,454 [shard 1:main] osd - pg_epoch 62 pg[9.9( v 62'317 (62'296,62'317] local-lis/les=60/61 n=40 ec=60/60 lis/c=60/60 les/c/f=61/61/0 sis=60) [3,0,2] r=0 lpr=60 pct=62'312 lua=0'0 crt=62'317 lcod 62'311 mlcod 62'311 active+clean ReplicatedBackend::got_rep_op_reply: got reply from 2 updating lcod to: 62'310 DEBUG 2025-03-16 10:20:55,454 [shard 1:main] osd - pg_epoch 62 pg[9.9( v 62'317 (62'296,62'317] local-lis/les=60/61 n=40 ec=60/60 lis/c=60/60 les/c/f=61/61/0 sis=60) [3,0,2] r=0 lpr=60 pct=62'312 lua=0'0 crt=62'317 lcod 62'311 mlcod 62'311 active+clean ReplicatedBackend::got_rep_op_reply: all peers have acked, completing write
looking on client.5896.0:4742 and client.5896.0:4744 (message received, starting operation, getting pg) all in the correct order:
DEBUG 2025-03-16 10:20:54,363 [shard 0:main] ms - [0x511000703680 osd.3(client) v2:172.21.15.111:6808/2542960152 >> client.5896 172.21.15.71:0/2790375747@50786] <== #1294 === osd_op(client.5896.0:4742 9.9 9.d9592ad9 (undecoded) ondisk+write+known_if_redirected+supports_pool_eio e62) v9 (42) DEBUG 2025-03-16 10:20:54,363 [shard 0:main] osd - client_request(id=87385, detail=m=[osd_op(client.5896.0:4742 9.9 9.d9592ad9 (undecoded) ondisk+write+known_if_redirected+supports_pool_eio e62)]): starting start_pg_operation DEBUG 2025-03-16 10:20:54,368 [shard 1:main] osd - client_request(id=87385, detail=m=[osd_op(client.5896.0:4742 9.9 9.d9592ad9 (undecoded) ondisk+write+known_if_redirected+supports_pool_eio e62)]): have_pg DEBUG 2025-03-16 10:20:54,369 [shard 1:main] osd - pg_epoch 62 pg[9.9( v 62'309 (62'296,62'309] local-lis/les=60/61 n=39 ec=60/60 lis/c=60/60 les/c/f=61/61/0 sis=60) [3,0,2] r=0 lpr=60 pct=62'296 lua=0'0 crt=62'309 lcod 62'295 mlcod 62'295 active+clean ClientRequest::with_pg_process: client_request(id=87385, detail=m=[osd_op(client.5896.0:4742 9.9 9:9b549a9b:::benchmark_data_smithi071_62203_object592:head [set-alloc-hint object_size 65536 write_size 8192,write 40960~8192 in=8192b] snapc 0=[] ondisk+write+known_if_redirected+supports_pool_eio e62)]) start DEBUG 2025-03-16 10:20:54,387 [shard 0:main] ms - [0x511000703680 osd.3(client) v2:172.21.15.111:6808/2542960152 >> client.5896 172.21.15.71:0/2790375747@50786] <== #1296 === osd_op(client.5896.0:4744 9.9 9.d9592ad9 (undecoded) ondisk+write+known_if_redirected+supports_pool_eio e62) v9 (42) DEBUG 2025-03-16 10:20:54,387 [shard 0:main] osd - client_request(id=87389, detail=m=[osd_op(client.5896.0:4744 9.9 9.d9592ad9 (undecoded) ondisk+write+known_if_redirected+supports_pool_eio e62)]): starting start_pg_operation DEBUG 2025-03-16 10:20:54,395 [shard 1:main] osd - client_request(id=87389, detail=m=[osd_op(client.5896.0:4744 9.9 9.d9592ad9 (undecoded) ondisk+write+known_if_redirected+supports_pool_eio e62)]): have_pg DEBUG 2025-03-16 10:20:54,395 [shard 1:main] osd - pg_epoch 62 pg[9.9( v 62'311 (62'296,62'311] local-lis/les=60/61 n=39 ec=60/60 lis/c=60/60 les/c/f=61/61/0 sis=60) [3,0,2] r=0 lpr=60 pct=62'296 lua=0'0 crt=62'311 lcod 62'295 mlcod 62'295 active+clean ClientRequest::with_pg_process: client_request(id=87389, detail=m=[osd_op(client.5896.0:4744 9.9 9:9b549a9b:::benchmark_data_smithi071_62203_object592:head [set-alloc-hint object_size 65536 write_size 8192,write 57344~8192 in=8192b] snapc 0=[] ondisk+write+known_if_redirected+supports_pool_eio e62)]) start
However all peers are acked in opposite order:
DEBUG 2025-03-16 10:20:55,452 [shard 1:main] osd - pg_epoch 62 pg[9.9( v 62'317 (62'296,62'317] local-lis/les=60/61 n=40 ec=60/60 lis/c=60/60 les/c/f=61/61/0 sis=60) [3,0,2] r=0 lpr=60 pct=62'311 lua=0'0 crt=62'317 lcod 62'310 mlcod 62'310 active+clean ReplicatedBackend::got_rep_op_reply: osd_repop_reply(client.5896.0:4744 9.9 e62/60 ondisk, result = 0) v2 DEBUG 2025-03-16 10:20:55,453 [shard 1:main] osd - pg_epoch 62 pg[9.9( v 62'317 (62'296,62'317] local-lis/les=60/61 n=40 ec=60/60 lis/c=60/60 les/c/f=61/61/0 sis=60) [3,0,2] r=0 lpr=60 pct=62'311 lua=0'0 crt=62'317 lcod 62'310 mlcod 62'310 active+clean ReplicatedBackend::got_rep_op_reply: all peers have acked, completing write DEBUG 2025-03-16 10:20:55,454 [shard 1:main] osd - pg_epoch 62 pg[9.9( v 62'317 (62'296,62'317] local-lis/les=60/61 n=40 ec=60/60 lis/c=60/60 les/c/f=61/61/0 sis=60) [3,0,2] r=0 lpr=60 pct=62'312 lua=0'0 crt=62'317 lcod 62'311 mlcod 62'311 active+clean ReplicatedBackend::got_rep_op_reply: osd_repop_reply(client.5896.0:4742 9.9 e62/60 ondisk, result = 0) v2 DEBUG 2025-03-16 10:20:55,454 [shard 1:main] osd - pg_epoch 62 pg[9.9( v 62'317 (62'296,62'317] local-lis/les=60/61 n=40 ec=60/60 lis/c=60/60 les/c/f=61/61/0 sis=60) [3,0,2] r=0 lpr=60 pct=62'312 lua=0'0 crt=62'317 lcod 62'311 mlcod 62'311 active+clean ReplicatedBackend::got_rep_op_reply: all peers have acked, completing write
Updated by Samuel Just about 1 year ago
Repops are supposed to be sent, processed, replied, reply-processed all in order -- just as with classic. Good chance I broke this in https://github.com/ceph/ceph/pull/61005 or https://github.com/ceph/ceph/pull/61086. Quick audit suggests that the primary side is probably right, sending the repop is done under the submit_lock along with local store submission. Replica repop side seems ok at first glance -- exclusive -> ordered exclusive -> exclusive.
Updated by Samuel Just about 1 year ago · Edited
Primary side processing of the repop reply is likely the issue.
seastar::future<> OSD::handle_rep_op_reply(
crimson::net::ConnectionRef conn,
Ref<MOSDRepOpReply> m)
{
LOG_PREFIX(OSD::handle_rep_op_reply);
spg_t pgid = m->get_spg();
return pg_shard_manager.with_pg(
pgid,
[FNAME, m=std::move(m)](auto &&pg) {
if (pg) {
m->finish_decode();
pg->handle_rep_op_reply(*m);
} else {
WARN("stale reply: {}", *m);
}
return seastar::now();
});
}
OSD::handle_rep_op_reply is called directly from do_ms_dispatch. That with_pg call is asynchronous and doesn't have any ordering guarantees -- two repops arriving very close in time could both call with_pg in sequence, but the processing order would be at the mercy of the seastar task scheduler in the common case that the pg isn't on the dispatch core.
template <typename F>
auto with_pg(spg_t pgid, F &&f) {
core_id_t core = get_pg_to_shard_mapping().get_pg_mapping(pgid);
return with_remote_shard_state(
core,
[pgid, f=std::move(f)](auto &local_state, auto &local_service) mutable {
return std::invoke(
std::move(f),
local_state.pg_map.get_pg(pgid));
});
}
I'll look into this tomorrow -- adding a lot of extra overhead here will show up pretty directly as a write throughput drop so ideally we'll find a cheap way to fix it.
Updated by Matan Breizman about 1 year ago · Edited
two repops arriving very close in time could both call with_pg in sequence, but the processing order would be at the mercy of the seastar task scheduler in the common case that the pg isn't on the dispatch core.
I'm not sure this is the issue, to me it seems that the two repops didn't arrive in sequence (while the processing was ok, meaning no task switches). See:
1) ReplicatedBackend::got_rep_op_reply: osd_repop_reply(client.5896.0:4744 - msg arrived
2) ReplicatedBackend::got_rep_op_reply: all peers have acked, completing write
3) ReplicatedBackend::got_rep_op_reply: osd_repop_reply(client.5896.0:4742 - msg arrived
4) ReplicatedBackend::got_rep_op_reply: all peers have acked, completing write
DEBUG 2025-03-16 10:20:55,452 [shard 1:main] osd - pg_epoch 62 pg[9.9( v 62'317 (62'296,62'317] local-lis/les=60/61 n=40 ec=60/60 lis/c=60/60 les/c/f=61/61/0 sis=60) [3,0,2] r=0 lpr=60 pct=62'311 lua=0'0 crt=62'317 lcod 62'310 mlcod 62'310 active+clean ReplicatedBackend::got_rep_op_reply: osd_repop_reply(client.5896.0:4744 9.9 e62/60 ondisk, result = 0) v2 DEBUG 2025-03-16 10:20:55,453 [shard 1:main] osd - pg_epoch 62 pg[9.9( v 62'317 (62'296,62'317] local-lis/les=60/61 n=40 ec=60/60 lis/c=60/60 les/c/f=61/61/0 sis=60) [3,0,2] r=0 lpr=60 pct=62'311 lua=0'0 crt=62'317 lcod 62'310 mlcod 62'310 active+clean ReplicatedBackend::got_rep_op_reply: all peers have acked, completing write DEBUG 2025-03-16 10:20:55,454 [shard 1:main] osd - pg_epoch 62 pg[9.9( v 62'317 (62'296,62'317] local-lis/les=60/61 n=40 ec=60/60 lis/c=60/60 les/c/f=61/61/0 sis=60) [3,0,2] r=0 lpr=60 pct=62'312 lua=0'0 crt=62'317 lcod 62'311 mlcod 62'311 active+clean ReplicatedBackend::got_rep_op_reply: osd_repop_reply(client.5896.0:4742 9.9 e62/60 ondisk, result = 0) v2 DEBUG 2025-03-16 10:20:55,454 [shard 1:main] osd - pg_epoch 62 pg[9.9( v 62'317 (62'296,62'317] local-lis/les=60/61 n=40 ec=60/60 lis/c=60/60 les/c/f=61/61/0 sis=60) [3,0,2] r=0 lpr=60 pct=62'312 lua=0'0 crt=62'317 lcod 62'311 mlcod 62'311 active+clean ReplicatedBackend::got_rep_op_reply: all peers have acked, completing write
Attaching "osd.3.shard1_pg9.9-short.txt" from: https://pulpito.ceph.com/matan-2025-03-16_09:38:25-crimson-rados-wip-matanb-crimson-only-complete-write-distro-crimson-smithi/8193634
Looking at the replica (osd.2) which has replies with the "final" ack, the order is correct - the replica applies the write and responses in the correct order client.5896.0:4742 and then client.5896.0:4744.
DEBUG 2025-03-16 10:20:54,382 [shard 1:main] ms - [0x5110000cac00 osd.2(cluster) v2:172.21.15.111:6806/3529203299 >> osd.3 v2:172.21.15.111:6807/2542960152] <== #46246,46207 === osd_repop(client.5896.0:4742 9.9 e62/60) v3 (112) DEBUG 2025-03-16 10:20:54,383 [shard 1:main] osd - replicated_request(id=16801017, detail=RepRequest(from=3 req=osd_repop(client.5896.0:4742 9.9 e62/60 9:9b549a9b:::benchmark_data_smithi071_62203_object592:head v 62'310, pct=62'296))): starting start_pg_operation DEBUG 2025-03-16 10:20:54,384 [shard 2:main] osd - replicated_request(id=16801017, detail=RepRequest(from=3 req=osd_repop(client.5896.0:4742 9.9 e62/60 9:9b549a9b:::benchmark_data_smithi071_62203_object592:head v 62'310, pct=62'296))): have_pg DEBUG 2025-03-16 10:20:54,386 [shard 2:main] osd - pg_epoch 62 pg[9.9( v 62'310 (62'296,62'310] local-lis/les=60/61 n=39 ec=60/60 lis/c=60/60 les/c/f=61/61/0 sis=60) [3,0,2] r=2 lpr=60 pct=62'296 lua=0'0 crt=62'310 lcod 62'309 active PG::handle_rep_op: osd_repop(client.5896.0:4742 9.9 e62/60 9:9b549a9b:::benchmark_data_smithi071_62203_object592:head v 62'310, pct=62'296) v3 do_transaction DEBUG 2025-03-16 10:20:54,393 [shard 0:main] ms - [0x5110000cac00 osd.2(cluster) v2:172.21.15.111:6806/3529203299 >> osd.3 v2:172.21.15.111:6807/2542960152@61008] send 46308 send() to core 1 -- osd_repop_reply(client.5896.0:4742 9.9 e62/60 ondisk, result = 0) v2 DEBUG 2025-03-16 10:20:54,394 [shard 1:main] ms - [0x5110000cac00 osd.2(cluster) v2:172.21.15.111:6806/3529203299 >> osd.3 v2:172.21.15.111:6807/2542960152] got 46308 do_send() from core 0 -- osd_repop_reply(client.5896.0:4742 9.9 e62/60 ondisk, result = 0) v2 DEBUG 2025-03-16 10:20:54,394 [shard 1:main] ms - [0x5110000cac00 osd.2(cluster) v2:172.21.15.111:6806/3529203299 >> osd.3 v2:172.21.15.111:6807/2542960152] --> #46308 === osd_repop_reply(client.5896.0:4742 9.9 e62/60 ondisk, result = 0) v2 (113) DEBUG 2025-03-16 10:20:54,410 [shard 1:main] ms - [0x5110000cac00 osd.2(cluster) v2:172.21.15.111:6806/3529203299 >> osd.3 v2:172.21.15.111:6807/2542960152] <== #46250,46211 === osd_repop(client.5896.0:4744 9.9 e62/60) v3 (112) DEBUG 2025-03-16 10:20:54,410 [shard 1:main] osd - replicated_request(id=16801019, detail=RepRequest(from=3 req=osd_repop(client.5896.0:4744 9.9 e62/60 9:9b549a9b:::benchmark_data_smithi071_62203_object592:head v 62'312, pct=62'296))): starting start_pg_operation DEBUG 2025-03-16 10:20:54,411 [shard 2:main] osd - replicated_request(id=16801019, detail=RepRequest(from=3 req=osd_repop(client.5896.0:4744 9.9 e62/60 9:9b549a9b:::benchmark_data_smithi071_62203_object592:head v 62'312, pct=62'296))): have_pg DEBUG 2025-03-16 10:20:54,413 [shard 2:main] osd - pg_epoch 62 pg[9.9( v 62'312 (62'296,62'312] local-lis/les=60/61 n=39 ec=60/60 lis/c=60/60 les/c/f=61/61/0 sis=60) [3,0,2] r=2 lpr=60 pct=62'296 lua=0'0 crt=62'312 lcod 62'311 active PG::handle_rep_op: osd_repop(client.5896.0:4744 9.9 e62/60 9:9b549a9b:::benchmark_data_smithi071_62203_object592:head v 62'312, pct=62'296) v3 do_transaction DEBUG 2025-03-16 10:20:54,418 [shard 0:main] ms - [0x5110000cac00 osd.2(cluster) v2:172.21.15.111:6806/3529203299 >> osd.3 v2:172.21.15.111:6807/2542960152@61008] send 46310 send() to core 1 -- osd_repop_reply(client.5896.0:4744 9.9 e62/60 ondisk, result = 0) v2 DEBUG 2025-03-16 10:20:54,421 [shard 1:main] ms - [0x5110000cac00 osd.2(cluster) v2:172.21.15.111:6806/3529203299 >> osd.3 v2:172.21.15.111:6807/2542960152] got 46310 do_send() from core 0 -- osd_repop_reply(client.5896.0:4744 9.9 e62/60 ondisk, result = 0) v2 DEBUG 2025-03-16 10:20:54,421 [shard 1:main] ms - [0x5110000cac00 osd.2(cluster) v2:172.21.15.111:6806/3529203299 >> osd.3 v2:172.21.15.111:6807/2542960152] --> #46310 === osd_repop_reply(client.5896.0:4744 9.9 e62/60 ondisk, result = 0) v2 (113)
Updated by Samuel Just about 1 year ago
Both log lines
DEBUG 2025-03-16 10:20:55,452 [shard 1:main] osd - pg_epoch 62 pg[9.9( v 62'317 (62'296,62'317] local-lis/les=60/61 n=40 ec=60/60 lis/c=60/60 les/c/f=61/61/0 sis=60) [3,0,2] r=0 lpr=60 pct=62'311 lua=0'0 crt=62'317 lcod 62'310 mlcod 62'310 active+clean ReplicatedBackend::got_rep_op_reply: osd_repop_reply(client.5896.0:4744 9.9 e62/60 ondisk, result = 0) v2 DEBUG 2025-03-16 10:20:55,453 [shard 1:main] osd - pg_epoch 62 pg[9.9( v 62'317 (62'296,62'317] local-lis/les=60/61 n=40 ec=60/60 lis/c=60/60 les/c/f=61/61/0 sis=60) [3,0,2] r=0 lpr=60 pct=62'311 lua=0'0 crt=62'317 lcod 62'310 mlcod 62'310 active+clean ReplicatedBackend::got_rep_op_reply: all peers have acked, completing write
are in ReplicatedBackend::got_rep_op_reply. They would be after the reactor switch.
Updated by Samuel Just about 1 year ago
- Assignee changed from Matan Breizman to Samuel Just
Updated by Matan Breizman about 1 year ago · Edited
Samuel Just wrote in #note-17:
Both log lines
[...]
are in ReplicatedBackend::got_rep_op_reply. They would be after the reactor switch.
Yes, messages are received in the correct order:
DEBUG 2025-03-16 10:20:55,444 [shard 0:main] ms - [0x5110000ccc80 osd.3(cluster) v2:172.21.15.111:6807/2542960152@61008 >> osd.2 v2:172.21.15.111:6806/3529203299] <== #46308,46246 === osd_repop_reply(client.5896.0:4742 9.9 e62/60) v2 (113) DEBUG 2025-03-16 10:20:55,447 [shard 0:main] ms - [0x5110000ccc80 osd.3(cluster) v2:172.21.15.111:6807/2542960152@61008 >> osd.2 v2:172.21.15.111:6806/3529203299] <== #46310,46250 === osd_repop_reply(client.5896.0:4744 9.9 e62/60) v2 (113) Switched order: DEBUG 2025-03-16 10:20:55,452 [shard 1:main] osd - pg_epoch 62 pg[9.9( v 62'317 (62'296,62'317] local-lis/les=60/61 n=40 ec=60/60 lis/c=60/60 les/c/f=61/61/0 sis=60) [3,0,2] r=0 lpr=60 pct=62'311 lua=0'0 crt=62'317 lcod 62'310 mlcod 62'310 active+clean ReplicatedBackend::got_rep_op_reply: osd_repop_reply(client.5896.0:4744 9.9 e62/60 ondisk, result = 0) v2 DEBUG 2025-03-16 10:20:55,454 [shard 1:main] osd - pg_epoch 62 pg[9.9( v 62'317 (62'296,62'317] local-lis/les=60/61 n=40 ec=60/60 lis/c=60/60 les/c/f=61/61/0 sis=60) [3,0,2] r=0 lpr=60 pct=62'312 lua=0'0 crt=62'317 lcod 62'311 mlcod 62'311 active+clean ReplicatedBackend::got_rep_op_reply: osd_repop_reply(client.5896.0:4742 9.9 e62/60 ondisk, result = 0) v2
Note sha1 for all the log lines here: e5820f1663a1be4dabdc8800a2d17aec17aec7f5
https://github.com/ceph/ceph-ci/commits/wip-matanb-crimson-only-complete-write/
Updated by Samuel Just about 1 year ago
Interestingly, the things that make it safe for handle_rep_op_reply to bypass the checks in start_pg_operation also apply to handle_rep_op. We know several things about the target pg if we've received a repop:
1. The epoch of the message is irrelevant so long as it's within the current pg interval
2. Given 1., the pg must be active
Should be possible to create a more efficient start_pg_operation_active variant optimized for the above assumptions and apply it to both the repop and the repop reply.
Updated by Aishwarya Mathuria 11 months ago
/a/amathuri-2025-04-11_07:28:54-crimson-rados-main-distro-default-smithi/8235447
Updated by Matan Breizman 11 months ago
- Backport set to tentacle
- Pull request ID changed from 62277 to 62836
Updated by Samuel Just 11 months ago
- Status changed from In Progress to Pending Backport
Updated by Upkeep Bot 11 months ago
- Copied to Backport #71137: tentacle: radosbench-high-concurrency: trim_to <= peering_state.get_pg_committed_to() added
Updated by Matan Breizman 11 months ago
- Status changed from Pending Backport to Resolved
Updated by Upkeep Bot 8 months ago
- Merge Commit set to 76dcf47d1cb755ee28ef3087e190bdd1952c4f5f
- Fixed In set to v20.3.0-118-g76dcf47d1cb
- Upkeep Timestamp set to 2025-07-10T00:36:08+00:00
Updated by Upkeep Bot 8 months ago
- Fixed In changed from v20.3.0-118-g76dcf47d1cb to v20.3.0-118-g76dcf47d1c
- Upkeep Timestamp changed from 2025-07-10T00:36:08+00:00 to 2025-07-14T19:37:47+00:00
Updated by Matan Breizman 8 months ago
- Related to Bug #72342: crimson::osd::PG::log_operation ceph_assert(trim_to <= peering_state.get_pg_committed_to()) added
Actions