Ceph

 -2753> 2017-03-05 20:17:16.777957 7f92624ac700 20 osd.3 pg_epoch: 77 pg[1.17s0( v 70'276 lc 14'13 (0'0,70'276] local-les=70 n=40 ec=30 les/c/f 70/64/0 68/68/68) [3,4,5] r=0 lpr=69 pi=56-67/1 crt=70'276 mlcod 14'13 active+recovery_wait+degraded m=34 snaptrimq=[1e~1,23~1]] generate_transactions: 1:e91883ae:::smithi1
6115294-916:head, current size is 3379200 buffers are {0~3008420(3008420)}
 -2740> 2017-03-05 20:17:16.778035 7f92624ac700 20 osd.3 pg_epoch: 77 pg[1.17s0( v 70'276 lc 14'13 (0'0,70'276] local-les=70 n=40 ec=30 les/c/f 70/64/0 68/68/68) [3,4,5] r=0 lpr=69 pi=56-67/1 crt=70'276 mlcod 14'13 active+recovery_wait+degraded m=34 snaptrimq=[1e~1,23~1]] operator(): new_size start 0
 -2696> 2017-03-05 20:17:16.778309 7f9273d63700  1 -- 172.21.15.106:6801/342614 <== osd.0 172.21.15.161:6801/14366 661 ==== pg_query(1.17s0 epoch 78) v3 ==== 148+0+0 (1009343438 0 0) 0x55d6eca13440 con 0x55d6e9752000
 -2695> 2017-03-05 20:17:16.778314 7f9273d63700 20 osd.3 78 OSD::ms_dispatch: pg_query(1.17s0 epoch 78) v3
 -2692> 2017-03-05 20:17:16.778317 7f9273d63700 20 osd.3 78 _dispatch 0x55d6eca13440 pg_query(1.17s0 epoch 78) v3
 -2532> 2017-03-05 20:17:16.778085 7f92624ac700 20 osd.3 pg_epoch: 77 pg[1.17s0( v 70'276 lc 14'13 (0'0,70'276] local-les=70 n=40 ec=30 les/c/f 70/64/0 68/68/68) [3,4,5] r=0 lpr=69 pi=56-67/1 crt=70'276 mlcod 14'13 active+recovery_wait+degraded m=34 snaptrimq=[1e~1,23~1]] operator(): adding buffer_update 0,3008420
 -2528> 2017-03-05 20:17:16.779055 7f92624ac700 20 osd.3 pg_epoch: 77 pg[1.17s0( v 70'276 lc 14'13 (0'0,70'276] local-les=70 n=40 ec=30 les/c/f 70/64/0 68/68/68) [3,4,5] r=0 lpr=69 pi=56-67/1 crt=70'276 mlcod 14'13 active+recovery_wait+degraded m=34 snaptrimq=[1e~1,23~1]] operator(): appending zeroes to align end 3
008420->3010560, len: 3008420->3010560
 -2521> 2017-03-05 20:17:16.779105 7f92624ac700 20 osd.3 pg_epoch: 77 pg[1.17s0( v 70'276 lc 14'13 (0'0,70'276] local-les=70 n=40 ec=30 les/c/f 70/64/0 68/68/68) [3,4,5] r=0 lpr=69 pi=56-67/1 crt=70'276 mlcod 14'13 active+recovery_wait+degraded m=34 snaptrimq=[1e~1,23~1]] operator(): to_overwrite: {}
 -2514> 2017-03-05 20:17:16.779148 7f92624ac700 20 osd.3 pg_epoch: 77 pg[1.17s0( v 70'276 lc 14'13 (0'0,70'276] local-les=70 n=40 ec=30 les/c/f 70/64/0 68/68/68) [3,4,5] r=0 lpr=69 pi=56-67/1 crt=70'276 mlcod 14'13 active+recovery_wait+degraded m=34 snaptrimq=[1e~1,23~1]] operator(): to_append: {0~3010560(3010560)}
 -2507> 2017-03-05 20:17:16.779191 7f92624ac700 20 osd.3 pg_epoch: 77 pg[1.17s0( v 70'276 lc 14'13 (0'0,70'276] local-les=70 n=40 ec=30 les/c/f 70/64/0 68/68/68) [3,4,5] r=0 lpr=69 pi=56-67/1 crt=70'276 mlcod 14'13 active+recovery_wait+degraded m=34 snaptrimq=[1e~1,23~1]] operator(): appending 0~3010560
 -2155> 2017-03-05 20:17:16.781957 7f92624ac700 20 osd.3 pg_epoch: 77 pg[1.17s0( v 70'276 lc 14'13 (0'0,70'276] local-les=70 n=40 ec=30 les/c/f 70/64/0 68/68/68) [3,4,5] r=0 lpr=69 pi=56-67/1 crt=70'276 mlcod 14'13 active+recovery_wait+degraded m=34 snaptrimq=[1e~1,23~1]] encode_and_write: 1:e91883ae:::smithi161152
