Ceph

2015-02-05T04:36:59.708 INFO:tasks.rados.rados.0.plana09.stdout:2022: finishing write tid 6 to plana092652-2022
2015-02-05T04:36:59.708 INFO:tasks.rados.rados.0.plana09.stdout:2025: finishing write tid 5 to plana092652-2025
2015-02-05T04:36:59.709 INFO:tasks.rados.rados.0.plana09.stdout:2020: finishing write tid 6 to plana092652-2020
2015-02-05T04:36:59.941 INFO:tasks.rados.rados.0.plana09.stdout:2023: finishing write tid 6 to plana092652-2023
2015-02-05T04:36:59.941 INFO:tasks.rados.rados.0.plana09.stdout:2024: finishing write tid 7 to plana092652-2024
2015-02-05T04:37:28.849 INFO:teuthology.task.background_exec.ubuntu@plana14.front.sepia.ceph.com.plana14.stderr:set cache-mode for pool 'cache' to readforward
2015-02-05T04:37:58.864 INFO:teuthology.task.background_exec.ubuntu@plana14.front.sepia.ceph.com.plana14.stdout:forward
2015-02-05T04:37:58.996 INFO:teuthology.task.background_exec.ubuntu@plana14.front.sepia.ceph.com.plana14.stderr:2015-02-05 04:37:59.006229 7f55337fe700 0 monclient: hunting for new mon
2015-02-05T04:37:59.286 INFO:teuthology.task.background_exec.ubuntu@plana14.front.sepia.ceph.com.plana14.stderr:set cache-mode for pool 'cache' to forward
2015-02-05T04:38:05.580 INFO:tasks.rados.rados.0.plana09.stdout:2012: finishing write tid 1 to plana092652-2012
2015-02-05T04:38:05.580 INFO:tasks.rados.rados.0.plana09.stderr:Error: finished tid 1 when last_acked_tid was 6
2015-02-05T04:38:05.605 INFO:tasks.rados.rados.0.plana09.stderr:./test/osd/RadosModel.h: In function 'virtual void WriteOp::_finish(TestOp::CallbackInfo*)' thread 7f3110ff9700 time 2015-02-05 04:38:05.590140
2015-02-05T04:38:05.606 INFO:tasks.rados.rados.0.plana09.stderr:./test/osd/RadosModel.h: 847: FAILED assert(0)
2015-02-05T04:38:05.606 INFO:tasks.rados.rados.0.plana09.stderr: ceph version 0.92-818-g8530739 (8530739e54fd2546e530d8cefd41cdc4cdb587ea)
2015-02-05T04:38:05.606 INFO:tasks.rados.rados.0.plana09.stderr: 1: (ceph::__ceph_assert_fail(char const*, char const*, int, char const*)+0x7f) [0x4db60f]
2015-02-05T04:38:05.607 INFO:tasks.rados.rados.0.plana09.stderr: 2: (WriteOp::_finish(TestOp::CallbackInfo*)+0x592) [0x4c54f2]
2015-02-05T04:38:05.607 INFO:tasks.rados.rados.0.plana09.stderr: 3: (write_callback(void*, void*)+0x21) [0x4d2f91]
2015-02-05T04:38:05.607 INFO:tasks.rados.rados.0.plana09.stderr: 4: (()+0x80ecd) [0x7f311cc99ecd]
2015-02-05T04:38:05.607 INFO:tasks.rados.rados.0.plana09.stderr: 5: (()+0x5eeb9) [0x7f311cc77eb9]
2015-02-05T04:38:05.608 INFO:tasks.rados.rados.0.plana09.stderr: 6: (()+0x1243e0) [0x7f311cd3d3e0]
2015-02-05T04:38:05.608 INFO:tasks.rados.rados.0.plana09.stderr: 7: (()+0x7e9a) [0x7f311c7eae9a

2015-02-05 04:36:57.614471 7f0a81407700 1 -- 10.214.131.26:6804/26213 <== client.4119 10.214.131.31:0/1002652 65 ==== osd_op(client.4119.0:16244 plana092652-2012 [write 647613~424582] 1.3b2063dc ack+ondisk+write+known_if_redirected e19) v4 ==== 167+0+424582 (2698440594 0 3425800611) 0x6323680 con 0x4a5fce0
2015-02-05 04:36:57.637192 7f0a81407700 1 -- 10.214.131.26:6804/26213 <== client.4119 10.214.131.31:0/1002652 66 ==== osd_op(client.4119.0:16245 plana092652-2012 [write 1605489~623176] 1.3b2063dc ack+ondisk+write+known_if_redirected e19) v4 ==== 167+0+623176 (2060268117 0 775899264) 0x6325700 con 0x4a5fce0
2015-02-05 04:36:57.637416 7f0a81407700 1 -- 10.214.131.26:6804/26213 <== client.4119 10.214.131.31:0/1002652 67 ==== osd_op(client.4119.0:16246 plana092652-2012 [write 2647612~1] 1.3b2063dc ack+ondisk+write+known_if_redirected e19) v4 ==== 167+0+1 (1800160216 0 1939049696) 0x62d8f00 con 0x4a5fce0
2015-02-05 04:36:57.637618 7f0a81407700 1 -- 10.214.131.26:6804/26213 <== client.4119 10.214.131.31:0/1002652 68 ==== osd_op(client.4119.0:16247 plana092652-2012 [setxattr _header (55),truncate 2647613] 1.3b2063dc ack+ondisk+write+known_if_redirected e19) v4 ==== 205+0+62 (1117510134 0 2477153506) 0x62da080 con 0x4a5fce0
2015-02-05 04:36:57.637817 7f0a81407700 1 -- 10.214.131.26:6804/26213 <== client.4119 10.214.131.31:0/1002652 69 ==== osd_op(client.4119.0:16248 plana092652-2012 [read 0~1] 1.3b2063dc ack+read+rwordered+known_if_redirected e19) v4 ==== 167+0+0 (3639684585 0 0) 0x62daa80 con 0x4a5fce0
2015-02-05 04:36:58.227087 7f0a99eab700 1 -- 10.214.131.26:6804/26213 --> 10.214.131.31:0/1002652 -- osd_op_reply(16244 plana092652-2012 [write 647613~424582] v19'1658 uv2037 ack = 0) v6 -- ?+0 0x6581e40 con 0x4a5fce0
2015-02-05 04:36:58.228479 7f0a99eab700 1 -- 10.214.131.26:6804/26213 --> 10.214.131.31:0/1002652 -- osd_op_reply(16245 plana092652-2012 [write 1605489~623176] v19'1659 uv2038 ack = 0) v6 -- ?+0 0x6580000 con 0x4a5fce0
2015-02-05 04:36:58.229213 7f0a99eab700 1 -- 10.214.131.26:6804/26213 --> 10.214.131.31:0/1002652 -- osd_op_reply(16246 plana092652-2012 [write 2647612~1] v19'1660 uv2039 ack = 0) v6 -- ?+0 0x5236680 con 0x4a5fce0
2015-02-05 04:36:58.291724 7f0a99eab700 1 -- 10.214.131.26:6804/26213 --> 10.214.131.31:0/1002652 -- osd_op_reply(16247 plana092652-2012 [setxattr _header (55),truncate 2647613] v19'1661 uv2040 ack = 0) v6 -- ?+0 0x6502580 con 0x4a5fce0
2015-02-05 04:36:58.362504 7f07b7b4d700 1 -- 10.214.131.31:6800/1938 <== client.4119 10.214.131.31:0/1002652 103 ==== osd_op(client.4119.0:16244 plana092652-2012 [write 647613~424582] 2.3b2063dc RETRY=1 reassert_version=19'1658 ondisk+retry+write+known_if_redirected e20) v4 ==== 167+0+424582 (1228800642 0 3425800611) 0x41f6780 con 0x3e3b2c0
2015-02-05 04:36:58.362950 7f07b7b4d700 1 -- 10.214.131.31:6800/1938 <== client.4119 10.214.131.31:0/1002652 104 ==== osd_op(client.4119.0:16245 plana092652-2012 [write 1605489~623176] 2.3b2063dc RETRY=1 reassert_version=19'1659 ondisk+retry+write+known_if_redirected e20) v4 ==== 167+0+623176 (91908041 0 775899264) 0x3d72000 con 0x3e3b2c0
2015-02-05 04:36:58.363087 7f07b7b4d700 1 -- 10.214.131.31:6800/1938 <== client.4119 10.214.131.31:0/1002652 105 ==== osd_op(client.4119.0:16246 plana092652-2012 [write 2647612~1] 2.3b2063dc RETRY=1 reassert_version=19'1660 ondisk+retry+write+known_if_redirected e20) v4 ==== 167+0+1 (4182877939 0 1939049696) 0x3ce6280 con 0x3e3b2c0
2015-02-05 04:36:58.363217 7f07b7b4d700 1 -- 10.214.131.31:6800/1938 <== client.4119 10.214.131.31:0/1002652 106 ==== osd_op(client.4119.0:16247 plana092652-2012 [setxattr _header (55),truncate 2647613] 2.3b2063dc RETRY=1 reassert_version=19'1661 ondisk+retry+write+known_if_redirected e20) v4 ==== 205+0+62 (2335794752 0 2477153506) 0x3e5c500 con 0x3e3b2c0
2015-02-05 04:36:58.363347 7f07b7b4d700 1 -- 10.214.131.31:6800/1938 <== client.4119 10.214.131.31:0/1002652 107 ==== osd_op(client.4119.0:16248 plana092652-2012 [read 0~1] 2.3b2063dc RETRY=1 ack+retry+read+rwordered+known_if_redirected e20) v4 ==== 167+0+0 (50371568 0 0) 0x4720a00 con 0x3e3b2c0
2015-02-05 04:36:58.363408 7f07c1f88700 1 -- 10.214.131.31:0/1938 --> 10.214.131.26:6804/26213 -- osd_op(osd.3.3:298 plana092652-2012@snapdir [list-snaps] 1.3b2063dc ack+read+ignore_cache+ignore_overlay+map_snap_clone+known_if_redirected e20) v4 -- ?+0 0x41f6a00 con 0x3e2b160
2015-02-05 04:36:58.363455 7f07c1f88700 1 -- 10.214.131.31:0/1938 --> 10.214.131.26:6804/26213 -- osd_op(osd.3.3:299 plana092652-2012 [copy-get max 8388608] 1.3b2063dc ack+read+ignore_cache+ignore_overlay+map_snap_clone+known_if_redirected e20) v4 -- ?+0 0x4138c80 con 0x3e2b160
2015-02-05 04:36:58.365457 7f0a808fc700 1 -- 10.214.131.26:6804/26213 <== osd.3 10.214.131.31:0/1938 81 ==== osd_op(osd.3.3:298 plana092652-2012@snapdir [list-snaps] 1.3b2063dc ack+read+ignore_cache+ignore_overlay+map_snap_clone+known_if_redirected e20) v4 ==== 167+0+0 (4073247819 0 0) 0x6322f00 con 0x4027de0
2015-02-05 04:36:58.365634 7f0a808fc700 1 -- 10.214.131.26:6804/26213 <== osd.3 10.214.131.31:0/1938 82 ==== osd_op(osd.3.3:299 plana092652-2012 [copy-get max 8388608] 1.3b2063dc ack+read+ignore_cache+ignore_overlay+map_snap_clone+known_if_redirected e20) v4 ==== 167+0+29 (4131925041 0 750716084) 0x6324800 con 0x4027de0
2015-02-05 04:36:58.542796 7f0a8a52f700 1 -- 10.214.131.26:6804/26213 --> 10.214.131.31:0/1002652 -- osd_op_reply(16244 plana092652-2012 [write 647613~424582] v19'1658 uv2037 ondisk = 0) v6 -- ?+0 0x4daf180 con 0x4a5fce0
2015-02-05 04:36:58.543208 7f0a8cd34700 1 -- 10.214.131.26:6804/26213 --> 10.214.131.31:0/1002652 -- osd_op_reply(16245 plana092652-2012 [write 1605489~623176] v19'1659 uv2038 ondisk = 0) v6 -- ?+0 0x6502840 con 0x4a5fce0
2015-02-05 04:36:58.543799 7f0a8a52f700 1 -- 10.214.131.26:6804/26213 --> 10.214.131.31:0/1002652 -- osd_op_reply(16246 plana092652-2012 [write 2647612~1] v19'1660 uv2039 ondisk = 0) v6 -- ?+0 0x62c7b80 con 0x4a5fce0
2015-02-05 04:36:58.544297 7f0a8cd34700 1 -- 10.214.131.26:6804/26213 --> 10.214.131.31:0/1002652 -- osd_op_reply(16247 plana092652-2012 [setxattr _header (55),truncate 2647613] v19'1661 uv2040 ondisk = 0) v6 -- ?+0 0x47e4ec0 con 0x4a5fce0
2015-02-05 04:36:58.553700 7f0a8a52f700 1 -- 10.214.131.26:6804/26213 --> 10.214.131.31:0/1938 -- osd_op_reply(298 plana092652-2012 [list-snaps] v0'0 uv2040 ondisk = 0) v6 -- ?+0 0x56f0680 con 0x4027de0
2015-02-05 04:36:58.563721 7f0a8cd34700 1 -- 10.214.131.26:6804/26213 --> 10.214.131.31:0/1938 -- osd_op_reply(299 plana092652-2012 [copy-get max 8388608] v0'0 uv2040 ondisk = 0) v6 -- ?+0 0x4680dc0 con 0x4027de0
2015-02-05 04:36:58.594743 7f07b7143700 1 -- 10.214.131.31:0/1938 <== osd.1 10.214.131.26:6804/26213 83 ==== osd_op_reply(298 plana092652-2012 [list-snaps] v0'0 uv2040 ondisk = 0) v6 ==== 183+0+48 (4009210847 0 4127159219) 0x47b4000 con 0x3e2b160
2015-02-05 04:36:58.635395 7f07b7143700 1 -- 10.214.131.31:0/1938 <== osd.1 10.214.131.26:6804/26213 84 ==== osd_op_reply(299 plana092652-2012 [copy-get max 8388608] v0'0 uv2040 ondisk = 0) v6 ==== 183+0+2647878 (2648761383 0 3632181080) 0x47b4000 con 0x3e2b160
2015-02-05 04:36:58.739526 7f07c1f88700 1 -- 10.214.131.31:6800/1938 --> 10.214.131.31:0/1002652 -- osd_op_reply(16248 plana092652-2012 [read 0~1] v0'0 uv2040 ondisk = 0) v6 -- ?+0 0x41438c0 con 0x3e3b2c0
2015-02-05 04:38:05.586925 7f07b7b4d700 1 -- 10.214.131.31:6800/1938 <== client.4119 10.214.131.31:0/1002652 1 ==== osd_op(client.4119.0:16244 plana092652-2012 [write 647613~424582] 2.3b2063dc RETRY=2 reassert_version=19'1658 ondisk+retry+write+known_if_redirected e22) v4 ==== 167+0+424582 (4038834414 0 3425800611) 0x3b5b500 con 0x3fa39a0
2015-02-05 04:38:05.587422 7f07c478d700 1 -- 10.214.131.31:6800/1938 --> 10.214.131.31:0/1002652 -- osd_op_reply(16244 plana092652-2012 [write 647613~424582] v20'687 uv0 ondisk = 0) v6 -- ?+0 0x47bb340 con 0x3fa39a0
2015-02-05 04:38:05.589290 7f07b7b4d700 1 -- 10.214.131.31:6800/1938 <== client.4119 10.214.131.31:0/1002652 1 ==== osd_op(client.4119.0:16244 plana092652-2012 [write 647613~424582] 2.3b2063dc RETRY=3 reassert_version=19'1658 ondisk+retry+write+known_if_redirected e22) v4 ==== 167+0+424582 (771625558 0 3425800611) 0x464c000 con 0x43a1160
2015-02-05 04:38:05.589606 7f07c1f88700 1 -- 10.214.131.31:6800/1938 --> 10.214.131.31:0/1002652 -- osd_op_reply(16244 plana092652-2012 [write 647613~424582] v20'687 uv0 ondisk = 0) v6 -- ?+0 0x471a080 con 0x43a1160
2015-02-05 04:38:05.589869 7f07b7b4d700 1 -- 10.214.131.31:6800/1938 <== client.4119 10.214.131.31:0/1002652 2 ==== osd_op(client.4119.0:16245 plana092652-2012 [write 1605489~623176] 2.3b2063dc RETRY=3 reassert_version=19'1659 ondisk+retry+write+known_if_redirected e22) v4 ==== 167+0+623176 (1639610141 0 775899264) 0x477cc80 con 0x43a1160
2015-02-05 04:38:05.590077 7f07b7b4d700 1 -- 10.214.131.31:6800/1938 <== client.4119 10.214.131.31:0/1002652 3 ==== osd_op(client.4119.0:16246 plana092652-2012 [write 2647612~1] 2.3b2063dc RETRY=3 reassert_version=19'1660 ondisk+retry+write+known_if_redirected e22) v4 ==== 167+0+1 (2643572263 0 1939049696) 0x464c780 con 0x43a1160
2015-02-05 04:38:05.590162 7f07c478d700 1 -- 10.214.131.31:6800/1938 --> 10.214.131.31:0/1002652 -- osd_op_reply(16245 plana092652-2012 [write 1605489~623176] v20'687 uv0 ondisk = 0) v6 -- ?+0 0x47bb340 con 0x43a1160
2015-02-05 04:38:05.590311 7f07c1f88700 1 -- 10.214.131.31:6800/1938 --> 10.214.131.31:0/1002652 -- osd_op_reply(16246 plana092652-2012 [write 2647612~1] v20'687 uv0 ondisk = 0) v6 -- ?+0 0x471a340 con 0x43a1160
2015-02-05 04:38:05.590288 7f07b7b4d700 1 -- 10.214.131.31:6800/1938 <== client.4119 10.214.131.31:0/1002652 4 ==== osd_op(client.4119.0:16247 plana092652-2012 [setxattr _header (55),truncate 2647613] 2.3b2063dc RETRY=3 reassert_version=19'1661 ondisk+retry+write+known_if_redirected e22) v4 ==== 205+0+62 (1610524766 0 2477153506) 0x464cc80 con 0x43a1160
2015-02-05 04:38:05.590733 7f07c478d700 1 -- 10.214.131.31:6800/1938 --> 10.214.131.31:0/1002652 -- osd_op_reply(16247 plana092652-2012 [setxattr _header (55),truncate 2647613] v20'687 uv0 ondisk = 0) v6 -- ?+0 0x3e41340 con 0x43a1160

2015-02-05 04:36:58.738708 7f07c1f88700 10 osd.3 pg_epoch: 20 pg[2.0( v 20'687 (0'0,20'687] local-les=7 n=4 ec=6 les/c 7/7 6/6/6) [3,5] r=0 lpr=6 luod=20'686 crt=16'684 lcod 16'685 mlcod 16'685 active+clean] repop_all_committed: repop tid 687 all committed
2015-02-05 04:36:58.738730 7f07c1f88700 10 osd.3 pg_epoch: 20 pg[2.0( v 20'687 (0'0,20'687] local-les=7 n=4 ec=6 les/c 7/7 6/6/6) [3,5] r=0 lpr=6 crt=16'684 lcod 20'686 mlcod 16'685 active+clean] eval_repop repgather(0x405c000 20'687 rep_tid=687 committed?=1 applied?=1 lock=0) (no op)
2015-02-05 04:36:58.738754 7f07c1f88700 15 osd.3 pg_epoch: 20 pg[2.0( v 20'687 (0'0,20'687] local-les=7 n=4 ec=6 les/c 7/7 6/6/6) [3,5] r=0 lpr=6 crt=16'684 lcod 20'686 mlcod 16'685 active+clean] do_osd_op_effects osd.3 con 0
2015-02-05 04:36:58.738776 7f07c1f88700 10 osd.3 pg_epoch: 20 pg[2.0( v 20'687 (0'0,20'687] local-les=7 n=4 ec=6 les/c 7/7 6/6/6) [3,5] r=0 lpr=6 crt=16'684 lcod 20'686 mlcod 20'686 active+clean] removing repgather(0x405c000 20'687 rep_tid=687 committed?=1 applied?=1 lock=0)
2015-02-05 04:36:58.738799 7f07c1f88700 20 osd.3 pg_epoch: 20 pg[2.0( v 20'687 (0'0,20'687] local-les=7 n=4 ec=6 les/c 7/7 6/6/6) [3,5] r=0 lpr=6 crt=16'684 lcod 20'686 mlcod 20'686 active+clean] q front is repgather(0x405c000 20'687 rep_tid=687 committed?=1 applied?=1 lock=0)
2015-02-05 04:36:58.738821 7f07c1f88700 20 osd.3 pg_epoch: 20 pg[2.0( v 20'687 (0'0,20'687] local-les=7 n=4 ec=6 les/c 7/7 6/6/6) [3,5] r=0 lpr=6 crt=16'684 lcod 20'686 mlcod 20'686 active+clean] remove_repop repgather(0x405c000 20'687 rep_tid=687 committed?=1 applied?=1 lock=0)
2015-02-05 04:36:58.738844 7f07c1f88700 20 osd.3 pg_epoch: 20 pg[2.0( v 20'687 (0'0,20'687] local-les=7 n=4 ec=6 les/c 7/7 6/6/6) [3,5] r=0 lpr=6 crt=16'684 lcod 20'686 mlcod 20'686 active+clean] obc obc(3b2063dc/plana092652-2012/head//2 rwstate(write n=1 w=1))
2015-02-05 04:36:58.738868 7f07c1f88700 15 osd.3 pg_epoch: 20 pg[2.0( v 20'687 (0'0,20'687] local-les=7 n=4 ec=6 les/c 7/7 6/6/6) [3,5] r=0 lpr=6 crt=16'684 lcod 20'686 mlcod 20'686 active+clean] requeue_ops 0x3993e00
2015-02-05 04:36:58.738913 7f07c1f88700 10 osd.3 20 dequeue_op 0x39d1300 finish
2015-02-05 04:36:58.738951 7f07c1f88700 10 osd.3 20 dequeue_op 0x3993e00 prio 63 cost 0 latency 0.375640 osd_op(client.4119.0:16248 plana092652-2012 [read 0~1] 2.3b2063dc RETRY=1 ack+retry+read+rwordered+known_if_redirected e20) v4 pg pg[2.0( v 20'687 (0'0,20'687] local-les=7 n=4 ec=6 les/c 7/7 6/6/6) [3,5] r=0 lpr=6 crt=16'684 lcod 20'686 mlcod 20'686 active+clean]
2015-02-05 04:36:58.739002 7f07c1f88700 20 osd.3 pg_epoch: 20 pg[2.0( v 20'687 (0'0,20'687] local-les=7 n=4 ec=6 les/c 7/7 6/6/6) [3,5] r=0 lpr=6 crt=16'684 lcod 20'686 mlcod 20'686 active+clean] op_has_sufficient_caps pool=2 (cache ) owner=0 need_read_cap=1 need_write_cap=0 need_class_read_cap=0 need_class_write_cap=0 > yes
2015-02-05 04:36:58.739030 7f07c1f88700 10 osd.3 pg_epoch: 20 pg[2.0( v 20'687 (0'0,20'687] local-les=7 n=4 ec=6 les/c 7/7 6/6/6) [3,5] r=0 lpr=6 crt=16'684 lcod 20'686 mlcod 20'686 active+clean] handle_message: 0x3993e00
2015-02-05 04:36:58.739051 7f07c1f88700 10 osd.3 pg_epoch: 20 pg[2.0( v 20'687 (0'0,20'687] local-les=7 n=4 ec=6 les/c 7/7 6/6/6) [3,5] r=0 lpr=6 crt=16'684 lcod 20'686 mlcod 20'686 active+clean] do_op osd_op(client.4119.0:16248 plana092652-2012 [read 0~1] 2.3b2063dc RETRY=1 ack+retry+read+rwordered+known_if_redirected e20) v4 may_read -> write-ordered flags ack+retry+read+rwordered+known_if_redirected
2015-02-05 04:36:58.739094 7f07c1f88700 10 osd.3 pg_epoch: 20 pg[2.0( v 20'687 (0'0,20'687] local-les=7 n=4 ec=6 les/c 7/7 6/6/6) [3,5] r=0 lpr=6 crt=16'684 lcod 20'686 mlcod 20'686 active+clean] get_object_context: found obc in cache: 0x43a58c0
2015-02-05 04:36:58.739117 7f07c1f88700 10 osd.3 pg_epoch: 20 pg[2.0( v 20'687 (0'0,20'687] local-les=7 n=4 ec=6 les/c 7/7 6/6/6) [3,5] r=0 lpr=6 crt=16'684 lcod 20'686 mlcod 20'686 active+clean] get_object_context: 0x43a58c0 3b2063dc/plana092652-2012/head//2 rwstate(none n=0 w=0) oi: 3b2063dc/plana092652-2012/head//2(20'687 osd.3.0:687 wrlock_by=unknown.0.0:0 s 2647613 uv 2040) ssc: 0x3951f00 snapset: 0=[]:[]+head
2015-02-05 04:36:58.739149 7f07c1f88700 10 osd.3 pg_epoch: 20 pg[2.0( v 20'687 (0'0,20'687] local-les=7 n=4 ec=6 les/c 7/7 6/6/6) [3,5] r=0 lpr=6 crt=16'684 lcod 20'686 mlcod 20'686 active+clean] find_object_context 3b2063dc/plana092652-2012/head//2 @head oi=3b2063dc/plana092652-2012/head//2(20'687 osd.3.0:687 wrlock_by=unknown.0.0:0 s 2647613 uv 2040)
2015-02-05 04:36:58.739180 7f07c1f88700 10 osd.3 pg_epoch: 20 pg[2.0( v 20'687 (0'0,20'687] local-les=7 n=4 ec=6 les/c 7/7 6/6/6) [3,5] r=0 lpr=6 crt=16'684 lcod 20'686 mlcod 20'686 active+clean] agent_choose_mode flush_mode: idle evict_mode: idle num_objects: 4 num_bytes: 4991182 num_objects_dirty: 0 num_objects_omap: 0 num_dirty: 0 num_user_objects: 2 num_user_bytes: 4990456 pool.info.target_max_bytes: 0 pool.info.target_max_objects: 500
2015-02-05 04:36:58.739184 7ffbf0548700 10 journal room 56631295 max_size 104857600 pos 103206912 header.start 54984704 top 4096
2015-02-05 04:36:58.739205 7f07c1f88700 20 osd.3 pg_epoch: 20 pg[2.0( v 20'687 (0'0,20'687] local-les=7 n=4 ec=6 les/c 7/7 6/6/6) [3,5] r=0 lpr=6 crt=16'684 lcod 20'686 mlcod 20'686 active+clean] agent_choose_mode dirty 0 full 0.016
2015-02-05 04:36:58.739207 7ffbf0548700 10 journal check_for_full at 103206912 : 3747840 < 56631295
2015-02-05 04:36:58.739210 7ffbf0548700 15 journal prepare_single_write 3 will write 103206912 : seq 4312 len 3742049 -> 3747840 (head 40 pre_pad 4046 ebl 3742049 post_pad 1665 tail 40) (ebl alignment 4086)
2015-02-05 04:36:58.739260 7f07c1f88700 10 osd.3 pg_epoch: 20 pg[2.0( v 20'687 (0'0,20'687] local-les=7 n=4 ec=6 les/c 7/7 6/6/6) [3,5] r=0 lpr=6 crt=16'684 lcod 20'686 mlcod 20'686 active+clean] execute_ctx 0x4004000
2015-02-05 04:36:58.739285 7f07c1f88700 10 osd.3 pg_epoch: 20 pg[2.0( v 20'687 (0'0,20'687] local-les=7 n=4 ec=6 les/c 7/7 6/6/6) [3,5] r=0 lpr=6 crt=16'684 lcod 20'686 mlcod 20'686 active+clean] do_op 3b2063dc/plana092652-2012/head//2 [read 0~1] ov 20'687
2015-02-05 04:36:58.739309 7f07c1f88700 10 osd.3 pg_epoch: 20 pg[2.0( v 20'687 (0'0,20'687] local-les=7 n=4 ec=6 les/c 7/7 6/6/6) [3,5] r=0 lpr=6 crt=16'684 lcod 20'686 mlcod 20'686 active+clean] taking ondisk_read_lock
2015-02-05 04:36:58.739330 7f07c1f88700 10 osd.3 pg_epoch: 20 pg[2.0( v 20'687 (0'0,20'687] local-les=7 n=4 ec=6 les/c 7/7 6/6/6) [3,5] r=0 lpr=6 crt=16'684 lcod 20'686 mlcod 20'686 active+clean] do_osd_op 3b2063dc/plana092652-2012/head//2 [read 0~1]
2015-02-05 04:36:58.739351 7f07c1f88700 10 osd.3 pg_epoch: 20 pg[2.0( v 20'687 (0'0,20'687] local-les=7 n=4 ec=6 les/c 7/7 6/6/6) [3,5] r=0 lpr=6 crt=16'684 lcod 20'686 mlcod 20'686 active+clean] do_osd_op read 0~1
2015-02-05 04:36:58.739372 7f07c1f88700 15 filestore(/var/lib/ceph/osd/ceph-3) read 2.0_head/3b2063dc/plana092652-2012/head//2 0~1
2015-02-05 04:36:58.739392 7f07c1f88700 10 filestore(/var/lib/ceph/osd/ceph-3) FileStore::read 2.0_head/3b2063dc/plana092652-2012/head//2 0~1/1
2015-02-05 04:36:58.739399 7f07c1f88700 10 osd.3 pg_epoch: 20 pg[2.0( v 20'687 (0'0,20'687] local-les=7 n=4 ec=6 les/c 7/7 6/6/6) [3,5] r=0 lpr=6 crt=16'684 lcod 20'686 mlcod 20'686 active+clean] read got 1 / 1 bytes from obj 3b2063dc/plana092652-2012/head//2
2015-02-05 04:36:58.739423 7f07c1f88700 10 osd.3 pg_epoch: 20 pg[2.0( v 20'687 (0'0,20'687] local-les=7 n=4 ec=6 les/c 7/7 6/6/6) [3,5] r=0 lpr=6 crt=16'684 lcod 20'686 mlcod 20'686 active+clean] dropping ondisk_read_lock
2015-02-05 04:36:58.739445 7f07c1f88700 15 osd.3 pg_epoch: 20 pg[2.0( v 20'687 (0'0,20'687] local-les=7 n=4 ec=6 les/c 7/7 6/6/6) [3,5] r=0 lpr=6 crt=16'684 lcod 20'686 mlcod 20'686 active+clean] do_osd_op_effects client.4119 con 0x3e3b2c0
2015-02-05 04:36:58.739469 7f07c1f88700 15 osd.3 pg_epoch: 20 pg[2.0( v 20'687 (0'0,20'687] local-les=7 n=4 ec=6 les/c 7/7 6/6/6) [3,5] r=0 lpr=6 crt=16'684 lcod 20'686 mlcod 20'686 active+clean] log_op_stats osd_op(client.4119.0:16248 plana092652-2012 [read 0~1] 2.3b2063dc RETRY=1 ack+retry+read+rwordered+known_if_redirected e20) v4 inb 0 outb 1 rlat 0.000000 lat 0.376157
2015-02-05 04:36:58.739504 7f07c1f88700 15 osd.3 pg_epoch: 20 pg[2.0( v 20'687 (0'0,20'687] local-les=7 n=4 ec=6 les/c 7/7 6/6/6) [3,5] r=0 lpr=6 crt=16'684 lcod 20'686 mlcod 20'686 active+clean] publish_stats_to_osd 20:187
2015-02-05 04:36:58.739526 7f07c1f88700 1 - 10.214.131.31:6800/1938 --> 10.214.131.31:0/1002652 -- osd_op_reply(16248 plana092652-2012 [read 0~1] v0'0 uv2040 ondisk = 0) v6 -- ?+0 0x41438c0 con 0x3e3b2c0
2015-02-05 04:36:58.739557 7f07c1f88700 15 osd.3 pg_epoch: 20 pg[2.0( v 20'687 (0'0,20'687] local-les=7 n=4 ec=6 les/c 7/7 6/6/6) [3,5] r=0 lpr=6 crt=16'684 lcod 20'686 mlcod 20'686 active+clean] requeue_ops
2015-02-05 04:36:58.739584 7f07c1f88700 10 osd.3 20 dequeue_op 0x3993e00 finish

2015-02-05 04:37:29.355332 7f07d58f7700 5 osd.3 21 tick
2015-02-05 04:37:29.355357 7f07d58f7700 20 osd.3 21 scrub_random_backoff lost coin flip, randomly backing off
2015-02-05 04:37:29.355361 7f07d58f7700 10 osd.3 21 do_waiters -- start
2015-02-05 04:37:29.355363 7f07d58f7700 10 osd.3 21 do_waiters -- finish
2015-02-05 04:37:29.355453 7f07d58f7700 0 log_channel(default) log [WRN] : 15 slow requests, 15 included below; oldest blocked for > 30.995028 secs
2015-02-05 04:37:29.355459 7f07d58f7700 0 log_channel(default) log [WRN] : slow request 30.992318 seconds old, received at 2015-02-05 04:36:58.363046: osd_op(client.4119.0:16246 plana092652-2012 [write 2647612~1] 2.3b2063dc RETRY=1 reassert_version=19'1660 ondisk+retry+write+known_if_redirected e20) currently waiting for ondisk
2015-02-05 04:37:29.355466 7f07d58f7700 0 log_channel(default) log [WRN] : slow request 30.992188 seconds old, received at 2015-02-05 04:36:58.363176: osd_op(client.4119.0:16247 plana092652-2012 [setxattr _header (55),truncate 2647613] 2.3b2063dc RETRY=1 reassert_version=19'1661 ondisk+retry+write+known_if_redirected e20) currently waiting for ondisk
2015-02-05 04:37:29.355470 7f07d58f7700 0 log_channel(default) log [WRN] : slow request 30.991933 seconds old, received at 2015-02-05 04:36:58.363431: osd_op(client.4119.0:16249 plana092652-2013 [write 742843~547810] 2.8f1efbb0 RETRY=1 reassert_version=19'1662 ondisk+retry+write+known_if_redirected e20) currently waiting for ondisk
2015-02-05 04:37:29.355475 7f07d58f7700 0 log_channel(default) log [WRN] : slow request 30.991474 seconds old, received at 2015-02-05 04:36:58.363890: osd_op(client.4119.0:16250 plana092652-2013 [write 1870021~444795] 2.8f1efbb0 RETRY=1 reassert_version=19'1663 ondisk+retry+write+known_if_redirected e20) currently waiting for ondisk
2015-02-05 04:37:29.355479 7f07d58f7700 0 log_channel(default) log [WRN] : slow request 30.991080 seconds old, received at 2015-02-05 04:36:58.364284: osd_op(client.4119.0:16251 plana092652-2013 [write 2342842~1] 2.8f1efbb0 RETRY=1 reassert_version=19'1664 ondisk+retry+write+known_if_redirected e20) currently waiting for ondisk
2015-02-05 04:37:29.395389 7ffbf254c700 5 osd.5 21 tick
2015-02-05 04:37:29.395417 7ffbf254c700 20 osd.5 21 scrub_should_schedule should run between 0 - 24 now 4 = yes