Project

General

Profile

Actions
Copy link

Bug #42978

closed

ops waiting for lock not requeued; client sees misordering

Added by Sage Weil over 4 years ago. Updated over 4 years ago.

Status:
Resolved
Priority:
Urgent
Assignee:
-
Category:
-
Target version:
-
% Done:

0%

Source:
Tags:
Backport:
Regression:
No
Severity:
3 - minor
Reviewed:
Affected Versions:
ceph-qa-suite:
Component(RADOS):
Pull request ID:
31864
Crash signature (v1):
Crash signature (v2):

Description

a ceph_test_rados sequence of ops come in, but replies go back out of order

2019-11-22T03:51:53.838+0000 7f0cdfa91700  1 -- v1:172.21.15.125:6805/13533 --> v1:172.21.15.18:0/3722197542 -- osd_op_reply(630 smithi01813615-143 oooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooo [write 786594~779712,stat] v111'17 uv17 ondisk = 0) v8 -- 0x55798740cb00 con 0x55798717bf80
2019-11-22T03:51:53.838+0000 7f0ce3a99700  1 -- v1:172.21.15.125:6805/13533 --> v1:172.21.15.18:0/3722197542 -- osd_op_reply(633 smithi01813615-143 oooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooo [read 0~1 out=1b] v0'0 uv17 ondisk = 0) v8 -- 0x55798740c000 con 0x55798717bf80
2019-11-22T03:55:04.572+0000 7f0ce3a99700  1 -- v1:172.21.15.125:6805/13533 --> v1:172.21.15.18:0/3722197542 -- osd_op_reply(631 smithi01813615-143 oooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooo [write 2326443~60151] v226'48 uv48 ondisk = 0) v8 -- 0x5579870b4580 con 0x55798717bf80
2019-11-22T03:55:04.572+0000 7f0ce3a99700  1 -- v1:172.21.15.125:6805/13533 --> v1:172.21.15.18:0/3722197542 -- osd_op_reply(632 smithi01813615-143 oooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooo [setxattr (358),truncate 2386594] v226'49 uv49 ondisk = 0) v8 -- 0x5579875c8680 con 0x55798717bf80

The first op, 630, gets started and takes excl lock

2019-11-22T03:51:53.834+0000 7f0ce3a99700 20 osd.5 pg_epoch: 111 pg[5.f( v 110'16 (0'0,110'16] local-lis/les=99/100 n=6 ec=95/95 lis/c=99/99 les/c/f=100/100/0 sis=99) [5,11] r=0 lpr=99 crt=110'16 lcod 110'15 mlcod 110'15 active+clean+laggy] do_op obc obc(5:fc1d170d:::smithi01813615-143 oooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooo:head(dne) rwstate(excl n=1 w=0))
...
2019-11-22T03:51:53.834+0000 7f0ce3a99700 10 osd.5 pg_epoch: 111 pg[5.f( v 110'16 (0'0,110'16] local-lis/les=99/100 n=6 ec=95/95 lis/c=99/99 les/c/f=100/100/0 sis=99) [5,11] r=0 lpr=99 crt=110'16 lcod 110'15 mlcod 110'15 active+clean+laggy] new_repop rep_tid 44 on osd_op(client.85634.0:630 5.f 5:fc1d170d:::smithi01813615-143 oooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooo:head [write 786594~779712 in=779712b,stat out=16b] snapc 0=[] ondisk+write+known_if_redirected e111) v8

the second waits
2019-11-22T03:51:53.838+0000 7f0cdfa91700 10 osd.5 pg_epoch: 111 pg[5.f( v 111'17 (0'0,111'17] local-lis/les=99/100 n=7 ec=95/95 lis/c=99/99 les/c/f=100/100/0 sis=99) [5,11] r=0 lpr=99 luod=110'16 crt=111'17 lcod 110'15 mlcod 110'15 active+clean+laggy] get_object_context: 0x557987e81440 5:fc1d170d:::smithi01813615-143 oooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooo:head rwstate(excl n=1 w=0) oi: 5:fc1d170d:::smithi01813615-143 oooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooo:head(111'17 client.85634.0:630 dirty s 1566306 uv 17 alloc_hint [0 0 0]) exists: 1 ssc: 0x557983a92ec0 snapset: 0=[]:{}
...
2019-11-22T03:51:53.838+0000 7f0cdfa91700 20 osd.5 pg_epoch: 111 pg[5.f( v 111'17 (0'0,111'17] local-lis/les=99/100 n=7 ec=95/95 lis/c=99/99 les/c/f=100/100/0 sis=99) [5,11] r=0 lpr=99 luod=110'16 crt=111'17 lcod 110'15 mlcod 110'15 active+clean+laggy] do_op waiting for rw locks

as does the next write
2019-11-22T03:51:53.838+0000 7f0ce3a99700 10 osd.5 pg_epoch: 111 pg[5.f( v 111'17 (0'0,111'17] local-lis/les=99/100 n=7 ec=95/95 lis/c=99/99 les/c/f=100/100/0 sis=99) [5,11] r=0 lpr=99 luod=110'16 crt=111'17 lcod 110'15 mlcod 110'15 active+clean+laggy] get_object_context: 0x557987e81440 5:fc1d170d:::smithi01813615-143 oooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooo:head rwstate(excl n=1 w=1) oi: 5:fc1d170d:::smithi01813615-143 oooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooo:head(111'17 client.85634.0:630 dirty s 1566306 uv 17 alloc_hint [0 0 0]) exists: 1 ssc: 0x557983a92ec0 snapset: 0=[]:{}
...
2019-11-22T03:51:53.838+0000 7f0ce3a99700 20 osd.5 pg_epoch: 111 pg[5.f( v 111'17 (0'0,111'17] local-lis/les=99/100 n=7 ec=95/95 lis/c=99/99 les/c/f=100/100/0 sis=99) [5,11] r=0 lpr=99 luod=110'16 crt=111'17 lcod 110'15 mlcod 110'15 active+clean+laggy] do_op waiting for rw locks

then 630 (the first one) finishes,
2019-11-22T03:51:53.838+0000 7f0cdfa91700  7 osd.5 pg_epoch: 111 pg[5.f( v 111'17 (0'0,111'17] local-lis/les=99/100 n=7 ec=95/95 lis/c=99/99 les/c/f=100/100/0 sis=99) [5,11] r=0 lpr=99 luod=110'16 crt=111'17 lcod 110'15 mlcod 110'15 active+clean+laggy] do_repop_reply: tid 44 op  ack_type 4 from 11
2019-11-22T03:51:53.838+0000 7f0cdfa91700 10 osd.5 pg_epoch: 111 pg[5.f( v 111'17 (0'0,111'17] local-lis/les=99/100 n=7 ec=95/95 lis/c=99/99 les/c/f=100/100/0 sis=99) [5,11] r=0 lpr=99 luod=110'16 crt=111'17 lcod 110'15 mlcod 110'15 active+clean+laggy] repop_all_committed: repop tid 44 all committed 
2019-11-22T03:51:53.838+0000 7f0cdfa91700 10 osd.5 pg_epoch: 111 pg[5.f( v 111'17 (0'0,111'17] local-lis/les=99/100 n=7 ec=95/95 lis/c=99/99 les/c/f=100/100/0 sis=99) [5,11] r=0 lpr=99 crt=111'17 lcod 110'16 mlcod 110'16 active+clean+laggy] eval_repop repgather(0x55798713f300 111'17 rep_tid=44 committed?=1 r=0)
2019-11-22T03:51:53.838+0000 7f0cdfa91700 10 osd.5 pg_epoch: 111 pg[5.f( v 111'17 (0'0,111'17] local-lis/les=99/100 n=7 ec=95/95 lis/c=99/99 les/c/f=100/100/0 sis=99) [5,11] r=0 lpr=99 crt=111'17 lcod 110'16 mlcod 110'16 active+clean+laggy]  commit: repgather(0x55798713f300 111'17 rep_tid=44 committed?=1 r=0)
2019-11-22T03:51:53.838+0000 7f0cdfa91700 15 osd.5 pg_epoch: 111 pg[5.f( v 111'17 (0'0,111'17] local-lis/les=99/100 n=7 ec=95/95 lis/c=99/99 les/c/f=100/100/0 sis=99) [5,11] r=0 lpr=99 crt=111'17 lcod 110'16 mlcod 110'16 active+clean+laggy] log_op_stats osd_op(client.85634.0:630 5.f 5:fc1d170d:::smithi01813615-143 oooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooo:head [write 786594~779712 in=779712b,stat out=16b] snapc 0=[] ondisk+write+known_if_redirected e111) v8 inb 779712 outb 0 lat 0.004936
2019-11-22T03:51:53.838+0000 7f0cdfa91700 10 osd.5 pg_epoch: 111 pg[5.f( v 111'17 (0'0,111'17] local-lis/les=99/100 n=7 ec=95/95 lis/c=99/99 les/c/f=100/100/0 sis=99) [5,11] r=0 lpr=99 crt=111'17 lcod 110'16 mlcod 110'16 active+clean+laggy]  sending reply on osd_op(client.85634.0:630 5.f 5:fc1d170d:::smithi01813615-143 oooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooo:head [write 786594~779712 in=779712b,stat out=16b] snapc 0=[] ondisk+write+known_if_redirected e111) v8 0x55798740cb00
2019-11-22T03:51:53.838+0000 7f0cdfa91700  1 -- v1:172.21.15.125:6805/13533 --> v1:172.21.15.18:0/3722197542 -- osd_op_reply(630 smithi01813615-143 oooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooo [write 786594~779712,stat] v111'17 uv17 ondisk = 0) v8 -- 0x55798740cb00 con 0x55798717bf80
2019-11-22T03:51:53.838+0000 7f0cdfa91700 20 osd.5 pg_epoch: 111 pg[5.f( v 111'17 (0'0,111'17] local-lis/les=99/100 n=7 ec=95/95 lis/c=99/99 les/c/f=100/100/0 sis=99) [5,11] r=0 lpr=99 crt=111'17 lcod 110'16 mlcod 110'16 active+clean+laggy] prepare_stats_for_publish reporting purged_snaps []
2019-11-22T03:51:53.838+0000 7f0cdfa91700 15 osd.5 pg_epoch: 111 pg[5.f( v 111'17 (0'0,111'17] local-lis/les=99/100 n=7 ec=95/95 lis/c=99/99 les/c/f=100/100/0 sis=99) [5,11] r=0 lpr=99 crt=111'17 lcod 110'16 mlcod 110'16 active+clean+laggy] publish_stats_to_osd 110:48
2019-11-22T03:51:53.838+0000 7f0cdfa91700 10 osd.5 pg_epoch: 111 pg[5.f( v 111'17 (0'0,111'17] local-lis/les=99/100 n=7 ec=95/95 lis/c=99/99 les/c/f=100/100/0 sis=99) [5,11] r=0 lpr=99 crt=111'17 lcod 110'16 mlcod 110'16 active+clean+laggy]  removing repgather(0x55798713f300 111'17 rep_tid=44 committed?=1 r=0)
2019-11-22T03:51:53.838+0000 7f0cdfa91700 20 osd.5 pg_epoch: 111 pg[5.f( v 111'17 (0'0,111'17] local-lis/les=99/100 n=7 ec=95/95 lis/c=99/99 les/c/f=100/100/0 sis=99) [5,11] r=0 lpr=99 crt=111'17 lcod 110'16 mlcod 110'16 active+clean+laggy]    q front is repgather(0x55798713f300 111'17 rep_tid=44 committed?=1 r=0)
2019-11-22T03:51:53.838+0000 7f0cdfa91700 15 osd.5 pg_epoch: 111 pg[5.f( v 111'17 (0'0,111'17] local-lis/les=99/100 n=7 ec=95/95 lis/c=99/99 les/c/f=100/100/0 sis=99) [5,11] r=0 lpr=99 crt=111'17 lcod 110'16 mlcod 110'16 active+clean+laggy] do_osd_op_effects client.85634 con 0x55798717bf80
2019-11-22T03:51:53.838+0000 7f0cdfa91700 20 osd.5 pg_epoch: 111 pg[5.f( v 111'17 (0'0,111'17] local-lis/les=99/100 n=7 ec=95/95 lis/c=99/99 les/c/f=100/100/0 sis=99) [5,11] r=0 lpr=99 crt=111'17 lcod 110'16 mlcod 110'16 active+clean+laggy] remove_repop repgather(0x55798713f300 111'17 rep_tid=44 committed?=1 r=0)
2019-11-22T03:51:53.838+0000 7f0cdfa91700 10 osd.5 111 dequeue_op 0x557987b6f5a0 finish

but the next op dequeued is 633, the read, which proceeds immeidately, even tho it is rwordered
2019-11-22T03:51:53.838+0000 7f0ce3a99700 10 osd.5 111 dequeue_op 0x5579873a1c80 prio 63 cost 0 latency 0.000474 osd_op(client.85634.0:633 5.f 5.b0e8b83f (undecoded) ondisk+read+rwordered+known_if_redirected e111) v8 pg pg[5.f( v 111'17 (0'0,111'17] local-lis/les=99/100 n=7 ec=95/95 lis/c=99/99 les/c/f=100/100/0 sis=99) [5,11] r=0 lpr=99 crt=111'17 lcod 110'16 mlcod 110'16 active+clean+laggy]
...
2019-11-22T03:51:53.838+0000 7f0ce3a99700 10 osd.5 pg_epoch: 111 pg[5.f( v 111'17 (0'0,111'17] local-lis/les=99/100 n=7 ec=95/95 lis/c=99/99 les/c/f=100/100/0 sis=99) [5,11] r=0 lpr=99 crt=111'17 lcod 110'16 mlcod 110'16 active+clean+laggy] get_object_context: 0x557987e81440 5:fc1d170d:::smithi01813615-143 oooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooo:head rwstate(none n=0 w=0) oi: 5:fc1d170d:::smithi01813615-143 oooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooo:head(111'17 client.85634.0:630 dirty s 1566306 uv 17 alloc_hint [0 0 0]) exists: 1 ssc: 0x557983a92ec0 snapset: 0=[]:{}
...
2019-11-22T03:51:53.838+0000 7f0ce3a99700 10 osd.5 pg_epoch: 111 pg[5.f( v 111'17 (0'0,111'17] local-lis/les=99/100 n=7 ec=95/95 lis/c=99/99 les/c/f=100/100/0 sis=99) [5,11] r=0 lpr=99 crt=111'17 lcod 110'16 mlcod 110'16 active+clean+laggy] execute_ctx 0x557987758900

and then 631 and 632 are lost...
eventually, we see
2019-11-22T03:52:24.334+0000 7f0cfe4d4700 20 slow op osd_op(client.85634.0:631 5.f 5:fc1d170d:::smithi01813615-143 oooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooo:head [write 2326443~60151 in=60151b] snapc 0=[] ondisk+write+known_if_redirected e111) initiated 2019-11-22T03:51:53.841236+0000
2019-11-22T03:52:24.334+0000 7f0cfe4d4700 20 slow op osd_op(client.85634.0:300 5.f 5:fb982235:::smithi01813615-72:head [read 0~1] snapc 0=[] ondisk+read+rwordered+known_if_redirected e109) initiated 2019-11-22T03:51:52.586966+0000
2019-11-22T03:52:24.334+0000 7f0cfe4d4700 20 slow op osd_op(client.85634.0:632 5.f 5:fc1d170d:::smithi01813615-143 oooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooo:head [setxattr _header (358) in=365b,truncate 2386594] snapc 0=[] ondisk+write+known_if_redirected e111) initiated 2019-11-22T03:51:53.841316+0000

/a/nojha-2019-11-22_01:55:39-rados-fix-merge-vs-backoff-with-revert-distro-basic-smithi/4531356

Related issues 1 (0 open — 1 closed)

Has duplicate RADOS - Bug #42975: out of order ops in rados/upgrade/nautilus-x-singleton Duplicate11/22/2019

Actions
Actions
Copy link
 #1

Updated by Sage Weil over 4 years ago

ok, 99% sure the problem si this bit of code in release_object_locks()

        p.second.end());
    } else if (is_laggy()) {
          for (auto& op : p.second) {
            op->mark_delayed("waiting for readable");

the pg is laggy, but we don't have all acting members on OCTOPUS, so we're ignoring the laggy/readable stuff in most but not all cases...

Actions
Copy link
 #2

Updated by Neha Ojha over 4 years ago

  • Has duplicate Bug #42975: out of order ops in rados/upgrade/nautilus-x-singleton added
Actions
Copy link
 #3

Updated by Neha Ojha over 4 years ago

reproduces with suite: rados:upgrade:nautilus-x-singleton

filter: '0-cluster/{openstack.yaml start.yaml} 1-install/nautilus.yaml 2-partial-upgrade/firsthalf.yaml 3-thrash/default.yaml 4-workload/{rbd-cls.yaml rbd-import-export.yaml readwrite.yaml snaps-few-objects.yaml} 5-workload/{radosbench.yaml rbd_api.yaml} 6-finish-upgrade.yaml 7-octopus.yaml 8-workload/{rbd-python.yaml rgw-swift.yaml snaps-many-objects.yaml'

/a/nojha-2019-11-22_18:41:03-rados:upgrade:nautilus-x-singleton-wip-revert-asio-distro-basic-smithi/4534108/

Actions
Copy link
 #4

Updated by Sage Weil over 4 years ago

  • Status changed from 12 to Fix Under Review
  • Pull request ID set to 31864
Actions
Copy link
 #5

Updated by Sage Weil over 4 years ago

  • Status changed from Fix Under Review to Resolved
Actions
Copy link

Also available in: Atom PDF