Actions
Bug #69412
closedcrimson: sparse read omitted non-zero data ...
% Done:
0%
Source:
Backport:
Regression:
No
Severity:
3 - minor
Reviewed:
Affected Versions:
ceph-qa-suite:
Pull request ID:
Tags (freeform):
Merge Commit:
Fixed In:
v19.3.0-7232-g44b51db681
Released In:
v20.2.0~1243
Upkeep Timestamp:
2025-11-01T01:15:02+00:00
Tags:
Updated by Samuel Just about 1 year ago · Edited
2025-01-02T07:08:17.782 INFO:tasks.rados.rados.0.smithi076.stdout:2107: oid 30 updating version 382 to 385
2025-01-02T07:08:17.782 INFO:tasks.rados.rados.0.smithi076.stdout:2107: oid 30 version 385 is already newer than 385
2025-01-02T07:08:17.782 INFO:tasks.rados.rados.0.smithi076.stdout:2107: oid 30 version 385 is already newer than 385
2025-01-02T07:08:17.782 INFO:tasks.rados.rados.0.smithi076.stdout:update_object_version oid 30 v 385 (ObjNum 947 snap 280 seq_num 947) dirty exists
2025-01-02T07:08:17.782 INFO:tasks.rados.rados.0.smithi076.stdout:2107: left oid 30 (ObjNum 947 snap 280 seq_num 947)
2025-01-02T07:08:17.801 DEBUG:teuthology.orchestra.run.smithi076:> sudo adjust-ulimits ceph-coverage /home/ubuntu/cephtest/archive/coverage timeout 0 ceph --cluster ceph --admin-daemon /var/run/ceph/ceph-osd.1.asok dump_ops_in_flight
2025-01-02T07:08:17.913 INFO:tasks.rados.rados.0.smithi076.stdout:2102: done (2 left)
2025-01-02T07:08:17.913 INFO:tasks.rados.rados.0.smithi076.stdout:2107: done (1 left)
2025-01-02T07:08:17.914 INFO:tasks.rados.rados.0.smithi076.stdout:2108: done (0 left)
2025-01-02T07:08:17.914 INFO:tasks.rados.rados.0.smithi076.stdout:2109: write (excl) oid 15 current snap is 280
2025-01-02T07:08:17.914 INFO:tasks.rados.rados.0.smithi076.stdout:2109: seq_num 949 ranges {749843=639073,2133294=544997,3211126=582199}
2025-01-02T07:08:17.921 INFO:tasks.rados.rados.0.smithi076.stdout:2109: writing smithi07634417-15 from 749843 to 1388916 tid 1
2025-01-02T07:08:17.929 INFO:tasks.rados.rados.0.smithi076.stdout:2109: writing smithi07634417-15 from 2133294 to 2678291 tid 2
2025-01-02T07:08:17.937 INFO:tasks.rados.rados.0.smithi076.stdout:2109: writing smithi07634417-15 from 3211126 to 3793325 tid 3
2025-01-02T07:08:17.937 INFO:tasks.rados.rados.0.smithi076.stdout:2110: read oid 50 snap -1
2025-01-02T07:08:17.937 INFO:tasks.rados.rados.0.smithi076.stdout:2110: expect deleted
2025-01-02T07:08:17.937 INFO:tasks.rados.rados.0.smithi076.stdout:2111: snap_remove snap 274
...
2025-01-02T07:08:18.173 INFO:tasks.rados.rados.0.smithi076.stdout:2111: done (2 left)
2025-01-02T07:08:18.173 INFO:tasks.rados.rados.0.smithi076.stdout:2112: read oid 46 snap -1
2025-01-02T07:08:18.173 INFO:tasks.rados.rados.0.smithi076.stdout:2112: expect (ObjNum 933 snap 274 seq_num 933)
2025-01-02T07:08:18.174 INFO:tasks.rados.rados.0.smithi076.stdout:2113: snap_remove snap 240
2025-01-02T07:08:19.174 INFO:teuthology.orchestra.run.smithi076.stderr:reweighted osd.0 to 1 (10000)
2025-01-02T07:08:19.178 INFO:tasks.rados.rados.0.smithi076.stdout:2113: done (3 left)
2025-01-02T07:08:19.178 INFO:tasks.rados.rados.0.smithi076.stdout:2114: read oid 23 snap -1
2025-01-02T07:08:19.178 INFO:tasks.rados.rados.0.smithi076.stdout:2114: expect (ObjNum 940 snap 277 seq_num 940)
2025-01-02T07:08:19.178 INFO:tasks.rados.rados.0.smithi076.stdout:2115: snap_create
2025-01-02T07:08:19.178 INFO:tasks.rados.rados.0.smithi076.stdout:2109: finishing write tid 1 to smithi07634417-15
2025-01-02T07:08:19.178 INFO:tasks.rados.rados.0.smithi076.stdout:2109: finishing write tid 2 to smithi07634417-15
2025-01-02T07:08:19.178 INFO:tasks.rados.rados.0.smithi076.stdout:2109: finishing write tid 3 to smithi07634417-15
2025-01-02T07:08:19.178 INFO:tasks.rados.rados.0.smithi076.stdout:2109: finishing write tid 4 to smithi07634417-15
2025-01-02T07:08:19.178 INFO:tasks.rados.rados.0.smithi076.stdout:2109: finishing write tid 5 to smithi07634417-15
2025-01-02T07:08:19.178 INFO:tasks.rados.rados.0.smithi076.stdout:2109: oid 15 updating version 0 to 624
2025-01-02T07:08:19.178 INFO:tasks.rados.rados.0.smithi076.stdout:2109: oid 15 version 624 is already newer than 624
2025-01-02T07:08:19.178 INFO:tasks.rados.rados.0.smithi076.stdout:2109: oid 15 version 624 is already newer than 621
2025-01-02T07:08:19.179 INFO:tasks.rados.rados.0.smithi076.stdout:2109: oid 15 version 624 is already newer than 624
2025-01-02T07:08:19.179 INFO:tasks.rados.rados.0.smithi076.stdout:update_object_version oid 15 v 624 (ObjNum 949 snap 280 seq_num 949) dirty exists
2025-01-02T07:08:19.179 INFO:tasks.rados.rados.0.smithi076.stdout:2109: left oid 15 (ObjNum 949 snap 280 seq_num 949)
2025-01-02T07:08:19.179 INFO:tasks.rados.rados.0.smithi076.stdout:2112: expect (ObjNum 933 snap 274 seq_num 933)
2025-01-02T07:08:19.187 INFO:tasks.rados.rados.0.smithi076.stdout:sparse read omitted non-zero data at 480931
8059498/mvdlogs » for i in ceph-osd.?.log; do echo $i; echo; grep 'smithi07634417-46' $i | grep 'execute' | tail; done ceph-osd.0.log DEBUG 2025-01-02 07:02:19,127 [shard 0:main] osd - pg_epoch 488 pg[3.8( v 486'453 (0'0,486'453] local-lis/les=473/474 n=9 ec=16/16 lis/c=473/450 les/c/f=474/451/0 sis=473) [0,2] r=0 lpr=473 pi=[450,473)/1 lua=459'439 crt=486'453 mlcod 486'453 active+undersized+degraded PG::run_executer: object 3:17ed7111:::smithi07634417-46:head handle op omap-get-keys in=12b DEBUG 2025-01-02 07:02:19,127 [shard 0:main] osd - pg_epoch 488 pg[3.8( v 486'453 (0'0,486'453] local-lis/les=473/474 n=9 ec=16/16 lis/c=473/450 les/c/f=474/451/0 sis=473) [0,2] r=0 lpr=473 pi=[450,473)/1 lua=459'439 crt=486'453 mlcod 486'453 active+undersized+degraded PG::run_executer: object 3:17ed7111:::smithi07634417-46:head handle op omap-get-vals in=16b DEBUG 2025-01-02 07:02:19,127 [shard 0:main] osd - pg_epoch 488 pg[3.8( v 486'453 (0'0,486'453] local-lis/les=473/474 n=9 ec=16/16 lis/c=473/450 les/c/f=474/451/0 sis=473) [0,2] r=0 lpr=473 pi=[450,473)/1 lua=459'439 crt=486'453 mlcod 486'453 active+undersized+degraded PG::run_executer: object 3:17ed7111:::smithi07634417-46:head handle op omap-get-header DEBUG 2025-01-02 07:02:19,128 [shard 0:main] osd - pg_epoch 488 pg[3.8( v 486'453 (0'0,486'453] local-lis/les=473/474 n=9 ec=16/16 lis/c=473/450 les/c/f=474/451/0 sis=473) [0,2] r=0 lpr=473 pi=[450,473)/1 lua=459'439 crt=486'453 mlcod 486'453 active+undersized+degraded PG::run_executer: object 3:17ed7111:::smithi07634417-46:head handle op getxattrs DEBUG 2025-01-02 07:02:19,133 [shard 0:main] osd - pg_epoch 488 pg[3.8( v 486'453 (0'0,486'453] local-lis/les=473/474 n=9 ec=16/16 lis/c=473/450 les/c/f=474/451/0 sis=473) [0,2] r=0 lpr=473 pi=[450,473)/1 lua=459'439 crt=486'453 mlcod 486'453 active+undersized+degraded PG::run_executer: object 3:17ed7111:::smithi07634417-46:head all operations successful DEBUG 2025-01-02 07:02:19,139 [shard 0:main] osd - pg_epoch 488 pg[3.8( v 486'453 (0'0,486'453] local-lis/les=473/474 n=9 ec=16/16 lis/c=473/450 les/c/f=474/451/0 sis=473) [0,2] r=0 lpr=473 pi=[450,473)/1 lua=459'439 crt=486'453 mlcod 486'453 active+undersized+degraded PG::run_executer: object 3:17ed7111:::smithi07634417-46:head handle op read 2258328~1187239 DEBUG 2025-01-02 07:02:19,140 [shard 0:main] osd - pg_epoch 488 pg[3.8( v 486'453 (0'0,486'453] local-lis/les=473/474 n=9 ec=16/16 lis/c=473/450 les/c/f=474/451/0 sis=473) [0,2] r=0 lpr=473 pi=[450,473)/1 lua=459'439 crt=486'453 mlcod 486'453 active+undersized+degraded PG::run_executer: object 3:17ed7111:::smithi07634417-46:head handle op checksum in=4b DEBUG 2025-01-02 07:02:19,144 [shard 0:main] osd - pg_epoch 488 pg[3.8( v 486'453 (0'0,486'453] local-lis/les=473/474 n=9 ec=16/16 lis/c=473/450 les/c/f=474/451/0 sis=473) [0,2] r=0 lpr=473 pi=[450,473)/1 lua=459'439 crt=486'453 mlcod 486'453 active+undersized+degraded PG::run_executer: object 3:17ed7111:::smithi07634417-46:head all operations successful DEBUG 2025-01-02 07:02:19,149 [shard 0:main] osd - pg_epoch 488 pg[3.8( v 486'453 (0'0,486'453] local-lis/les=473/474 n=9 ec=16/16 lis/c=473/450 les/c/f=474/451/0 sis=473) [0,2] r=0 lpr=473 pi=[450,473)/1 lua=459'439 crt=486'453 mlcod 486'453 active+undersized+degraded PG::run_executer: object 3:17ed7111:::smithi07634417-46:head handle op sparse-read 0~3445567 DEBUG 2025-01-02 07:02:19,154 [shard 0:main] osd - pg_epoch 488 pg[3.8( v 486'453 (0'0,486'453] local-lis/les=473/474 n=9 ec=16/16 lis/c=473/450 les/c/f=474/451/0 sis=473) [0,2] r=0 lpr=473 pi=[450,473)/1 lua=459'439 crt=486'453 mlcod 486'453 active+undersized+degraded PG::run_executer: object 3:17ed7111:::smithi07634417-46:head all operations successful ceph-osd.1.log DEBUG 2025-01-02 07:08:18,404 [shard 1:main] osd - pg_epoch 688 pg[3.8( v 688'624 lc 670'604 (0'0,688'624] local-lis/les=686/687 n=19 ec=16/16 lis/c=686/636 les/c/f=687/637/0 sis=686) [1,3,2] r=0 lpr=686 pi=[636,686)/1 pct=688'623 lua=676'619 crt=688'624 mlcod 670'604 active+recovering+degraded PG::run_executer: object 3:17ed7111:::smithi07634417-46:head handle op omap-get-vals-by-keys in=4b DEBUG 2025-01-02 07:08:18,404 [shard 1:main] osd - pg_epoch 688 pg[3.8( v 688'624 lc 670'604 (0'0,688'624] local-lis/les=686/687 n=19 ec=16/16 lis/c=686/636 les/c/f=687/637/0 sis=686) [1,3,2] r=0 lpr=686 pi=[636,686)/1 pct=688'623 lua=676'619 crt=688'624 mlcod 670'604 active+recovering+degraded PG::run_executer: object 3:17ed7111:::smithi07634417-46:head handle op omap-get-keys in=12b DEBUG 2025-01-02 07:08:18,404 [shard 1:main] osd - pg_epoch 688 pg[3.8( v 688'624 lc 670'604 (0'0,688'624] local-lis/les=686/687 n=19 ec=16/16 lis/c=686/636 les/c/f=687/637/0 sis=686) [1,3,2] r=0 lpr=686 pi=[636,686)/1 pct=688'623 lua=676'619 crt=688'624 mlcod 670'604 active+recovering+degraded PG::run_executer: object 3:17ed7111:::smithi07634417-46:head handle op omap-get-vals in=16b DEBUG 2025-01-02 07:08:18,405 [shard 1:main] osd - pg_epoch 688 pg[3.8( v 688'624 lc 670'604 (0'0,688'624] local-lis/les=686/687 n=19 ec=16/16 lis/c=686/636 les/c/f=687/637/0 sis=686) [1,3,2] r=0 lpr=686 pi=[636,686)/1 pct=688'623 lua=676'619 crt=688'624 mlcod 670'604 active+recovering+degraded PG::run_executer: object 3:17ed7111:::smithi07634417-46:head handle op omap-get-header DEBUG 2025-01-02 07:08:18,405 [shard 1:main] osd - pg_epoch 688 pg[3.8( v 688'624 lc 670'604 (0'0,688'624] local-lis/les=686/687 n=19 ec=16/16 lis/c=686/636 les/c/f=687/637/0 sis=686) [1,3,2] r=0 lpr=686 pi=[636,686)/1 pct=688'623 lua=676'619 crt=688'624 mlcod 670'604 active+recovering+degraded PG::run_executer: object 3:17ed7111:::smithi07634417-46:head handle op getxattrs DEBUG 2025-01-02 07:08:18,429 [shard 1:main] osd - pg_epoch 688 pg[3.8( v 688'624 lc 670'604 (0'0,688'624] local-lis/les=686/687 n=19 ec=16/16 lis/c=686/636 les/c/f=687/637/0 sis=686) [1,3,2] r=0 lpr=686 pi=[636,686)/1 pct=688'623 lua=676'619 crt=688'624 mlcod 670'604 active+recovering+degraded PG::run_executer: object 3:17ed7111:::smithi07634417-46:head all operations successful DEBUG 2025-01-02 07:08:18,432 [shard 1:main] osd - pg_epoch 688 pg[3.8( v 688'624 lc 670'604 (0'0,688'624] local-lis/les=686/687 n=19 ec=16/16 lis/c=686/636 les/c/f=687/637/0 sis=686) [1,3,2] r=0 lpr=686 pi=[636,686)/1 pct=688'623 lua=676'619 crt=688'624 mlcod 670'604 active+recovering+degraded PG::run_executer: object 3:17ed7111:::smithi07634417-46:head handle op sparse-read 0~3680931 DEBUG 2025-01-02 07:08:18,444 [shard 1:main] osd - pg_epoch 688 pg[3.8( v 688'624 lc 670'604 (0'0,688'624] local-lis/les=686/687 n=19 ec=16/16 lis/c=686/636 les/c/f=687/637/0 sis=686) [1,3,2] r=0 lpr=686 pi=[636,686)/1 lua=676'619 crt=688'624 mlcod 670'604 active+recovering+degraded PG::run_executer: object 3:17ed7111:::smithi07634417-46:head all operations successful DEBUG 2025-01-02 07:08:18,448 [shard 1:main] osd - pg_epoch 688 pg[3.8( v 688'624 lc 670'604 (0'0,688'624] local-lis/les=686/687 n=19 ec=16/16 lis/c=686/636 les/c/f=687/637/0 sis=686) [1,3,2] r=0 lpr=686 pi=[636,686)/1 lua=676'619 crt=688'624 mlcod 670'604 active+recovering+degraded PG::run_executer: object 3:17ed7111:::smithi07634417-46:head handle op sparse-read 230907~3450024 DEBUG 2025-01-02 07:08:18,458 [shard 1:main] osd - pg_epoch 688 pg[3.8( v 688'624 lc 670'604 (0'0,688'624] local-lis/les=686/687 n=19 ec=16/16 lis/c=686/636 les/c/f=687/637/0 sis=686) [1,3,2] r=0 lpr=686 pi=[636,686)/1 lua=676'619 crt=688'624 mlcod 670'604 active+recovering+degraded PG::run_executer: object 3:17ed7111:::smithi07634417-46:head all operations successful ceph-osd.2.log ceph-osd.3.log DEBUG 2025-01-02 07:08:00,518 [shard 1:main] osd - pg_epoch 670 pg[3.8( v 670'606 (0'0,670'606] local-lis/les=669/670 n=17 ec=16/16 lis/c=669/636 les/c/f=670/637/0 sis=669) [3,2] r=0 lpr=669 pi=[636,669)/1 lua=661'599 crt=670'606 mlcod 670'606 active+undersized+degraded PG::run_executer: object 3:17ed7111:::smithi07634417-46:head all operations successful DEBUG 2025-01-02 07:08:00,532 [shard 1:main] osd - pg_epoch 670 pg[3.8( v 670'607 (0'0,670'607] local-lis/les=669/670 n=17 ec=16/16 lis/c=669/636 les/c/f=670/637/0 sis=669) [3,2] r=0 lpr=669 pi=[636,669)/1 pct=670'606 lua=661'599 crt=670'607 lcod 670'606 mlcod 670'606 active+undersized+degraded PG::run_executer: object 3:17ed7111:::smithi07634417-46:head handle op write 2488711~452788 in=452788b DEBUG 2025-01-02 07:08:00,533 [shard 1:main] osd - pg_epoch 670 pg[3.8( v 670'607 (0'0,670'607] local-lis/les=669/670 n=17 ec=16/16 lis/c=669/636 les/c/f=670/637/0 sis=669) [3,2] r=0 lpr=669 pi=[636,669)/1 pct=670'606 lua=661'599 crt=670'607 lcod 670'606 mlcod 670'606 active+undersized+degraded PG::run_executer: object 3:17ed7111:::smithi07634417-46:head all operations successful DEBUG 2025-01-02 07:08:00,549 [shard 1:main] osd - pg_epoch 670 pg[3.8( v 670'608 (0'0,670'608] local-lis/les=669/670 n=17 ec=16/16 lis/c=669/636 les/c/f=670/637/0 sis=669) [3,2] r=0 lpr=669 pi=[636,669)/1 pct=670'606 lua=661'599 crt=670'608 lcod 670'606 mlcod 670'606 active+undersized+degraded PG::run_executer: object 3:17ed7111:::smithi07634417-46:head handle op write 3443230~237701 in=237701b DEBUG 2025-01-02 07:08:00,549 [shard 1:main] osd - pg_epoch 670 pg[3.8( v 670'608 (0'0,670'608] local-lis/les=669/670 n=17 ec=16/16 lis/c=669/636 les/c/f=670/637/0 sis=669) [3,2] r=0 lpr=669 pi=[636,669)/1 pct=670'606 lua=661'599 crt=670'608 lcod 670'606 mlcod 670'606 active+undersized+degraded PG::run_executer: object 3:17ed7111:::smithi07634417-46:head all operations successful DEBUG 2025-01-02 07:08:00,563 [shard 1:main] osd - pg_epoch 670 pg[3.8( v 670'609 (0'0,670'609] local-lis/les=669/670 n=17 ec=16/16 lis/c=669/636 les/c/f=670/637/0 sis=669) [3,2] r=0 lpr=669 pi=[636,669)/1 pct=670'606 lua=661'599 crt=670'609 lcod 670'606 mlcod 670'606 active+undersized+degraded PG::run_executer: object 3:17ed7111:::smithi07634417-46:head handle op setxattr _header (58) in=65b DEBUG 2025-01-02 07:08:00,563 [shard 1:main] osd - pg_epoch 670 pg[3.8( v 670'609 (0'0,670'609] local-lis/les=669/670 n=17 ec=16/16 lis/c=669/636 les/c/f=670/637/0 sis=669) [3,2] r=0 lpr=669 pi=[636,669)/1 pct=670'606 lua=661'599 crt=670'609 lcod 670'606 mlcod 670'606 active+undersized+degraded PG::run_executer: object 3:17ed7111:::smithi07634417-46:head handle op truncate 3680931 DEBUG 2025-01-02 07:08:00,564 [shard 1:main] osd - pg_epoch 670 pg[3.8( v 670'609 (0'0,670'609] local-lis/les=669/670 n=17 ec=16/16 lis/c=669/636 les/c/f=670/637/0 sis=669) [3,2] r=0 lpr=669 pi=[636,669)/1 pct=670'606 lua=661'599 crt=670'609 lcod 670'606 mlcod 670'606 active+undersized+degraded PG::run_executer: object 3:17ed7111:::smithi07634417-46:head all operations successful DEBUG 2025-01-02 07:08:00,620 [shard 1:main] osd - pg_epoch 670 pg[3.8( v 670'610 (0'0,670'610] local-lis/les=669/670 n=17 ec=16/16 lis/c=669/636 les/c/f=670/637/0 sis=669) [3,2] r=0 lpr=669 pi=[636,669)/1 lua=661'599 crt=670'610 mlcod 670'610 active+undersized+degraded PG::run_executer: object 3:17ed7111:::smithi07634417-46:head handle op read 0~1 DEBUG 2025-01-02 07:08:00,620 [shard 1:main] osd - pg_epoch 670 pg[3.8( v 670'610 (0'0,670'610] local-lis/les=669/670 n=17 ec=16/16 lis/c=669/636 les/c/f=670/637/0 sis=669) [3,2] r=0 lpr=669 pi=[636,669)/1 lua=661'599 crt=670'610 mlcod 670'610 active+undersized+degraded PG::run_executer: object 3:17ed7111:::smithi07634417-46:head all operations successful
Updated by Samuel Just about 1 year ago
ReplicatedRecoveryBackend::_handle_pull_response calls on_local_recover() which calls recover_got() prior to actually submitting the transaction. Because we do not hold a write lock, client operations can overlap that commit time.
Updated by Matan Breizman about 1 year ago
- Related to Bug #69436: thrash: ceph_assert(version == old_value.version) added
Updated by Matan Breizman about 1 year ago
- Related to Bug #69439: radosbench-high-concurrency: trim_to <= peering_state.get_pg_committed_to() added
Updated by Matan Breizman about 1 year ago
- Related to Bug #69438: thrash/short_pg_log: bluestore op got ENOENT - setattr added
Updated by Matan Breizman about 1 year ago
Samuel Just wrote in #note-3:
ReplicatedRecoveryBackend::_handle_pull_response calls on_local_recover() which calls recover_got() prior to actually submitting the transaction. Because we do not hold a write lock, client operations can overlap that commit time.
Added few possibly related trackers here, so we can see if those keep happening after this one is resolved
Updated by Matan Breizman about 1 year ago
- Related to Bug #69602: thrash/balanced: read returned error code -2 added
Updated by Samuel Just about 1 year ago
- Related to Bug #69702: crimson: take obc lock on replica during push commit added
Updated by Matan Breizman about 1 year ago
- Status changed from New to Resolved
- Pull request ID set to 61561
Updated by Upkeep Bot 9 months ago
- Merge Commit set to 44b51db6813fb456c78075909d800e4ec3b2679f
- Fixed In set to v19.3.0-7232-g44b51db6813
- Upkeep Timestamp set to 2025-07-10T00:36:11+00:00
Updated by Upkeep Bot 8 months ago
- Fixed In changed from v19.3.0-7232-g44b51db6813 to v19.3.0-7232-g44b51db681
- Upkeep Timestamp changed from 2025-07-10T00:36:11+00:00 to 2025-07-14T19:37:50+00:00
Updated by Upkeep Bot 5 months ago
- Released In set to v20.2.0~1243
- Upkeep Timestamp changed from 2025-07-14T19:37:50+00:00 to 2025-11-01T01:15:02+00:00
Actions