Bug #65491
Updated by Matan Breizman about 1 month ago
<pre><code class="diff">
2024-04-11T12:37:08.234 INFO:tasks.rados.rados.0.smithi090.stderr:Error: racing read on 55 returned version 16 rather than version 15
</code></pre>
See requests 16777355 and 16777354:
Req 16777355 in in 'process_op' (checking already_complete) before 16777354 completing handle:
<pre><code class="diff">
v 18'10 active+clean ClientRequest::process_op: client_request(id=16777353 checking already_complete
v 18'10 active+clean ClientRequest::process_op: client_request(id=16777354 checking already_complete
v 18'10 active+clean ClientRequest::process_op: client_request(id=16777353 in process stage, calling do_process
v 18'11 active+clean ClientRequest::with_pg_int: client_request(id=16777353 process[_pg]_op complete, completing handle
v 18'11 active+clean ClientRequest::with_pg_int: client_request(id=16777353 process[_pg]_op complete, completing handle
v 18'11 active+clean ClientRequest::process_op: client_request(id=16777355 checking already_complete
v 18'11 active+clean ClientRequest::process_op: client_request(id=16777355 checking already_complete
v 18'11 active+clean ClientRequest::process_op: client_request(id=16777354 in process stage, calling do_process
v 18'12 active+recovery_wait ClientRequest::process_op: client_request(id=16777354 checking already_complete
v 18'12 active+recovery_wait ClientRequest::with_pg_int: client_request(id=16777354 process[_pg]_op complete, completing handle
v 18'12 active+recovery_wait ClientRequest::process_op: client_request(id=16777355 checking already_complete
v 18'12 active+recovery_wait ClientRequest::process_op: client_request(id=16777355 in process stage, calling do_process
v 18'12 active+recovery_wait ClientRequest::with_pg_int: client_request(id=16777355 process[_pg]_op complete, completing handle
</code></pre>
osd.1 handling the read req:
<pre><code class="diff">
DEBUG 2024-04-11 12:37:08,230 [shard 1:main] osd - do_osd_ops_execute: object 3:3c38bf7a:::smithi09032091-55:head - handling op read
</code></pre>
osd.1 updating version from 15 to 16:
<pre><code class="diff">
DEBUG 2024-04-11 12:36:57,442 [shard 1:main] osd - pg_epoch 19 pg[3.c( v 19'15 (0'0,19'15] local-lis/les=16/17 n=5 ec=16/16 lis/c=16/16 les/c/f=17/17/0 sis=16) [0,3,2] r=0 lpr=16 luod=19'16 lua=0'0 crt=19'16 mlcod 19'15 active+clean ObjectContextLoader::with_head_obc: object 3:3c38bf7a:::smithi09032091-55:head
DEBUG 2024-04-11 12:36:57,442 [shard 1:main] osd - pg_epoch 19 pg[3.c( v 19'15 (0'0,19'15] local-lis/les=16/17 n=5 ec=16/16 lis/c=16/16 les/c/f=17/17/0 sis=16) [0,3,2] r=0 lpr=16 luod=19'16 lua=0'0 crt=19'16 mlcod 19'15 active+clean PeeringState::calc_trim_to_aggressive limit = 19'15
DEBUG 2024-04-11 12:36:57,443 [shard 1:main] osd - pg_epoch 19 pg[3.c( v 19'15 (0'0,19'15] local-lis/les=16/17 n=5 ec=16/16 lis/c=16/16 les/c/f=17/17/0 sis=16) [0,3,2] r=0 lpr=16 luod=19'16 lua=0'0 crt=19'16 mlcod 19'15 active+clean PeeringState::append_log append_log log((0'0,19'15], crt=19'16) {19'16 (19'16) modify 3:3c38bf7a:::smithi09032091-55:head by client.4258.0:222 2024-04-11T12:36:57.165438+0000 0 ObjectCleanRegions clean_offsets: [(0, 18446744073709551615)], clean_omap: true, new_object: false}
DEBUG 2024-04-11 12:36:57,443 [shard 1:main] osd - pg_epoch 19 pg[3.c( v 19'16 (0'0,19'16] local-lis/les=16/17 n=5 ec=16/16 lis/c=16/16 les/c/f=17/17/0 sis=16) [0,3,2] r=0 lpr=16 lua=0'0 crt=19'16 lcod 19'15 mlcod 19'15 active+clean PeeringState::add_log_entry add_log_entry 19'16 (19'16) modify 3:3c38bf7a:::smithi09032091-55:head by client.4258.0:222 2024-04-11T12:36:57.165438+0000 0 ObjectCleanRegions clean_offsets: [(0, 18446744073709551615)], clean_omap: true, new_object: false
DEBUG 2024-04-11 12:36:57,443 [shard 1:main] osd - pg_epoch 19 pg[3.c( v 19'16 (0'0,19'16] local-lis/les=16/17 n=5 ec=16/16 lis/c=16/16 les/c/f=17/17/0 sis=16) [0,3,2] r=0 lpr=16 lua=0'0 crt=19'17 lcod 19'15 mlcod 19'15 active+clean PeeringState::append_log approx pg log length = 16
DEBUG 2024-04-11 12:36:57,443 [shard 1:main] osd - pg_epoch 19 pg[3.c( v 19'16 (0'0,19'16] local-lis/les=16/17 n=5 ec=16/16 lis/c=16/16 les/c/f=17/17/0 sis=16) [0,3,2] r=0 lpr=16 lua=0'0 crt=19'17 lcod 19'15 mlcod 19'15 active+clean PeeringState::append_log dups pg log length = 0
DEBUG 2024-04-11 12:36:57,443 [shard 1:main] osd - pg_epoch 19 pg[3.c( v 19'16 (0'0,19'16] local-lis/les=16/17 n=5 ec=16/16 lis/c=16/16 les/c/f=17/17/0 sis=16) [0,3,2] r=0 lpr=16 lua=0'0 crt=19'17 lcod 19'15 mlcod 19'15 active+clean PeeringState::append_log transaction_applied = 1
</code></pre>
See: https://gist.github.com/Matan-B/02e88c375760c1cb29f87d39de9122c9
https://pulpito.ceph.com/matan-2024-04-11_11:23:27-crimson-rados-wip-matanb-crimson-replicated-testing-distro-crimson-smithi/7652230
https://pulpito.ceph.com/matan-2024-04-11_11:23:27-crimson-rados-wip-matanb-crimson-replicated-testing-distro-crimson-smithi/7652234/