94-916:head new_size 3010560
 -2097> 2017-03-05 20:17:16.783719 7f92624ac700 20 osd.3 pg_epoch: 77 pg[1.17s0( v 70'276 lc 14'13 (0'0,70'276] local-les=70 n=40 ec=30 les/c/f 70/64/0 68/68/68) [3,4,5] r=0 lpr=69 pi=56-67/1 crt=70'276 mlcod 14'13 active+recovery_wait+degraded m=34 snaptrimq=[1e~1,23~1]] operator(): 1:e91883ae:::smithi16115294-916
:head resetting hinfo to logical size 3010560
 -2096> 2017-03-05 20:17:16.783769 7f92624ac700 20 osd.3 pg_epoch: 77 pg[1.17s0( v 70'276 lc 14'13 (0'0,70'276] local-les=70 n=40 ec=30 les/c/f 70/64/0 68/68/68) [3,4,5] r=0 lpr=69 pi=56-67/1 crt=70'276 mlcod 14'13 active+recovery_wait+degraded m=34 snaptrimq=[1e~1,23~1]] operator(): marking append 0
 -2095> 2017-03-05 20:17:16.783814 7f92624ac700 20 osd.3 pg_epoch: 77 pg[1.17s0( v 70'276 lc 14'13 (0'0,70'276] local-les=70 n=40 ec=30 les/c/f 70/64/0 68/68/68) [3,4,5] r=0 lpr=69 pi=56-67/1 crt=70'276 mlcod 14'13 active+recovery_wait+degraded m=34 snaptrimq=[1e~1,23~1]] try_reads_to_commit: ExtentCache(
 -2094> 2017-03-05 20:17:16.783840 7f92624ac700 20 osd.3 pg_epoch: 77 pg[1.17s0( v 70'276 lc 14'13 (0'0,70'276] local-les=70 n=40 ec=30 les/c/f 70/64/0 68/68/68) [3,4,5] r=0 lpr=69 pi=56-67/1 crt=70'276 mlcod 14'13 active+recovery_wait+degraded m=34 snaptrimq=[1e~1,23~1]] try_reads_to_commit: written: {1:e91883ae::
:smithi16115294-916:24={},1:e91883ae:::smithi16115294-916:head={0~3010560(3010560)}}
 -2093> 2017-03-05 20:17:16.783872 7f92624ac700 20 osd.3 pg_epoch: 77 pg[1.17s0( v 70'276 lc 14'13 (0'0,70'276] local-les=70 n=40 ec=30 les/c/f 70/64/0 68/68/68) [3,4,5] r=0 lpr=69 pi=56-67/1 crt=70'276 mlcod 14'13 active+recovery_wait+degraded m=34 snaptrimq=[1e~1,23~1]] try_reads_to_commit: op: Op(1:e91883ae:::sm
ithi16115294-916:head v=77'278 tt=0'0 tid=1786 reqid=client.4143.0:5297 client_op=osd_op(client.4143.0:5297 1.17s0 1:e91883ae:::smithi16115294-916:head [copy-from ver 37] snapc 24=[24,22,21,20,1f,1d,1c,1b,1a,19,18,17,8] ondisk+write+known_if_redirected e77) roll_forward_to=70'276 temp_added= temp_cleared= pending_r
ead={} remote_read={} remote_read_result={} pending_apply= pending_commit= plan.to_read={} plan.will_write={1:e91883ae:::smithi16115294-916:24=[],1:e91883ae:::smithi16115294-916:head=[0~3010560]})
 -2092> 2017-03-05 20:17:16.783912 7f92624ac700 20 osd.3 pg_epoch: 77 pg[1.17s0( v 70'276 lc 14'13 (0'0,70'276] local-les=70 n=40 ec=30 les/c/f 70/64/0 68/68/68) [3,4,5] r=0 lpr=69 pi=56-67/1 crt=70'276 mlcod 14'13 active+recovery_wait+degraded m=34 snaptrimq=[1e~1,23~1]] try_reads_to_commit: written_set: {1:e91883
ae:::smithi16115294-916:24=[],1:e91883ae:::smithi16115294-916:head=[0~3010560]}
 -2091> 2017-03-05 20:17:16.783940 7f92624ac700 10 osd.3 pg_epoch: 77 pg[1.17s0( v 70'276 lc 14'13 (0'0,70'276] local-les=70 n=40 ec=30 les/c/f 70/64/0 68/68/68) [3,4,5] r=0 lpr=69 pi=56-67/1 crt=70'276 mlcod 14'13 active+recovery_wait+degraded m=34 snaptrimq=[1e~1,23~1]] onreadable_sync: 0x55d6ec517cc0
 -2080> 2017-03-05 20:17:16.784667 7f92624ac700 10 osd.3 pg_epoch: 77 pg[1.17s0( v 70'276 lc 14'13 (0'0,70'276] local-les=70 n=40 ec=30 les/c/f 70/64/0 68/68/68) [3,4,5] r=0 lpr=69 pi=56-67/1 crt=70'276 mlcod 14'13 active+recovery_wait+degraded m=34 snaptrimq=[1e~1,23~1]] append_log log((0'0,70'276], crt=70'276) [7
7'277 (25'218) clone    1:e91883ae:::smithi16115294-916:24 by unknown.0.0:0 2017-03-05 20:16:10.594154 0 snaps [24,22,21,20,1f,1d,1c,1b,1a,19,18,17,8],77'278 (25'218) modify   1:e91883ae:::smithi16115294-916:head by client.4143.0:5297 2017-03-05 20:17:15.775261 0]
 -2079> 2017-03-05 20:17:16.784708 7f92624ac700 10 osd.3 pg_epoch: 77 pg[1.17s0( v 77'277 lc 14'13 (0'0,77'277] local-les=70 n=40 ec=30 les/c/f 70/64/0 68/68/68) [3,4,5] r=0 lpr=69 pi=56-67/1 luod=70'276 lua=70'276 crt=70'276 mlcod 14'13 active+recovery_wait+degraded m=34 snaptrimq=[1e~1,23~1]] add_log_entry 77'277
 (25'218) clone    1:e91883ae:::smithi16115294-916:24 by unknown.0.0:0 2017-03-05 20:16:10.594154 0 snaps [24,22,21,20,1f,1d,1c,1b,1a,19,18,17,8]
 -2078> 2017-03-05 20:17:16.784746 7f92624ac700 10 osd.3 pg_epoch: 77 pg[1.17s0( v 77'278 lc 14'13 (0'0,77'278] local-les=70 n=40 ec=30 les/c/f 70/64/0 68/68/68) [3,4,5] r=0 lpr=69 pi=56-67/1 luod=70'276 lua=70'276 crt=70'276 mlcod 14'13 active+recovery_wait+degraded m=34 snaptrimq=[1e~1,23~1]] add_log_entry 77'278
 (25'218) modify   1:e91883ae:::smithi16115294-916:head by client.4143.0:5297 2017-03-05 20:17:15.775261 0
 -2076> 2017-03-05 20:17:16.784876 7f92624ac700 10 osd.3 pg_epoch: 77 pg[1.17s0( v 77'278 lc 14'13 (0'0,77'278] local-les=70 n=40 ec=30 les/c/f 70/64/0 68/68/68) [3,4,5] r=0 lpr=69 pi=56-67/1 luod=70'276 lua=70'276 crt=70'276 mlcod 14'13 active+recovery_wait+degraded m=34 snaptrimq=[1e~1,23~1]] Queueing onreadable_
sync: 0x55d6ec517cc0
...
 -1566> 2017-03-05 20:17:16.792256 7f92624ac700 10 osd.3 pg_epoch: 77 pg[1.17s0( v 77'278 lc 14'13 (0'0,77'278] local-les=70 n=40 ec=30 les/c/f 70/64/0 68/68/68) [3,4,5] r=0 lpr=69 pi=56-67/1 luod=70'276 lua=70'276 crt=70'276 mlcod 14'13 active+recovery_wait+degraded m=34 snaptrimq=[1e~1,23~1]] onreadable_sync: 0
 -1565> 2017-03-05 20:17:16.792312 7f92624ac700 10 osd.3 pg_epoch: 77 pg[1.17s0( v 77'278 lc 14'13 (0'0,77'278] local-les=70 n=40 ec=30 les/c/f 70/64/0 68/68/68) [3,4,5] r=0 lpr=69 pi=56-67/1 luod=70'276 lua=70'276 crt=70'276 mlcod 14'13 active+recovery_wait+degraded m=34 snaptrimq=[1e~1,23~1]] eval_repop repgather(0x55d6ef365500 77'278 rep_tid=1786 committed?=0 applied?=0 r=0)
 -1563> 2017-03-05 20:17:16.792348 7f92624ac700 10 osd.3 pg_epoch: 77 pg[1.17s0( v 77'278 lc 14'13 (0'0,77'278] local-les=70 n=40 ec=30 les/c/f 70/64/0 68/68/68) [3,4,5] r=0 lpr=69 pi=56-67/1 luod=70'276 lua=70'276 crt=70'276 mlcod 14'13 active+recovery_wait+degraded m=34 snaptrimq=[1e~1,23~1]] kick_object_context_blocked 1:e91883ae:::smithi16115294-916:head requeuing 1 requests
 -1552> 2017-03-05 20:17:16.792378 7f92624ac700 20 osd.3 pg_epoch: 77 pg[1.17s0( v 77'278 lc 14'13 (0'0,77'278] local-les=70 n=40 ec=30 les/c/f 70/64/0 68/68/68) [3,4,5] r=0 lpr=69 pi=56-67/1 luod=70'276 lua=70'276 crt=70'276 mlcod 14'13 active+recovery_wait+degraded m=34 snaptrimq=[1e~1,23~1]] requeue_ops 0x55d6eef63200
...
  -333> 2017-03-05 20:17:16.797635 7f926ecc5700 10 osd.3 pg_epoch: 78 pg[1.17s0( v 77'278 lc 14'13 (0'0,77'278] local-les=70 n=40 ec=30 les/c/f 70/64/0 78/78/78) [0,4,5] r=-1 lpr=78 pi=56-77/2 crt=70'276 inactive NOTIFY m=34] flushed
  -318> 2017-03-05 20:17:16.797736 7f926a4bc700 10 osd.3 pg_epoch: 78 pg[1.17s0( v 77'278 lc 14'13 (0'0,77'278] local-les=70 n=40 ec=30 les/c/f 70/64/0 78/78/78) [0,4,5] r=-1 lpr=78 pi=56-77/2 crt=70'276 inactive NOTIFY m=34] handle_peering_event: epoch_sent: 78 epoch_requested: 78 FlushedEvt
  -315> 2017-03-05 20:17:16.797747 7f926a4bc700 -1 osd.3 pg_epoch: 78 pg[1.17s0( v 77'278 lc 14'13 (0'0,77'278] local-les=70 n=40 ec=30 les/c/f 70/64/0 78/78/78) [0,4,5] r=-1 lpr=78 pi=56-77/2 crt=70'276 inactive NOTIFY m=34] on_flushed: object 1:e91883ae:::smithi16115294-916:head obc still alive

/a/sage-2017-03-05_19:08:46-rados:thrash-erasure-code-wip-osd-full---basic-smithi/884545