Ceph » CephFS

here is the lsat bit of log, starting with the incomplete readahead that caused the crash

  -360> 2014-03-24 11:43:52.029384 7f60c4b47780  3 client.4182 ll_read 0x31aa8a0 1000000beb5  458752~65536
  -359> 2014-03-24 11:43:52.029398 7f60c4b47780 10 client.4182 get_caps 1000000beb5.head(ref=3 cap_refs={1024=1,2048=0,4096=0,8192=0} open={1=1,2=0} mode=100644 size=1039335424 mtime=2014-03-24 11:43:28.314490 caps=pAsLsXsFsxcrwb(0=pAsLsXsFsxcrwb) objectset[1000000beb5 ts 0/0 objects 248 dirty_or_tx 0] parents=0x6edaed0 0x80b2880) have pAsLsXsFsxcrwb need Fr want Fc but not Fc revoking -
  -358> 2014-03-24 11:43:52.029416 7f60c4b47780 10 client.4182 _read_async 1000000beb5.head(ref=3 cap_refs={1024=1,2048=1,4096=0,8192=0} open={1=1,2=0} mode=100644 size=1039335424 mtime=2014-03-24 11:43:28.314490 caps=pAsLsXsFsxcrwb(0=pAsLsXsFsxcrwb) objectset[1000000beb5 ts 0/0 objects 248 dirty_or_tx 0] parents=0x6edaed0 0x80b2880) 458752~65536
  -357> 2014-03-24 11:43:52.029426 7f60c4b47780 10 client.4182 readahead=1 nr_consec=124 max_byes=0 max_periods=4
  -356> 2014-03-24 11:43:52.029428 7f60c4b47780 20 client.4182 readahead 124 reads 16252928 bytes ... readahead 458752~16318464 min 65536 (caller wants 458752~65536)
  -355> 2014-03-24 11:43:52.029462 7f60c4b47780  1 -- 10.2.0.252:0/8255 --> 10.2.0.252:6800/7128 -- osd_op(client.4182.0:72689 1000000beb5.00000000 [read 458752~3735552] 0.8c7f3546 e362) v4 -- ?+0 0x135ba400 con 0x3259340
  -354> 2014-03-24 11:43:52.029486 7f60c4b47780  1 -- 10.2.0.252:0/8255 --> 10.2.0.1:6801/3632 -- osd_op(client.4182.0:72690 1000000beb5.00000001 [read 0~4194304] 0.230e491b e362) v4 -- ?+0 0x31c5100 con 0x565ac00
  -353> 2014-03-24 11:43:52.029508 7f60c4b47780  1 -- 10.2.0.252:0/8255 --> 10.2.0.253:6804/8054 -- osd_op(client.4182.0:72691 1000000beb5.00000002 [read 0~4194304] 0.388125ac e362) v4 -- ?+0 0xdd41b00 con 0x8b26300
  -352> 2014-03-24 11:43:52.029535 7f60c4b47780  1 -- 10.2.0.252:0/8255 --> 10.2.0.253:6800/7423 -- osd_op(client.4182.0:72692 1000000beb5.00000003 [read 0~4194304] 0.ecd5ff57 e362) v4 -- ?+0 0x3899d40 con 0x8b206e0
  -351> 2014-03-24 11:43:52.029555 7f60c4b47780 20 client.4182 readahead initiated
  -350> 2014-03-24 11:43:52.037005 7f60bd625700  1 -- 10.2.0.252:0/8255 <== osd.2 10.2.0.252:6800/7128 256 ==== osd_op_reply(72689 1000000beb5.00000000 [read 458752~3735552] ondisk = 0) v4 ==== 119+0+3735552 (956711537 0 3185106206) 0x4c82600 con 0x3259340
  -349> 2014-03-24 11:43:52.037192 7f60c4b47780 10 client.4182 readahead nr_consec_read 0 for 65536 bytes .. last_pos 927399936 .. offset 458752
  -348> 2014-03-24 11:43:52.039969 7f60bd625700  1 -- 10.2.0.252:0/8255 <== osd.4 10.2.0.253:6804/8054 268 ==== osd_op_reply(72691 1000000beb5.00000002 [read 0~4194304] ondisk = 0) v4 ==== 119+0+4194304 (4141864084 0 0) 0xd219e00 con 0x8b26300
  -347> 2014-03-24 11:43:52.042469 7f60bd625700  1 -- 10.2.0.252:0/8255 <== osd.0 10.2.0.1:6801/3632 217 ==== osd_op_reply(72690 1000000beb5.00000001 [read 0~4194304] ondisk = 0) v4 ==== 119+0+4194304 (356929205 0 1331629502) 0xe721c00 con 0x565ac00
  -346> 2014-03-24 11:43:52.098666 7f60bd625700  1 -- 10.2.0.252:0/8255 <== osd.4 10.2.0.253:6804/8054 269 ==== osd_op_reply(72678 1000000beb6.00000425 [write 0~4194304] ondisk = 0) v4 ==== 119+0+0 (126181431 0 0) 0xd219800 con 0x8b26300
  -345> 2014-03-24 11:43:52.202994 7f60bd625700  1 -- 10.2.0.252:0/8255 <== osd.4 10.2.0.253:6804/8054 270 ==== osd_op_reply(72680 1000000beb6.00000427 [write 0~4194304] ondisk = 0) v4 ==== 119+0+0 (2431460103 0 0) 0x1921a200 con 0x8b26300
  -344> 2014-03-24 11:43:52.257110 7f60c4b47780  3 client.4182 ll_read 0x31aa8a0 1000000beb5  1703936~131072
  -343> 2014-03-24 11:43:52.257127 7f60c4b47780 10 client.4182 get_caps 1000000beb5.head(ref=3 cap_refs={1024=1,2048=0,4096=0,8192=0} open={1=1,2=0} mode=100644 size=1039335424 mtime=2014-03-24 11:43:28.314490 caps=pAsLsXsFsxcrwb(0=pAsLsXsFsxcrwb) objectset[1000000beb5 ts 0/0 objects 248 dirty_or_tx 0] parents=0x6edaed0 0x80b2880) have pAsLsXsFsxcrwb need Fr want Fc but not Fc revoking -
  -342> 2014-03-24 11:43:52.257169 7f60c4b47780 10 client.4182 _read_async 1000000beb5.head(ref=3 cap_refs={1024=1,2048=1,4096=0,8192=0} open={1=1,2=0} mode=100644 size=1039335424 mtime=2014-03-24 11:43:28.314490 caps=pAsLsXsFsxcrwb(0=pAsLsXsFsxcrwb) objectset[1000000beb5 ts 0/0 objects 248 dirty_or_tx 0] parents=0x6edaed0 0x80b2880) 1703936~131072
  -341> 2014-03-24 11:43:52.257182 7f60c4b47780 10 client.4182 readahead=1 nr_consec=0 max_byes=0 max_periods=4
  -340> 2014-03-24 11:43:52.257233 7f60c4b47780 10 client.4182 readahead nr_consec_read 0 for 131072 bytes .. last_pos 524288 .. offset 1703936
  -339> 2014-03-24 11:43:52.257288 7f60c4b47780  3 client.4182 ll_read 0x31aa8a0 1000000beb5  1835008~131072
  -338> 2014-03-24 11:43:52.257294 7f60c4b47780 10 client.4182 get_caps 1000000beb5.head(ref=3 cap_refs={1024=1,2048=0,4096=0,8192=0} open={1=1,2=0} mode=100644 size=1039335424 mtime=2014-03-24 11:43:28.314490 caps=pAsLsXsFsxcrwb(0=pAsLsXsFsxcrwb) objectset[1000000beb5 ts 0/0 objects 248 dirty_or_tx 0] parents=0x6edaed0 0x80b2880) have pAsLsXsFsxcrwb need Fr want Fc but not Fc revoking -
  -337> 2014-03-24 11:43:52.257306 7f60c4b47780 10 client.4182 _read_async 1000000beb5.head(ref=3 cap_refs={1024=1,2048=1,4096=0,8192=0} open={1=1,2=0} mode=100644 size=1039335424 mtime=2014-03-24 11:43:28.314490 caps=pAsLsXsFsxcrwb(0=pAsLsXsFsxcrwb) objectset[1000000beb5 ts 0/0 objects 248 dirty_or_tx 0] parents=0x6edaed0 0x80b2880) 1835008~131072
  -336> 2014-03-24 11:43:52.257314 7f60c4b47780 10 client.4182 readahead=1 nr_consec=0 max_byes=0 max_periods=4
  -335> 2014-03-24 11:43:52.257322 7f60c4b47780 10 client.4182 readahead nr_consec_read 1 for 262144 bytes .. last_pos 1835008 .. offset 1835008
  -334> 2014-03-24 11:43:52.257373 7f60c4b47780  3 client.4182 ll_read 0x31aa8a0 1000000beb5  1966080~131072
  -333> 2014-03-24 11:43:52.257376 7f60c4b47780 10 client.4182 get_caps 1000000beb5.head(ref=3 cap_refs={1024=1,2048=0,4096=0,8192=0} open={1=1,2=0} mode=100644 size=1039335424 mtime=2014-03-24 11:43:28.314490 caps=pAsLsXsFsxcrwb(0=pAsLsXsFsxcrwb) objectset[1000000beb5 ts 0/0 objects 248 dirty_or_tx 0] parents=0x6edaed0 0x80b2880) have pAsLsXsFsxcrwb need Fr want Fc but not Fc revoking -
  -332> 2014-03-24 11:43:52.257388 7f60c4b47780 10 client.4182 _read_async 1000000beb5.head(ref=3 cap_refs={1024=1,2048=1,4096=0,8192=0} open={1=1,2=0} mode=100644 size=1039335424 mtime=2014-03-24 11:43:28.314490 caps=pAsLsXsFsxcrwb(0=pAsLsXsFsxcrwb) objectset[1000000beb5 ts 0/0 objects 248 dirty_or_tx 0] parents=0x6edaed0 0x80b2880) 1966080~131072
  -331> 2014-03-24 11:43:52.257396 7f60c4b47780 10 client.4182 readahead=1 nr_consec=1 max_byes=0 max_periods=4
  -330> 2014-03-24 11:43:52.257398 7f60c4b47780 20 client.4182 readahead 1 reads 262144 bytes ... readahead 1966080~524288 min 131072 (caller wants 1966080~131072)
  -329> 2014-03-24 11:43:52.257405 7f60c4b47780 20 client.4182 readahead already have min
  -328> 2014-03-24 11:43:52.257411 7f60c4b47780 10 client.4182 readahead nr_consec_read 2 for 393216 bytes .. last_pos 1966080 .. offset 1966080
  -327> 2014-03-24 11:43:52.257459 7f60c4b47780  3 client.4182 ll_read 0x31aa8a0 1000000beb5  2097152~131072
  -326> 2014-03-24 11:43:52.257464 7f60c4b47780 10 client.4182 get_caps 1000000beb5.head(ref=3 cap_refs={1024=1,2048=0,4096=0,8192=0} open={1=1,2=0} mode=100644 size=1039335424 mtime=2014-03-24 11:43:28.314490 caps=pAsLsXsFsxcrwb(0=pAsLsXsFsxcrwb) objectset[1000000beb5 ts 0/0 objects 248 dirty_or_tx 0] parents=0x6edaed0 0x80b2880) have pAsLsXsFsxcrwb need Fr want Fc but not Fc revoking -
  -325> 2014-03-24 11:43:52.257476 7f60c4b47780 10 client.4182 _read_async 1000000beb5.head(ref=3 cap_refs={1024=1,2048=1,4096=0,8192=0} open={1=1,2=0} mode=100644 size=1039335424 mtime=2014-03-24 11:43:28.314490 caps=pAsLsXsFsxcrwb(0=pAsLsXsFsxcrwb) objectset[1000000beb5 ts 0/0 objects 248 dirty_or_tx 0] parents=0x6edaed0 0x80b2880) 2097152~131072
  -324> 2014-03-24 11:43:52.257485 7f60c4b47780 10 client.4182 readahead=1 nr_consec=2 max_byes=0 max_periods=4
  -323> 2014-03-24 11:43:52.257487 7f60c4b47780 20 client.4182 readahead 2 reads 393216 bytes ... readahead 2097152~786432 min 131072 (caller wants 2097152~131072)
  -322> 2014-03-24 11:43:52.257493 7f60c4b47780 20 client.4182 readahead already have min
  -321> 2014-03-24 11:43:52.257498 7f60c4b47780 10 client.4182 readahead nr_consec_read 3 for 524288 bytes .. last_pos 2097152 .. offset 2097152
  -320> 2014-03-24 11:43:52.257546 7f60c4b47780  3 client.4182 ll_read 0x31aa8a0 1000000beb5  2228224~131072
  -319> 2014-03-24 11:43:52.257552 7f60c4b47780 10 client.4182 get_caps 1000000beb5.head(ref=3 cap_refs={1024=1,2048=0,4096=0,8192=0} open={1=1,2=0} mode=100644 size=1039335424 mtime=2014-03-24 11:43:28.314490 caps=pAsLsXsFsxcrwb(0=pAsLsXsFsxcrwb) objectset[1000000beb5 ts 0/0 objects 248 dirty_or_tx 0] parents=0x6edaed0 0x80b2880) have pAsLsXsFsxcrwb need Fr want Fc but not Fc revoking -
  -318> 2014-03-24 11:43:52.257564 7f60c4b47780 10 client.4182 _read_async 1000000beb5.head(ref=3 cap_refs={1024=1,2048=1,4096=0,8192=0} open={1=1,2=0} mode=100644 size=1039335424 mtime=2014-03-24 11:43:28.314490 caps=pAsLsXsFsxcrwb(0=pAsLsXsFsxcrwb) objectset[1000000beb5 ts 0/0 objects 248 dirty_or_tx 0] parents=0x6edaed0 0x80b2880) 2228224~131072
  -317> 2014-03-24 11:43:52.257572 7f60c4b47780 10 client.4182 readahead=1 nr_consec=3 max_byes=0 max_periods=4
  -316> 2014-03-24 11:43:52.257573 7f60c4b47780 20 client.4182 readahead 3 reads 524288 bytes ... readahead 2228224~1048576 min 131072 (caller wants 2228224~131072)
  -315> 2014-03-24 11:43:52.257579 7f60c4b47780 20 client.4182 readahead already have min
  -314> 2014-03-24 11:43:52.257584 7f60c4b47780 10 client.4182 readahead nr_consec_read 4 for 655360 bytes .. last_pos 2228224 .. offset 2228224
  -313> 2014-03-24 11:43:52.257632 7f60c4b47780  3 client.4182 ll_read 0x31aa8a0 1000000beb5  2359296~131072
  -312> 2014-03-24 11:43:52.257635 7f60c4b47780 10 client.4182 get_caps 1000000beb5.head(ref=3 cap_refs={1024=1,2048=0,4096=0,8192=0} open={1=1,2=0} mode=100644 size=1039335424 mtime=2014-03-24 11:43:28.314490 caps=pAsLsXsFsxcrwb(0=pAsLsXsFsxcrwb) objectset[1000000beb5 ts 0/0 objects 248 dirty_or_tx 0] parents=0x6edaed0 0x80b2880) have pAsLsXsFsxcrwb need Fr want Fc but not Fc revoking -
  -311> 2014-03-24 11:43:52.257647 7f60c4b47780 10 client.4182 _read_async 1000000beb5.head(ref=3 cap_refs={1024=1,2048=1,4096=0,8192=0} open={1=1,2=0} mode=100644 size=1039335424 mtime=2014-03-24 11:43:28.314490 caps=pAsLsXsFsxcrwb(0=pAsLsXsFsxcrwb) objectset[1000000beb5 ts 0/0 objects 248 dirty_or_tx 0] parents=0x6edaed0 0x80b2880) 2359296~131072
  -310> 2014-03-24 11:43:52.257655 7f60c4b47780 10 client.4182 readahead=1 nr_consec=4 max_byes=0 max_periods=4
  -309> 2014-03-24 11:43:52.257657 7f60c4b47780 20 client.4182 readahead 4 reads 655360 bytes ... readahead 2359296~1310720 min 131072 (caller wants 2359296~131072)
  -308> 2014-03-24 11:43:52.257662 7f60c4b47780 20 client.4182 readahead already have min
  -307> 2014-03-24 11:43:52.257668 7f60c4b47780 10 client.4182 readahead nr_consec_read 5 for 786432 bytes .. last_pos 2359296 .. offset 2359296
  -306> 2014-03-24 11:43:52.258583 7f60c4b47780  3 client.4182 ll_release 0x31afdf0 1000000beb6 
  -305> 2014-03-24 11:43:52.258596 7f60c4b47780  5 client.4182 _release_fh 0x31afdf0 mode 3 on 1000000beb6.head(ref=5 cap_refs={4096=0,8192=1} open={1=0,2=0,3=1} mode=100644 size=5368709120 mtime=2014-03-24 11:43:51.883318 caps=pAsxLsXsxFsxcrwb(0=pAsxLsXsxFsxcrwb) dirty_caps=Fw objectset[1000000beb6 ts 0/0 objects 253 dirty_or_tx 55881216] parents=0x6ed96c0 0x80b3a80)
  -304> 2014-03-24 11:43:52.258623 7f60c4b47780 10 client.4182 _flush 1000000beb6.head(ref=5 cap_refs={4096=0,8192=1} open={1=0,2=0,3=0} mode=100644 size=5368709120 mtime=2014-03-24 11:43:51.883318 caps=pAsxLsXsxFsxcrwb(0=pAsxLsXsxFsxcrwb) dirty_caps=Fw objectset[1000000beb6 ts 0/0 objects 253 dirty_or_tx 55881216] parents=0x6ed96c0 0x80b3a80)
  -303> 2014-03-24 11:43:52.258733 7f60c4b47780  1 -- 10.2.0.252:0/8255 --> 10.2.0.252:6804/7799 -- osd_op(client.4182.0:72693 1000000beb6.0000042b [write 2097152~2097152] 0.57612c56 snapc 1=[] e362) v4 -- ?+0 0x31c21c0 con 0x15e539c0
  -302> 2014-03-24 11:43:52.258766 7f60c4b47780  1 -- 10.2.0.252:0/8255 --> 10.2.0.252:6800/7128 -- osd_op(client.4182.0:72694 1000000beb6.0000042c [write 0~2097152] 0.b670c3a4 snapc 1=[] e362) v4 -- ?+0 0x35f0fc0 con 0x3259340
  -301> 2014-03-24 11:43:52.258786 7f60c4b47780  1 -- 10.2.0.252:0/8255 --> 10.2.0.252:6800/7128 -- osd_op(client.4182.0:72695 1000000beb6.0000042c [write 2097664~2096128] 0.b670c3a4 snapc 1=[] e362) v4 -- ?+0 0xdd40fc0 con 0x3259340
  -300> 2014-03-24 11:43:52.258801 7f60c4b47780  1 -- 10.2.0.252:0/8255 --> 10.2.0.252:6800/7128 -- osd_op(client.4182.0:72696 1000000beb6.0000042d [write 0~937984] 0.4a73e32 snapc 1=[] e362) v4 -- ?+0 0x31c6540 con 0x3259340
  -299> 2014-03-24 11:43:52.258813 7f60c4b47780  1 -- 10.2.0.252:0/8255 --> 10.2.0.252:6800/7128 -- osd_op(client.4182.0:72697 1000000beb6.0000042d [write 944640~7680] 0.4a73e32 snapc 1=[] e362) v4 -- ?+0 0x31c5580 con 0x3259340
  -298> 2014-03-24 11:43:52.258827 7f60c4b47780  1 -- 10.2.0.252:0/8255 --> 10.2.0.252:6800/7128 -- osd_op(client.4182.0:72698 1000000beb6.0000042d [write 966144~1061376] 0.4a73e32 snapc 1=[] e362) v4 -- ?+0 0x35f57c0 con 0x3259340
  -297> 2014-03-24 11:43:52.259929 7f60c4b47780 10 client.4182 check_caps on 1000000beb6.head(ref=6 cap_refs={4096=0,8192=1} open={1=0,2=0,3=0} mode=100644 size=5368709120 mtime=2014-03-24 11:43:51.883318 caps=pAsxLsXsxFsxcrwb(0=pAsxLsXsxFsxcrwb) dirty_caps=Fw objectset[1000000beb6 ts 0/0 objects 253 dirty_or_tx 55881216] parents=0x6ed96c0 0x80b3a80) wanted Fxb used Fb is_delayed=0
  -296> 2014-03-24 11:43:52.259959 7f60c4b47780 10 client.4182 cap_delay_requeue on 1000000beb6.head(ref=6 cap_refs={4096=0,8192=1} open={1=0,2=0,3=0} mode=100644 size=5368709120 mtime=2014-03-24 11:43:51.883318 caps=pAsxLsXsxFsxcrwb(0=pAsxLsXsxFsxcrwb) dirty_caps=Fw objectset[1000000beb6 ts 0/0 objects 253 dirty_or_tx 55881216] parents=0x6ed96c0 0x80b3a80)
  -295> 2014-03-24 11:43:52.259977 7f60c4b47780 10 client.4182  cap mds.0 issued pAsxLsXsxFsxcrwb implemented pAsxLsXsxFsxcrwb revoking -
  -294> 2014-03-24 11:43:52.259985 7f60c4b47780 10 client.4182 delaying cap release
  -293> 2014-03-24 11:43:52.259987 7f60c4b47780 10 client.4182 put_inode on 1000000beb6.head(ref=6 cap_refs={4096=0,8192=1} open={1=0,2=0,3=0} mode=100644 size=5368709120 mtime=2014-03-24 11:43:51.883318 caps=pAsxLsXsxFsxcrwb(0=pAsxLsXsxFsxcrwb) dirty_caps=Fw objectset[1000000beb6 ts 0/0 objects 253 dirty_or_tx 55881216] parents=0x6ed96c0 0x80b3a80)
  -292> 2014-03-24 11:43:52.260013 7f60c4b47780  3 client.4182 ll_fsync 0x31aa8a0 1000000beb5 
  -291> 2014-03-24 11:43:52.260017 7f60c4b47780  3 client.4182 _fsync(0x31aa8a0, dataonly)
  -290> 2014-03-24 11:43:52.260020 7f60c4b47780 10 client.4182 _flush 1000000beb5.head(ref=4 cap_refs={1024=1,2048=0,4096=0,8192=0} open={1=1,2=0} mode=100644 size=1039335424 mtime=2014-03-24 11:43:28.314490 caps=pAsLsXsFsxcrwb(0=pAsLsXsFsxcrwb) objectset[1000000beb5 ts 0/0 objects 248 dirty_or_tx 0] parents=0x6edaed0 0x80b2880)
  -289> 2014-03-24 11:43:52.260035 7f60c4b47780 10 client.4182  nothing to flush
  -288> 2014-03-24 11:43:52.260037 7f60c4b47780 15 client.4182 using return-valued form of _fsync
  -287> 2014-03-24 11:43:52.260038 7f60c4b47780 10 client.4182 no metadata needs to commit
  -286> 2014-03-24 11:43:52.260040 7f60c4b47780 15 client.4182 waiting on data to flush
  -285> 2014-03-24 11:43:52.260042 7f60c4b47780 10 client.4182 put_inode on 1000000beb5.head(ref=4 cap_refs={1024=1,2048=0,4096=0,8192=0} open={1=1,2=0} mode=100644 size=1039335424 mtime=2014-03-24 11:43:28.314490 caps=pAsLsXsFsxcrwb(0=pAsLsXsFsxcrwb) objectset[1000000beb5 ts 0/0 objects 248 dirty_or_tx 0] parents=0x6edaed0 0x80b2880)
  -284> 2014-03-24 11:43:52.260059 7f60c4b47780 15 client.4182 got 0 from flush writeback
  -283> 2014-03-24 11:43:52.260060 7f60c4b47780 10 client.4182 ino 1000000beb5 has no uncommitted writes
  -282> 2014-03-24 11:43:52.260251 7f60c4b47780  3 client.4182 ll_fsync 0x31aa8a0 1000000beb5 
  -281> 2014-03-24 11:43:52.260259 7f60c4b47780  3 client.4182 _fsync(0x31aa8a0, dataonly)
  -280> 2014-03-24 11:43:52.260262 7f60c4b47780 10 client.4182 _flush 1000000beb5.head(ref=4 cap_refs={1024=1,2048=0,4096=0,8192=0} open={1=1,2=0} mode=100644 size=1039335424 mtime=2014-03-24 11:43:28.314490 caps=pAsLsXsFsxcrwb(0=pAsLsXsFsxcrwb) objectset[1000000beb5 ts 0/0 objects 248 dirty_or_tx 0] parents=0x6edaed0 0x80b2880)
  -279> 2014-03-24 11:43:52.260283 7f60c4b47780 10 client.4182  nothing to flush
  -278> 2014-03-24 11:43:52.260287 7f60c4b47780 15 client.4182 using return-valued form of _fsync
  -277> 2014-03-24 11:43:52.260288 7f60c4b47780 10 client.4182 no metadata needs to commit
  -276> 2014-03-24 11:43:52.260290 7f60c4b47780 15 client.4182 waiting on data to flush
  -275> 2014-03-24 11:43:52.260291 7f60c4b47780 10 client.4182 put_inode on 1000000beb5.head(ref=4 cap_refs={1024=1,2048=0,4096=0,8192=0} open={1=1,2=0} mode=100644 size=1039335424 mtime=2014-03-24 11:43:28.314490 caps=pAsLsXsFsxcrwb(0=pAsLsXsFsxcrwb) objectset[1000000beb5 ts 0/0 objects 248 dirty_or_tx 0] parents=0x6edaed0 0x80b2880)
  -274> 2014-03-24 11:43:52.260307 7f60c4b47780 15 client.4182 got 0 from flush writeback
  -273> 2014-03-24 11:43:52.260309 7f60c4b47780 10 client.4182 ino 1000000beb5 has no uncommitted writes
  -272> 2014-03-24 11:43:52.260565 7f60c4b47780  3 client.4182 ll_release 0x31aa8a0 1000000beb5 
  -271> 2014-03-24 11:43:52.260573 7f60c4b47780  5 client.4182 _release_fh 0x31aa8a0 mode 1 on 1000000beb5.head(ref=3 cap_refs={1024=1,2048=0,4096=0,8192=0} open={1=1,2=0} mode=100644 size=1039335424 mtime=2014-03-24 11:43:28.314490 caps=pAsLsXsFsxcrwb(0=pAsLsXsFsxcrwb) objectset[1000000beb5 ts 0/0 objects 248 dirty_or_tx 0] parents=0x6edaed0 0x80b2880)
  -270> 2014-03-24 11:43:52.260596 7f60c4b47780 10 client.4182 _flush 1000000beb5.head(ref=3 cap_refs={1024=1,2048=0,4096=0,8192=0} open={1=0,2=0} mode=100644 size=1039335424 mtime=2014-03-24 11:43:28.314490 caps=pAsLsXsFsxcrwb(0=pAsLsXsFsxcrwb) objectset[1000000beb5 ts 0/0 objects 248 dirty_or_tx 0] parents=0x6edaed0 0x80b2880)
  -269> 2014-03-24 11:43:52.260612 7f60c4b47780 10 client.4182  nothing to flush
  -268> 2014-03-24 11:43:52.260615 7f60c4b47780 10 client.4182 check_caps on 1000000beb5.head(ref=3 cap_refs={1024=1,2048=0,4096=0,8192=0} open={1=0,2=0} mode=100644 size=1039335424 mtime=2014-03-24 11:43:28.314490 caps=pAsLsXsFsxcrwb(0=pAsLsXsFsxcrwb) objectset[1000000beb5 ts 0/0 objects 248 dirty_or_tx 0] parents=0x6edaed0 0x80b2880) wanted Fc used Fc is_delayed=0
  -267> 2014-03-24 11:43:52.260631 7f60c4b47780 10 client.4182 cap_delay_requeue on 1000000beb5.head(ref=3 cap_refs={1024=1,2048=0,4096=0,8192=0} open={1=0,2=0} mode=100644 size=1039335424 mtime=2014-03-24 11:43:28.314490 caps=pAsLsXsFsxcrwb(0=pAsLsXsFsxcrwb) objectset[1000000beb5 ts 0/0 objects 248 dirty_or_tx 0] parents=0x6edaed0 0x80b2880)
  -266> 2014-03-24 11:43:52.260646 7f60c4b47780 10 client.4182  cap mds.0 issued pAsLsXsFsxcrwb implemented pAsLsXsFsxcrwb revoking -
  -265> 2014-03-24 11:43:52.260653 7f60c4b47780 10 client.4182 delaying cap release
  -264> 2014-03-24 11:43:52.260655 7f60c4b47780 10 client.4182 put_inode on 1000000beb5.head(ref=3 cap_refs={1024=1,2048=0,4096=0,8192=0} open={1=0,2=0} mode=100644 size=1039335424 mtime=2014-03-24 11:43:28.314490 caps=pAsLsXsFsxcrwb(0=pAsLsXsFsxcrwb) objectset[1000000beb5 ts 0/0 objects 248 dirty_or_tx 0] parents=0x6edaed0 0x80b2880)
  -263> 2014-03-24 11:43:52.261609 7f60c4b47780  3 client.4182 ll_getattr 1.head
  -262> 2014-03-24 11:43:52.261619 7f60c4b47780 10 client.4182 _getattr mask pAsLsXsFs issued=0
  -261> 2014-03-24 11:43:52.261630 7f60c4b47780 20 client.4182 choose_target_mds starting with req->inode 1.head(ref=4 cap_refs={} open={} mode=40755 size=0 mtime=2014-03-24 11:41:25.398365 caps=pAsLsXs(0=pAsLsXs) has_dir_layout 0x31b1b00)
  -260> 2014-03-24 11:43:52.261645 7f60c4b47780 20 client.4182 choose_target_mds 1.head(ref=4 cap_refs={} open={} mode=40755 size=0 mtime=2014-03-24 11:41:25.398365 caps=pAsLsXs(0=pAsLsXs) has_dir_layout 0x31b1b00) is_hash=0 hash=0
  -259> 2014-03-24 11:43:52.261656 7f60c4b47780 10 client.4182 choose_target_mds from caps on inode 1.head(ref=4 cap_refs={} open={} mode=40755 size=0 mtime=2014-03-24 11:41:25.398365 caps=pAsLsXs(0=pAsLsXs) has_dir_layout 0x31b1b00)
  -258> 2014-03-24 11:43:52.261665 7f60c4b47780 20 client.4182 mds is 0
  -257> 2014-03-24 11:43:52.261668 7f60c4b47780 10 client.4182 send_request rebuilding request 61544 for mds.0
  -256> 2014-03-24 11:43:52.261672 7f60c4b47780 20 client.4182 encode_cap_releases enter (req: 0x328cd00, mds: 0)
  -255> 2014-03-24 11:43:52.261675 7f60c4b47780 20 client.4182 send_request set sent_stamp to 2014-03-24 11:43:52.261675
  -254> 2014-03-24 11:43:52.261678 7f60c4b47780 10 client.4182 send_request client_request(unknown.0:61544 getattr pAsLsXsFs #1) v1 to mds.0
  -253> 2014-03-24 11:43:52.261685 7f60c4b47780  1 -- 10.2.0.252:0/8255 --> 10.2.0.253:6809/8355 -- client_request(client.4182:61544 getattr pAsLsXsFs #1) v1 -- ?+0 0x6e28000 con 0x4b93f40
  -252> 2014-03-24 11:43:52.261705 7f60c4b47780 20 client.4182 awaiting reply|forward|kick on 0x7fffee941770
  -251> 2014-03-24 11:43:52.262699 7f60bd625700  1 -- 10.2.0.252:0/8255 <== mds.0 10.2.0.253:6809/8355 211012 ==== client_reply(???:61544 = 0 Success) v1 ==== 312+0+0 (2392131568 0 0) 0x3849340 con 0x4b93f40
  -250> 2014-03-24 11:43:52.262740 7f60bd625700 20 client.4182 handle_client_reply got a reply. Safe:1 tid 61544
  -249> 2014-03-24 11:43:52.262747 7f60bd625700 10 client.4182 insert_trace from 2014-03-24 11:43:52.261675 mds.0 is_target=1 is_dentry=0
  -248> 2014-03-24 11:43:52.262757 7f60bd625700 10 client.4182  features 0x7ffffffff
  -247> 2014-03-24 11:43:52.262760 7f60bd625700 10 client.4182 update_snap_trace len 48
  -246> 2014-03-24 11:43:52.262765 7f60bd625700 20 client.4182 get_snap_realm 1 0x32149f0 16398 -> 16399
  -245> 2014-03-24 11:43:52.262771 7f60bd625700 10 client.4182 update_snap_trace snaprealm(1 nref=16399 c=0 seq=1 parent=0 my_snaps=[] cached_snapc=1=[]) seq 1 <= 1 and same parent, SKIPPING
  -244> 2014-03-24 11:43:52.262779 7f60bd625700 20 client.4182 put_snap_realm 1 0x32149f0 16399 -> 16398
  -243> 2014-03-24 11:43:52.262783 7f60bd625700 10 client.4182  hrm  is_target=1 is_dentry=0
  -242> 2014-03-24 11:43:52.262790 7f60bd625700 12 client.4182 add_update_inode had 1.head(ref=4 cap_refs={} open={} mode=40755 size=0 mtime=2014-03-24 11:41:25.398365 caps=pAsLsXs(0=pAsLsXs) has_dir_layout 0x31b1b00) caps pAsLsXsFs
  -241> 2014-03-24 11:43:52.262813 7f60bd625700 20 client.4182  dir hash is 2
  -240> 2014-03-24 11:43:52.262817 7f60bd625700 10 client.4182 update_inode_file_bits 1.head(ref=4 cap_refs={} open={} mode=40755 size=0 mtime=2014-03-24 11:41:25.398365 caps=pAsLsXs(0=pAsLsXs) has_dir_layout 0x31b1b00) pAsLsXs mtime 2014-03-24 11:43:36.551490
  -239> 2014-03-24 11:43:52.262830 7f60bd625700 10 client.4182 add_update_cap issued pAsLsXs -> pAsLsXsFs from mds.0 on 1.head(ref=4 cap_refs={} open={} mode=40755 size=0 mtime=2014-03-24 11:43:36.551490 caps=pAsLsXsFs(0=pAsLsXsFs) has_dir_layout 0x31b1b00)
  -238> 2014-03-24 11:43:52.262844 7f60bd625700 20 client.4182 handle_client_reply signalling caller 0x7fffee941770
  -237> 2014-03-24 11:43:52.262849 7f60bd625700 20 client.4182 handle_client_reply awaiting kickback on tid 61544 0x7f60bd624850
  -236> 2014-03-24 11:43:52.262884 7f60c4b47780 20 client.4182 sendrecv kickback on tid 61544 0x7f60bd624850
  -235> 2014-03-24 11:43:52.262892 7f60c4b47780 20 client.4182 lat 0.001217
  -234> 2014-03-24 11:43:52.262895 7f60c4b47780 10 client.4182 _getattr result=0
  -233> 2014-03-24 11:43:52.262897 7f60c4b47780 10 client.4182 fill_stat on 1 snap/devhead mode 040755 mtime 2014-03-24 11:43:36.551490 ctime 2014-03-24 11:43:36.551490
  -232> 2014-03-24 11:43:52.262903 7f60c4b47780  3 client.4182 ll_getattr 1.head = 0
  -231> 2014-03-24 11:43:52.262941 7f60c4b47780  3 client.4182 ll_lookup 1.head nova
  -230> 2014-03-24 11:43:52.262951 7f60c4b47780 20 client.4182 _lookup have dn nova mds.0 ttl 2014-03-23 04:38:47.878264 seq 1545
  -229> 2014-03-24 11:43:52.262958 7f60c4b47780 10 client.4182 _do_lookup on #1/nova
  -228> 2014-03-24 11:43:52.262960 7f60c4b47780 20 client.4182 choose_target_mds starting with req->inode 1.head(ref=5 cap_refs={} open={} mode=40755 size=0 mtime=2014-03-24 11:43:36.551490 caps=pAsLsXsFs(0=pAsLsXsFs) has_dir_layout 0x31b1b00)
  -227> 2014-03-24 11:43:52.262971 7f60c4b47780 20 client.4182 choose_target_mds inode dir hash is 2 on nova => 2171355314
  -226> 2014-03-24 11:43:52.262973 7f60c4b47780 20 client.4182 choose_target_mds 1.head(ref=5 cap_refs={} open={} mode=40755 size=0 mtime=2014-03-24 11:43:36.551490 caps=pAsLsXsFs(0=pAsLsXsFs) has_dir_layout 0x31b1b00) is_hash=1 hash=2171355314
  -225> 2014-03-24 11:43:52.262979 7f60c4b47780 10 client.4182 choose_target_mds from caps on inode 1.head(ref=5 cap_refs={} open={} mode=40755 size=0 mtime=2014-03-24 11:43:36.551490 caps=pAsLsXsFs(0=pAsLsXsFs) has_dir_layout 0x31b1b00)
  -224> 2014-03-24 11:43:52.262985 7f60c4b47780 20 client.4182 mds is 0
  -223> 2014-03-24 11:43:52.262987 7f60c4b47780 10 client.4182 send_request rebuilding request 61545 for mds.0
  -222> 2014-03-24 11:43:52.262989 7f60c4b47780 20 client.4182 encode_cap_releases enter (req: 0x328b440, mds: 0)
  -221> 2014-03-24 11:43:52.262990 7f60c4b47780 20 client.4182 send_request set sent_stamp to 2014-03-24 11:43:52.262990
  -220> 2014-03-24 11:43:52.262993 7f60c4b47780 10 client.4182 send_request client_request(unknown.0:61545 lookup #1/nova) v1 to mds.0
  -219> 2014-03-24 11:43:52.262996 7f60c4b47780  1 -- 10.2.0.252:0/8255 --> 10.2.0.253:6809/8355 -- client_request(client.4182:61545 lookup #1/nova) v1 -- ?+0 0x6e2aa80 con 0x4b93f40
  -218> 2014-03-24 11:43:52.263005 7f60c4b47780 20 client.4182 awaiting reply|forward|kick on 0x7fffee9415d0
  -217> 2014-03-24 11:43:52.263065 7f60bd625700 10 client.4182 put_inode on 1.head(ref=5 cap_refs={} open={} mode=40755 size=0 mtime=2014-03-24 11:43:36.551490 caps=pAsLsXsFs(0=pAsLsXsFs) has_dir_layout 0x31b1b00)
  -216> 2014-03-24 11:43:52.263721 7f60bd625700  1 -- 10.2.0.252:0/8255 <== mds.0 10.2.0.253:6809/8355 211013 ==== client_reply(???:61545 = 0 Success) v1 ==== 579+0+0 (3058164751 0 0) 0x38823c0 con 0x4b93f40
  -215> 2014-03-24 11:43:52.263755 7f60bd625700 20 client.4182 handle_client_reply got a reply. Safe:1 tid 61545
  -214> 2014-03-24 11:43:52.263760 7f60bd625700 10 client.4182 insert_trace from 2014-03-24 11:43:52.262990 mds.0 is_target=1 is_dentry=1
  -213> 2014-03-24 11:43:52.263766 7f60bd625700 10 client.4182  features 0x7ffffffff
  -212> 2014-03-24 11:43:52.263768 7f60bd625700 10 client.4182 update_snap_trace len 48
  -211> 2014-03-24 11:43:52.263770 7f60bd625700 20 client.4182 get_snap_realm 1 0x32149f0 16398 -> 16399
  -210> 2014-03-24 11:43:52.263773 7f60bd625700 10 client.4182 update_snap_trace snaprealm(1 nref=16399 c=0 seq=1 parent=0 my_snaps=[] cached_snapc=1=[]) seq 1 <= 1 and same parent, SKIPPING
  -209> 2014-03-24 11:43:52.263778 7f60bd625700 20 client.4182 put_snap_realm 1 0x32149f0 16399 -> 16398
  -208> 2014-03-24 11:43:52.263780 7f60bd625700 10 client.4182  hrm  is_target=1 is_dentry=1
  -207> 2014-03-24 11:43:52.263785 7f60bd625700 12 client.4182 add_update_inode had 1000000b85e.head(ref=3 cap_refs={} open={} mode=40755 size=0 mtime=2014-03-24 11:43:06.150385 caps=pAsLsXsFs(0=pAsLsXsFs) parents=0x31c9420 0x31b3600) caps pAsLsXsFs
  -206> 2014-03-24 11:43:52.263800 7f60bd625700 20 client.4182  dir hash is 2
  -205> 2014-03-24 11:43:52.263802 7f60bd625700 10 client.4182 update_inode_file_bits 1000000b85e.head(ref=3 cap_refs={} open={} mode=40755 size=0 mtime=2014-03-24 11:43:06.150385 caps=pAsLsXsFs(0=pAsLsXsFs) parents=0x31c9420 0x31b3600) pAsLsXsFs mtime 2014-03-24 11:43:06.150385
  -204> 2014-03-24 11:43:52.263817 7f60bd625700 10 client.4182 add_update_cap issued pAsLsXsFs -> pAsLsXsFs from mds.0 on 1000000b85e.head(ref=3 cap_refs={} open={} mode=40755 size=0 mtime=2014-03-24 11:43:06.150385 caps=pAsLsXsFs(0=pAsLsXsFs) parents=0x31c9420 0x31b3600)
  -203> 2014-03-24 11:43:52.263831 7f60bd625700 12 client.4182 add_update_inode had 1.head(ref=4 cap_refs={} open={} mode=40755 size=0 mtime=2014-03-24 11:43:36.551490 caps=pAsLsXsFs(0=pAsLsXsFs) has_dir_layout 0x31b1b00) caps pAsLsXsFs
  -202> 2014-03-24 11:43:52.263842 7f60bd625700 10 client.4182 add_update_cap issued pAsLsXsFs -> pAsLsXsFs from mds.0 on 1.head(ref=4 cap_refs={} open={} mode=40755 size=0 mtime=2014-03-24 11:43:36.551490 caps=pAsLsXsFs(0=pAsLsXsFs) has_dir_layout 0x31b1b00)
  -201> 2014-03-24 11:43:52.263854 7f60bd625700 20 client.4182 got dirfrag map for 1 frag * to mds 0
  -200> 2014-03-24 11:43:52.263858 7f60bd625700 12 client.4182 insert_dentry_inode 'nova' vino 1000000b85e.head in dir 1.head dn 0x31c9420
  -199> 2014-03-24 11:43:52.263864 7f60bd625700 12 client.4182  had dentry nova with correct vino 1000000b85e.head
  -198> 2014-03-24 11:43:52.263867 7f60bd625700 20 client.4182 handle_client_reply signalling caller 0x7fffee9415d0
  -197> 2014-03-24 11:43:52.263870 7f60bd625700 20 client.4182 handle_client_reply awaiting kickback on tid 61545 0x7f60bd624850
  -196> 2014-03-24 11:43:52.263919 7f60c4b47780 20 client.4182 sendrecv kickback on tid 61545 0x7f60bd624850
  -195> 2014-03-24 11:43:52.263928 7f60c4b47780 20 client.4182 make_request target is 1000000b85e.head(ref=3 cap_refs={} open={} mode=40755 size=0 mtime=2014-03-24 11:43:06.150385 caps=pAsLsXsFs(0=pAsLsXsFs) parents=0x31c9420 0x31b3600)
  -194> 2014-03-24 11:43:52.263942 7f60c4b47780 20 client.4182 lat 0.000952
  -193> 2014-03-24 11:43:52.263945 7f60c4b47780 10 client.4182 _do_lookup res is 0
  -192> 2014-03-24 11:43:52.263947 7f60c4b47780 10 client.4182 _lookup 1.head(ref=4 cap_refs={} open={} mode=40755 size=0 mtime=2014-03-24 11:43:36.551490 caps=pAsLsXsFs(0=pAsLsXsFs) has_dir_layout 0x31b1b00) nova = 1000000b85e.head(ref=3 cap_refs={} open={} mode=40755 size=0 mtime=2014-03-24 11:43:06.150385 caps=pAsLsXsFs(0=pAsLsXsFs) parents=0x31c9420 0x31b3600)
  -191> 2014-03-24 11:43:52.263960 7f60c4b47780 10 client.4182 fill_stat on 1000000b85e snap/devhead mode 040755 mtime 2014-03-24 11:43:06.150385 ctime 2014-03-24 11:43:06.150385
  -190> 2014-03-24 11:43:52.263965 7f60c4b47780 20 client.4182 _ll_get 0x31b3600 1000000b85e -> 37254
  -189> 2014-03-24 11:43:52.263967 7f60c4b47780  3 client.4182 ll_lookup 1.head nova -> 0 (1000000b85e)
  -188> 2014-03-24 11:43:52.263975 7f60bd625700 10 client.4182 put_inode on 1.head(ref=4 cap_refs={} open={} mode=40755 size=0 mtime=2014-03-24 11:43:36.551490 caps=pAsLsXsFs(0=pAsLsXsFs) has_dir_layout 0x31b1b00)
  -187> 2014-03-24 11:43:52.264046 7f60c4b47780  3 client.4182 ll_getattr 1000000b85e.head
  -186> 2014-03-24 11:43:52.264059 7f60c4b47780 10 client.4182 _getattr mask pAsLsXsFs issued=1
  -185> 2014-03-24 11:43:52.264068 7f60c4b47780 10 client.4182 fill_stat on 1000000b85e snap/devhead mode 040755 mtime 2014-03-24 11:43:06.150385 ctime 2014-03-24 11:43:06.150385
  -184> 2014-03-24 11:43:52.264074 7f60c4b47780  3 client.4182 ll_getattr 1000000b85e.head = 0
  -183> 2014-03-24 11:43:52.264174 7f60c4b47780  3 client.4182 ll_lookup 1000000b85e.head _base
  -182> 2014-03-24 11:43:52.264185 7f60c4b47780 20 client.4182 _lookup have dn _base mds.-1 ttl 0.000000 seq 0
  -181> 2014-03-24 11:43:52.264188 7f60c4b47780 10 client.4182 _lookup 1000000b85e.head(ref=3 cap_refs={} open={} mode=40755 size=0 mtime=2014-03-24 11:43:06.150385 caps=pAsLsXsFs(0=pAsLsXsFs) parents=0x31c9420 0x31b3600) _base = 100000079dd.head(ref=3 cap_refs={} open={} mode=40755 size=0 mtime=2014-03-24 11:43:30.027290 caps=pAsLsXsFs(0=pAsLsXsFs) parents=0x35d6f90 0x8ac5580)
  -180> 2014-03-24 11:43:52.264204 7f60c4b47780 10 client.4182 fill_stat on 100000079dd snap/devhead mode 040755 mtime 2014-03-24 11:43:30.027290 ctime 2014-03-24 11:43:30.027290
  -179> 2014-03-24 11:43:52.264209 7f60c4b47780 20 client.4182 _ll_get 0x8ac5580 100000079dd -> 4446
  -178> 2014-03-24 11:43:52.264211 7f60c4b47780  3 client.4182 ll_lookup 1000000b85e.head _base -> 0 (100000079dd)
  -177> 2014-03-24 11:43:52.264232 7f60c4b47780  3 client.4182 ll_getattr 100000079dd.head
  -176> 2014-03-24 11:43:52.264236 7f60c4b47780 10 client.4182 _getattr mask pAsLsXsFs issued=1
  -175> 2014-03-24 11:43:52.264239 7f60c4b47780 10 client.4182 fill_stat on 100000079dd snap/devhead mode 040755 mtime 2014-03-24 11:43:30.027290 ctime 2014-03-24 11:43:30.027290
  -174> 2014-03-24 11:43:52.264243 7f60c4b47780  3 client.4182 ll_getattr 100000079dd.head = 0
  -173> 2014-03-24 11:43:52.264271 7f60c4b47780  3 client.4182 ll_getattr 100000079dd.head
  -172> 2014-03-24 11:43:52.264276 7f60c4b47780 10 client.4182 _getattr mask pAsLsXsFs issued=1
  -171> 2014-03-24 11:43:52.264279 7f60c4b47780 10 client.4182 fill_stat on 100000079dd snap/devhead mode 040755 mtime 2014-03-24 11:43:30.027290 ctime 2014-03-24 11:43:30.027290
  -170> 2014-03-24 11:43:52.264286 7f60c4b47780  3 client.4182 ll_getattr 100000079dd.head = 0
  -169> 2014-03-24 11:43:52.264310 7f60c4b47780  3 client.4182 ll_lookup 100000079dd.head c623a396d7f454cd0a82aae8e67d909e14ac73c6.part
  -168> 2014-03-24 11:43:52.264316 7f60c4b47780 20 client.4182 _lookup have dn c623a396d7f454cd0a82aae8e67d909e14ac73c6.part mds.0 ttl 2014-03-24 11:43:36.397976 seq 1944
  -167> 2014-03-24 11:43:52.264322 7f60c4b47780 10 client.4182 _do_lookup on #100000079dd/c623a396d7f454cd0a82aae8e67d909e14ac73c6.part
  -166> 2014-03-24 11:43:52.264325 7f60c4b47780 20 client.4182 choose_target_mds starting with req->inode 100000079dd.head(ref=4 cap_refs={} open={} mode=40755 size=0 mtime=2014-03-24 11:43:30.027290 caps=pAsLsXsFs(0=pAsLsXsFs) parents=0x35d6f90 0x8ac5580)
  -165> 2014-03-24 11:43:52.264332 7f60c4b47780 20 client.4182 choose_target_mds inode dir hash is 2 on c623a396d7f454cd0a82aae8e67d909e14ac73c6.part => 1777206007
  -164> 2014-03-24 11:43:52.264334 7f60c4b47780 20 client.4182 choose_target_mds 100000079dd.head(ref=4 cap_refs={} open={} mode=40755 size=0 mtime=2014-03-24 11:43:30.027290 caps=pAsLsXsFs(0=pAsLsXsFs) parents=0x35d6f90 0x8ac5580) is_hash=1 hash=1777206007
  -163> 2014-03-24 11:43:52.264340 7f60c4b47780 10 client.4182 choose_target_mds from caps on inode 100000079dd.head(ref=4 cap_refs={} open={} mode=40755 size=0 mtime=2014-03-24 11:43:30.027290 caps=pAsLsXsFs(0=pAsLsXsFs) parents=0x35d6f90 0x8ac5580)
  -162> 2014-03-24 11:43:52.264348 7f60c4b47780 20 client.4182 mds is 0
  -161> 2014-03-24 11:43:52.264350 7f60c4b47780 10 client.4182 send_request rebuilding request 61546 for mds.0
  -160> 2014-03-24 11:43:52.264353 7f60c4b47780 20 client.4182 encode_cap_releases enter (req: 0x3883440, mds: 0)
  -159> 2014-03-24 11:43:52.264354 7f60c4b47780 20 client.4182 send_request set sent_stamp to 2014-03-24 11:43:52.264354
  -158> 2014-03-24 11:43:52.264356 7f60c4b47780 10 client.4182 send_request client_request(unknown.0:61546 lookup #100000079dd/c623a396d7f454cd0a82aae8e67d909e14ac73c6.part) v1 to mds.0
  -157> 2014-03-24 11:43:52.264358 7f60c4b47780  1 -- 10.2.0.252:0/8255 --> 10.2.0.253:6809/8355 -- client_request(client.4182:61546 lookup #100000079dd/c623a396d7f454cd0a82aae8e67d909e14ac73c6.part) v1 -- ?+0 0x6e29400 con 0x4b93f40
  -156> 2014-03-24 11:43:52.264368 7f60c4b47780 20 client.4182 awaiting reply|forward|kick on 0x7fffee9415d0
  -155> 2014-03-24 11:43:52.265166 7f60bd625700  1 -- 10.2.0.252:0/8255 <== mds.0 10.2.0.253:6809/8355 211014 ==== client_reply(???:61546 = 0 Success) v1 ==== 620+0+0 (965891109 0 0) 0x328c780 con 0x4b93f40
  -154> 2014-03-24 11:43:52.265186 7f60bd625700 20 client.4182 handle_client_reply got a reply. Safe:1 tid 61546
  -153> 2014-03-24 11:43:52.265189 7f60bd625700 10 client.4182 insert_trace from 2014-03-24 11:43:52.264354 mds.0 is_target=1 is_dentry=1
  -152> 2014-03-24 11:43:52.265193 7f60bd625700 10 client.4182  features 0x7ffffffff
  -151> 2014-03-24 11:43:52.265194 7f60bd625700 10 client.4182 update_snap_trace len 48
  -150> 2014-03-24 11:43:52.265196 7f60bd625700 20 client.4182 get_snap_realm 1 0x32149f0 16398 -> 16399
  -149> 2014-03-24 11:43:52.265198 7f60bd625700 10 client.4182 update_snap_trace snaprealm(1 nref=16399 c=0 seq=1 parent=0 my_snaps=[] cached_snapc=1=[]) seq 1 <= 1 and same parent, SKIPPING
  -148> 2014-03-24 11:43:52.265201 7f60bd625700 20 client.4182 put_snap_realm 1 0x32149f0 16399 -> 16398
  -147> 2014-03-24 11:43:52.265202 7f60bd625700 10 client.4182  hrm  is_target=1 is_dentry=1
  -146> 2014-03-24 11:43:52.265206 7f60bd625700 12 client.4182 add_update_inode had 1000000beb5.head(ref=2 cap_refs={1024=1,2048=0,4096=0,8192=0} open={1=0,2=0} mode=100644 size=1039335424 mtime=2014-03-24 11:43:28.314490 caps=pAsLsXsFsxcrwb(0=pAsLsXsFsxcrwb) objectset[1000000beb5 ts 0/0 objects 248 dirty_or_tx 0] parents=0x6edaed0 0x80b2880) caps pAsLsXsFsxcrwb
  -145> 2014-03-24 11:43:52.265218 7f60bd625700 10 client.4182 update_inode_file_bits 1000000beb5.head(ref=2 cap_refs={1024=1,2048=0,4096=0,8192=0} open={1=0,2=0} mode=100644 size=1039335424 mtime=2014-03-24 11:43:28.314490 caps=pAsLsXsFsxcrwb(0=pAsLsXsFsxcrwb) objectset[1000000beb5 ts 0/0 objects 248 dirty_or_tx 0] parents=0x6edaed0 0x80b2880) pAsLsXsFsxcrwb mtime 2014-03-24 11:43:28.314490
  -144> 2014-03-24 11:43:52.265233 7f60bd625700 10 client.4182 add_update_cap issued pAsLsXsFsxcrwb -> pAsLsXsFsxcrwb from mds.0 on 1000000beb5.head(ref=2 cap_refs={1024=1,2048=0,4096=0,8192=0} open={1=0,2=0} mode=100644 size=1039335424 mtime=2014-03-24 11:43:28.314490 caps=pAsLsXsFsxcrwb(0=pAsLsXsFsxcrwb) objectset[1000000beb5 ts 0/0 objects 248 dirty_or_tx 0] parents=0x6edaed0 0x80b2880)
  -143> 2014-03-24 11:43:52.265243 7f60bd625700 12 client.4182 add_update_inode had 100000079dd.head(ref=4 cap_refs={} open={} mode=40755 size=0 mtime=2014-03-24 11:43:30.027290 caps=pAsLsXsFs(0=pAsLsXsFs) parents=0x35d6f90 0x8ac5580) caps pAsLsXsFs
  -142> 2014-03-24 11:43:52.265262 7f60bd625700 20 client.4182  dir hash is 2
  -141> 2014-03-24 11:43:52.265263 7f60bd625700 10 client.4182 update_inode_file_bits 100000079dd.head(ref=4 cap_refs={} open={} mode=40755 size=0 mtime=2014-03-24 11:43:30.027290 caps=pAsLsXsFs(0=pAsLsXsFs) parents=0x35d6f90 0x8ac5580) pAsLsXsFs mtime 2014-03-24 11:43:30.027290
  -140> 2014-03-24 11:43:52.265271 7f60bd625700 10 client.4182 add_update_cap issued pAsLsXsFs -> pAsLsXsFs from mds.0 on 100000079dd.head(ref=4 cap_refs={} open={} mode=40755 size=0 mtime=2014-03-24 11:43:30.027290 caps=pAsLsXsFs(0=pAsLsXsFs) parents=0x35d6f90 0x8ac5580)
  -139> 2014-03-24 11:43:52.265277 7f60bd625700 20 client.4182 got dirfrag map for 100000079dd frag * to mds -1
  -138> 2014-03-24 11:43:52.265279 7f60bd625700 12 client.4182 insert_dentry_inode 'c623a396d7f454cd0a82aae8e67d909e14ac73c6.part' vino 1000000beb5.head in dir 100000079dd.head dn 0x6edaed0
  -137> 2014-03-24 11:43:52.265281 7f60bd625700 12 client.4182  had dentry c623a396d7f454cd0a82aae8e67d909e14ac73c6.part with correct vino 1000000beb5.head
  -136> 2014-03-24 11:43:52.265283 7f60bd625700 20 client.4182 handle_client_reply signalling caller 0x7fffee9415d0
  -135> 2014-03-24 11:43:52.265286 7f60bd625700 20 client.4182 handle_client_reply awaiting kickback on tid 61546 0x7f60bd624850
  -134> 2014-03-24 11:43:52.265339 7f60c4b47780 20 client.4182 sendrecv kickback on tid 61546 0x7f60bd624850
  -133> 2014-03-24 11:43:52.265345 7f60c4b47780 20 client.4182 make_request target is 1000000beb5.head(ref=2 cap_refs={1024=1,2048=0,4096=0,8192=0} open={1=0,2=0} mode=100644 size=1039335424 mtime=2014-03-24 11:43:28.314490 caps=pAsLsXsFsxcrwb(0=pAsLsXsFsxcrwb) objectset[1000000beb5 ts 0/0 objects 248 dirty_or_tx 0] parents=0x6edaed0 0x80b2880)
  -132> 2014-03-24 11:43:52.265361 7f60c4b47780 20 client.4182 lat 0.001007
  -131> 2014-03-24 11:43:52.265363 7f60c4b47780 10 client.4182 _do_lookup res is 0
  -130> 2014-03-24 11:43:52.265365 7f60c4b47780 10 client.4182 _lookup 100000079dd.head(ref=4 cap_refs={} open={} mode=40755 size=0 mtime=2014-03-24 11:43:30.027290 caps=pAsLsXsFs(0=pAsLsXsFs) parents=0x35d6f90 0x8ac5580) c623a396d7f454cd0a82aae8e67d909e14ac73c6.part = 1000000beb5.head(ref=2 cap_refs={1024=1,2048=0,4096=0,8192=0} open={1=0,2=0} mode=100644 size=1039335424 mtime=2014-03-24 11:43:28.314490 caps=pAsLsXsFsxcrwb(0=pAsLsXsFsxcrwb) objectset[1000000beb5 ts 0/0 objects 248 dirty_or_tx 0] parents=0x6edaed0 0x80b2880)
  -129> 2014-03-24 11:43:52.265379 7f60c4b47780 10 client.4182 fill_stat on 1000000beb5 snap/devhead mode 0100644 mtime 2014-03-24 11:43:28.314490 ctime 2014-03-24 11:43:06.399097
  -128> 2014-03-24 11:43:52.265383 7f60c4b47780 20 client.4182 _ll_get 0x80b2880 1000000beb5 -> 15
  -127> 2014-03-24 11:43:52.265384 7f60c4b47780  3 client.4182 ll_lookup 100000079dd.head c623a396d7f454cd0a82aae8e67d909e14ac73c6.part -> 0 (1000000beb5)
  -126> 2014-03-24 11:43:52.265391 7f60bd625700 10 client.4182 put_inode on 100000079dd.head(ref=4 cap_refs={} open={} mode=40755 size=0 mtime=2014-03-24 11:43:30.027290 caps=pAsLsXsFs(0=pAsLsXsFs) parents=0x35d6f90 0x8ac5580)
  -125> 2014-03-24 11:43:52.265502 7f60c4b47780  3 client.4182 ll_getattr 100000079dd.head
  -124> 2014-03-24 11:43:52.265516 7f60c4b47780 10 client.4182 _getattr mask pAsLsXsFs issued=1
  -123> 2014-03-24 11:43:52.265525 7f60c4b47780 10 client.4182 fill_stat on 100000079dd snap/devhead mode 040755 mtime 2014-03-24 11:43:30.027290 ctime 2014-03-24 11:43:30.027290
  -122> 2014-03-24 11:43:52.265532 7f60c4b47780  3 client.4182 ll_getattr 100000079dd.head = 0
  -121> 2014-03-24 11:43:52.265669 7f60c4b47780  3 client.4182 ll_unlink 100000079dd.head c623a396d7f454cd0a82aae8e67d909e14ac73c6.part
  -120> 2014-03-24 11:43:52.265685 7f60c4b47780  3 client.4182 _unlink(100000079dd c623a396d7f454cd0a82aae8e67d909e14ac73c6.part uid 162 gid 162)
  -119> 2014-03-24 11:43:52.265692 7f60c4b47780 20 client.4182 get_or_create 100000079dd.head(ref=3 cap_refs={} open={} mode=40755 size=0 mtime=2014-03-24 11:43:30.027290 caps=pAsLsXsFs(0=pAsLsXsFs) parents=0x35d6f90 0x8ac5580) name c623a396d7f454cd0a82aae8e67d909e14ac73c6.part
  -118> 2014-03-24 11:43:52.265709 7f60c4b47780 20 client.4182 _lookup have dn c623a396d7f454cd0a82aae8e67d909e14ac73c6.part mds.0 ttl 2014-03-24 11:43:36.397976 seq 1944
  -117> 2014-03-24 11:43:52.265713 7f60c4b47780 10 client.4182 _lookup 100000079dd.head(ref=3 cap_refs={} open={} mode=40755 size=0 mtime=2014-03-24 11:43:30.027290 caps=pAsLsXsFs(0=pAsLsXsFs) parents=0x35d6f90 0x8ac5580) c623a396d7f454cd0a82aae8e67d909e14ac73c6.part = 1000000beb5.head(ref=2 cap_refs={1024=1,2048=0,4096=0,8192=0} open={1=0,2=0} mode=100644 size=1039335424 mtime=2014-03-24 11:43:28.314490 caps=pAsLsXsFsxcrwb(0=pAsLsXsFsxcrwb) objectset[1000000beb5 ts 0/0 objects 248 dirty_or_tx 0] parents=0x6edaed0 0x80b2880)
  -116> 2014-03-24 11:43:52.265727 7f60c4b47780 20 client.4182 choose_target_mds starting with req->inode 100000079dd.head(ref=4 cap_refs={} open={} mode=40755 size=0 mtime=2014-03-24 11:43:30.027290 caps=pAsLsXsFs(0=pAsLsXsFs) parents=0x35d6f90 0x8ac5580)
  -115> 2014-03-24 11:43:52.265734 7f60c4b47780 20 client.4182 choose_target_mds inode dir hash is 2 on c623a396d7f454cd0a82aae8e67d909e14ac73c6.part => 1777206007
  -114> 2014-03-24 11:43:52.265735 7f60c4b47780 20 client.4182 choose_target_mds 100000079dd.head(ref=4 cap_refs={} open={} mode=40755 size=0 mtime=2014-03-24 11:43:30.027290 caps=pAsLsXsFs(0=pAsLsXsFs) parents=0x35d6f90 0x8ac5580) is_hash=1 hash=1777206007
  -113> 2014-03-24 11:43:52.265741 7f60c4b47780 10 client.4182 choose_target_mds from caps on inode 100000079dd.head(ref=4 cap_refs={} open={} mode=40755 size=0 mtime=2014-03-24 11:43:30.027290 caps=pAsLsXsFs(0=pAsLsXsFs) parents=0x35d6f90 0x8ac5580)
  -112> 2014-03-24 11:43:52.265746 7f60c4b47780 20 client.4182 mds is 0
  -111> 2014-03-24 11:43:52.265747 7f60c4b47780 10 client.4182 send_request rebuilding request 61547 for mds.0
  -110> 2014-03-24 11:43:52.265753 7f60c4b47780 20 client.4182 encode_cap_releases enter (req: 0x3289e40, mds: 0)
  -109> 2014-03-24 11:43:52.265755 7f60c4b47780 20 client.4182 encode_inode_release enter(in:1000000beb5.head(ref=3 cap_refs={1024=1,2048=0,4096=0,8192=0} open={1=0,2=0} mode=100644 size=1039335424 mtime=2014-03-24 11:43:28.314490 caps=pAsLsXsFsxcrwb(0=pAsLsXsFsxcrwb) objectset[1000000beb5 ts 0/0 objects 248 dirty_or_tx 0] parents=0x6edaed0 0x80b2880), req:0x3289e40 mds:0, drop:48, unless:0, have:, force:0)
  -108> 2014-03-24 11:43:52.265765 7f60c4b47780 20 client.4182 encode_dentry_release enter(dn:0x6edaed0)
  -107> 2014-03-24 11:43:52.265767 7f60c4b47780 20 client.4182 encode_inode_release enter(in:100000079dd.head(ref=4 cap_refs={} open={} mode=40755 size=0 mtime=2014-03-24 11:43:30.027290 caps=pAsLsXsFs(0=pAsLsXsFs) parents=0x35d6f90 0x8ac5580), req:0x3289e40 mds:0, drop:256, unless:512, have:, force:1)
  -106> 2014-03-24 11:43:52.265773 7f60c4b47780 20 client.4182 send_request set sent_stamp to 2014-03-24 11:43:52.265773
  -105> 2014-03-24 11:43:52.265775 7f60c4b47780 10 client.4182 send_request client_request(unknown.0:61547 unlink #100000079dd/c623a396d7f454cd0a82aae8e67d909e14ac73c6.part) v1 to mds.0
  -104> 2014-03-24 11:43:52.265778 7f60c4b47780  1 -- 10.2.0.252:0/8255 --> 10.2.0.253:6809/8355 -- client_request(client.4182:61547 unlink #100000079dd/c623a396d7f454cd0a82aae8e67d909e14ac73c6.part) v1 -- ?+0 0x6e28f00 con 0x4b93f40
  -103> 2014-03-24 11:43:52.265789 7f60c4b47780 20 client.4182 awaiting reply|forward|kick on 0x7fffee941810
  -102> 2014-03-24 11:43:52.266473 7f60bd625700  1 -- 10.2.0.252:0/8255 <== mds.0 10.2.0.253:6809/8355 211015 ==== client_reply(???:61547 = 0 Success unsafe) v1 ==== 383+0+0 (1429905447 0 0) 0x390e880 con 0x4b93f40
  -101> 2014-03-24 11:43:52.266491 7f60bd625700 20 client.4182 handle_client_reply got a reply. Safe:0 tid 61547
  -100> 2014-03-24 11:43:52.266493 7f60bd625700 10 client.4182 insert_trace from 2014-03-24 11:43:52.265773 mds.0 is_target=0 is_dentry=1
   -99> 2014-03-24 11:43:52.266496 7f60bd625700 10 client.4182  features 0x7ffffffff
   -98> 2014-03-24 11:43:52.266497 7f60bd625700 10 client.4182 update_snap_trace len 48
   -97> 2014-03-24 11:43:52.266499 7f60bd625700 20 client.4182 get_snap_realm 1 0x32149f0 16398 -> 16399
   -96> 2014-03-24 11:43:52.266500 7f60bd625700 10 client.4182 update_snap_trace snaprealm(1 nref=16399 c=0 seq=1 parent=0 my_snaps=[] cached_snapc=1=[]) seq 1 <= 1 and same parent, SKIPPING
   -95> 2014-03-24 11:43:52.266503 7f60bd625700 20 client.4182 put_snap_realm 1 0x32149f0 16399 -> 16398
   -94> 2014-03-24 11:43:52.266504 7f60bd625700 10 client.4182  hrm  is_target=0 is_dentry=1
   -93> 2014-03-24 11:43:52.266507 7f60bd625700 12 client.4182 add_update_inode had 100000079dd.head(ref=4 cap_refs={} open={} mode=40755 size=0 mtime=2014-03-24 11:43:30.027290 caps=pAsLsXs(0=pAsLsXs) parents=0x35d6f90 0x8ac5580) caps pAsLsXs
   -92> 2014-03-24 11:43:52.266514 7f60bd625700 20 client.4182  dir hash is 2
   -91> 2014-03-24 11:43:52.266515 7f60bd625700 10 client.4182 update_inode_file_bits 100000079dd.head(ref=4 cap_refs={} open={} mode=40755 size=0 mtime=2014-03-24 11:43:30.027290 caps=pAsLsXs(0=pAsLsXs) parents=0x35d6f90 0x8ac5580) pAsLsXs mtime 2014-03-24 11:43:30.027290
   -90> 2014-03-24 11:43:52.266522 7f60bd625700 10 client.4182 add_update_cap issued pAsLsXs -> pAsLsXs from mds.0 on 100000079dd.head(ref=4 cap_refs={} open={} mode=40755 size=0 mtime=2014-03-24 11:43:30.027290 caps=pAsLsXs(0=pAsLsXs) parents=0x35d6f90 0x8ac5580)
   -89> 2014-03-24 11:43:52.266528 7f60bd625700 20 client.4182 got dirfrag map for 100000079dd frag * to mds -1
   -88> 2014-03-24 11:43:52.266531 7f60bd625700 15 client.4182 unlink dir 0x8ac5580 'c623a396d7f454cd0a82aae8e67d909e14ac73c6.part' dn 0x6edaed0 inode 0x80b2880
   -87> 2014-03-24 11:43:52.266533 7f60bd625700 20 client.4182 unlink  inode 0x80b2880 parents now 
   -86> 2014-03-24 11:43:52.266538 7f60bd625700 10 client.4182 put_inode on 1000000beb5.head(ref=3 cap_refs={1024=1,2048=0,4096=0,8192=0} open={1=0,2=0} mode=100644 size=1039335424 mtime=2014-03-24 11:43:28.314490 caps=pAsXsFsxcrwb(0=pAsXsFsxcrwb) objectset[1000000beb5 ts 0/0 objects 248 dirty_or_tx 0] 0x80b2880)
   -85> 2014-03-24 11:43:52.266548 7f60bd625700 20 client.4182 handle_client_reply signalling caller 0x7fffee941810
   -84> 2014-03-24 11:43:52.266551 7f60bd625700 20 client.4182 handle_client_reply awaiting kickback on tid 61547 0x7f60bd624850
   -83> 2014-03-24 11:43:52.266594 7f60c4b47780 20 client.4182 sendrecv kickback on tid 61547 0x7f60bd624850
   -82> 2014-03-24 11:43:52.266600 7f60c4b47780 20 client.4182 lat 0.000827
   -81> 2014-03-24 11:43:52.266604 7f60c4b47780 10 client.4182 unlink result is 0
   -80> 2014-03-24 11:43:52.266605 7f60c4b47780 20 client.4182 trim_cache size 16383 max 16384
   -79> 2014-03-24 11:43:52.266607 7f60c4b47780  3 client.4182 unlink(#100000079dd/c623a396d7f454cd0a82aae8e67d909e14ac73c6.part) = 0
   -78> 2014-03-24 11:43:52.307915 7f60bd625700  1 -- 10.2.0.252:0/8255 <== osd.2 10.2.0.252:6800/7128 257 ==== osd_op_reply(72681 1000000beb6.00000428 [write 0~4194304] ondisk = 0) v4 ==== 119+0+0 (892597262 0 0) 0x4c83800 con 0x3259340
   -77> 2014-03-24 11:43:52.343043 7f60c4b47780  3 client.4182 ll_forget 1000000beb5.head 15
   -76> 2014-03-24 11:43:52.343057 7f60c4b47780 20 client.4182 _ll_put 0x80b2880 1000000beb5 15 -> 0
   -75> 2014-03-24 11:43:52.343062 7f60c4b47780 10 client.4182 put_inode on 1000000beb5.head(ref=2 cap_refs={1024=1,2048=0,4096=0,8192=0} open={1=0,2=0} mode=100644 size=1039335424 mtime=2014-03-24 11:43:28.314490 caps=pAsXsFsxcrwb(0=pAsXsFsxcrwb) objectset[1000000beb5 ts 0/0 objects 248 dirty_or_tx 0] 0x80b2880)
   -74> 2014-03-24 11:43:52.343092 7f60c4b47780  3 client.4182 ll_getattr 1.head
   -73> 2014-03-24 11:43:52.343098 7f60c4b47780 10 client.4182 _getattr mask pAsLsXsFs issued=1
   -72> 2014-03-24 11:43:52.343103 7f60c4b47780 10 client.4182 fill_stat on 1 snap/devhead mode 040755 mtime 2014-03-24 11:43:36.551490 ctime 2014-03-24 11:43:36.551490
   -71> 2014-03-24 11:43:52.343123 7f60c4b47780  3 client.4182 ll_getattr 1.head = 0
   -70> 2014-03-24 11:43:52.343157 7f60c4b47780  3 client.4182 ll_lookup 1.head nova
   -69> 2014-03-24 11:43:52.343164 7f60c4b47780 20 client.4182 _lookup have dn nova mds.0 ttl 2014-03-23 04:38:47.878264 seq 1545
   -68> 2014-03-24 11:43:52.343167 7f60c4b47780 10 client.4182 _lookup 1.head(ref=3 cap_refs={} open={} mode=40755 size=0 mtime=2014-03-24 11:43:36.551490 caps=pAsLsXsFs(0=pAsLsXsFs) has_dir_layout 0x31b1b00) nova = 1000000b85e.head(ref=3 cap_refs={} open={} mode=40755 size=0 mtime=2014-03-24 11:43:06.150385 caps=pAsLsXsFs(0=pAsLsXsFs) parents=0x31c9420 0x31b3600)
   -67> 2014-03-24 11:43:52.343179 7f60c4b47780 10 client.4182 fill_stat on 1000000b85e snap/devhead mode 040755 mtime 2014-03-24 11:43:06.150385 ctime 2014-03-24 11:43:06.150385
   -66> 2014-03-24 11:43:52.343182 7f60c4b47780 20 client.4182 _ll_get 0x31b3600 1000000b85e -> 37255
   -65> 2014-03-24 11:43:52.343184 7f60c4b47780  3 client.4182 ll_lookup 1.head nova -> 0 (1000000b85e)
   -64> 2014-03-24 11:43:52.343196 7f60c4b47780  3 client.4182 ll_getattr 1000000b85e.head
   -63> 2014-03-24 11:43:52.343200 7f60c4b47780 10 client.4182 _getattr mask pAsLsXsFs issued=1
   -62> 2014-03-24 11:43:52.343202 7f60c4b47780 10 client.4182 fill_stat on 1000000b85e snap/devhead mode 040755 mtime 2014-03-24 11:43:06.150385 ctime 2014-03-24 11:43:06.150385
   -61> 2014-03-24 11:43:52.343205 7f60c4b47780  3 client.4182 ll_getattr 1000000b85e.head = 0
   -60> 2014-03-24 11:43:52.343220 7f60c4b47780  3 client.4182 ll_lookup 1000000b85e.head _base
   -59> 2014-03-24 11:43:52.343222 7f60c4b47780 20 client.4182 _lookup have dn _base mds.-1 ttl 0.000000 seq 0
   -58> 2014-03-24 11:43:52.343224 7f60c4b47780 10 client.4182 _lookup 1000000b85e.head(ref=3 cap_refs={} open={} mode=40755 size=0 mtime=2014-03-24 11:43:06.150385 caps=pAsLsXsFs(0=pAsLsXsFs) parents=0x31c9420 0x31b3600) _base = 100000079dd.head(ref=4 cap_refs={} open={} mode=40755 size=0 mtime=2014-03-24 11:43:30.027290 caps=pAsLsXs(0=pAsLsXs) parents=0x35d6f90 0x8ac5580)
   -57> 2014-03-24 11:43:52.343235 7f60c4b47780 10 client.4182 fill_stat on 100000079dd snap/devhead mode 040755 mtime 2014-03-24 11:43:30.027290 ctime 2014-03-24 11:43:52.266200
   -56> 2014-03-24 11:43:52.343239 7f60c4b47780 20 client.4182 _ll_get 0x8ac5580 100000079dd -> 4447
   -55> 2014-03-24 11:43:52.343240 7f60c4b47780  3 client.4182 ll_lookup 1000000b85e.head _base -> 0 (100000079dd)
   -54> 2014-03-24 11:43:52.343251 7f60c4b47780  3 client.4182 ll_getattr 100000079dd.head
   -53> 2014-03-24 11:43:52.343252 7f60c4b47780 10 client.4182 _getattr mask pAsLsXsFs issued=0
   -52> 2014-03-24 11:43:52.343257 7f60c4b47780 20 client.4182 choose_target_mds starting with req->inode 100000079dd.head(ref=5 cap_refs={} open={} mode=40755 size=0 mtime=2014-03-24 11:43:30.027290 caps=pAsLsXs(0=pAsLsXs) parents=0x35d6f90 0x8ac5580)
   -51> 2014-03-24 11:43:52.343263 7f60c4b47780 20 client.4182 choose_target_mds 100000079dd.head(ref=5 cap_refs={} open={} mode=40755 size=0 mtime=2014-03-24 11:43:30.027290 caps=pAsLsXs(0=pAsLsXs) parents=0x35d6f90 0x8ac5580) is_hash=0 hash=0
   -50> 2014-03-24 11:43:52.343269 7f60c4b47780 10 client.4182 choose_target_mds from caps on inode 100000079dd.head(ref=5 cap_refs={} open={} mode=40755 size=0 mtime=2014-03-24 11:43:30.027290 caps=pAsLsXs(0=pAsLsXs) parents=0x35d6f90 0x8ac5580)
   -49> 2014-03-24 11:43:52.343274 7f60c4b47780 20 client.4182 mds is 0
   -48> 2014-03-24 11:43:52.343276 7f60c4b47780 10 client.4182 send_request rebuilding request 61548 for mds.0
   -47> 2014-03-24 11:43:52.343278 7f60c4b47780 20 client.4182 encode_cap_releases enter (req: 0x3848b00, mds: 0)
   -46> 2014-03-24 11:43:52.343280 7f60c4b47780 20 client.4182 send_request set sent_stamp to 2014-03-24 11:43:52.343280
   -45> 2014-03-24 11:43:52.343282 7f60c4b47780 10 client.4182 send_request client_request(unknown.0:61548 getattr pAsLsXsFs #100000079dd) v1 to mds.0
   -44> 2014-03-24 11:43:52.343286 7f60c4b47780  1 -- 10.2.0.252:0/8255 --> 10.2.0.253:6809/8355 -- client_request(client.4182:61548 getattr pAsLsXsFs #100000079dd) v1 -- ?+0 0x6e2ee00 con 0x4b93f40
   -43> 2014-03-24 11:43:52.343297 7f60c4b47780 20 client.4182 awaiting reply|forward|kick on 0x7fffee941770
   -42> 2014-03-24 11:43:52.412322 7f60bd625700  1 -- 10.2.0.252:0/8255 <== osd.4 10.2.0.253:6804/8054 271 ==== osd_op_reply(72687 1000000beb6.0000042a [write 0~4194304] ondisk = 0) v4 ==== 119+0+0 (2220781616 0 0) 0x1921a000 con 0x8b26300
   -41> 2014-03-24 11:43:52.414207 7f60bd625700  1 -- 10.2.0.252:0/8255 <== mds.0 10.2.0.253:6809/8355 211016 ==== client_reply(???:61548 = 0 Success) v1 ==== 312+0+0 (1636533857 0 0) 0x3882680 con 0x4b93f40
   -40> 2014-03-24 11:43:52.414230 7f60bd625700 20 client.4182 handle_client_reply got a reply. Safe:1 tid 61548
   -39> 2014-03-24 11:43:52.414235 7f60bd625700 10 client.4182 insert_trace from 2014-03-24 11:43:52.343280 mds.0 is_target=1 is_dentry=0
   -38> 2014-03-24 11:43:52.414240 7f60bd625700 10 client.4182  features 0x7ffffffff
   -37> 2014-03-24 11:43:52.414241 7f60bd625700 10 client.4182 update_snap_trace len 48
   -36> 2014-03-24 11:43:52.414244 7f60bd625700 20 client.4182 get_snap_realm 1 0x32149f0 16398 -> 16399
   -35> 2014-03-24 11:43:52.414247 7f60bd625700 10 client.4182 update_snap_trace snaprealm(1 nref=16399 c=0 seq=1 parent=0 my_snaps=[] cached_snapc=1=[]) seq 1 <= 1 and same parent, SKIPPING
   -34> 2014-03-24 11:43:52.414251 7f60bd625700 20 client.4182 put_snap_realm 1 0x32149f0 16399 -> 16398
   -33> 2014-03-24 11:43:52.414252 7f60bd625700 10 client.4182  hrm  is_target=1 is_dentry=0
   -32> 2014-03-24 11:43:52.414255 7f60bd625700 12 client.4182 add_update_inode had 100000079dd.head(ref=5 cap_refs={} open={} mode=40755 size=0 mtime=2014-03-24 11:43:30.027290 caps=pAsLsXs(0=pAsLsXs) parents=0x35d6f90 0x8ac5580) caps pAsLsXsFs
   -31> 2014-03-24 11:43:52.414265 7f60bd625700 20 client.4182  dir hash is 2
   -30> 2014-03-24 11:43:52.414267 7f60bd625700 10 client.4182 update_inode_file_bits 100000079dd.head(ref=5 cap_refs={} open={} mode=40755 size=0 mtime=2014-03-24 11:43:30.027290 caps=pAsLsXs(0=pAsLsXs) parents=0x35d6f90 0x8ac5580) pAsLsXs mtime 2014-03-24 11:43:52.266200
   -29> 2014-03-24 11:43:52.414275 7f60bd625700 10 client.4182 add_update_cap issued pAsLsXs -> pAsLsXsFs from mds.0 on 100000079dd.head(ref=5 cap_refs={} open={} mode=40755 size=0 mtime=2014-03-24 11:43:52.266200 caps=pAsLsXsFs(0=pAsLsXsFs) parents=0x35d6f90 0x8ac5580)
   -28> 2014-03-24 11:43:52.414283 7f60bd625700 20 client.4182 handle_client_reply signalling caller 0x7fffee941770
   -27> 2014-03-24 11:43:52.414286 7f60bd625700 20 client.4182 handle_client_reply awaiting kickback on tid 61548 0x7f60bd624850
   -26> 2014-03-24 11:43:52.414353 7f60c4b47780 20 client.4182 sendrecv kickback on tid 61548 0x7f60bd624850
   -25> 2014-03-24 11:43:52.414359 7f60c4b47780 20 client.4182 lat 0.071079
   -24> 2014-03-24 11:43:52.414362 7f60c4b47780 10 client.4182 _getattr result=0
   -23> 2014-03-24 11:43:52.414365 7f60c4b47780 10 client.4182 fill_stat on 100000079dd snap/devhead mode 040755 mtime 2014-03-24 11:43:52.266200 ctime 2014-03-24 11:43:52.266200
   -22> 2014-03-24 11:43:52.414371 7f60c4b47780  3 client.4182 ll_getattr 100000079dd.head = 0
   -21> 2014-03-24 11:43:52.414400 7f60c4b47780  3 client.4182 ll_lookup 100000079dd.head c623a396d7f454cd0a82aae8e67d909e14ac73c6.converted
   -20> 2014-03-24 11:43:52.414409 7f60c4b47780 20 client.4182 _lookup have dn c623a396d7f454cd0a82aae8e67d909e14ac73c6.converted mds.0 ttl 2014-03-24 11:44:00.026833 seq 1945
   -19> 2014-03-24 11:43:52.414415 7f60c4b47780 10 client.4182 _lookup 100000079dd.head(ref=5 cap_refs={} open={} mode=40755 size=0 mtime=2014-03-24 11:43:52.266200 caps=pAsLsXsFs(0=pAsLsXsFs) parents=0x35d6f90 0x8ac5580) c623a396d7f454cd0a82aae8e67d909e14ac73c6.converted = 1000000beb6.head(ref=5 cap_refs={4096=0,8192=1} open={1=0,2=0,3=0} mode=100644 size=5368709120 mtime=2014-03-24 11:43:51.883318 caps=pAsxLsXsxFsxcrwb(0=pAsxLsXsxFsxcrwb) dirty_caps=Fw objectset[1000000beb6 ts 0/0 objects 253 dirty_or_tx 47492608] parents=0x6ed96c0 0x80b3a80)
   -18> 2014-03-24 11:43:52.414436 7f60c4b47780 10 client.4182 fill_stat on 1000000beb6 snap/devhead mode 0100644 mtime 2014-03-24 11:43:51.883318 ctime 2014-03-24 11:43:30.028946
   -17> 2014-03-24 11:43:52.414439 7f60c4b47780 20 client.4182 _ll_get 0x80b3a80 1000000beb6 -> 5
   -16> 2014-03-24 11:43:52.414440 7f60c4b47780  3 client.4182 ll_lookup 100000079dd.head c623a396d7f454cd0a82aae8e67d909e14ac73c6.converted -> 0 (1000000beb6)
   -15> 2014-03-24 11:43:52.414464 7f60c4b47780  3 client.4182 ll_getattr 1000000beb6.head
   -14> 2014-03-24 11:43:52.414468 7f60c4b47780 10 client.4182 _getattr mask pAsLsXsFs issued=1
   -13> 2014-03-24 11:43:52.414471 7f60c4b47780 10 client.4182 fill_stat on 1000000beb6 snap/devhead mode 0100644 mtime 2014-03-24 11:43:51.883318 ctime 2014-03-24 11:43:30.028946
   -12> 2014-03-24 11:43:52.414475 7f60c4b47780  3 client.4182 ll_getattr 1000000beb6.head = 0
   -11> 2014-03-24 11:43:52.414497 7f60bd625700 10 client.4182 put_inode on 100000079dd.head(ref=5 cap_refs={} open={} mode=40755 size=0 mtime=2014-03-24 11:43:52.266200 caps=pAsLsXsFs(0=pAsLsXsFs) parents=0x35d6f90 0x8ac5580)
   -10> 2014-03-24 11:43:52.414517 7f60bd625700  1 -- 10.2.0.252:0/8255 <== mds.0 10.2.0.253:6809/8355 211017 ==== client_reply(???:61547 = 0 Success safe) v1 ==== 27+0+0 (2907377481 0 0) 0x3849080 con 0x4b93f40
    -9> 2014-03-24 11:43:52.414532 7f60bd625700 20 client.4182 handle_client_reply got a reply. Safe:1 tid 61547
    -8> 2014-03-24 11:43:52.414535 7f60bd625700 10 client.4182 insert_trace from 2014-03-24 11:43:52.265773 mds.0 is_target=0 is_dentry=0
    -7> 2014-03-24 11:43:52.414538 7f60bd625700 10 client.4182 insert_trace -- no trace
    -6> 2014-03-24 11:43:52.414541 7f60bd625700 10 client.4182 put_inode on 100000079dd.head(ref=4 cap_refs={} open={} mode=40755 size=0 mtime=2014-03-24 11:43:52.266200 caps=pAsLsXsFs(0=pAsLsXsFs) parents=0x35d6f90 0x8ac5580)
    -5> 2014-03-24 11:43:52.414548 7f60bd625700 10 client.4182 put_inode on 1000000beb5.head(ref=1 cap_refs={1024=1,2048=0,4096=0,8192=0} open={1=0,2=0} mode=100644 size=1039335424 mtime=2014-03-24 11:43:28.314490 caps=pAsXsFsxcrwb(0=pAsXsFsxcrwb) objectset[1000000beb5 ts 0/0 objects 248 dirty_or_tx 0] 0x80b2880)
    -4> 2014-03-24 11:43:52.414559 7f60bd625700 10 client.4182 remove_cap mds.0 on 1000000beb5.head(ref=0 cap_refs={1024=1,2048=0,4096=0,8192=0} open={1=0,2=0} mode=100644 size=1039335424 mtime=2014-03-24 11:43:28.314490 caps=pAsXsFsxcrwb(0=pAsXsFsxcrwb) objectset[1000000beb5 ts 0/0 objects 248 dirty_or_tx 0] 0x80b2880)
    -3> 2014-03-24 11:43:52.414572 7f60bd625700 15 client.4182 remove_cap last one, closing snaprealm 0x32149f0
    -2> 2014-03-24 11:43:52.414574 7f60bd625700 20 client.4182 put_snap_realm 1 0x32149f0 16398 -> 16397
    -1> 2014-03-24 11:43:52.414576 7f60bd625700 10 client.4182 put_inode deleting 1000000beb5.head(ref=0 cap_refs={1024=1,2048=0,4096=0,8192=0} open={1=0,2=0} mode=100644 size=1039335424 mtime=2014-03-24 11:43:28.314490 caps=- objectset[1000000beb5 ts 0/0 objects 248 dirty_or_tx 0] 0x80b2880)
     0> 2014-03-24 11:43:52.415682 7f60bd625700 -1 client/Client.cc: In function 'void Client::put_inode(Inode*, int)' thread 7f60bd625700 time 2014-03-24 11:43:52.414846
client/Client.cc: 2087: FAILED assert(!unclean)

 ceph version 0.67.7 (d7ab4244396b57aac8b7e80812115bbd079e6b73)
 1: (Client::put_inode(Inode*, int)+0x675) [0x531e25]
 2: (Client::put_request(MetaRequest*)+0xd0) [0x536840]
 3: (Client::handle_client_reply(MClientReply*)+0xaa1) [0x55e181]
 4: (Client::ms_dispatch(Message*)+0x5a3) [0x56d3f3]
 5: (DispatchQueue::entry()+0x582) [0x6d6d92]
 6: (DispatchQueue::DispatchThread::entry()+0xd) [0x67dead]
 7: (()+0x79d1) [0x7f60c3f779d1]
 8: (clone()+0x6d) [0x7f60c2c96b6d]
 NOTE: a copy of the executable, or `objdump -rdS <executable>` is needed to interpret this.