Actions
Bug #2947
closedosd: out of order reply
% Done:
0%
Source:
Q/A
Tags:
Backport:
Regression:
Severity:
Reviewed:
Affected Versions:
ceph-qa-suite:
Pull request ID:
Crash signature (v1):
Crash signature (v2):
Description
triggered by thrashing by this job:
nuke-on-error: true
overrides:
ceph:
fs: ext4
log-whitelist:
- slow request
conf:
osd:
debug ms: 20
debug osd: 20
debug filestore: 20
client:
debug ms: 20
debug objecter: 20
roles:
- - mon.a
- osd.0
- osd.1
- osd.2
- - mds.a
- osd.3
- osd.4
- osd.5
- - client.0
tasks:
- chef: null
- clock: null
- ceph:
log-whitelist:
- wrongly marked me down
- objects unfound and apparently lost
- thrashosds:
timeout: 1200
- rados:
clients:
- client.0
objects: 500
op_weights:
delete: 10
read: 45
write: 45
ops: 4000
we observe (after 10-20 successes) a failure like this:
2012-08-13T17:17:26.349 INFO:teuthology.task.rados.rados.0.out:finishing write tid 2 to plana689588-300 2012-08-13T17:17:26.349 INFO:teuthology.task.rados.rados.0.out:finishing write tid 1 to plana689588-300 2012-08-13T17:17:26.349 INFO:teuthology.task.rados.rados.0.err:Error: finished tid 1 when last_acked_tid was 2 2012-08-13T17:17:26.349 INFO:teuthology.task.rados.rados.0.err:./test/osd/RadosModel.h: In function 'virtual void WriteOp::_finish(TestOp::CallbackInfo*)' thread 7f9bc37fe700 time 2012-08-13 17:17:26.342537 2012-08-13T17:17:26.350 INFO:teuthology.task.rados.rados.0.err:./test/osd/RadosModel.h: 822: FAILED assert(0) 2012-08-13T17:17:26.350 INFO:teuthology.task.rados.rados.0.err: ceph version 0.50-157-g4e7d49e (commit:4e7d49e0c66ef39593e3bf5e6684779620c4eeda) 2012-08-13T17:17:26.350 INFO:teuthology.task.rados.rados.0.err: 1: (WriteOp::_finish(TestOp::CallbackInfo*)+0x29e) [0x41385e] 2012-08-13T17:17:26.350 INFO:teuthology.task.rados.rados.0.err: 2: (write_callback(void*, void*)+0x23) [0x421a43] 2012-08-13T17:17:26.350 INFO:teuthology.task.rados.rados.0.err: 3: (librados::C_AioComplete::finish(int)+0x1e) [0x7f9bdd3b4dae] 2012-08-13T17:17:26.350 INFO:teuthology.task.rados.rados.0.err: 4: (Finisher::finisher_thread_entry()+0x218) [0x7f9bdd4114e8] 2012-08-13T17:17:26.350 INFO:teuthology.task.rados.rados.0.err: 5: (()+0x7e9a) [0x7f9bdd077e9a] 2012-08-13T17:17:26.350 INFO:teuthology.task.rados.rados.0.err: 6: (clone()+0x6d) [0x7f9bdc88f4bd] 2012-08-13T17:17:26.351 INFO:teuthology.task.rados.rados.0.err: NOTE: a copy of the executable, or `objdump -rdS <executable>` is needed to interpret this.
from the osd, we see
ubuntu@teuthology:/a/sage-msgr-rados/14$ zcat remote/ubuntu@plana66.front.sepia.ceph.com/log/osd.2.log.gz | grep client.4117.0:313 | egrep '( ==| -->)' 2012-08-13 17:17:24.040289 7f47062b3700 1 -- 10.214.132.12:6805/6031 <== client.4117 10.214.132.10:0/1009588 444 ==== osd_op(client.4117.0:3133 plana689588-300 [write 0~56] 0.1860ffb4) v4 ==== 154+0+56 (2650586133 0 4000434292) 0x33f5000 con 0x2e13780 2012-08-13 17:17:24.084791 7f47062b3700 1 -- 10.214.132.12:6805/6031 <== client.4117 10.214.132.10:0/1009588 445 ==== osd_op(client.4117.0:3134 plana689588-300 [write 561017~484826] 0.1860ffb4) v4 ==== 154+0+484826 (681737827 0 1415563408) 0x3249d80 con 0x2e13780 2012-08-13 17:17:24.237951 7f47062b3700 1 -- 10.214.132.12:6805/6031 <== client.4117 10.214.132.10:0/1009588 446 ==== osd_op(client.4117.0:3135 plana689588-300 [write 1813902~618476] 0.1860ffb4) v4 ==== 154+0+618476 (1857590084 0 20743113) 0x3249b40 con 0x2e13780 2012-08-13 17:17:24.239559 7f47062b3700 1 -- 10.214.132.12:6805/6031 <== client.4117 10.214.132.10:0/1009588 447 ==== osd_op(client.4117.0:3136 plana689588-300 [write 2845880~601117] 0.1860ffb4) v4 ==== 154+0+601117 (2960727005 0 399445279) 0x33d7480 con 0x2e13780 2012-08-13 17:17:25.389857 7f47031ac700 1 -- 10.214.132.12:6807/6031 --> osd.1 10.214.132.12:6804/6033 -- osd_sub_op(client.4117.0:3134 0.14 1860ffb4/plana689588-300/head//0 [] v 88'109 snapset=0=[]:[] snapc=0=[]) v7 -- ?+485369 0x307f400 2012-08-13 17:17:25.390836 7f47031ac700 1 -- 10.214.132.12:6807/6031 --> osd.1 10.214.132.12:6804/6033 -- osd_sub_op(client.4117.0:3133 0.14 1860ffb4/plana689588-300/head//0 [] v 88'110 snapset=0=[]:[] snapc=0=[]) v7 -- ?+599 0x372a400 2012-08-13 17:17:25.391718 7f47029ab700 1 -- 10.214.132.12:6807/6031 --> osd.1 10.214.132.12:6804/6033 -- osd_sub_op(client.4117.0:3135 0.14 1860ffb4/plana689588-300/head//0 [] v 88'111 snapset=0=[]:[] snapc=0=[]) v7 -- ?+619019 0x34a2400 2012-08-13 17:17:25.392604 7f47029ab700 1 -- 10.214.132.12:6807/6031 --> osd.1 10.214.132.12:6804/6033 -- osd_sub_op(client.4117.0:3136 0.14 1860ffb4/plana689588-300/head//0 [] v 88'112 snapset=0=[]:[] snapc=0=[]) v7 -- ?+601660 0x34a1a00 2012-08-13 17:17:25.489379 7f4705ab2700 1 -- 10.214.132.12:6807/6031 <== osd.1 10.214.132.12:6804/6033 482 ==== osd_sub_op_reply(client.4117.0:3134 0.14 1860ffb4/plana689588-300/head//0 [] ondisk, result = 0) v1 ==== 141+0+0 (3830699219 0 0) 0x344b500 con 0x2cd5140 2012-08-13 17:17:25.489574 7f4705ab2700 1 -- 10.214.132.12:6807/6031 <== osd.1 10.214.132.12:6804/6033 483 ==== osd_sub_op_reply(client.4117.0:3133 0.14 1860ffb4/plana689588-300/head//0 [] ondisk, result = 0) v1 ==== 141+0+0 (1714506867 0 0) 0x344b280 con 0x2cd5140 2012-08-13 17:17:25.490041 7f4705ab2700 1 -- 10.214.132.12:6807/6031 <== osd.1 10.214.132.12:6804/6033 484 ==== osd_sub_op_reply(client.4117.0:3135 0.14 1860ffb4/plana689588-300/head//0 [] ondisk, result = 0) v1 ==== 141+0+0 (1725329692 0 0) 0x344b000 con 0x2cd5140 2012-08-13 17:17:25.490392 7f4705ab2700 1 -- 10.214.132.12:6807/6031 <== osd.1 10.214.132.12:6804/6033 485 ==== osd_sub_op_reply(client.4117.0:3136 0.14 1860ffb4/plana689588-300/head//0 [] ondisk, result = 0) v1 ==== 141+0+0 (4081841846 0 0) 0x2fa2c80 con 0x2cd5140
note that :3134 and :3133 switch order.
the reason appears to be:
- 3133 put on waiting_for_missing queue, recovery ensues
- 3134 put on op_waiters (waiting for map) (client had a newer map epoch for this request)
- pg does advance_map
- on_change requeues waiting_for_missing
- pg does activate_map
- take_waiters requeues op_waiters (waiting for map)
-> 3134 now preceeds 3133 in the op_queue.
Actions