Project

General

Profile

Bug #5665 » ceph-mds.a.log

Sage Weil, 07/18/2013 09:10 AM

 
2013-07-17 21:50:23.855428 7f8799010780 0 ceph version 0.61.4-77-g39bffac (39bffac6b6c898882d03de392f7f2218933d942b), process ceph-mds, pid 27816
2013-07-17 21:50:23.855970 7f8799010780 1 accepter.accepter.bind my_inst.addr is 0.0.0.0:6803/27816 need_addr=1
2013-07-17 21:50:23.856363 7f8799010780 0 lockdep is enabled
2013-07-17 21:50:23.856465 7f8799010780 1 -- 0.0.0.0:6803/27816 messenger.start
2013-07-17 21:50:23.856810 7f8799010780 10 mds.-1.0 168 MDSCacheObject
2013-07-17 21:50:23.856824 7f8799010780 10 mds.-1.0 2144 CInode
2013-07-17 21:50:23.856830 7f8799010780 10 mds.-1.0 16 elist<>::item *7=112
2013-07-17 21:50:23.856833 7f8799010780 10 mds.-1.0 384 inode_t
2013-07-17 21:50:23.856836 7f8799010780 10 mds.-1.0 56 nest_info_t
2013-07-17 21:50:23.856838 7f8799010780 10 mds.-1.0 32 frag_info_t
2013-07-17 21:50:23.856840 7f8799010780 10 mds.-1.0 40 SimpleLock *5=200
2013-07-17 21:50:23.856842 7f8799010780 10 mds.-1.0 48 ScatterLock *3=144
2013-07-17 21:50:23.856845 7f8799010780 10 mds.-1.0 472 CDentry
2013-07-17 21:50:23.856848 7f8799010780 10 mds.-1.0 16 elist<>::item
2013-07-17 21:50:23.856850 7f8799010780 10 mds.-1.0 40 SimpleLock
2013-07-17 21:50:23.856853 7f8799010780 10 mds.-1.0 1016 CDir
2013-07-17 21:50:23.856864 7f8799010780 10 mds.-1.0 16 elist<>::item *2=32
2013-07-17 21:50:23.856867 7f8799010780 10 mds.-1.0 192 fnode_t
2013-07-17 21:50:23.856869 7f8799010780 10 mds.-1.0 56 nest_info_t *2
2013-07-17 21:50:23.856871 7f8799010780 10 mds.-1.0 32 frag_info_t *2
2013-07-17 21:50:23.856874 7f8799010780 10 mds.-1.0 168 Capability
2013-07-17 21:50:23.856879 7f8799010780 10 mds.-1.0 32 xlist<>::item *2=64
2013-07-17 21:50:23.856929 7f8799010780 1 accepter.accepter.start
2013-07-17 21:50:23.871319 7f8799010780 1 -- 0.0.0.0:6803/27816 --> 10.214.132.29:6790/0 -- auth(proto 0 26 bytes epoch 0) v1 -- ?+0 0x33196c0 con 0x3335580
2013-07-17 21:50:23.874676 7f879900c700 0 -- 0.0.0.0:6803/27816 >> 10.214.132.29:6790/0 pipe(0x333a280 sd=16 :0 s=1 pgs=0 cs=0 l=1).fault
2013-07-17 21:50:24.075765 7f879900c700 1 -- 10.214.131.4:6803/27816 learned my addr 10.214.131.4:6803/27816
2013-07-17 21:50:24.075858 7f879900c700 10 mds.-1.0 MDS::ms_get_authorizer type=mon
2013-07-17 21:50:24.077115 7f8794894700 5 mds.-1.0 ms_handle_connect on 10.214.132.29:6790/0
2013-07-17 21:50:26.857677 7f8793892700 1 -- 10.214.131.4:6803/27816 mark_down 0x3335580 -- 0x333a280
2013-07-17 21:50:26.857907 7f8793892700 1 -- 10.214.131.4:6803/27816 --> 10.214.132.29:6789/0 -- auth(proto 0 26 bytes epoch 0) v1 -- ?+0 0x33196c0 con 0x3335840
2013-07-17 21:50:26.858518 7f879278f700 10 mds.-1.0 MDS::ms_get_authorizer type=mon
2013-07-17 21:50:26.858912 7f8794894700 5 mds.-1.0 ms_handle_connect on 10.214.132.29:6789/0
2013-07-17 21:50:26.961598 7f8794894700 1 -- 10.214.131.4:6803/27816 <== mon.1 10.214.132.29:6789/0 1 ==== mon_map v1 ==== 473+0+0 (1166952924 0 0) 0x3322a00 con 0x3335840
2013-07-17 21:50:26.963046 7f8794894700 1 -- 10.214.131.4:6803/27816 <== mon.1 10.214.132.29:6789/0 2 ==== auth_reply(proto 2 0 Success) v1 ==== 33+0+0 (2363082495 0 0) 0x3322800 con 0x3335840
2013-07-17 21:50:26.963311 7f8794894700 1 -- 10.214.131.4:6803/27816 --> 10.214.132.29:6789/0 -- auth(proto 2 32 bytes epoch 0) v1 -- ?+0 0x3319b40 con 0x3335840
2013-07-17 21:50:26.964410 7f8794894700 1 -- 10.214.131.4:6803/27816 <== mon.1 10.214.132.29:6789/0 3 ==== auth_reply(proto 2 0 Success) v1 ==== 206+0+0 (2298726799 0 0) 0x3322c00 con 0x3335840
2013-07-17 21:50:26.964569 7f8794894700 1 -- 10.214.131.4:6803/27816 --> 10.214.132.29:6789/0 -- auth(proto 2 165 bytes epoch 0) v1 -- ?+0 0x3319b40 con 0x3335840
2013-07-17 21:50:27.077479 7f8794894700 1 -- 10.214.131.4:6803/27816 <== mon.1 10.214.132.29:6789/0 4 ==== auth_reply(proto 2 0 Success) v1 ==== 580+0+0 (3076182515 0 0) 0x3322a00 con 0x3335840
2013-07-17 21:50:27.077585 7f8794894700 1 -- 10.214.131.4:6803/27816 --> 10.214.132.29:6789/0 -- mon_subscribe({monmap=0+}) v2 -- ?+0 0x333b700 con 0x3335840
2013-07-17 21:50:27.080761 7f8794894700 1 -- 10.214.131.4:6803/27816 --> 10.214.132.29:6789/0 -- auth(proto 2 2 bytes epoch 0) v1 -- ?+0 0x33196c0 con 0x3335840
2013-07-17 21:50:27.081892 7f8794894700 1 -- 10.214.131.4:6803/27816 <== mon.1 10.214.132.29:6789/0 5 ==== mon_map v1 ==== 473+0+0 (1166952924 0 0) 0x3322e00 con 0x3335840
2013-07-17 21:50:27.081961 7f8794894700 1 -- 10.214.131.4:6803/27816 <== mon.1 10.214.132.29:6789/0 6 ==== mon_subscribe_ack(300s) v1 ==== 20+0+0 (673156111 0 0) 0x333ba80 con 0x3335840
2013-07-17 21:50:27.081988 7f8794894700 1 -- 10.214.131.4:6803/27816 <== mon.1 10.214.132.29:6789/0 7 ==== auth_reply(proto 2 0 Success) v1 ==== 194+0+0 (2032907317 0 0) 0x3322a00 con 0x3335840
2013-07-17 21:50:27.082202 7f8799010780 10 mds.-1.0 beacon_send up:boot seq 1 (currently up:boot)
2013-07-17 21:50:27.083167 7f8799010780 1 -- 10.214.131.4:6803/27816 --> 10.214.132.29:6789/0 -- mdsbeacon(4099/a up:boot seq 1 v0) v2 -- ?+0 0x334f000 con 0x3335840
2013-07-17 21:50:27.087294 7f8799010780 1 -- 10.214.131.4:6803/27816 --> 10.214.132.29:6789/0 -- mon_subscribe({monmap=2+,osdmap=0}) v2 -- ?+0 0x333b540 con 0x3335840
2013-07-17 21:50:27.087367 7f8799010780 1 -- 10.214.131.4:6803/27816 --> 10.214.132.29:6789/0 -- mon_subscribe({mdsmap=0+,monmap=2+,osdmap=0}) v2 -- ?+0 0x333be00 con 0x3335840
2013-07-17 21:50:27.087398 7f8799010780 10 mds.-1.0 create_logger
2013-07-17 21:50:27.088693 7f8794894700 1 -- 10.214.131.4:6803/27816 <== mon.1 10.214.132.29:6789/0 8 ==== osd_map(3..3 src has 1..3) v3 ==== 3962+0+0 (1009265937 0 0) 0x3319d80 con 0x3335840
2013-07-17 21:50:27.090086 7f8794894700 1 -- 10.214.131.4:6803/27816 <== mon.1 10.214.132.29:6789/0 9 ==== mon_subscribe_ack(300s) v1 ==== 20+0+0 (673156111 0 0) 0x333b540 con 0x3335840
2013-07-17 21:50:27.090242 7f8794894700 1 -- 10.214.131.4:6803/27816 <== mon.1 10.214.132.29:6789/0 10 ==== mdsmap(e 2) v1 ==== 356+0+0 (3333750197 0 0) 0x3322c00 con 0x3335840
2013-07-17 21:50:27.090326 7f8794894700 5 mds.-1.0 handle_mds_map epoch 2 from mon.1
2013-07-17 21:50:27.090349 7f8794894700 10 mds.-1.0 my compat compat={},rocompat={},incompat={1=base v0.20,2=client writeable ranges,3=default file layouts on dirs,4=dir inode in separate object,5=mds uses versioned encoding}
2013-07-17 21:50:27.090357 7f8794894700 10 mds.-1.0 mdsmap compat compat={},rocompat={},incompat={1=base v0.20,2=client writeable ranges,3=default file layouts on dirs,4=dir inode in separate object,5=mds uses versioned encoding}
2013-07-17 21:50:27.090364 7f8794894700 10 mds.-1.-1 map says i am 10.214.131.4:6803/27816 mds.-1.-1 state down:dne
2013-07-17 21:50:27.090370 7f8794894700 10 mds.-1.-1 not in map yet
2013-07-17 21:50:27.090410 7f8794894700 1 -- 10.214.131.4:6803/27816 <== mon.1 10.214.132.29:6789/0 11 ==== osd_map(3..3 src has 1..3) v3 ==== 3962+0+0 (1009265937 0 0) 0x3359240 con 0x3335840
2013-07-17 21:50:27.090438 7f8794894700 1 -- 10.214.131.4:6803/27816 <== mon.1 10.214.132.29:6789/0 12 ==== mon_subscribe_ack(300s) v1 ==== 20+0+0 (673156111 0 0) 0x333b700 con 0x3335840
2013-07-17 21:50:27.226619 7f8794894700 1 -- 10.214.131.4:6803/27816 <== mon.1 10.214.132.29:6789/0 13 ==== mdsmap(e 3) v1 ==== 559+0+0 (1454482218 0 0) 0x3322800 con 0x3335840
2013-07-17 21:50:27.226647 7f8794894700 5 mds.-1.-1 handle_mds_map epoch 3 from mon.1
2013-07-17 21:50:27.226698 7f8794894700 10 mds.-1.-1 my compat compat={},rocompat={},incompat={1=base v0.20,2=client writeable ranges,3=default file layouts on dirs,4=dir inode in separate object,5=mds uses versioned encoding}
2013-07-17 21:50:27.226705 7f8794894700 10 mds.-1.-1 mdsmap compat compat={},rocompat={},incompat={1=base v0.20,2=client writeable ranges,3=default file layouts on dirs,4=dir inode in separate object,5=mds uses versioned encoding}
2013-07-17 21:50:27.226710 7f8794894700 10 mds.-1.0 map says i am 10.214.131.4:6803/27816 mds.-1.0 state up:standby
2013-07-17 21:50:27.226719 7f8794894700 1 mds.-1.0 handle_mds_map standby
2013-07-17 21:50:27.335355 7f8794894700 1 -- 10.214.131.4:6803/27816 <== mon.1 10.214.132.29:6789/0 14 ==== mdsmap(e 4) v1 ==== 767+0+0 (1950902404 0 0) 0x3322c00 con 0x3335840
2013-07-17 21:50:27.335383 7f8794894700 5 mds.-1.0 handle_mds_map epoch 4 from mon.1
2013-07-17 21:50:27.335405 7f8794894700 10 mds.-1.0 my compat compat={},rocompat={},incompat={1=base v0.20,2=client writeable ranges,3=default file layouts on dirs,4=dir inode in separate object,5=mds uses versioned encoding}
2013-07-17 21:50:27.335412 7f8794894700 10 mds.-1.0 mdsmap compat compat={},rocompat={},incompat={1=base v0.20,2=client writeable ranges,3=default file layouts on dirs,4=dir inode in separate object,5=mds uses versioned encoding}
2013-07-17 21:50:27.335417 7f8794894700 10 mds.-1.0 map says i am 10.214.131.4:6803/27816 mds.-1.0 state up:standby
2013-07-17 21:50:27.335423 7f8794894700 1 mds.-1.0 handle_mds_map standby
2013-07-17 21:50:27.444011 7f8794894700 1 -- 10.214.131.4:6803/27816 <== mon.1 10.214.132.29:6789/0 15 ==== mdsmap(e 5) v1 ==== 791+0+0 (3038094493 0 0) 0x3322a00 con 0x3335840
2013-07-17 21:50:27.444039 7f8794894700 5 mds.-1.0 handle_mds_map epoch 5 from mon.1
2013-07-17 21:50:27.444109 7f8794894700 10 mds.-1.0 my compat compat={},rocompat={},incompat={1=base v0.20,2=client writeable ranges,3=default file layouts on dirs,4=dir inode in separate object,5=mds uses versioned encoding}
2013-07-17 21:50:27.444116 7f8794894700 10 mds.-1.0 mdsmap compat compat={},rocompat={},incompat={1=base v0.20,2=client writeable ranges,3=default file layouts on dirs,4=dir inode in separate object,5=mds uses versioned encoding}
2013-07-17 21:50:27.444122 7f8794894700 10 mds.0.1 map says i am 10.214.131.4:6803/27816 mds.0.1 state up:creating
2013-07-17 21:50:27.444128 7f8794894700 1 mds.0.1 handle_mds_map i am now mds.0.1
2013-07-17 21:50:27.444130 7f8794894700 1 mds.0.1 handle_mds_map state change up:standby --> up:creating
2013-07-17 21:50:27.444134 7f8794894700 3 mds.0.1 boot_create
2013-07-17 21:50:27.444137 7f8794894700 10 mds.0.1 boot_create creating fresh journal
2013-07-17 21:50:27.444146 7f8794894700 5 mds.0.log create empty log
2013-07-17 21:50:27.461591 7f8794894700 1 -- 10.214.131.4:6803/27816 --> 10.214.132.29:6806/8238 -- osd_op(mds.0.1:1 200.00000000 [writefull 0~84] 1.844f3494 e3) v4 -- ?+0 0x3359000 con 0x33359a0
2013-07-17 21:50:27.462278 7f879900c700 10 mds.0.1 MDS::ms_get_authorizer type=osd
2013-07-17 21:50:27.463363 7f8794894700 7 mds.0.log start_new_segment at 4194304
2013-07-17 21:50:27.463375 7f8794894700 10 mds.0.cache create_subtree_map 0 subtrees, 0 fullauth
2013-07-17 21:50:27.463380 7f8794894700 10 mds.0.cache show_subtrees - no subtrees
2013-07-17 21:50:27.463387 7f8794894700 15 mds.0.cache subtrees {}
2013-07-17 21:50:27.463389 7f8794894700 15 mds.0.cache ambiguous_subtrees
2013-07-17 21:50:27.463414 7f8794894700 5 mds.0.log submit_entry 4194304~156 : ESubtreeMap 0 subtrees , 0 ambiguous [metablob]
2013-07-17 21:50:27.463511 7f8794894700 1 -- 10.214.131.4:6803/27816 --> 10.214.132.29:6806/8238 -- osd_op(mds.0.1:2 200.00000001 [delete] 1.6e5f474 e3) v4 -- ?+0 0x3319d80 con 0x33359a0
2013-07-17 21:50:27.463718 7f8794894700 1 -- 10.214.131.4:6803/27816 --> 10.214.132.29:6806/8238 -- osd_op(mds.0.1:3 200.00000002 [delete] 1.eb272dbb e3) v4 -- ?+0 0x3359900 con 0x33359a0
2013-07-17 21:50:27.463832 7f8794894700 1 -- 10.214.131.4:6803/27816 --> 10.214.132.29:6806/8238 -- osd_op(mds.0.1:4 200.00000003 [delete] 1.95e3ab e3) v4 -- ?+0 0x33596c0 con 0x33359a0
2013-07-17 21:50:27.463890 7f8794894700 1 -- 10.214.131.4:6803/27816 --> 10.214.132.29:6806/8238 -- osd_op(mds.0.1:5 200.00000004 [delete] 1.1ba6bc1f e3) v4 -- ?+0 0x3359480 con 0x33359a0
2013-07-17 21:50:27.463952 7f8794894700 1 -- 10.214.131.4:6803/27816 --> 10.214.132.29:6806/8238 -- osd_op(mds.0.1:6 200.00000005 [delete] 1.96d5827a e3) v4 -- ?+0 0x3359d80 con 0x33359a0
2013-07-17 21:50:27.464021 7f8794894700 1 -- 10.214.131.4:6803/27816 --> 10.214.132.29:6806/8238 -- osd_op(mds.0.1:7 200.00000006 [delete] 1.ade7efde e3) v4 -- ?+0 0x3359b40 con 0x33359a0
2013-07-17 21:50:27.464052 7f8794894700 10 mds.0.log Advancing to next stray directory on mds 0
2013-07-17 21:50:27.464055 7f8794894700 3 mds.0.1 boot_create creating fresh hierarchy
2013-07-17 21:50:27.464061 7f8794894700 0 mds.0.cache creating system inode with ino:1
2013-07-17 21:50:27.464139 7f8794894700 7 mds.0.cache adjust_subtree_auth -1,-2 -> 0,-2 on [dir 1 / [2,head] auth v=0 cv=0/0 state=1073741824 f() n() hs=0+0,ss=0+0 0x337a000]
2013-07-17 21:50:27.464162 7f8794894700 10 mds.0.cache show_subtrees - no subtrees
2013-07-17 21:50:27.464176 7f8794894700 7 mds.0.cache current root is [dir 1 / [2,head] auth v=0 cv=0/0 state=1073741824 f() n() hs=0+0,ss=0+0 | subtree=1 0x337a000]
2013-07-17 21:50:27.464184 7f8794894700 10 mds.0.cache.dir(1) setting dir_auth=0,-2 from -1,-2 on [dir 1 / [2,head] auth v=0 cv=0/0 state=1073741824 f() n() hs=0+0,ss=0+0 | subtree=1 0x337a000]
2013-07-17 21:50:27.464190 7f8794894700 10 mds.0.cache.dir(1) new subtree root, adjusting auth_pins
2013-07-17 21:50:27.464194 7f8794894700 15 mds.0.cache show_subtrees
2013-07-17 21:50:27.464203 7f8794894700 10 mds.0.cache |__ 0 auth [dir 1 / [2,head] auth v=0 cv=0/0 dir_auth=0 state=1073741824 f() n() hs=0+0,ss=0+0 | subtree=1 0x337a000]
2013-07-17 21:50:27.464209 7f8794894700 0 mds.0.cache creating system inode with ino:2
2013-07-17 21:50:27.464230 7f8794894700 12 mds.0.cache.dir(1) add_primary_dentry [dentry #1/.ceph [2,head] auth (dversion lock) v=0 inode=0x3369860 0x3382000]
2013-07-17 21:50:27.464251 7f8794894700 10 mds.0.cache.dir(2) pre_dirty 1
2013-07-17 21:50:27.464257 7f8794894700 10 mds.0.cache.dir(2) mark_dirty (was clean) [dir 2 /.ceph/ [2,head] auth v=1 cv=0/0 REP state=1073741826|complete f() n() hs=0+0,ss=0+0 0x337a3f8] version 1
2013-07-17 21:50:27.464268 7f8794894700 10 mds.0.cache.dir(2) commit want 0 on [dir 2 /.ceph/ [2,head] auth v=1 cv=0/0 REP state=1610612738|complete f() n() hs=0+0,ss=0+0 | dirty=1 0x337a3f8]
2013-07-17 21:50:27.464275 7f8794894700 10 mds.0.cache.dir(2) auth_pin by 0x337a3f8 on [dir 2 /.ceph/ [2,head] auth v=1 cv=0/0 REP ap=1+0+0 state=1610612738|complete f() n() hs=0+0,ss=0+0 | dirty=1 authpin=1 0x337a3f8] count now 1 + 0
2013-07-17 21:50:27.464284 7f8794894700 15 mds.0.cache.dir(1) adjust_nested_auth_pins 1/0 on [dir 1 / [2,head] auth v=0 cv=0/0 REP dir_auth=0 ap=0+0+1 state=1073741824 f(v0 1=0+1) n(v0 1=0+1) hs=1+0,ss=0+0 dirty=1 | child=1 subtree=1 0x337a000] by 0x337a3f8 count now 0 + 1
2013-07-17 21:50:27.464297 7f8794894700 10 mds.0.cache.dir(2) _commit want 1 on [dir 2 /.ceph/ [2,head] auth v=1 cv=0/0 REP ap=1+0+0 state=1610612738|complete f() n() hs=0+0,ss=0+0 | dirty=1 authpin=1 0x337a3f8]
2013-07-17 21:50:27.464306 7f8794894700 10 mds.0.cache.dir(2) marking committing
2013-07-17 21:50:27.466380 7f8794894700 10 mds.0.cache.snaprealm(1 seq 1 0x3359000) have_past_parents_open [1,head]
2013-07-17 21:50:27.466395 7f8794894700 10 mds.0.cache.snaprealm(1 seq 1 0x3359000) build_snap_set [0,head] on snaprealm(1 seq 1 lc 0 cr 0 cps 1 snaps={} 0x3359000)
2013-07-17 21:50:27.466403 7f8794894700 10 mds.0.cache.snaprealm(1 seq 1 0x3359000) build_snap_trace my_snaps []
2013-07-17 21:50:27.466409 7f8794894700 10 mds.0.cache.snaprealm(1 seq 1 0x3359000) check_cache rebuilt seq 1 cached_seq 1 cached_last_created 0 cached_last_destroyed 0)
2013-07-17 21:50:27.466415 7f8794894700 10 mds.0.cache.dir(2) _commit_partial
2013-07-17 21:50:27.466543 7f8794894700 1 -- 10.214.131.4:6803/27816 --> 10.214.132.29:6806/8238 -- osd_op(mds.0.1:8 2.00000000 [tmapup 0~0] 1.96f33707 e3) v4 -- ?+0 0x3319d80 con 0x33359a0
2013-07-17 21:50:27.466585 7f8794894700 10 mds.0.cache.dir(1) pre_dirty 1
2013-07-17 21:50:27.466588 7f8794894700 10 mds.0.cache.dir(1) mark_dirty (was clean) [dir 1 / [2,head] auth v=1 cv=0/0 REP dir_auth=0 ap=0+0+1 state=1073741826|complete f(v0 1=0+1) n(v0 1=0+1) hs=1+0,ss=0+0 dirty=1 | child=1 subtree=1 0x337a000] version 1
2013-07-17 21:50:27.466599 7f8794894700 10 mds.0.cache.dir(1) commit want 0 on [dir 1 / [2,head] auth v=1 cv=0/0 REP dir_auth=0 ap=0+0+1 state=1610612738|complete f(v0 1=0+1) n(v0 1=0+1) hs=1+0,ss=0+0 dirty=1 | child=1 subtree=1 dirty=1 0x337a000]
2013-07-17 21:50:27.466609 7f8794894700 10 mds.0.cache.dir(1) auth_pin by 0x337a000 on [dir 1 / [2,head] auth v=1 cv=0/0 REP dir_auth=0 ap=1+0+1 state=1610612738|complete f(v0 1=0+1) n(v0 1=0+1) hs=1+0,ss=0+0 dirty=1 | child=1 subtree=1 dirty=1 authpin=1 0x337a000] count now 1 + 1
2013-07-17 21:50:27.466618 7f8794894700 10 mds.0.cache.dir(1) _commit want 1 on [dir 1 / [2,head] auth v=1 cv=0/0 REP dir_auth=0 ap=1+0+1 state=1610612738|complete f(v0 1=0+1) n(v0 1=0+1) hs=1+0,ss=0+0 dirty=1 | child=1 subtree=1 dirty=1 authpin=1 0x337a000]
2013-07-17 21:50:27.466627 7f8794894700 10 mds.0.cache.dir(1) marking committing
2013-07-17 21:50:27.466630 7f8794894700 10 mds.0.cache.snaprealm(1 seq 1 0x3359000) have_past_parents_open [1,head]
2013-07-17 21:50:27.466633 7f8794894700 10 mds.0.cache.dir(1) _commit_full
2013-07-17 21:50:27.466651 7f8794894700 14 mds.0.cache.dir(1) pos 26 dn '.ceph' inode [inode 2 [...2,head] /.ceph/ auth v1 ap=0+1 f() n(v0 1=0+1) (iversion lock) | dirfrag=1 0x3369860]
2013-07-17 21:50:27.466708 7f8794894700 1 -- 10.214.131.4:6803/27816 --> 10.214.132.29:6806/8238 -- osd_op(mds.0.1:9 1.00000000 [tmapput 0~606] 1.6b2cdaff e3) v4 -- ?+0 0x3359480 con 0x33359a0
2013-07-17 21:50:27.466744 7f8794894700 10 mds.0.cache.ino(1) store 1
2013-07-17 21:50:27.466760 7f8794894700 20 mds.0.cache.ino(1) encode_snap_blob snaprealm(1 seq 1 lc 0 cr 0 cps 1 snaps={} 0x3359000)
2013-07-17 21:50:27.466799 7f8794894700 1 -- 10.214.131.4:6803/27816 --> 10.214.132.29:6806/8238 -- osd_op(mds.0.1:10 1.00000000.inode [writefull 0~432] 1.232c0e14 e3) v4 -- ?+0 0x33596c0 con 0x33359a0
2013-07-17 21:50:27.466827 7f8794894700 3 mds.0.1 boot_create creating mydir hierarchy
2013-07-17 21:50:27.466831 7f8794894700 0 mds.0.cache creating system inode with ino:100
2013-07-17 21:50:27.466837 7f8794894700 7 mds.0.cache adjust_subtree_auth -1,-2 -> 0,-2 on [dir 100 ~mds0/ [2,head] auth v=0 cv=0/0 state=1073741824 f() n() hs=0+0,ss=0+0 0x337a7f0]
2013-07-17 21:50:27.466846 7f8794894700 15 mds.0.cache show_subtrees
2013-07-17 21:50:27.466850 7f8794894700 10 mds.0.cache |__ 0 auth [dir 1 / [2,head] auth v=1 cv=1/0 REP dir_auth=0 ap=1+0+1 state=1610612802|complete f(v0 1=0+1) n(v0 1=0+1) hs=1+0,ss=0+0 dirty=1 | child=1 subtree=1 dirty=1 authpin=1 0x337a000]
2013-07-17 21:50:27.466861 7f8794894700 7 mds.0.cache current root is [dir 100 ~mds0/ [2,head] auth v=0 cv=0/0 state=1073741824 f() n() hs=0+0,ss=0+0 | subtree=1 0x337a7f0]
2013-07-17 21:50:27.466867 7f8794894700 10 mds.0.cache.dir(100) setting dir_auth=0,-2 from -1,-2 on [dir 100 ~mds0/ [2,head] auth v=0 cv=0/0 state=1073741824 f() n() hs=0+0,ss=0+0 | subtree=1 0x337a7f0]
2013-07-17 21:50:27.466874 7f8794894700 10 mds.0.cache.dir(100) new subtree root, adjusting auth_pins
2013-07-17 21:50:27.466876 7f8794894700 15 mds.0.cache show_subtrees
2013-07-17 21:50:27.466879 7f8794894700 10 mds.0.cache |__ 0 auth [dir 1 / [2,head] auth v=1 cv=1/0 REP dir_auth=0 ap=1+0+1 state=1610612802|complete f(v0 1=0+1) n(v0 1=0+1) hs=1+0,ss=0+0 dirty=1 | child=1 subtree=1 dirty=1 authpin=1 0x337a000]
2013-07-17 21:50:27.466889 7f8794894700 10 mds.0.cache |__ 0 auth [dir 100 ~mds0/ [2,head] auth v=0 cv=0/0 dir_auth=0 state=1073741824 f() n() hs=0+0,ss=0+0 | subtree=1 0x337a7f0]
2013-07-17 21:50:27.466896 7f8794894700 0 mds.0.cache creating system inode with ino:600
2013-07-17 21:50:27.466906 7f8794894700 12 mds.0.cache.dir(100) add_primary_dentry [dentry #100/stray0 [2,head] auth (dversion lock) v=0 inode=0x336a920 0x33821d8]
2013-07-17 21:50:27.466912 7f8794894700 10 mds.0.cache.dir(600) pre_dirty 1
2013-07-17 21:50:27.466914 7f8794894700 10 mds.0.cache.dir(600) mark_dirty (was clean) [dir 600 ~mds0/stray0/ [2,head] auth v=1 cv=0/0 state=1073741826|complete f() n() hs=0+0,ss=0+0 0x337abe8] version 1
2013-07-17 21:50:27.466922 7f8794894700 10 mds.0.cache.dir(600) commit want 0 on [dir 600 ~mds0/stray0/ [2,head] auth v=1 cv=0/0 state=1610612738|complete f() n() hs=0+0,ss=0+0 | dirty=1 0x337abe8]
2013-07-17 21:50:27.466929 7f8794894700 10 mds.0.cache.dir(600) auth_pin by 0x337abe8 on [dir 600 ~mds0/stray0/ [2,head] auth v=1 cv=0/0 ap=1+0+0 state=1610612738|complete f() n() hs=0+0,ss=0+0 | dirty=1 authpin=1 0x337abe8] count now 1 + 0
2013-07-17 21:50:27.466938 7f8794894700 15 mds.0.cache.dir(100) adjust_nested_auth_pins 1/0 on [dir 100 ~mds0/ [2,head] auth v=0 cv=0/0 dir_auth=0 ap=0+0+1 state=1073741824 f(v0 1=0+1)/f() n(v0 1=0+1)/n() hs=1+0,ss=0+0 dirty=1 | child=1 subtree=1 0x337a7f0] by 0x337abe8 count now 0 + 1
2013-07-17 21:50:27.466949 7f8794894700 10 mds.0.cache.dir(600) _commit want 1 on [dir 600 ~mds0/stray0/ [2,head] auth v=1 cv=0/0 ap=1+0+0 state=1610612738|complete f() n() hs=0+0,ss=0+0 | dirty=1 authpin=1 0x337abe8]
2013-07-17 21:50:27.466957 7f8794894700 10 mds.0.cache.dir(600) marking committing
2013-07-17 21:50:27.466961 7f8794894700 10 mds.0.cache.snaprealm(100 seq 1 0x3359900) have_past_parents_open [1,head]
2013-07-17 21:50:27.466963 7f8794894700 10 mds.0.cache.snaprealm(100 seq 1 0x3359900) build_snap_set [0,head] on snaprealm(100 seq 1 lc 0 cr 0 cps 1 snaps={} 0x3359900)
2013-07-17 21:50:27.466968 7f8794894700 10 mds.0.cache.snaprealm(100 seq 1 0x3359900) build_snap_trace my_snaps []
2013-07-17 21:50:27.466977 7f8794894700 10 mds.0.cache.snaprealm(100 seq 1 0x3359900) check_cache rebuilt seq 1 cached_seq 1 cached_last_created 0 cached_last_destroyed 0)
2013-07-17 21:50:27.466981 7f8794894700 10 mds.0.cache.dir(600) _commit_partial
2013-07-17 21:50:27.467021 7f8794894700 1 -- 10.214.131.4:6803/27816 --> 10.214.132.29:6806/8238 -- osd_op(mds.0.1:11 600.00000000 [tmapup 0~0] 1.c2e541b0 e3) v4 -- ?+0 0x3359b40 con 0x33359a0
2013-07-17 21:50:27.467037 7f8794894700 0 mds.0.cache creating system inode with ino:601
2013-07-17 21:50:27.467050 7f8794894700 12 mds.0.cache.dir(100) add_primary_dentry [dentry #100/stray1 [2,head] auth (dversion lock) v=0 inode=0x336b180 0x33823b0]
2013-07-17 21:50:27.467057 7f8794894700 10 mds.0.cache.dir(601) pre_dirty 1
2013-07-17 21:50:27.467059 7f8794894700 10 mds.0.cache.dir(601) mark_dirty (was clean) [dir 601 ~mds0/stray1/ [2,head] auth v=1 cv=0/0 state=1073741826|complete f() n() hs=0+0,ss=0+0 0x337afe0] version 1
2013-07-17 21:50:27.467069 7f8794894700 10 mds.0.cache.dir(601) commit want 0 on [dir 601 ~mds0/stray1/ [2,head] auth v=1 cv=0/0 state=1610612738|complete f() n() hs=0+0,ss=0+0 | dirty=1 0x337afe0]
2013-07-17 21:50:27.467076 7f8794894700 10 mds.0.cache.dir(601) auth_pin by 0x337afe0 on [dir 601 ~mds0/stray1/ [2,head] auth v=1 cv=0/0 ap=1+0+0 state=1610612738|complete f() n() hs=0+0,ss=0+0 | dirty=1 authpin=1 0x337afe0] count now 1 + 0
2013-07-17 21:50:27.467084 7f8794894700 15 mds.0.cache.dir(100) adjust_nested_auth_pins 1/0 on [dir 100 ~mds0/ [2,head] auth v=0 cv=0/0 dir_auth=0 ap=0+0+2 state=1073741824 f(v0 2=0+2)/f() n(v0 2=0+2)/n() hs=2+0,ss=0+0 dirty=2 | child=1 subtree=1 0x337a7f0] by 0x337afe0 count now 0 + 2
2013-07-17 21:50:27.467095 7f8794894700 10 mds.0.cache.dir(601) _commit want 1 on [dir 601 ~mds0/stray1/ [2,head] auth v=1 cv=0/0 ap=1+0+0 state=1610612738|complete f() n() hs=0+0,ss=0+0 | dirty=1 authpin=1 0x337afe0]
2013-07-17 21:50:27.467102 7f8794894700 10 mds.0.cache.dir(601) marking committing
2013-07-17 21:50:27.467105 7f8794894700 10 mds.0.cache.snaprealm(100 seq 1 0x3359900) have_past_parents_open [1,head]
2013-07-17 21:50:27.467108 7f8794894700 10 mds.0.cache.dir(601) _commit_partial
2013-07-17 21:50:27.467147 7f8794894700 1 -- 10.214.131.4:6803/27816 --> 10.214.132.29:6806/8238 -- osd_op(mds.0.1:12 601.00000000 [tmapup 0~0] 1.81580290 e3) v4 -- ?+0 0x3359d80 con 0x33359a0
2013-07-17 21:50:27.467167 7f8794894700 0 mds.0.cache creating system inode with ino:602
2013-07-17 21:50:27.467176 7f8794894700 12 mds.0.cache.dir(100) add_primary_dentry [dentry #100/stray2 [2,head] auth (dversion lock) v=0 inode=0x336b9e0 0x3382588]
2013-07-17 21:50:27.467182 7f8794894700 10 mds.0.cache.dir(602) pre_dirty 1
2013-07-17 21:50:27.467184 7f8794894700 10 mds.0.cache.dir(602) mark_dirty (was clean) [dir 602 ~mds0/stray2/ [2,head] auth v=1 cv=0/0 state=1073741826|complete f() n() hs=0+0,ss=0+0 0x337b3d8] version 1
2013-07-17 21:50:27.467194 7f8794894700 10 mds.0.cache.dir(602) commit want 0 on [dir 602 ~mds0/stray2/ [2,head] auth v=1 cv=0/0 state=1610612738|complete f() n() hs=0+0,ss=0+0 | dirty=1 0x337b3d8]
2013-07-17 21:50:27.467201 7f8794894700 10 mds.0.cache.dir(602) auth_pin by 0x337b3d8 on [dir 602 ~mds0/stray2/ [2,head] auth v=1 cv=0/0 ap=1+0+0 state=1610612738|complete f() n() hs=0+0,ss=0+0 | dirty=1 authpin=1 0x337b3d8] count now 1 + 0
2013-07-17 21:50:27.467209 7f8794894700 15 mds.0.cache.dir(100) adjust_nested_auth_pins 1/0 on [dir 100 ~mds0/ [2,head] auth v=0 cv=0/0 dir_auth=0 ap=0+0+3 state=1073741824 f(v0 3=0+3)/f() n(v0 3=0+3)/n() hs=3+0,ss=0+0 dirty=3 | child=1 subtree=1 0x337a7f0] by 0x337b3d8 count now 0 + 3
2013-07-17 21:50:27.467220 7f8794894700 10 mds.0.cache.dir(602) _commit want 1 on [dir 602 ~mds0/stray2/ [2,head] auth v=1 cv=0/0 ap=1+0+0 state=1610612738|complete f() n() hs=0+0,ss=0+0 | dirty=1 authpin=1 0x337b3d8]
2013-07-17 21:50:27.467228 7f8794894700 10 mds.0.cache.dir(602) marking committing
2013-07-17 21:50:27.467231 7f8794894700 10 mds.0.cache.snaprealm(100 seq 1 0x3359900) have_past_parents_open [1,head]
2013-07-17 21:50:27.467234 7f8794894700 10 mds.0.cache.dir(602) _commit_partial
2013-07-17 21:50:27.467275 7f8794894700 1 -- 10.214.131.4:6803/27816 --> 10.214.132.29:6806/8238 -- osd_op(mds.0.1:13 602.00000000 [tmapup 0~0] 1.2a8b6bd0 e3) v4 -- ?+0 0x3319d80 con 0x33359a0
2013-07-17 21:50:27.467295 7f8794894700 0 mds.0.cache creating system inode with ino:603
2013-07-17 21:50:27.467305 7f8794894700 12 mds.0.cache.dir(100) add_primary_dentry [dentry #100/stray3 [2,head] auth (dversion lock) v=0 inode=0x336c240 0x3382760]
2013-07-17 21:50:27.467311 7f8794894700 10 mds.0.cache.dir(603) pre_dirty 1
2013-07-17 21:50:27.467313 7f8794894700 10 mds.0.cache.dir(603) mark_dirty (was clean) [dir 603 ~mds0/stray3/ [2,head] auth v=1 cv=0/0 state=1073741826|complete f() n() hs=0+0,ss=0+0 0x337b7d0] version 1
2013-07-17 21:50:27.467322 7f8794894700 10 mds.0.cache.dir(603) commit want 0 on [dir 603 ~mds0/stray3/ [2,head] auth v=1 cv=0/0 state=1610612738|complete f() n() hs=0+0,ss=0+0 | dirty=1 0x337b7d0]
2013-07-17 21:50:27.467329 7f8794894700 10 mds.0.cache.dir(603) auth_pin by 0x337b7d0 on [dir 603 ~mds0/stray3/ [2,head] auth v=1 cv=0/0 ap=1+0+0 state=1610612738|complete f() n() hs=0+0,ss=0+0 | dirty=1 authpin=1 0x337b7d0] count now 1 + 0
2013-07-17 21:50:27.467336 7f8794894700 15 mds.0.cache.dir(100) adjust_nested_auth_pins 1/0 on [dir 100 ~mds0/ [2,head] auth v=0 cv=0/0 dir_auth=0 ap=0+0+4 state=1073741824 f(v0 4=0+4)/f() n(v0 4=0+4)/n() hs=4+0,ss=0+0 dirty=4 | child=1 subtree=1 0x337a7f0] by 0x337b7d0 count now 0 + 4
2013-07-17 21:50:27.467352 7f8794894700 10 mds.0.cache.dir(603) _commit want 1 on [dir 603 ~mds0/stray3/ [2,head] auth v=1 cv=0/0 ap=1+0+0 state=1610612738|complete f() n() hs=0+0,ss=0+0 | dirty=1 authpin=1 0x337b7d0]
2013-07-17 21:50:27.467361 7f8794894700 10 mds.0.cache.dir(603) marking committing
2013-07-17 21:50:27.467364 7f8794894700 10 mds.0.cache.snaprealm(100 seq 1 0x3359900) have_past_parents_open [1,head]
2013-07-17 21:50:27.467367 7f8794894700 10 mds.0.cache.dir(603) _commit_partial
2013-07-17 21:50:27.467404 7f8794894700 1 -- 10.214.131.4:6803/27816 --> 10.214.132.29:6806/8238 -- osd_op(mds.0.1:14 603.00000000 [tmapup 0~0] 1.7a4d91b0 e3) v4 -- ?+0 0x33a0d80 con 0x33359a0
2013-07-17 21:50:27.467424 7f8794894700 0 mds.0.cache creating system inode with ino:604
2013-07-17 21:50:27.467433 7f8794894700 12 mds.0.cache.dir(100) add_primary_dentry [dentry #100/stray4 [2,head] auth (dversion lock) v=0 inode=0x336caa0 0x3382938]
2013-07-17 21:50:27.467439 7f8794894700 10 mds.0.cache.dir(604) pre_dirty 1
2013-07-17 21:50:27.467441 7f8794894700 10 mds.0.cache.dir(604) mark_dirty (was clean) [dir 604 ~mds0/stray4/ [2,head] auth v=1 cv=0/0 state=1073741826|complete f() n() hs=0+0,ss=0+0 0x337bbc8] version 1
2013-07-17 21:50:27.467450 7f8794894700 10 mds.0.cache.dir(604) commit want 0 on [dir 604 ~mds0/stray4/ [2,head] auth v=1 cv=0/0 state=1610612738|complete f() n() hs=0+0,ss=0+0 | dirty=1 0x337bbc8]
2013-07-17 21:50:27.467456 7f8794894700 10 mds.0.cache.dir(604) auth_pin by 0x337bbc8 on [dir 604 ~mds0/stray4/ [2,head] auth v=1 cv=0/0 ap=1+0+0 state=1610612738|complete f() n() hs=0+0,ss=0+0 | dirty=1 authpin=1 0x337bbc8] count now 1 + 0
2013-07-17 21:50:27.467464 7f8794894700 15 mds.0.cache.dir(100) adjust_nested_auth_pins 1/0 on [dir 100 ~mds0/ [2,head] auth v=0 cv=0/0 dir_auth=0 ap=0+0+5 state=1073741824 f(v0 5=0+5)/f() n(v0 5=0+5)/n() hs=5+0,ss=0+0 dirty=5 | child=1 subtree=1 0x337a7f0] by 0x337bbc8 count now 0 + 5
2013-07-17 21:50:27.467475 7f8794894700 10 mds.0.cache.dir(604) _commit want 1 on [dir 604 ~mds0/stray4/ [2,head] auth v=1 cv=0/0 ap=1+0+0 state=1610612738|complete f() n() hs=0+0,ss=0+0 | dirty=1 authpin=1 0x337bbc8]
2013-07-17 21:50:27.467482 7f8794894700 10 mds.0.cache.dir(604) marking committing
2013-07-17 21:50:27.467486 7f8794894700 10 mds.0.cache.snaprealm(100 seq 1 0x3359900) have_past_parents_open [1,head]
2013-07-17 21:50:27.467488 7f8794894700 10 mds.0.cache.dir(604) _commit_partial
2013-07-17 21:50:27.467546 7f8794894700 1 -- 10.214.131.4:6803/27816 --> 10.214.132.29:6806/8238 -- osd_op(mds.0.1:15 604.00000000 [tmapup 0~0] 1.43e85c95 e3) v4 -- ?+0 0x33a0b40 con 0x33359a0
2013-07-17 21:50:27.467566 7f8794894700 0 mds.0.cache creating system inode with ino:605
2013-07-17 21:50:27.467575 7f8794894700 12 mds.0.cache.dir(100) add_primary_dentry [dentry #100/stray5 [2,head] auth (dversion lock) v=0 inode=0x336d300 0x3382b10]
2013-07-17 21:50:27.467581 7f8794894700 10 mds.0.cache.dir(605) pre_dirty 1
2013-07-17 21:50:27.467583 7f8794894700 10 mds.0.cache.dir(605) mark_dirty (was clean) [dir 605 ~mds0/stray5/ [2,head] auth v=1 cv=0/0 state=1073741826|complete f() n() hs=0+0,ss=0+0 0x337bfc0] version 1
2013-07-17 21:50:27.467592 7f8794894700 10 mds.0.cache.dir(605) commit want 0 on [dir 605 ~mds0/stray5/ [2,head] auth v=1 cv=0/0 state=1610612738|complete f() n() hs=0+0,ss=0+0 | dirty=1 0x337bfc0]
2013-07-17 21:50:27.467599 7f8794894700 10 mds.0.cache.dir(605) auth_pin by 0x337bfc0 on [dir 605 ~mds0/stray5/ [2,head] auth v=1 cv=0/0 ap=1+0+0 state=1610612738|complete f() n() hs=0+0,ss=0+0 | dirty=1 authpin=1 0x337bfc0] count now 1 + 0
2013-07-17 21:50:27.467609 7f8794894700 15 mds.0.cache.dir(100) adjust_nested_auth_pins 1/0 on [dir 100 ~mds0/ [2,head] auth v=0 cv=0/0 dir_auth=0 ap=0+0+6 state=1073741824 f(v0 6=0+6)/f() n(v0 6=0+6)/n() hs=6+0,ss=0+0 dirty=6 | child=1 subtree=1 0x337a7f0] by 0x337bfc0 count now 0 + 6
2013-07-17 21:50:27.467620 7f8794894700 10 mds.0.cache.dir(605) _commit want 1 on [dir 605 ~mds0/stray5/ [2,head] auth v=1 cv=0/0 ap=1+0+0 state=1610612738|complete f() n() hs=0+0,ss=0+0 | dirty=1 authpin=1 0x337bfc0]
2013-07-17 21:50:27.467628 7f8794894700 10 mds.0.cache.dir(605) marking committing
2013-07-17 21:50:27.467631 7f8794894700 10 mds.0.cache.snaprealm(100 seq 1 0x3359900) have_past_parents_open [1,head]
2013-07-17 21:50:27.467634 7f8794894700 10 mds.0.cache.dir(605) _commit_partial
2013-07-17 21:50:27.467671 7f8794894700 1 -- 10.214.131.4:6803/27816 --> 10.214.132.29:6806/8238 -- osd_op(mds.0.1:16 605.00000000 [tmapup 0~0] 1.d0c18e1d e3) v4 -- ?+0 0x33a0900 con 0x33359a0
2013-07-17 21:50:27.467690 7f8794894700 0 mds.0.cache creating system inode with ino:606
2013-07-17 21:50:27.467698 7f8794894700 12 mds.0.cache.dir(100) add_primary_dentry [dentry #100/stray6 [2,head] auth (dversion lock) v=0 inode=0x336db60 0x3382ce8]
2013-07-17 21:50:27.467704 7f8794894700 10 mds.0.cache.dir(606) pre_dirty 1
2013-07-17 21:50:27.467706 7f8794894700 10 mds.0.cache.dir(606) mark_dirty (was clean) [dir 606 ~mds0/stray6/ [2,head] auth v=1 cv=0/0 state=1073741826|complete f() n() hs=0+0,ss=0+0 0x337c3b8] version 1
2013-07-17 21:50:27.467716 7f8794894700 10 mds.0.cache.dir(606) commit want 0 on [dir 606 ~mds0/stray6/ [2,head] auth v=1 cv=0/0 state=1610612738|complete f() n() hs=0+0,ss=0+0 | dirty=1 0x337c3b8]
2013-07-17 21:50:27.467744 7f8794894700 10 mds.0.cache.dir(606) auth_pin by 0x337c3b8 on [dir 606 ~mds0/stray6/ [2,head] auth v=1 cv=0/0 ap=1+0+0 state=1610612738|complete f() n() hs=0+0,ss=0+0 | dirty=1 authpin=1 0x337c3b8] count now 1 + 0
2013-07-17 21:50:27.467752 7f8794894700 15 mds.0.cache.dir(100) adjust_nested_auth_pins 1/0 on [dir 100 ~mds0/ [2,head] auth v=0 cv=0/0 dir_auth=0 ap=0+0+7 state=1073741824 f(v0 7=0+7)/f() n(v0 7=0+7)/n() hs=7+0,ss=0+0 dirty=7 | child=1 subtree=1 0x337a7f0] by 0x337c3b8 count now 0 + 7
2013-07-17 21:50:27.467763 7f8794894700 10 mds.0.cache.dir(606) _commit want 1 on [dir 606 ~mds0/stray6/ [2,head] auth v=1 cv=0/0 ap=1+0+0 state=1610612738|complete f() n() hs=0+0,ss=0+0 | dirty=1 authpin=1 0x337c3b8]
2013-07-17 21:50:27.467770 7f8794894700 10 mds.0.cache.dir(606) marking committing
2013-07-17 21:50:27.467773 7f8794894700 10 mds.0.cache.snaprealm(100 seq 1 0x3359900) have_past_parents_open [1,head]
2013-07-17 21:50:27.467776 7f8794894700 10 mds.0.cache.dir(606) _commit_partial
2013-07-17 21:50:27.467834 7f8794894700 1 -- 10.214.131.4:6803/27816 --> 10.214.132.29:6806/8238 -- osd_op(mds.0.1:17 606.00000000 [tmapup 0~0] 1.f89eaaf4 e3) v4 -- ?+0 0x33a06c0 con 0x33359a0
2013-07-17 21:50:27.467854 7f8794894700 0 mds.0.cache creating system inode with ino:607
2013-07-17 21:50:27.467866 7f8794894700 12 mds.0.cache.dir(100) add_primary_dentry [dentry #100/stray7 [2,head] auth (dversion lock) v=0 inode=0x336e3c0 0x3382ec0]
2013-07-17 21:50:27.467872 7f8794894700 10 mds.0.cache.dir(607) pre_dirty 1
2013-07-17 21:50:27.467874 7f8794894700 10 mds.0.cache.dir(607) mark_dirty (was clean) [dir 607 ~mds0/stray7/ [2,head] auth v=1 cv=0/0 state=1073741826|complete f() n() hs=0+0,ss=0+0 0x337c7b0] version 1
2013-07-17 21:50:27.467884 7f8794894700 10 mds.0.cache.dir(607) commit want 0 on [dir 607 ~mds0/stray7/ [2,head] auth v=1 cv=0/0 state=1610612738|complete f() n() hs=0+0,ss=0+0 | dirty=1 0x337c7b0]
2013-07-17 21:50:27.467891 7f8794894700 10 mds.0.cache.dir(607) auth_pin by 0x337c7b0 on [dir 607 ~mds0/stray7/ [2,head] auth v=1 cv=0/0 ap=1+0+0 state=1610612738|complete f() n() hs=0+0,ss=0+0 | dirty=1 authpin=1 0x337c7b0] count now 1 + 0
2013-07-17 21:50:27.467898 7f8794894700 15 mds.0.cache.dir(100) adjust_nested_auth_pins 1/0 on [dir 100 ~mds0/ [2,head] auth v=0 cv=0/0 dir_auth=0 ap=0+0+8 state=1073741824 f(v0 8=0+8)/f() n(v0 8=0+8)/n() hs=8+0,ss=0+0 dirty=8 | child=1 subtree=1 0x337a7f0] by 0x337c7b0 count now 0 + 8
2013-07-17 21:50:27.467910 7f8794894700 10 mds.0.cache.dir(607) _commit want 1 on [dir 607 ~mds0/stray7/ [2,head] auth v=1 cv=0/0 ap=1+0+0 state=1610612738|complete f() n() hs=0+0,ss=0+0 | dirty=1 authpin=1 0x337c7b0]
2013-07-17 21:50:27.467918 7f8794894700 10 mds.0.cache.dir(607) marking committing
2013-07-17 21:50:27.467921 7f8794894700 10 mds.0.cache.snaprealm(100 seq 1 0x3359900) have_past_parents_open [1,head]
2013-07-17 21:50:27.467923 7f8794894700 10 mds.0.cache.dir(607) _commit_partial
2013-07-17 21:50:27.467963 7f8794894700 1 -- 10.214.131.4:6803/27816 --> 10.214.132.29:6806/8238 -- osd_op(mds.0.1:18 607.00000000 [tmapup 0~0] 1.bb590b7c e3) v4 -- ?+0 0x33a0480 con 0x33359a0
2013-07-17 21:50:27.467982 7f8794894700 0 mds.0.cache creating system inode with ino:608
2013-07-17 21:50:27.467991 7f8794894700 12 mds.0.cache.dir(100) add_primary_dentry [dentry #100/stray8 [2,head] auth (dversion lock) v=0 inode=0x336ec20 0x3383098]
2013-07-17 21:50:27.467997 7f8794894700 10 mds.0.cache.dir(608) pre_dirty 1
2013-07-17 21:50:27.467999 7f8794894700 10 mds.0.cache.dir(608) mark_dirty (was clean) [dir 608 ~mds0/stray8/ [2,head] auth v=1 cv=0/0 state=1073741826|complete f() n() hs=0+0,ss=0+0 0x337cba8] version 1
2013-07-17 21:50:27.468007 7f8794894700 10 mds.0.cache.dir(608) commit want 0 on [dir 608 ~mds0/stray8/ [2,head] auth v=1 cv=0/0 state=1610612738|complete f() n() hs=0+0,ss=0+0 | dirty=1 0x337cba8]
2013-07-17 21:50:27.468014 7f8794894700 10 mds.0.cache.dir(608) auth_pin by 0x337cba8 on [dir 608 ~mds0/stray8/ [2,head] auth v=1 cv=0/0 ap=1+0+0 state=1610612738|complete f() n() hs=0+0,ss=0+0 | dirty=1 authpin=1 0x337cba8] count now 1 + 0
2013-07-17 21:50:27.468022 7f8794894700 15 mds.0.cache.dir(100) adjust_nested_auth_pins 1/0 on [dir 100 ~mds0/ [2,head] auth v=0 cv=0/0 dir_auth=0 ap=0+0+9 state=1073741824 f(v0 9=0+9)/f() n(v0 9=0+9)/n() hs=9+0,ss=0+0 dirty=9 | child=1 subtree=1 0x337a7f0] by 0x337cba8 count now 0 + 9
2013-07-17 21:50:27.468033 7f8794894700 10 mds.0.cache.dir(608) _commit want 1 on [dir 608 ~mds0/stray8/ [2,head] auth v=1 cv=0/0 ap=1+0+0 state=1610612738|complete f() n() hs=0+0,ss=0+0 | dirty=1 authpin=1 0x337cba8]
2013-07-17 21:50:27.468047 7f8794894700 10 mds.0.cache.dir(608) marking committing
2013-07-17 21:50:27.468050 7f8794894700 10 mds.0.cache.snaprealm(100 seq 1 0x3359900) have_past_parents_open [1,head]
2013-07-17 21:50:27.468053 7f8794894700 10 mds.0.cache.dir(608) _commit_partial
2013-07-17 21:50:27.468086 7f8794894700 1 -- 10.214.131.4:6803/27816 --> 10.214.132.29:6806/8238 -- osd_op(mds.0.1:19 608.00000000 [tmapup 0~0] 1.c4405e8e e3) v4 -- ?+0 0x33a0240 con 0x33359a0
2013-07-17 21:50:27.468105 7f8794894700 0 mds.0.cache creating system inode with ino:609
2013-07-17 21:50:27.468114 7f8794894700 12 mds.0.cache.dir(100) add_primary_dentry [dentry #100/stray9 [2,head] auth (dversion lock) v=0 inode=0x336f480 0x3383270]
2013-07-17 21:50:27.468120 7f8794894700 10 mds.0.cache.dir(609) pre_dirty 1
2013-07-17 21:50:27.468122 7f8794894700 10 mds.0.cache.dir(609) mark_dirty (was clean) [dir 609 ~mds0/stray9/ [2,head] auth v=1 cv=0/0 state=1073741826|complete f() n() hs=0+0,ss=0+0 0x337cfa0] version 1
2013-07-17 21:50:27.468130 7f8794894700 10 mds.0.cache.dir(609) commit want 0 on [dir 609 ~mds0/stray9/ [2,head] auth v=1 cv=0/0 state=1610612738|complete f() n() hs=0+0,ss=0+0 | dirty=1 0x337cfa0]
2013-07-17 21:50:27.468137 7f8794894700 10 mds.0.cache.dir(609) auth_pin by 0x337cfa0 on [dir 609 ~mds0/stray9/ [2,head] auth v=1 cv=0/0 ap=1+0+0 state=1610612738|complete f() n() hs=0+0,ss=0+0 | dirty=1 authpin=1 0x337cfa0] count now 1 + 0
2013-07-17 21:50:27.468145 7f8794894700 15 mds.0.cache.dir(100) adjust_nested_auth_pins 1/0 on [dir 100 ~mds0/ [2,head] auth v=0 cv=0/0 dir_auth=0 ap=0+0+10 state=1073741824 f(v0 10=0+10)/f() n(v0 10=0+10)/n() hs=10+0,ss=0+0 dirty=10 | child=1 subtree=1 0x337a7f0] by 0x337cfa0 count now 0 + 10
2013-07-17 21:50:27.468157 7f8794894700 10 mds.0.cache.dir(609) _commit want 1 on [dir 609 ~mds0/stray9/ [2,head] auth v=1 cv=0/0 ap=1+0+0 state=1610612738|complete f() n() hs=0+0,ss=0+0 | dirty=1 authpin=1 0x337cfa0]
2013-07-17 21:50:27.468164 7f8794894700 10 mds.0.cache.dir(609) marking committing
2013-07-17 21:50:27.468167 7f8794894700 10 mds.0.cache.snaprealm(100 seq 1 0x3359900) have_past_parents_open [1,head]
2013-07-17 21:50:27.468170 7f8794894700 10 mds.0.cache.dir(609) _commit_partial
2013-07-17 21:50:27.468207 7f8794894700 1 -- 10.214.131.4:6803/27816 --> 10.214.132.29:6806/8238 -- osd_op(mds.0.1:20 609.00000000 [tmapup 0~0] 1.60b82d07 e3) v4 -- ?+0 0x33a0000 con 0x33359a0
2013-07-17 21:50:27.468227 7f8794894700 0 mds.0.cache creating system inode with ino:200
2013-07-17 21:50:27.468232 7f8794894700 12 mds.0.cache.dir(100) add_primary_dentry [dentry #100/journal [2,head] auth (dversion lock) v=0 inode=0x336fce0 0x3383448]
2013-07-17 21:50:27.468238 7f8794894700 10 mds.0.cache.dir(100) pre_dirty 1
2013-07-17 21:50:27.468246 7f8794894700 10 mds.0.cache.dir(100) mark_dirty (was clean) [dir 100 ~mds0/ [2,head] auth v=1 cv=0/0 dir_auth=0 ap=0+0+10 state=1073741826|complete f(v0 11=1+10) n(v0 11=1+10) hs=11+0,ss=0+0 dirty=11 | child=1 subtree=1 0x337a7f0] version 1
2013-07-17 21:50:27.468257 7f8794894700 10 mds.0.cache.dir(100) commit want 0 on [dir 100 ~mds0/ [2,head] auth v=1 cv=0/0 dir_auth=0 ap=0+0+10 state=1610612738|complete f(v0 11=1+10) n(v0 11=1+10) hs=11+0,ss=0+0 dirty=11 | child=1 subtree=1 dirty=1 0x337a7f0]
2013-07-17 21:50:27.468268 7f8794894700 10 mds.0.cache.dir(100) auth_pin by 0x337a7f0 on [dir 100 ~mds0/ [2,head] auth v=1 cv=0/0 dir_auth=0 ap=1+0+10 state=1610612738|complete f(v0 11=1+10) n(v0 11=1+10) hs=11+0,ss=0+0 dirty=11 | child=1 subtree=1 dirty=1 authpin=1 0x337a7f0] count now 1 + 10
2013-07-17 21:50:27.468279 7f8794894700 10 mds.0.cache.dir(100) _commit want 1 on [dir 100 ~mds0/ [2,head] auth v=1 cv=0/0 dir_auth=0 ap=1+0+10 state=1610612738|complete f(v0 11=1+10) n(v0 11=1+10) hs=11+0,ss=0+0 dirty=11 | child=1 subtree=1 dirty=1 authpin=1 0x337a7f0]
2013-07-17 21:50:27.468288 7f8794894700 10 mds.0.cache.dir(100) marking committing
2013-07-17 21:50:27.468291 7f8794894700 10 mds.0.cache.snaprealm(100 seq 1 0x3359900) have_past_parents_open [1,head]
2013-07-17 21:50:27.468294 7f8794894700 10 mds.0.cache.dir(100) _commit_full
2013-07-17 21:50:27.468301 7f8794894700 14 mds.0.cache.dir(100) pos 28 dn 'journal' inode [inode 200 [2,head] ~mds0/journal auth v1 s=0 n(v0 1=1+0) (iversion lock) 0x336fce0]
2013-07-17 21:50:27.468314 7f8794894700 14 mds.0.cache.dir(100) pos 405 dn 'stray0' inode [inode 600 [...2,head] ~mds0/stray0/ auth v1 ap=0+1 f() n(v0 1=0+1) (iversion lock) | dirfrag=1 0x336a920]
2013-07-17 21:50:27.468326 7f8794894700 14 mds.0.cache.dir(100) pos 782 dn 'stray1' inode [inode 601 [...2,head] ~mds0/stray1/ auth v1 ap=0+1 f() n(v0 1=0+1) (iversion lock) | dirfrag=1 0x336b180]
2013-07-17 21:50:27.468338 7f8794894700 14 mds.0.cache.dir(100) pos 1159 dn 'stray2' inode [inode 602 [...2,head] ~mds0/stray2/ auth v1 ap=0+1 f() n(v0 1=0+1) (iversion lock) | dirfrag=1 0x336b9e0]
2013-07-17 21:50:27.468349 7f8794894700 14 mds.0.cache.dir(100) pos 1536 dn 'stray3' inode [inode 603 [...2,head] ~mds0/stray3/ auth v1 ap=0+1 f() n(v0 1=0+1) (iversion lock) | dirfrag=1 0x336c240]
2013-07-17 21:50:27.468360 7f8794894700 14 mds.0.cache.dir(100) pos 1913 dn 'stray4' inode [inode 604 [...2,head] ~mds0/stray4/ auth v1 ap=0+1 f() n(v0 1=0+1) (iversion lock) | dirfrag=1 0x336caa0]
2013-07-17 21:50:27.468371 7f8794894700 14 mds.0.cache.dir(100) pos 2290 dn 'stray5' inode [inode 605 [...2,head] ~mds0/stray5/ auth v1 ap=0+1 f() n(v0 1=0+1) (iversion lock) | dirfrag=1 0x336d300]
2013-07-17 21:50:27.468383 7f8794894700 14 mds.0.cache.dir(100) pos 2667 dn 'stray6' inode [inode 606 [...2,head] ~mds0/stray6/ auth v1 ap=0+1 f() n(v0 1=0+1) (iversion lock) | dirfrag=1 0x336db60]
2013-07-17 21:50:27.468394 7f8794894700 14 mds.0.cache.dir(100) pos 3044 dn 'stray7' inode [inode 607 [...2,head] ~mds0/stray7/ auth v1 ap=0+1 f() n(v0 1=0+1) (iversion lock) | dirfrag=1 0x336e3c0]
2013-07-17 21:50:27.468405 7f8794894700 14 mds.0.cache.dir(100) pos 3421 dn 'stray8' inode [inode 608 [...2,head] ~mds0/stray8/ auth v1 ap=0+1 f() n(v0 1=0+1) (iversion lock) | dirfrag=1 0x336ec20]
2013-07-17 21:50:27.468416 7f8794894700 14 mds.0.cache.dir(100) pos 3798 dn 'stray9' inode [inode 609 [...2,head] ~mds0/stray9/ auth v1 ap=0+1 f() n(v0 1=0+1) (iversion lock) | dirfrag=1 0x336f480]
2013-07-17 21:50:27.468457 7f8794894700 1 -- 10.214.131.4:6803/27816 --> 10.214.132.29:6806/8238 -- osd_op(mds.0.1:21 100.00000000 [tmapput 0~4378] 1.c5265ab3 e3) v4 -- ?+0 0x3359480 con 0x33359a0
2013-07-17 21:50:27.468484 7f8794894700 10 mds.0.cache.ino(100) store 1
2013-07-17 21:50:27.468498 7f8794894700 20 mds.0.cache.ino(100) encode_snap_blob snaprealm(100 seq 1 lc 0 cr 0 cps 1 snaps={} 0x3359900)
2013-07-17 21:50:27.468534 7f8794894700 1 -- 10.214.131.4:6803/27816 --> 10.214.132.29:6806/8238 -- osd_op(mds.0.1:22 100.00000000.inode [writefull 0~432] 1.85dde07f e3) v4 -- ?+0 0x3319d80 con 0x33359a0
2013-07-17 21:50:27.468551 7f8794894700 10 mds.0.1 boot_create creating fresh inotable table
2013-07-17 21:50:27.468573 7f8794894700 10 mds.0.inotable: save v 0
2013-07-17 21:50:27.468612 7f8794894700 1 -- 10.214.131.4:6803/27816 --> 10.214.132.29:6806/8238 -- osd_op(mds.0.1:23 mds0_inotable [writefull 0~34] 1.b852b893 e3) v4 -- ?+0 0x3359d80 con 0x33359a0
2013-07-17 21:50:27.468632 7f8794894700 10 mds.0.sessionmap save needv 0, v 0
2013-07-17 21:50:27.468671 7f8794894700 1 -- 10.214.131.4:6803/27816 --> 10.214.132.29:6806/8238 -- osd_op(mds.0.1:24 mds0_sessionmap [writefull 0~22] 1.3270c60b e3) v4 -- ?+0 0x3359b40 con 0x33359a0
2013-07-17 21:50:27.468687 7f8794894700 10 mds.0.1 boot_create creating fresh anchortable
2013-07-17 21:50:27.468696 7f8794894700 10 mds.0.anchortable: save v 0
2013-07-17 21:50:27.468729 7f8794894700 1 -- 10.214.131.4:6803/27816 --> 10.214.132.29:6806/8238 -- osd_op(mds.0.1:25 mds_anchortable [writefull 0~34] 1.a977f6a7 e3) v4 -- ?+0 0x33596c0 con 0x33359a0
2013-07-17 21:50:27.468745 7f8794894700 7 mds.0.tableserver(anchortable) handle_mds_recovery mds.0
2013-07-17 21:50:27.468751 7f8794894700 1 -- 10.214.131.4:6803/27816 --> mds.0 10.214.131.4:6803/27816 -- mds_table_request(anchortable server_ready) v1 -- ?+0 0x3322c00
2013-07-17 21:50:27.468768 7f8794894700 10 mds.0.1 boot_create creating fresh snaptable
2013-07-17 21:50:27.468773 7f8794894700 10 mds.0.snaptable: save v 0
2013-07-17 21:50:27.468810 7f8794894700 1 -- 10.214.131.4:6803/27816 --> 10.214.132.29:6806/8238 -- osd_op(mds.0.1:26 mds_snaptable [writefull 0~46] 1.d90270ad e3) v4 -- ?+0 0x33c0d80 con 0x33359a0
2013-07-17 21:50:27.468829 7f8794894700 7 mds.0.tableserver(snaptable) handle_mds_recovery mds.0
2013-07-17 21:50:27.468832 7f8794894700 1 -- 10.214.131.4:6803/27816 --> mds.0 10.214.131.4:6803/27816 -- mds_table_request(snaptable server_ready) v1 -- ?+0 0x3322800
2013-07-17 21:50:27.468858 7f8794894700 10 mds.0.bal check_targets have need want
2013-07-17 21:50:27.468885 7f8794894700 15 mds.0.bal map: i imported [dir 1 / [2,head] auth v=1 cv=1/0 REP dir_auth=0 ap=1+0+1 state=1610612802|complete f(v0 1=0+1) n(v0 1=0+1) hs=1+0,ss=0+0 dirty=1 | child=1 subtree=1 dirty=1 authpin=1 0x337a000] from 0
2013-07-17 21:50:27.468897 7f8794894700 15 mds.0.bal map: i imported [dir 100 ~mds0/ [2,head] auth v=1 cv=1/0 dir_auth=0 ap=1+0+10 state=1610612802|complete f(v0 11=1+10) n(v0 11=1+10) hs=11+0,ss=0+0 dirty=11 | child=1 subtree=1 dirty=1 authpin=1 0x337a7f0] from 0
2013-07-17 21:50:27.468910 7f8794894700 5 mds.0.bal rebalance done
2013-07-17 21:50:27.468914 7f8794894700 15 mds.0.cache show_subtrees
2013-07-17 21:50:27.468919 7f8794894700 10 mds.0.cache |__ 0 auth [dir 1 / [2,head] auth v=1 cv=1/0 REP dir_auth=0 ap=1+0+1 state=1610612802|complete f(v0 1=0+1) n(v0 1=0+1) hs=1+0,ss=0+0 dirty=1 | child=1 subtree=1 dirty=1 authpin=1 0x337a000]
2013-07-17 21:50:27.468929 7f8794894700 10 mds.0.cache |__ 0 auth [dir 100 ~mds0/ [2,head] auth v=1 cv=1/0 dir_auth=0 ap=1+0+10 state=1610612802|complete f(v0 11=1+10) n(v0 11=1+10) hs=11+0,ss=0+0 dirty=11 | child=1 subtree=1 dirty=1 authpin=1 0x337a7f0]
2013-07-17 21:50:27.468971 7f8794894700 5 mds.0.1 ms_handle_connect on 10.214.132.29:6806/8238
2013-07-17 21:50:27.468978 7f8794894700 1 -- 10.214.131.4:6803/27816 <== osd.2 10.214.132.29:6806/8238 1 ==== osd_op_reply(3 200.00000002 [delete] ondisk = -2 (No such file or directory)) v4 ==== 111+0+0 (4267176877 0 0) 0x3389000 con 0x33359a0
2013-07-17 21:50:27.470842 7f8794894700 1 -- 10.214.131.4:6803/27816 <== mds.0 10.214.131.4:6803/27816 0 ==== mds_table_request(anchortable server_ready) v1 ==== 0+0+0 (0 0 0) 0x3322c00 con 0x33352c0
2013-07-17 21:50:27.470904 7f8794894700 10 mds.0.tableclient(anchortable) handle_request mds_table_request(anchortable server_ready) v1
2013-07-17 21:50:27.470925 7f8794894700 1 -- 10.214.131.4:6803/27816 <== osd.2 10.214.132.29:6806/8238 2 ==== osd_op_reply(2 200.00000001 [delete] ondisk = -2 (No such file or directory)) v4 ==== 111+0+0 (617372672 0 0) 0x3389400 con 0x33359a0
2013-07-17 21:50:27.470989 7f8794894700 1 -- 10.214.131.4:6803/27816 --> 10.214.132.29:6806/8238 -- osd_op(mds.0.1:27 200.00000001 [write 0~160] 1.6e5f474 e3) v4 -- ?+0 0x33c0b40 con 0x33359a0
2013-07-17 21:50:27.471025 7f8794894700 1 -- 10.214.131.4:6803/27816 <== mds.0 10.214.131.4:6803/27816 0 ==== mds_table_request(snaptable server_ready) v1 ==== 0+0+0 (0 0 0) 0x3322800 con 0x33352c0
2013-07-17 21:50:27.471036 7f8794894700 10 mds.0.tableclient(snaptable) handle_request mds_table_request(snaptable server_ready) v1
2013-07-17 21:50:27.471049 7f8794894700 1 -- 10.214.131.4:6803/27816 <== osd.2 10.214.132.29:6806/8238 3 ==== osd_op_reply(4 200.00000003 [delete] ondisk = -2 (No such file or directory)) v4 ==== 111+0+0 (2719387935 0 0) 0x3389200 con 0x33359a0
2013-07-17 21:50:27.471093 7f8794894700 1 -- 10.214.131.4:6803/27816 <== osd.2 10.214.132.29:6806/8238 4 ==== osd_op_reply(5 200.00000004 [delete] ondisk = -2 (No such file or directory)) v4 ==== 111+0+0 (3312959205 0 0) 0x3389a00 con 0x33359a0
2013-07-17 21:50:27.471129 7f8794894700 1 -- 10.214.131.4:6803/27816 <== osd.2 10.214.132.29:6806/8238 5 ==== osd_op_reply(6 200.00000005 [delete] ondisk = -2 (No such file or directory)) v4 ==== 111+0+0 (2304079618 0 0) 0x3389800 con 0x33359a0
2013-07-17 21:50:27.471160 7f8794894700 1 -- 10.214.131.4:6803/27816 <== osd.2 10.214.132.29:6806/8238 6 ==== osd_op_reply(7 200.00000006 [delete] ondisk = -2 (No such file or directory)) v4 ==== 111+0+0 (3003053436 0 0) 0x3389600 con 0x33359a0
2013-07-17 21:50:27.492339 7f8794894700 1 -- 10.214.131.4:6803/27816 <== osd.2 10.214.132.29:6806/8238 7 ==== osd_op_reply(1 200.00000000 [writefull 0~84] ondisk = 0) v4 ==== 111+0+0 (1348897530 0 0) 0x3389000 con 0x33359a0
2013-07-17 21:50:27.517293 7f8794894700 1 -- 10.214.131.4:6803/27816 <== osd.2 10.214.132.29:6806/8238 8 ==== osd_op_reply(8 2.00000000 [tmapup 0~0] ondisk = 0) v4 ==== 109+0+0 (642622765 0 0) 0x3322800 con 0x33359a0
2013-07-17 21:50:27.517358 7f8794894700 10 mds.0.cache.dir(2) _committed v 1 (last renamed 0) on [dir 2 /.ceph/ [2,head] auth v=1 cv=1/0 REP ap=1+0+0 state=1610612802|complete f() n() hs=0+0,ss=0+0 | dirty=1 authpin=1 0x337a3f8]
2013-07-17 21:50:27.517374 7f8794894700 10 mds.0.cache.dir(2) mark_clean [dir 2 /.ceph/ [2,head] auth v=1 cv=1/1 REP ap=1+0+0 state=1610612738|complete f() n() hs=0+0,ss=0+0 | dirty=1 authpin=1 0x337a3f8] version 1
2013-07-17 21:50:27.517385 7f8794894700 10 mds.0.cache.dir(2) auth_unpin by 0x337a3f8 on [dir 2 /.ceph/ [2,head] auth v=1 cv=1/1 REP state=1073741826|complete f() n() hs=0+0,ss=0+0 0x337a3f8] count now 0 + 0
2013-07-17 21:50:27.517392 7f8794894700 15 mds.0.cache.dir(1) adjust_nested_auth_pins -1/0 on [dir 1 / [2,head] auth v=1 cv=1/0 REP dir_auth=0 ap=1+0+0 state=1610612802|complete f(v0 1=0+1) n(v0 1=0+1) hs=1+0,ss=0+0 dirty=1 | child=1 subtree=1 dirty=1 authpin=1 0x337a000] by 0x337a3f8 count now 1 + 0
2013-07-17 21:50:27.517403 7f8794894700 7 mds.0.1 mds has 1 queued contexts
2013-07-17 21:50:27.517405 7f8794894700 10 mds.0.1 0x330e170
2013-07-17 21:50:27.517406 7f8794894700 10 mds.0.1 finish 0x330e170
2013-07-17 21:50:27.517615 7f8794894700 1 -- 10.214.131.4:6803/27816 <== osd.2 10.214.132.29:6806/8238 9 ==== osd_op_reply(9 1.00000000 [tmapput 0~606] ondisk = 0) v4 ==== 109+0+0 (835089120 0 0) 0x3322c00 con 0x33359a0
2013-07-17 21:50:27.517660 7f8794894700 10 mds.0.cache.dir(1) _committed v 1 (last renamed 0) on [dir 1 / [2,head] auth v=1 cv=1/0 REP dir_auth=0 ap=1+0+0 state=1610612802|complete f(v0 1=0+1) n(v0 1=0+1) hs=1+0,ss=0+0 dirty=1 | child=1 subtree=1 dirty=1 authpin=1 0x337a000]
2013-07-17 21:50:27.517675 7f8794894700 10 mds.0.cache.dir(1) mark_clean [dir 1 / [2,head] auth v=1 cv=1/1 REP dir_auth=0 ap=1+0+0 state=1610612738|complete f(v0 1=0+1) n(v0 1=0+1) hs=1+0,ss=0+0 dirty=1 | child=1 subtree=1 dirty=1 authpin=1 0x337a000] version 1
2013-07-17 21:50:27.517685 7f8794894700 15 mds.0.cache.dir(1) dir 1 >= dn 0 now clean [dentry #1/.ceph [2,head] auth (dversion lock) v=0 inode=0x3369860 | inodepin=0 dirty=1 0x3382000]
2013-07-17 21:50:27.517693 7f8794894700 10 mds.0.cache.den(1 .ceph) mark_clean [dentry #1/.ceph [2,head] auth (dversion lock) v=0 inode=0x3369860 | inodepin=0 dirty=1 0x3382000]
2013-07-17 21:50:27.517700 7f8794894700 10 mds.0.cache.dir(1) auth_unpin by 0x337a000 on [dir 1 / [2,head] auth v=1 cv=1/1 REP dir_auth=0 state=1073741826|complete f(v0 1=0+1) n(v0 1=0+1) hs=1+0,ss=0+0 | child=1 subtree=1 dirty=0 authpin=0 0x337a000] count now 0 + 0
2013-07-17 21:50:27.517711 7f8794894700 7 mds.0.1 mds has 1 queued contexts
2013-07-17 21:50:27.517713 7f8794894700 10 mds.0.1 0x330e260
2013-07-17 21:50:27.517714 7f8794894700 10 mds.0.1 finish 0x330e260
2013-07-17 21:50:27.517734 7f8794894700 1 -- 10.214.131.4:6803/27816 <== osd.2 10.214.132.29:6806/8238 10 ==== osd_op_reply(11 600.00000000 [tmapup 0~0] ondisk = 0) v4 ==== 111+0+0 (1492093217 0 0) 0x3322a00 con 0x33359a0
2013-07-17 21:50:27.517756 7f8794894700 10 mds.0.cache.dir(600) _committed v 1 (last renamed 0) on [dir 600 ~mds0/stray0/ [2,head] auth v=1 cv=1/0 ap=1+0+0 state=1610612802|complete f() n() hs=0+0,ss=0+0 | dirty=1 authpin=1 0x337abe8]
2013-07-17 21:50:27.517767 7f8794894700 10 mds.0.cache.dir(600) mark_clean [dir 600 ~mds0/stray0/ [2,head] auth v=1 cv=1/1 ap=1+0+0 state=1610612738|complete f() n() hs=0+0,ss=0+0 | dirty=1 authpin=1 0x337abe8] version 1
2013-07-17 21:50:27.517775 7f8794894700 10 mds.0.cache.dir(600) auth_unpin by 0x337abe8 on [dir 600 ~mds0/stray0/ [2,head] auth v=1 cv=1/1 state=1073741826|complete f() n() hs=0+0,ss=0+0 0x337abe8] count now 0 + 0
2013-07-17 21:50:27.517782 7f8794894700 15 mds.0.cache.dir(100) adjust_nested_auth_pins -1/0 on [dir 100 ~mds0/ [2,head] auth v=1 cv=1/0 dir_auth=0 ap=1+0+9 state=1610612802|complete f(v0 11=1+10) n(v0 11=1+10) hs=11+0,ss=0+0 dirty=11 | child=1 subtree=1 dirty=1 authpin=1 0x337a7f0] by 0x337abe8 count now 1 + 9
2013-07-17 21:50:27.517793 7f8794894700 7 mds.0.1 mds has 1 queued contexts
2013-07-17 21:50:27.517795 7f8794894700 10 mds.0.1 0x330e240
2013-07-17 21:50:27.517797 7f8794894700 10 mds.0.1 finish 0x330e240
2013-07-17 21:50:27.517830 7f8794894700 1 -- 10.214.131.4:6803/27816 <== osd.2 10.214.132.29:6806/8238 11 ==== osd_op_reply(12 601.00000000 [tmapup 0~0] ondisk = 0) v4 ==== 111+0+0 (3759910191 0 0) 0x3322800 con 0x33359a0
2013-07-17 21:50:27.517851 7f8794894700 10 mds.0.cache.dir(601) _committed v 1 (last renamed 0) on [dir 601 ~mds0/stray1/ [2,head] auth v=1 cv=1/0 ap=1+0+0 state=1610612802|complete f() n() hs=0+0,ss=0+0 | dirty=1 authpin=1 0x337afe0]
2013-07-17 21:50:27.517861 7f8794894700 10 mds.0.cache.dir(601) mark_clean [dir 601 ~mds0/stray1/ [2,head] auth v=1 cv=1/1 ap=1+0+0 state=1610612738|complete f() n() hs=0+0,ss=0+0 | dirty=1 authpin=1 0x337afe0] version 1
2013-07-17 21:50:27.517868 7f8794894700 10 mds.0.cache.dir(601) auth_unpin by 0x337afe0 on [dir 601 ~mds0/stray1/ [2,head] auth v=1 cv=1/1 state=1073741826|complete f() n() hs=0+0,ss=0+0 0x337afe0] count now 0 + 0
2013-07-17 21:50:27.517875 7f8794894700 15 mds.0.cache.dir(100) adjust_nested_auth_pins -1/0 on [dir 100 ~mds0/ [2,head] auth v=1 cv=1/0 dir_auth=0 ap=1+0+8 state=1610612802|complete f(v0 11=1+10) n(v0 11=1+10) hs=11+0,ss=0+0 dirty=11 | child=1 subtree=1 dirty=1 authpin=1 0x337a7f0] by 0x337afe0 count now 1 + 8
2013-07-17 21:50:27.517887 7f8794894700 7 mds.0.1 mds has 1 queued contexts
2013-07-17 21:50:27.517889 7f8794894700 10 mds.0.1 0x330e230
2013-07-17 21:50:27.517890 7f8794894700 10 mds.0.1 finish 0x330e230
2013-07-17 21:50:27.517929 7f8794894700 1 -- 10.214.131.4:6803/27816 <== osd.2 10.214.132.29:6806/8238 12 ==== osd_op_reply(13 602.00000000 [tmapup 0~0] ondisk = 0) v4 ==== 111+0+0 (3329043125 0 0) 0x3398a00 con 0x33359a0
2013-07-17 21:50:27.517949 7f8794894700 10 mds.0.cache.dir(602) _committed v 1 (last renamed 0) on [dir 602 ~mds0/stray2/ [2,head] auth v=1 cv=1/0 ap=1+0+0 state=1610612802|complete f() n() hs=0+0,ss=0+0 | dirty=1 authpin=1 0x337b3d8]
2013-07-17 21:50:27.517958 7f8794894700 10 mds.0.cache.dir(602) mark_clean [dir 602 ~mds0/stray2/ [2,head] auth v=1 cv=1/1 ap=1+0+0 state=1610612738|complete f() n() hs=0+0,ss=0+0 | dirty=1 authpin=1 0x337b3d8] version 1
2013-07-17 21:50:27.517966 7f8794894700 10 mds.0.cache.dir(602) auth_unpin by 0x337b3d8 on [dir 602 ~mds0/stray2/ [2,head] auth v=1 cv=1/1 state=1073741826|complete f() n() hs=0+0,ss=0+0 0x337b3d8] count now 0 + 0
2013-07-17 21:50:27.517973 7f8794894700 15 mds.0.cache.dir(100) adjust_nested_auth_pins -1/0 on [dir 100 ~mds0/ [2,head] auth v=1 cv=1/0 dir_auth=0 ap=1+0+7 state=1610612802|complete f(v0 11=1+10) n(v0 11=1+10) hs=11+0,ss=0+0 dirty=11 | child=1 subtree=1 dirty=1 authpin=1 0x337a7f0] by 0x337b3d8 count now 1 + 7
2013-07-17 21:50:27.517986 7f8794894700 7 mds.0.1 mds has 1 queued contexts
2013-07-17 21:50:27.517987 7f8794894700 10 mds.0.1 0x330e1f0
2013-07-17 21:50:27.517989 7f8794894700 10 mds.0.1 finish 0x330e1f0
2013-07-17 21:50:27.518003 7f8794894700 1 -- 10.214.131.4:6803/27816 <== osd.2 10.214.132.29:6806/8238 13 ==== osd_op_reply(15 604.00000000 [tmapup 0~0] ondisk = 0) v4 ==== 111+0+0 (2598908472 0 0) 0x3398800 con 0x33359a0
2013-07-17 21:50:27.518024 7f8794894700 10 mds.0.cache.dir(604) _committed v 1 (last renamed 0) on [dir 604 ~mds0/stray4/ [2,head] auth v=1 cv=1/0 ap=1+0+0 state=1610612802|complete f() n() hs=0+0,ss=0+0 | dirty=1 authpin=1 0x337bbc8]
2013-07-17 21:50:27.518033 7f8794894700 10 mds.0.cache.dir(604) mark_clean [dir 604 ~mds0/stray4/ [2,head] auth v=1 cv=1/1 ap=1+0+0 state=1610612738|complete f() n() hs=0+0,ss=0+0 | dirty=1 authpin=1 0x337bbc8] version 1
2013-07-17 21:50:27.518041 7f8794894700 10 mds.0.cache.dir(604) auth_unpin by 0x337bbc8 on [dir 604 ~mds0/stray4/ [2,head] auth v=1 cv=1/1 state=1073741826|complete f() n() hs=0+0,ss=0+0 0x337bbc8] count now 0 + 0
2013-07-17 21:50:27.518048 7f8794894700 15 mds.0.cache.dir(100) adjust_nested_auth_pins -1/0 on [dir 100 ~mds0/ [2,head] auth v=1 cv=1/0 dir_auth=0 ap=1+0+6 state=1610612802|complete f(v0 11=1+10) n(v0 11=1+10) hs=11+0,ss=0+0 dirty=11 | child=1 subtree=1 dirty=1 authpin=1 0x337a7f0] by 0x337bbc8 count now 1 + 6
2013-07-17 21:50:27.518059 7f8794894700 7 mds.0.1 mds has 1 queued contexts
2013-07-17 21:50:27.518060 7f8794894700 10 mds.0.1 0x330e220
2013-07-17 21:50:27.518062 7f8794894700 10 mds.0.1 finish 0x330e220
2013-07-17 21:50:27.518128 7f8794894700 1 -- 10.214.131.4:6803/27816 <== osd.2 10.214.132.29:6806/8238 14 ==== osd_op_reply(14 603.00000000 [tmapup 0~0] ondisk = 0) v4 ==== 111+0+0 (1065151045 0 0) 0x3398600 con 0x33359a0
2013-07-17 21:50:27.518170 7f8794894700 10 mds.0.cache.dir(603) _committed v 1 (last renamed 0) on [dir 603 ~mds0/stray3/ [2,head] auth v=1 cv=1/0 ap=1+0+0 state=1610612802|complete f() n() hs=0+0,ss=0+0 | dirty=1 authpin=1 0x337b7d0]
2013-07-17 21:50:27.518183 7f8794894700 10 mds.0.cache.dir(603) mark_clean [dir 603 ~mds0/stray3/ [2,head] auth v=1 cv=1/1 ap=1+0+0 state=1610612738|complete f() n() hs=0+0,ss=0+0 | dirty=1 authpin=1 0x337b7d0] version 1
2013-07-17 21:50:27.518192 7f8794894700 10 mds.0.cache.dir(603) auth_unpin by 0x337b7d0 on [dir 603 ~mds0/stray3/ [2,head] auth v=1 cv=1/1 state=1073741826|complete f() n() hs=0+0,ss=0+0 0x337b7d0] count now 0 + 0
2013-07-17 21:50:27.518198 7f8794894700 15 mds.0.cache.dir(100) adjust_nested_auth_pins -1/0 on [dir 100 ~mds0/ [2,head] auth v=1 cv=1/0 dir_auth=0 ap=1+0+5 state=1610612802|complete f(v0 11=1+10) n(v0 11=1+10) hs=11+0,ss=0+0 dirty=11 | child=1 subtree=1 dirty=1 authpin=1 0x337a7f0] by 0x337b7d0 count now 1 + 5
2013-07-17 21:50:27.518210 7f8794894700 7 mds.0.1 mds has 1 queued contexts
2013-07-17 21:50:27.518212 7f8794894700 10 mds.0.1 0x330e1e0
2013-07-17 21:50:27.518214 7f8794894700 10 mds.0.1 finish 0x330e1e0
2013-07-17 21:50:27.518257 7f8794894700 1 -- 10.214.131.4:6803/27816 <== osd.2 10.214.132.29:6806/8238 15 ==== osd_op_reply(16 605.00000000 [tmapup 0~0] ondisk = 0) v4 ==== 111+0+0 (1524791589 0 0) 0x3398400 con 0x33359a0
2013-07-17 21:50:27.518279 7f8794894700 10 mds.0.cache.dir(605) _committed v 1 (last renamed 0) on [dir 605 ~mds0/stray5/ [2,head] auth v=1 cv=1/0 ap=1+0+0 state=1610612802|complete f() n() hs=0+0,ss=0+0 | dirty=1 authpin=1 0x337bfc0]
2013-07-17 21:50:27.518289 7f8794894700 10 mds.0.cache.dir(605) mark_clean [dir 605 ~mds0/stray5/ [2,head] auth v=1 cv=1/1 ap=1+0+0 state=1610612738|complete f() n() hs=0+0,ss=0+0 | dirty=1 authpin=1 0x337bfc0] version 1
2013-07-17 21:50:27.518297 7f8794894700 10 mds.0.cache.dir(605) auth_unpin by 0x337bfc0 on [dir 605 ~mds0/stray5/ [2,head] auth v=1 cv=1/1 state=1073741826|complete f() n() hs=0+0,ss=0+0 0x337bfc0] count now 0 + 0
2013-07-17 21:50:27.518303 7f8794894700 15 mds.0.cache.dir(100) adjust_nested_auth_pins -1/0 on [dir 100 ~mds0/ [2,head] auth v=1 cv=1/0 dir_auth=0 ap=1+0+4 state=1610612802|complete f(v0 11=1+10) n(v0 11=1+10) hs=11+0,ss=0+0 dirty=11 | child=1 subtree=1 dirty=1 authpin=1 0x337a7f0] by 0x337bfc0 count now 1 + 4
2013-07-17 21:50:27.518314 7f8794894700 7 mds.0.1 mds has 1 queued contexts
2013-07-17 21:50:27.518316 7f8794894700 10 mds.0.1 0x330e210
2013-07-17 21:50:27.518317 7f8794894700 10 mds.0.1 finish 0x330e210
2013-07-17 21:50:27.518346 7f8794894700 1 -- 10.214.131.4:6803/27816 <== osd.2 10.214.132.29:6806/8238 16 ==== osd_op_reply(17 606.00000000 [tmapup 0~0] ondisk = 0) v4 ==== 111+0+0 (1392700299 0 0) 0x3398200 con 0x33359a0
2013-07-17 21:50:27.518366 7f8794894700 10 mds.0.cache.dir(606) _committed v 1 (last renamed 0) on [dir 606 ~mds0/stray6/ [2,head] auth v=1 cv=1/0 ap=1+0+0 state=1610612802|complete f() n() hs=0+0,ss=0+0 | dirty=1 authpin=1 0x337c3b8]
2013-07-17 21:50:27.518375 7f8794894700 10 mds.0.cache.dir(606) mark_clean [dir 606 ~mds0/stray6/ [2,head] auth v=1 cv=1/1 ap=1+0+0 state=1610612738|complete f() n() hs=0+0,ss=0+0 | dirty=1 authpin=1 0x337c3b8] version 1
2013-07-17 21:50:27.518383 7f8794894700 10 mds.0.cache.dir(606) auth_unpin by 0x337c3b8 on [dir 606 ~mds0/stray6/ [2,head] auth v=1 cv=1/1 state=1073741826|complete f() n() hs=0+0,ss=0+0 0x337c3b8] count now 0 + 0
2013-07-17 21:50:27.518390 7f8794894700 15 mds.0.cache.dir(100) adjust_nested_auth_pins -1/0 on [dir 100 ~mds0/ [2,head] auth v=1 cv=1/0 dir_auth=0 ap=1+0+3 state=1610612802|complete f(v0 11=1+10) n(v0 11=1+10) hs=11+0,ss=0+0 dirty=11 | child=1 subtree=1 dirty=1 authpin=1 0x337a7f0] by 0x337c3b8 count now 1 + 3
2013-07-17 21:50:27.518401 7f8794894700 7 mds.0.1 mds has 1 queued contexts
2013-07-17 21:50:27.518403 7f8794894700 10 mds.0.1 0x330e200
2013-07-17 21:50:27.518404 7f8794894700 10 mds.0.1 finish 0x330e200
2013-07-17 21:50:27.518439 7f8794894700 1 -- 10.214.131.4:6803/27816 <== osd.2 10.214.132.29:6806/8238 17 ==== osd_op_reply(18 607.00000000 [tmapup 0~0] ondisk = 0) v4 ==== 111+0+0 (59527337 0 0) 0x3398000 con 0x33359a0
2013-07-17 21:50:27.518459 7f8794894700 10 mds.0.cache.dir(607) _committed v 1 (last renamed 0) on [dir 607 ~mds0/stray7/ [2,head] auth v=1 cv=1/0 ap=1+0+0 state=1610612802|complete f() n() hs=0+0,ss=0+0 | dirty=1 authpin=1 0x337c7b0]
2013-07-17 21:50:27.518469 7f8794894700 10 mds.0.cache.dir(607) mark_clean [dir 607 ~mds0/stray7/ [2,head] auth v=1 cv=1/1 ap=1+0+0 state=1610612738|complete f() n() hs=0+0,ss=0+0 | dirty=1 authpin=1 0x337c7b0] version 1
2013-07-17 21:50:27.518477 7f8794894700 10 mds.0.cache.dir(607) auth_unpin by 0x337c7b0 on [dir 607 ~mds0/stray7/ [2,head] auth v=1 cv=1/1 state=1073741826|complete f() n() hs=0+0,ss=0+0 0x337c7b0] count now 0 + 0
2013-07-17 21:50:27.518484 7f8794894700 15 mds.0.cache.dir(100) adjust_nested_auth_pins -1/0 on [dir 100 ~mds0/ [2,head] auth v=1 cv=1/0 dir_auth=0 ap=1+0+2 state=1610612802|complete f(v0 11=1+10) n(v0 11=1+10) hs=11+0,ss=0+0 dirty=11 | child=1 subtree=1 dirty=1 authpin=1 0x337a7f0] by 0x337c7b0 count now 1 + 2
2013-07-17 21:50:27.518495 7f8794894700 7 mds.0.1 mds has 1 queued contexts
2013-07-17 21:50:27.518496 7f8794894700 10 mds.0.1 0x330e3b0
2013-07-17 21:50:27.518498 7f8794894700 10 mds.0.1 finish 0x330e3b0
2013-07-17 21:50:27.518513 7f8794894700 1 -- 10.214.131.4:6803/27816 <== osd.2 10.214.132.29:6806/8238 18 ==== osd_op_reply(19 608.00000000 [tmapup 0~0] ondisk = 0) v4 ==== 111+0+0 (2183418526 0 0) 0x3398400 con 0x33359a0
2013-07-17 21:50:27.518532 7f8794894700 10 mds.0.cache.dir(608) _committed v 1 (last renamed 0) on [dir 608 ~mds0/stray8/ [2,head] auth v=1 cv=1/0 ap=1+0+0 state=1610612802|complete f() n() hs=0+0,ss=0+0 | dirty=1 authpin=1 0x337cba8]
2013-07-17 21:50:27.518541 7f8794894700 10 mds.0.cache.dir(608) mark_clean [dir 608 ~mds0/stray8/ [2,head] auth v=1 cv=1/1 ap=1+0+0 state=1610612738|complete f() n() hs=0+0,ss=0+0 | dirty=1 authpin=1 0x337cba8] version 1
2013-07-17 21:50:27.518549 7f8794894700 10 mds.0.cache.dir(608) auth_unpin by 0x337cba8 on [dir 608 ~mds0/stray8/ [2,head] auth v=1 cv=1/1 state=1073741826|complete f() n() hs=0+0,ss=0+0 0x337cba8] count now 0 + 0
2013-07-17 21:50:27.518555 7f8794894700 15 mds.0.cache.dir(100) adjust_nested_auth_pins -1/0 on [dir 100 ~mds0/ [2,head] auth v=1 cv=1/0 dir_auth=0 ap=1+0+1 state=1610612802|complete f(v0 11=1+10) n(v0 11=1+10) hs=11+0,ss=0+0 dirty=11 | child=1 subtree=1 dirty=1 authpin=1 0x337a7f0] by 0x337cba8 count now 1 + 1
2013-07-17 21:50:27.518578 7f8794894700 7 mds.0.1 mds has 1 queued contexts
2013-07-17 21:50:27.518580 7f8794894700 10 mds.0.1 0x330e3a0
2013-07-17 21:50:27.518582 7f8794894700 10 mds.0.1 finish 0x330e3a0
2013-07-17 21:50:27.518707 7f8794894700 1 -- 10.214.131.4:6803/27816 <== osd.2 10.214.132.29:6806/8238 19 ==== osd_op_reply(20 609.00000000 [tmapup 0~0] ondisk = 0) v4 ==== 111+0+0 (3620214516 0 0) 0x3398600 con 0x33359a0
2013-07-17 21:50:27.518761 7f8794894700 10 mds.0.cache.dir(609) _committed v 1 (last renamed 0) on [dir 609 ~mds0/stray9/ [2,head] auth v=1 cv=1/0 ap=1+0+0 state=1610612802|complete f() n() hs=0+0,ss=0+0 | dirty=1 authpin=1 0x337cfa0]
2013-07-17 21:50:27.518774 7f8794894700 10 mds.0.cache.dir(609) mark_clean [dir 609 ~mds0/stray9/ [2,head] auth v=1 cv=1/1 ap=1+0+0 state=1610612738|complete f() n() hs=0+0,ss=0+0 | dirty=1 authpin=1 0x337cfa0] version 1
2013-07-17 21:50:27.518783 7f8794894700 10 mds.0.cache.dir(609) auth_unpin by 0x337cfa0 on [dir 609 ~mds0/stray9/ [2,head] auth v=1 cv=1/1 state=1073741826|complete f() n() hs=0+0,ss=0+0 0x337cfa0] count now 0 + 0
2013-07-17 21:50:27.518790 7f8794894700 15 mds.0.cache.dir(100) adjust_nested_auth_pins -1/0 on [dir 100 ~mds0/ [2,head] auth v=1 cv=1/0 dir_auth=0 ap=1+0+0 state=1610612802|complete f(v0 11=1+10) n(v0 11=1+10) hs=11+0,ss=0+0 dirty=11 | child=1 subtree=1 dirty=1 authpin=1 0x337a7f0] by 0x337cfa0 count now 1 + 0
2013-07-17 21:50:27.518802 7f8794894700 7 mds.0.1 mds has 1 queued contexts
2013-07-17 21:50:27.518805 7f8794894700 10 mds.0.1 0x330e390
2013-07-17 21:50:27.518807 7f8794894700 10 mds.0.1 finish 0x330e390
2013-07-17 21:50:27.518823 7f8794894700 1 -- 10.214.131.4:6803/27816 <== osd.2 10.214.132.29:6806/8238 20 ==== osd_op_reply(21 100.00000000 [tmapput 0~4378] ondisk = 0) v4 ==== 111+0+0 (3227118653 0 0) 0x3398800 con 0x33359a0
2013-07-17 21:50:27.518848 7f8794894700 10 mds.0.cache.dir(100) _committed v 1 (last renamed 0) on [dir 100 ~mds0/ [2,head] auth v=1 cv=1/0 dir_auth=0 ap=1+0+0 state=1610612802|complete f(v0 11=1+10) n(v0 11=1+10) hs=11+0,ss=0+0 dirty=11 | child=1 subtree=1 dirty=1 authpin=1 0x337a7f0]
2013-07-17 21:50:27.518861 7f8794894700 10 mds.0.cache.dir(100) mark_clean [dir 100 ~mds0/ [2,head] auth v=1 cv=1/1 dir_auth=0 ap=1+0+0 state=1610612738|complete f(v0 11=1+10) n(v0 11=1+10) hs=11+0,ss=0+0 dirty=11 | child=1 subtree=1 dirty=1 authpin=1 0x337a7f0] version 1
2013-07-17 21:50:27.518871 7f8794894700 15 mds.0.cache.dir(100) dir 1 >= dn 0 now clean [dentry #100/journal [2,head] auth (dversion lock) v=0 inode=0x336fce0 | dirty=1 0x3383448]
2013-07-17 21:50:27.518878 7f8794894700 10 mds.0.cache.den(100 journal) mark_clean [dentry #100/journal [2,head] auth (dversion lock) v=0 inode=0x336fce0 | dirty=1 0x3383448]
2013-07-17 21:50:27.518884 7f8794894700 15 mds.0.cache.dir(100) dir 1 >= dn 0 now clean [dentry #100/stray0 [2,head] auth (dversion lock) v=0 inode=0x336a920 | inodepin=0 dirty=1 0x33821d8]
2013-07-17 21:50:27.518889 7f8794894700 10 mds.0.cache.den(100 stray0) mark_clean [dentry #100/stray0 [2,head] auth (dversion lock) v=0 inode=0x336a920 | inodepin=0 dirty=1 0x33821d8]
2013-07-17 21:50:27.518894 7f8794894700 15 mds.0.cache.dir(100) dir 1 >= dn 0 now clean [dentry #100/stray1 [2,head] auth (dversion lock) v=0 inode=0x336b180 | inodepin=0 dirty=1 0x33823b0]
2013-07-17 21:50:27.518899 7f8794894700 10 mds.0.cache.den(100 stray1) mark_clean [dentry #100/stray1 [2,head] auth (dversion lock) v=0 inode=0x336b180 | inodepin=0 dirty=1 0x33823b0]
2013-07-17 21:50:27.518904 7f8794894700 15 mds.0.cache.dir(100) dir 1 >= dn 0 now clean [dentry #100/stray2 [2,head] auth (dversion lock) v=0 inode=0x336b9e0 | inodepin=0 dirty=1 0x3382588]
2013-07-17 21:50:27.518908 7f8794894700 10 mds.0.cache.den(100 stray2) mark_clean [dentry #100/stray2 [2,head] auth (dversion lock) v=0 inode=0x336b9e0 | inodepin=0 dirty=1 0x3382588]
2013-07-17 21:50:27.518913 7f8794894700 15 mds.0.cache.dir(100) dir 1 >= dn 0 now clean [dentry #100/stray3 [2,head] auth (dversion lock) v=0 inode=0x336c240 | inodepin=0 dirty=1 0x3382760]
2013-07-17 21:50:27.518918 7f8794894700 10 mds.0.cache.den(100 stray3) mark_clean [dentry #100/stray3 [2,head] auth (dversion lock) v=0 inode=0x336c240 | inodepin=0 dirty=1 0x3382760]
2013-07-17 21:50:27.518923 7f8794894700 15 mds.0.cache.dir(100) dir 1 >= dn 0 now clean [dentry #100/stray4 [2,head] auth (dversion lock) v=0 inode=0x336caa0 | inodepin=0 dirty=1 0x3382938]
2013-07-17 21:50:27.518927 7f8794894700 10 mds.0.cache.den(100 stray4) mark_clean [dentry #100/stray4 [2,head] auth (dversion lock) v=0 inode=0x336caa0 | inodepin=0 dirty=1 0x3382938]
2013-07-17 21:50:27.518932 7f8794894700 15 mds.0.cache.dir(100) dir 1 >= dn 0 now clean [dentry #100/stray5 [2,head] auth (dversion lock) v=0 inode=0x336d300 | inodepin=0 dirty=1 0x3382b10]
2013-07-17 21:50:27.518937 7f8794894700 10 mds.0.cache.den(100 stray5) mark_clean [dentry #100/stray5 [2,head] auth (dversion lock) v=0 inode=0x336d300 | inodepin=0 dirty=1 0x3382b10]
2013-07-17 21:50:27.518943 7f8794894700 15 mds.0.cache.dir(100) dir 1 >= dn 0 now clean [dentry #100/stray6 [2,head] auth (dversion lock) v=0 inode=0x336db60 | inodepin=0 dirty=1 0x3382ce8]
2013-07-17 21:50:27.518948 7f8794894700 10 mds.0.cache.den(100 stray6) mark_clean [dentry #100/stray6 [2,head] auth (dversion lock) v=0 inode=0x336db60 | inodepin=0 dirty=1 0x3382ce8]
2013-07-17 21:50:27.518953 7f8794894700 15 mds.0.cache.dir(100) dir 1 >= dn 0 now clean [dentry #100/stray7 [2,head] auth (dversion lock) v=0 inode=0x336e3c0 | inodepin=0 dirty=1 0x3382ec0]
2013-07-17 21:50:27.518957 7f8794894700 10 mds.0.cache.den(100 stray7) mark_clean [dentry #100/stray7 [2,head] auth (dversion lock) v=0 inode=0x336e3c0 | inodepin=0 dirty=1 0x3382ec0]
2013-07-17 21:50:27.518962 7f8794894700 15 mds.0.cache.dir(100) dir 1 >= dn 0 now clean [dentry #100/stray8 [2,head] auth (dversion lock) v=0 inode=0x336ec20 | inodepin=0 dirty=1 0x3383098]
2013-07-17 21:50:27.518967 7f8794894700 10 mds.0.cache.den(100 stray8) mark_clean [dentry #100/stray8 [2,head] auth (dversion lock) v=0 inode=0x336ec20 | inodepin=0 dirty=1 0x3383098]
2013-07-17 21:50:27.518971 7f8794894700 15 mds.0.cache.dir(100) dir 1 >= dn 0 now clean [dentry #100/stray9 [2,head] auth (dversion lock) v=0 inode=0x336f480 | inodepin=0 dirty=1 0x3383270]
2013-07-17 21:50:27.518976 7f8794894700 10 mds.0.cache.den(100 stray9) mark_clean [dentry #100/stray9 [2,head] auth (dversion lock) v=0 inode=0x336f480 | inodepin=0 dirty=1 0x3383270]
2013-07-17 21:50:27.518981 7f8794894700 10 mds.0.cache.dir(100) auth_unpin by 0x337a7f0 on [dir 100 ~mds0/ [2,head] auth v=1 cv=1/1 dir_auth=0 state=1073741826|complete f(v0 11=1+10) n(v0 11=1+10) hs=11+0,ss=0+0 | child=1 subtree=1 dirty=0 authpin=0 0x337a7f0] count now 0 + 0
2013-07-17 21:50:27.518991 7f8794894700 7 mds.0.1 mds has 1 queued contexts
2013-07-17 21:50:27.518993 7f8794894700 10 mds.0.1 0x330e380
2013-07-17 21:50:27.518995 7f8794894700 10 mds.0.1 finish 0x330e380
2013-07-17 21:50:27.519009 7f8794894700 1 -- 10.214.131.4:6803/27816 <== osd.2 10.214.132.29:6806/8238 21 ==== osd_op_reply(10 1.00000000.inode [writefull 0~432] ondisk = 0) v4 ==== 115+0+0 (3288133365 0 0) 0x3398a00 con 0x33359a0
2013-07-17 21:50:27.519050 7f8794894700 10 mds.0.cache.ino(1) _stored 1 [inode 1 [...2,head] / auth v1 snaprealm=0x3359000 f(v0 1=0+1) n(v0 1=0+1) (iversion lock) | dirfrag=1 0x3369000]
2013-07-17 21:50:27.519061 7f8794894700 10 mds.0.cache.ino(1) mark_clean [inode 1 [...2,head] / auth v1 snaprealm=0x3359000 f(v0 1=0+1) n(v0 1=0+1) (iversion lock) | dirfrag=1 0x3369000]
2013-07-17 21:50:27.519081 7f8794894700 1 -- 10.214.131.4:6803/27816 <== osd.2 10.214.132.29:6806/8238 22 ==== osd_op_reply(22 100.00000000.inode [writefull 0~432] ondisk = 0) v4 ==== 117+0+0 (2075139126 0 0) 0x3322800 con 0x33359a0
2013-07-17 21:50:27.519102 7f8794894700 10 mds.0.cache.ino(100) _stored 1 [inode 100 [...2,head] ~mds0/ auth v1 snaprealm=0x3359900 f(v0 11=1+10) n(v0 11=1+10) (iversion lock) | dirfrag=1 0x336a0c0]
2013-07-17 21:50:27.519111 7f8794894700 10 mds.0.cache.ino(100) mark_clean [inode 100 [...2,head] ~mds0/ auth v1 snaprealm=0x3359900 f(v0 11=1+10) n(v0 11=1+10) (iversion lock) | dirfrag=1 0x336a0c0]
2013-07-17 21:50:27.519130 7f8794894700 1 -- 10.214.131.4:6803/27816 <== osd.2 10.214.132.29:6806/8238 23 ==== osd_op_reply(23 mds0_inotable [writefull 0~34] ondisk = 0) v4 ==== 112+0+0 (3061785893 0 0) 0x3322a00 con 0x33359a0
2013-07-17 21:50:27.519167 7f8794894700 10 mds.0.inotable: save_2 v 0
2013-07-17 21:50:27.519205 7f8794894700 1 -- 10.214.131.4:6803/27816 <== osd.2 10.214.132.29:6806/8238 24 ==== osd_op_reply(24 mds0_sessionmap [writefull 0~22] ondisk = 0) v4 ==== 114+0+0 (1605777595 0 0) 0x3322c00 con 0x33359a0
2013-07-17 21:50:27.519225 7f8794894700 10 mds.0.sessionmap _save_finish v0
2013-07-17 21:50:27.519240 7f8794894700 1 -- 10.214.131.4:6803/27816 <== osd.2 10.214.132.29:6806/8238 25 ==== osd_op_reply(25 mds_anchortable [writefull 0~34] ondisk = 0) v4 ==== 114+0+0 (2213932715 0 0) 0x3398e00 con 0x33359a0
2013-07-17 21:50:27.519268 7f8794894700 10 mds.0.anchortable: save_2 v 0
2013-07-17 21:50:27.519283 7f8794894700 1 -- 10.214.131.4:6803/27816 <== osd.2 10.214.132.29:6806/8238 26 ==== osd_op_reply(26 mds_snaptable [writefull 0~46] ondisk = 0) v4 ==== 112+0+0 (1800148471 0 0) 0x3398c00 con 0x33359a0
2013-07-17 21:50:27.519300 7f8794894700 10 mds.0.snaptable: save_2 v 0
2013-07-17 21:50:27.519313 7f8794894700 1 -- 10.214.131.4:6803/27816 <== osd.2 10.214.132.29:6806/8238 27 ==== osd_op_reply(27 200.00000001 [write 0~160] ondisk = 0) v4 ==== 111+0+0 (1261161421 0 0) 0x3322a00 con 0x33359a0
2013-07-17 21:50:27.519338 7f8794894700 1 mds.0.1 creating_done
2013-07-17 21:50:27.519341 7f8794894700 3 mds.0.1 request_state up:active
2013-07-17 21:50:27.519343 7f8794894700 10 mds.0.1 beacon_send up:active seq 2 (currently up:creating)
2013-07-17 21:50:27.519356 7f8794894700 1 -- 10.214.131.4:6803/27816 --> 10.214.132.29:6789/0 -- mdsbeacon(4099/a up:active seq 2 v5) v2 -- ?+0 0x334f840 con 0x3335840
2013-07-17 21:50:27.519379 7f8794894700 7 mds.0.log start_new_segment at 4194464
2013-07-17 21:50:27.519382 7f8794894700 10 mds.0.cache create_subtree_map 2 subtrees, 2 fullauth
2013-07-17 21:50:27.519385 7f8794894700 15 mds.0.cache show_subtrees
2013-07-17 21:50:27.519390 7f8794894700 10 mds.0.cache |__ 0 auth [dir 1 / [2,head] auth v=1 cv=1/1 REP dir_auth=0 state=1073741826|complete f(v0 1=0+1) n(v0 1=0+1) hs=1+0,ss=0+0 | child=1 subtree=1 dirty=0 authpin=0 0x337a000]
2013-07-17 21:50:27.519401 7f8794894700 10 mds.0.cache |__ 0 auth [dir 100 ~mds0/ [2,head] auth v=1 cv=1/1 dir_auth=0 state=1073741826|complete f(v0 11=1+10) n(v0 11=1+10) hs=11+0,ss=0+0 | child=1 subtree=1 dirty=0 authpin=0 0x337a7f0]
2013-07-17 21:50:27.519414 7f8794894700 15 mds.0.cache subtree [dir 1 / [2,head] auth v=1 cv=1/1 REP dir_auth=0 state=1073741826|complete f(v0 1=0+1) n(v0 1=0+1) hs=1+0,ss=0+0 | child=1 subtree=1 dirty=0 authpin=0 0x337a000]
2013-07-17 21:50:27.519428 7f8794894700 20 mds.0.journal EMetaBlob::add_dir_context final:
2013-07-17 21:50:27.519433 7f8794894700 15 mds.0.cache subtree [dir 100 ~mds0/ [2,head] auth v=1 cv=1/1 dir_auth=0 state=1073741826|complete f(v0 11=1+10) n(v0 11=1+10) hs=11+0,ss=0+0 | child=1 subtree=1 dirty=0 authpin=0 0x337a7f0]
2013-07-17 21:50:27.519443 7f8794894700 20 mds.0.journal EMetaBlob::add_dir_context final:
2013-07-17 21:50:27.519446 7f8794894700 15 mds.0.cache subtrees {1=[],100=[]}
2013-07-17 21:50:27.519448 7f8794894700 15 mds.0.cache ambiguous_subtrees
2013-07-17 21:50:27.519464 7f8794894700 5 mds.0.log submit_entry 4194464~756 : ESubtreeMap 2 subtrees , 0 ambiguous [metablob 1, 2 dirs]
2013-07-17 21:50:27.519475 7f8794894700 10 mds.0.log Advancing to next stray directory on mds 0
2013-07-17 21:50:27.652751 7f8794894700 1 -- 10.214.131.4:6803/27816 <== mon.1 10.214.132.29:6789/0 16 ==== mdsmap(e 6) v1 ==== 791+0+0 (2287223844 0 0) 0x3322e00 con 0x3335840
2013-07-17 21:50:27.652778 7f8794894700 5 mds.0.1 handle_mds_map epoch 6 from mon.1
2013-07-17 21:50:27.652798 7f8794894700 10 mds.0.1 my compat compat={},rocompat={},incompat={1=base v0.20,2=client writeable ranges,3=default file layouts on dirs,4=dir inode in separate object,5=mds uses versioned encoding}
2013-07-17 21:50:27.652804 7f8794894700 10 mds.0.1 mdsmap compat compat={},rocompat={},incompat={1=base v0.20,2=client writeable ranges,3=default file layouts on dirs,4=dir inode in separate object,5=mds uses versioned encoding}
2013-07-17 21:50:27.652808 7f8794894700 10 mds.0.1 map says i am 10.214.131.4:6803/27816 mds.0.1 state up:active
2013-07-17 21:50:27.652814 7f8794894700 1 mds.0.1 handle_mds_map i am now mds.0.1
2013-07-17 21:50:27.652816 7f8794894700 1 mds.0.1 handle_mds_map state change up:creating --> up:active
2013-07-17 21:50:27.652822 7f8794894700 1 mds.0.1 active_start
2013-07-17 21:50:27.652826 7f8794894700 10 mds.0.cache open_root
2013-07-17 21:50:27.652828 7f8794894700 7 mds.0.cache adjust_subtree_auth 0,-2 -> 0,-2 on [dir 100 ~mds0/ [2,head] auth v=1 cv=1/1 dir_auth=0 state=1073741826|complete f(v0 11=1+10) n(v0 11=1+10) hs=11+0,ss=0+0 | child=1 subtree=1 dirty=0 authpin=0 0x337a7f0]
2013-07-17 21:50:27.652843 7f8794894700 15 mds.0.cache show_subtrees
2013-07-17 21:50:27.652849 7f8794894700 10 mds.0.cache |__ 0 auth [dir 1 / [2,head] auth v=1 cv=1/1 REP dir_auth=0 state=1073741826|complete f(v0 1=0+1) n(v0 1=0+1) hs=1+0,ss=0+0 | child=1 subtree=1 dirty=0 authpin=0 0x337a000]
2013-07-17 21:50:27.652860 7f8794894700 10 mds.0.cache |__ 0 auth [dir 100 ~mds0/ [2,head] auth v=1 cv=1/1 dir_auth=0 state=1073741826|complete f(v0 11=1+10) n(v0 11=1+10) hs=11+0,ss=0+0 | child=1 subtree=1 dirty=0 authpin=0 0x337a7f0]
2013-07-17 21:50:27.652871 7f8794894700 7 mds.0.cache current root is [dir 100 ~mds0/ [2,head] auth v=1 cv=1/1 dir_auth=0 state=1073741826|complete f(v0 11=1+10) n(v0 11=1+10) hs=11+0,ss=0+0 | child=1 subtree=1 dirty=0 authpin=0 0x337a7f0]
2013-07-17 21:50:27.652879 7f8794894700 10 mds.0.cache.dir(100) setting dir_auth=0,-2 from 0,-2 on [dir 100 ~mds0/ [2,head] auth v=1 cv=1/1 dir_auth=0 state=1073741826|complete f(v0 11=1+10) n(v0 11=1+10) hs=11+0,ss=0+0 | child=1 subtree=1 dirty=0 authpin=0 0x337a7f0]
2013-07-17 21:50:27.652888 7f8794894700 15 mds.0.cache show_subtrees
2013-07-17 21:50:27.652892 7f8794894700 10 mds.0.cache |__ 0 auth [dir 1 / [2,head] auth v=1 cv=1/1 REP dir_auth=0 state=1073741826|complete f(v0 1=0+1) n(v0 1=0+1) hs=1+0,ss=0+0 | child=1 subtree=1 dirty=0 authpin=0 0x337a000]
2013-07-17 21:50:27.652901 7f8794894700 10 mds.0.cache |__ 0 auth [dir 100 ~mds0/ [2,head] auth v=1 cv=1/1 dir_auth=0 state=1073741826|complete f(v0 11=1+10) n(v0 11=1+10) hs=11+0,ss=0+0 | child=1 subtree=1 dirty=0 authpin=0 0x337a7f0]
2013-07-17 21:50:27.652914 7f8794894700 10 mds.0.cache populate_mydir [dir 100 ~mds0/ [2,head] auth v=1 cv=1/1 dir_auth=0 state=1073741826|complete f(v0 11=1+10) n(v0 11=1+10) hs=11+0,ss=0+0 | child=1 subtree=1 dirty=0 authpin=0 0x337a7f0]
2013-07-17 21:50:27.652928 7f8794894700 20 mds.0.cache.dir(100) lookup (head, 'stray0')
2013-07-17 21:50:27.652931 7f8794894700 20 mds.0.cache.dir(100) hit -> (stray0,head)
2013-07-17 21:50:27.652935 7f8794894700 20 mds.0.cache stray num 0 is [inode 600 [...2,head] ~mds0/stray0/ auth v1 f() n(v0 1=0+1) (iversion lock) | dirfrag=1 stickydirs=1 stray=1 0x336a920]
2013-07-17 21:50:27.652950 7f8794894700 20 mds.0.cache.dir(100) lookup (head, 'stray1')
2013-07-17 21:50:27.652952 7f8794894700 20 mds.0.cache.dir(100) hit -> (stray1,head)
2013-07-17 21:50:27.652955 7f8794894700 20 mds.0.cache stray num 1 is [inode 601 [...2,head] ~mds0/stray1/ auth v1 f() n(v0 1=0+1) (iversion lock) | dirfrag=1 stickydirs=1 stray=1 0x336b180]
2013-07-17 21:50:27.652965 7f8794894700 20 mds.0.cache.dir(100) lookup (head, 'stray2')
2013-07-17 21:50:27.652967 7f8794894700 20 mds.0.cache.dir(100) hit -> (stray2,head)
2013-07-17 21:50:27.652969 7f8794894700 20 mds.0.cache stray num 2 is [inode 602 [...2,head] ~mds0/stray2/ auth v1 f() n(v0 1=0+1) (iversion lock) | dirfrag=1 stickydirs=1 stray=1 0x336b9e0]
2013-07-17 21:50:27.652978 7f8794894700 20 mds.0.cache.dir(100) lookup (head, 'stray3')
2013-07-17 21:50:27.652980 7f8794894700 20 mds.0.cache.dir(100) hit -> (stray3,head)
2013-07-17 21:50:27.652982 7f8794894700 20 mds.0.cache stray num 3 is [inode 603 [...2,head] ~mds0/stray3/ auth v1 f() n(v0 1=0+1) (iversion lock) | dirfrag=1 stickydirs=1 stray=1 0x336c240]
2013-07-17 21:50:27.652992 7f8794894700 20 mds.0.cache.dir(100) lookup (head, 'stray4')
2013-07-17 21:50:27.652994 7f8794894700 20 mds.0.cache.dir(100) hit -> (stray4,head)
2013-07-17 21:50:27.652996 7f8794894700 20 mds.0.cache stray num 4 is [inode 604 [...2,head] ~mds0/stray4/ auth v1 f() n(v0 1=0+1) (iversion lock) | dirfrag=1 stickydirs=1 stray=1 0x336caa0]
2013-07-17 21:50:27.653005 7f8794894700 20 mds.0.cache.dir(100) lookup (head, 'stray5')
2013-07-17 21:50:27.653007 7f8794894700 20 mds.0.cache.dir(100) hit -> (stray5,head)
2013-07-17 21:50:27.653009 7f8794894700 20 mds.0.cache stray num 5 is [inode 605 [...2,head] ~mds0/stray5/ auth v1 f() n(v0 1=0+1) (iversion lock) | dirfrag=1 stickydirs=1 stray=1 0x336d300]
2013-07-17 21:50:27.653018 7f8794894700 20 mds.0.cache.dir(100) lookup (head, 'stray6')
2013-07-17 21:50:27.653020 7f8794894700 20 mds.0.cache.dir(100) hit -> (stray6,head)
2013-07-17 21:50:27.653022 7f8794894700 20 mds.0.cache stray num 6 is [inode 606 [...2,head] ~mds0/stray6/ auth v1 f() n(v0 1=0+1) (iversion lock) | dirfrag=1 stickydirs=1 stray=1 0x336db60]
2013-07-17 21:50:27.653031 7f8794894700 20 mds.0.cache.dir(100) lookup (head, 'stray7')
2013-07-17 21:50:27.653033 7f8794894700 20 mds.0.cache.dir(100) hit -> (stray7,head)
2013-07-17 21:50:27.653035 7f8794894700 20 mds.0.cache stray num 7 is [inode 607 [...2,head] ~mds0/stray7/ auth v1 f() n(v0 1=0+1) (iversion lock) | dirfrag=1 stickydirs=1 stray=1 0x336e3c0]
2013-07-17 21:50:27.653045 7f8794894700 20 mds.0.cache.dir(100) lookup (head, 'stray8')
2013-07-17 21:50:27.653047 7f8794894700 20 mds.0.cache.dir(100) hit -> (stray8,head)
2013-07-17 21:50:27.653049 7f8794894700 20 mds.0.cache stray num 8 is [inode 608 [...2,head] ~mds0/stray8/ auth v1 f() n(v0 1=0+1) (iversion lock) | dirfrag=1 stickydirs=1 stray=1 0x336ec20]
2013-07-17 21:50:27.653059 7f8794894700 20 mds.0.cache.dir(100) lookup (head, 'stray9')
2013-07-17 21:50:27.653061 7f8794894700 20 mds.0.cache.dir(100) hit -> (stray9,head)
2013-07-17 21:50:27.653064 7f8794894700 20 mds.0.cache stray num 9 is [inode 609 [...2,head] ~mds0/stray9/ auth v1 f() n(v0 1=0+1) (iversion lock) | dirfrag=1 stickydirs=1 stray=1 0x336f480]
2013-07-17 21:50:27.653071 7f8794894700 20 mds.0.cache.dir(100) lookup (head, 'journal')
2013-07-17 21:50:27.653074 7f8794894700 20 mds.0.cache.dir(100) hit -> (journal,head)
2013-07-17 21:50:27.653076 7f8794894700 10 mds.0.cache populate_mydir done
2013-07-17 21:50:27.653079 7f8794894700 10 mds.0.cache clean_open_file_lists
2013-07-17 21:50:27.653083 7f8794894700 10 mds.0.cache scan_stray_dir
2013-07-17 21:50:27.653089 7f8794894700 10 mds.0.cache export_remaining_imported_caps
2013-07-17 21:50:27.653097 7f8794894700 10 mds.0.bal check_targets have need want
2013-07-17 21:50:27.653101 7f8794894700 15 mds.0.bal map: i imported [dir 1 / [2,head] auth v=1 cv=1/1 REP dir_auth=0 state=1073741826|complete f(v0 1=0+1) n(v0 1=0+1) hs=1+0,ss=0+0 | child=1 subtree=1 dirty=0 authpin=0 0x337a000] from 0
2013-07-17 21:50:27.653111 7f8794894700 15 mds.0.bal map: i imported [dir 100 ~mds0/ [2,head] auth v=1 cv=1/1 dir_auth=0 state=1073741826|complete f(v0 11=1+10) n(v0 11=1+10) hs=11+0,ss=0+0 | child=1 subtree=1 dirty=0 authpin=0 0x337a7f0] from 0
2013-07-17 21:50:27.653120 7f8794894700 5 mds.0.bal rebalance done
2013-07-17 21:50:27.653122 7f8794894700 15 mds.0.cache show_subtrees
2013-07-17 21:50:27.653125 7f8794894700 10 mds.0.cache |__ 0 auth [dir 1 / [2,head] auth v=1 cv=1/1 REP dir_auth=0 state=1073741826|complete f(v0 1=0+1) n(v0 1=0+1) hs=1+0,ss=0+0 | child=1 subtree=1 dirty=0 authpin=0 0x337a000]
2013-07-17 21:50:27.653135 7f8794894700 10 mds.0.cache |__ 0 auth [dir 100 ~mds0/ [2,head] auth v=1 cv=1/1 dir_auth=0 state=1073741826|complete f(v0 11=1+10) n(v0 11=1+10) hs=11+0,ss=0+0 | child=1 subtree=1 dirty=0 authpin=0 0x337a7f0]
2013-07-17 21:50:31.519524 7f879268e700 10 mds.0.1 beacon_send up:active seq 3 (currently up:active)
2013-07-17 21:50:31.519577 7f879268e700 1 -- 10.214.131.4:6803/27816 --> 10.214.132.29:6789/0 -- mdsbeacon(4099/a up:active seq 3 v6) v2 -- ?+0 0x334f000 con 0x3335840
2013-07-17 21:50:31.521855 7f8794894700 1 -- 10.214.131.4:6803/27816 <== mon.1 10.214.132.29:6789/0 17 ==== mdsbeacon(4099/a up:active seq 3 v6) v2 ==== 103+0+0 (3919253856 0 0) 0x334f840 con 0x3335840
2013-07-17 21:50:31.521887 7f8794894700 10 mds.0.1 handle_mds_beacon up:active seq 3 rtt 0.002344
2013-07-17 21:50:32.087485 7f879268e700 1 -- 10.214.131.4:6803/27816 --> 10.214.132.29:6806/8238 -- osd_op(mds.0.1:28 200.00000001 [write 160~760] 1.6e5f474 e3) v4 -- ?+0 0x3319d80 con 0x33359a0
2013-07-17 21:50:32.087575 7f879268e700 7 mds.0.cache trim max=100000 cur=12
2013-07-17 21:50:32.087587 7f879268e700 10 mds.0.cache trim_client_leases
2013-07-17 21:50:32.088069 7f879268e700 2 mds.0.cache check_memory_usage total 131400, rss 17232, heap 8208, malloc 507 mmap 0, baseline 8208, buffers 0, max 1048576, 0 / 14 inodes have caps, 0 caps, 0 caps per inode
2013-07-17 21:50:32.088112 7f879268e700 10 mds.0.log trim 2 / 30 segments, 2 / -1 events, 0 (0) expiring, 0 (0) expired
2013-07-17 21:50:32.088119 7f879268e700 10 mds.0.log _trim_expired_segments waiting for 4194304 to expire
2013-07-17 21:50:32.088194 7f879268e700 15 mds.0.bal get_load mdsload<[0,0 0]/[0,0 0], req 0, hr 0, qlen 0, cpu 1.05>
2013-07-17 21:50:32.088251 7f879268e700 10 mds.0.locker scatter_tick
2013-07-17 21:50:32.088268 7f879268e700 10 mds.0.server find_idle_sessions. laggy until 0.000000
2013-07-17 21:50:32.088281 7f879268e700 15 mds.0.bal tick last_sample now 2013-07-17 21:50:32.088281
2013-07-17 21:50:32.088293 7f879268e700 10 mds.0.snap check_osd_map - version unchanged
2013-07-17 21:50:35.519759 7f879268e700 10 mds.0.1 beacon_send up:active seq 4 (currently up:active)
2013-07-17 21:50:35.519800 7f879268e700 1 -- 10.214.131.4:6803/27816 --> 10.214.132.29:6789/0 -- mdsbeacon(4099/a up:active seq 4 v6) v2 -- ?+0 0x334fdc0 con 0x3335840
2013-07-17 21:50:35.522098 7f8794894700 1 -- 10.214.131.4:6803/27816 <== mon.1 10.214.132.29:6789/0 18 ==== mdsbeacon(4099/a up:active seq 4 v6) v2 ==== 103+0+0 (2208896420 0 0) 0x3350340 con 0x3335840
2013-07-17 21:50:35.522129 7f8794894700 10 mds.0.1 handle_mds_beacon up:active seq 4 rtt 0.002351
2013-07-17 21:50:37.087577 7f879268e700 7 mds.0.cache trim max=100000 cur=12
2013-07-17 21:50:37.087593 7f879268e700 10 mds.0.cache trim_client_leases
2013-07-17 21:50:37.087990 7f879268e700 2 mds.0.cache check_memory_usage total 131400, rss 17312, heap 8208, malloc 510 mmap 0, baseline 8208, buffers 0, max 1048576, 0 / 14 inodes have caps, 0 caps, 0 caps per inode
2013-07-17 21:50:37.088015 7f879268e700 10 mds.0.log trim 2 / 30 segments, 2 / -1 events, 0 (0) expiring, 0 (0) expired
2013-07-17 21:50:37.088023 7f879268e700 10 mds.0.log _trim_expired_segments waiting for 4194304 to expire
2013-07-17 21:50:37.088070 7f879268e700 15 mds.0.bal get_load mdsload<[0,0 0]/[0,0 0], req 0, hr 0, qlen 0, cpu 0.96>
2013-07-17 21:50:37.088133 7f879268e700 10 mds.0.locker scatter_tick
2013-07-17 21:50:37.088147 7f879268e700 10 mds.0.server find_idle_sessions. laggy until 0.000000
2013-07-17 21:50:37.088153 7f879268e700 15 mds.0.bal tick last_sample now 2013-07-17 21:50:37.088152
2013-07-17 21:50:37.088159 7f879268e700 10 mds.0.snap check_osd_map - version unchanged
2013-07-17 21:50:38.237135 7f8791d8c700 1 -- 10.214.131.4:6803/27816 >> :/0 pipe(0x335c500 sd=18 :6803 s=0 pgs=0 cs=0 l=0).accept sd=18 10.214.131.17:51708/0
2013-07-17 21:50:38.240557 7f8791d8c700 10 mds.0.1 new session 0x3359b40 for client.4136 10.214.131.17:0/1109 con 0x33a5000
2013-07-17 21:50:38.240657 7f8794894700 10 mds.0.1 ms_handle_accept 10.214.131.17:0/1109 con 0x33a5000 session 0x3359b40
2013-07-17 21:50:38.241187 7f8794894700 1 -- 10.214.131.4:6803/27816 <== client.4136 10.214.131.17:0/1109 1 ==== client_session(request_open) v1 ==== 28+0+0 (0 0 0) 0x33a6000 con 0x33a5000
2013-07-17 21:50:38.241263 7f8794894700 20 mds.0.server get_session have 0x3359b40 client.4136 10.214.131.17:0/1109 state closed
2013-07-17 21:50:38.241277 7f8794894700 3 mds.0.server handle_client_session client_session(request_open) v1 from client.4136
2013-07-17 21:50:38.241291 7f8794894700 5 mds.0.log submit_entry 4195224~194 : ESession client.4136 10.214.131.17:0/1109 open cmapv 1
2013-07-17 21:50:38.241359 7f8794894700 1 -- 10.214.131.4:6803/27816 --> 10.214.132.29:6806/8238 -- osd_op(mds.0.1:29 200.00000001 [write 920~198] 1.6e5f474 e3) v4 -- ?+0 0x33c06c0 con 0x33359a0
2013-07-17 21:50:39.235653 7f8794894700 1 -- 10.214.131.4:6803/27816 <== client.4136 10.214.131.17:0/1109 2 ==== client_session(request_renewcaps seq 1) v1 ==== 28+0+0 (968950716 0 0) 0x333b540 con 0x33a5000
2013-07-17 21:50:39.235687 7f8794894700 20 mds.0.server get_session have 0x3359b40 client.4136 10.214.131.17:0/1109 state opening
2013-07-17 21:50:39.235693 7f8794894700 3 mds.0.server handle_client_session client_session(request_renewcaps seq 1) v1 from client.4136
2013-07-17 21:50:39.235716 7f8794894700 10 mds.0.server ignoring renewcaps on non open|stale session (opening)
2013-07-17 21:50:39.519978 7f879268e700 10 mds.0.1 beacon_send up:active seq 5 (currently up:active)
2013-07-17 21:50:39.520019 7f879268e700 1 -- 10.214.131.4:6803/27816 --> 10.214.132.29:6789/0 -- mdsbeacon(4099/a up:active seq 5 v6) v2 -- ?+0 0x334fb00 con 0x3335840
2013-07-17 21:50:39.522224 7f8794894700 1 -- 10.214.131.4:6803/27816 <== mon.1 10.214.132.29:6789/0 19 ==== mdsbeacon(4099/a up:active seq 5 v6) v2 ==== 103+0+0 (4202719427 0 0) 0x3350080 con 0x3335840
2013-07-17 21:50:39.522257 7f8794894700 10 mds.0.1 handle_mds_beacon up:active seq 5 rtt 0.002260
(2-2/2)