Actions
Bug #7867
closedclient/Client.cc: 2087: FAILED assert(!unclean)
% Done:
0%
Source:
Support
Tags:
Backport:
Regression:
Severity:
3 - minor
Reviewed:
Affected Versions:
ceph-qa-suite:
Component(FS):
Labels (FS):
Pull request ID:
Crash signature (v1):
Crash signature (v2):
Description
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.
Updated by Sage Weil about 10 years ago
pushed a simpler version, wip-7867-b, that just pins the Inode* for the duration of the readahead. This avoids a possible Objecter assert on shutdown if the read still hasn't completed yet.
Updated by Sage Weil about 10 years ago
- Status changed from Fix Under Review to 7
Updated by Sage Weil about 10 years ago
- Assignee changed from Greg Farnum to Sage Weil
Updated by Sage Weil about 10 years ago
- Status changed from 7 to Pending Backport
Updated by Sage Weil about 10 years ago
- Status changed from Pending Backport to Resolved
Updated by John Spray over 7 years ago
- Project changed from Ceph to CephFS
- Category deleted (
11)
Bulk updating project=ceph category=ceph-fuse issues to move to fs project so that we can remove the ceph-fuse category from the ceph project
Actions