client.admin.log - CephFS - Ceph

Bug #3301 » client.admin.log

Sam Lang, 10/16/2012 10:48 AM

 -10-16 12:43:27.375679 7f493b4a9780  0 ceph version  (commit:), process ceph-fuse, pid 17998
 -10-16 12:43:27.377306 7f4936906700 10 client.-1 ms_handle_connect on 127.0.0.1:6789/0
 -10-16 12:43:27.383791 7f493b4a9780  2 client.4110 mounted: have osdmap 0 and mdsmap 0
 -10-16 12:43:27.383839 7f493b4a9780 10 client.4110 did not get mds through better means, so chose random mds -1
 -10-16 12:43:27.383846 7f493b4a9780 20 client.4110 mds is -1
 -10-16 12:43:27.383849 7f493b4a9780 10 client.4110  target mds.-1 not active, waiting for new mdsmap
 -10-16 12:43:27.386330 7f4936906700  1 client.4110 handle_mds_map epoch 11
 -10-16 12:43:27.386733 7f493b4a9780 10 client.4110 did not get mds through better means, so chose random mds 1
 -10-16 12:43:27.386741 7f493b4a9780 20 client.4110 mds is 1
 -10-16 12:43:27.386754 7f493b4a9780 10 client.4110 opening session to mds.1
 -10-16 12:43:27.386859 7f493b4a9780 10 client.4110 waiting for session to mds.1 to open
 -10-16 12:43:27.387966 7f4936906700 10 client.4110 ms_handle_connect on 127.0.0.1:6804/17802
 -10-16 12:43:27.398512 7f4936906700 10 client.4110 handle_client_session client_session(open) v1 from mds.1
 -10-16 12:43:27.398531 7f4936906700 10 client.4110 renew_caps mds.1
 -10-16 12:43:27.398575 7f4936906700 10 client.4110 connect_mds_targets for mds.1
 -10-16 12:43:27.398859 7f493b4a9780 10 client.4110 send_request rebuilding request 1 for mds.1
 -10-16 12:43:27.398887 7f493b4a9780 20 client.4110 encode_cap_releases enter (req: 0x2283000, mds: 1)
 -10-16 12:43:27.398894 7f493b4a9780 20 client.4110 send_request set sent_stamp to 2012-10-16 12:43:27.398893
 -10-16 12:43:27.398914 7f493b4a9780 10 client.4110 send_request client_request(unknown.0:1 getattr pAsLsXsFs #1) v1 to mds.1
 -10-16 12:43:27.398979 7f493b4a9780 20 client.4110 awaiting reply|forward|kick on 0x7fffa2bb98c0
 -10-16 12:43:27.399152 7f4936906700 10 client.4110 handle_client_session client_session(renewcaps seq 1) v1 from mds.1
 -10-16 12:43:27.399746 7f4936906700 20 client.4110 handle_client_reply got a reply. Safe:1 tid 1
 -10-16 12:43:27.399759 7f4936906700 10 client.4110 insert_trace from 2012-10-16 12:43:27.398893 mds.1 is_target=1 is_dentry=0
 -10-16 12:43:27.399767 7f4936906700 10 client.4110  features 0x7fffff
 -10-16 12:43:27.399770 7f4936906700 10 client.4110 update_snap_trace len 48
 -10-16 12:43:27.399783 7f4936906700 10 client.4110 update_snap_trace snaprealm(1 nref=2 c=0 seq=0 parent=0 my_snaps=[] cached_snapc=0=[]) seq 1 > 0
 -10-16 12:43:27.399794 7f4936906700 10 client.4110  flushing caps on snaprealm(1 nref=2 c=0 seq=0 parent=0 my_snaps=[] cached_snapc=0=[])
 -10-16 12:43:27.399806 7f4936906700 10 client.4110 invalidate_snaprealm_and_children snaprealm(1 nref=2 c=0 seq=1 parent=0 my_snaps=[] cached_snapc=0=[])
 -10-16 12:43:27.399812 7f4936906700 15 client.4110 update_snap_trace snaprealm(1 nref=2 c=0 seq=1 parent=0 my_snaps=[] cached_snapc=0=[]) self|parent updated
 -10-16 12:43:27.399817 7f4936906700 15 client.4110   snapc 1=[]
 -10-16 12:43:27.399826 7f4936906700 10 client.4110  hrm  is_target=1 is_dentry=0
 -10-16 12:43:27.399851 7f4936906700 12 client.4110 add_update_inode adding 1.head(ref=1 cap_refs={} open={} mode=40000 size=0 mtime=0.000000 caps=- 0x2257d80) caps pAsLsXsFs
 -10-16 12:43:27.399869 7f4936906700 20 client.4110  dir hash is 2
 -10-16 12:43:27.399872 7f4936906700 10 client.4110 update_inode_file_bits 1.head(ref=1 cap_refs={} open={} mode=40755 size=0 mtime=0.000000 caps=- 0x2257d80) - mtime 2012-10-16 12:42:04.740872
 -10-16 12:43:27.399889 7f4936906700 15 client.4110 add_update_cap first one, opened snaprealm 0x2289c30
 -10-16 12:43:27.399898 7f4936906700 10 client.4110 add_update_cap issued - -> pAsLsXsFs from mds.1 on 1.head(ref=1 cap_refs={} open={} mode=40755 size=0 mtime=2012-10-16 12:42:04.740872 caps=pAsLsXsFs(1=pAsLsXsFs) 0x2257d80)
 -10-16 12:43:27.399918 7f4936906700 20 client.4110 handle_client_reply signalling caller 0x7fffa2bb98c0
 -10-16 12:43:27.399921 7f4936906700 20 client.4110 handle_client_reply awaiting kickback on tid 1 0x7f49369056d0
 -10-16 12:43:27.399968 7f493b4a9780 20 client.4110 sendrecv kickback on tid 1 0x7f49369056d0
 -10-16 12:43:27.399977 7f493b4a9780 20 client.4110 lat 0.001082
 -10-16 12:43:27.399992 7f493b4a9780 10 client.4110 root getattr result=0
 -10-16 12:43:27.399997 7f493b4a9780 20 client.4110 _ll_get 0x2257d80 1 -> 1
 -10-16 12:43:27.403205 7f493b4a9780  3 client.4110 ll_getattr 1.head
 -10-16 12:43:27.403280 7f493b4a9780 10 client.4110 _getattr mask pAsLsXsFs issued=1
 -10-16 12:43:27.403298 7f493b4a9780 10 client.4110 fill_stat on 1 snap/devhead mode 040755 mtime 2012-10-16 12:42:04.740872 ctime 2012-10-16 12:42:04.740872
 -10-16 12:43:27.403324 7f493b4a9780  3 client.4110 ll_getattr 1.head = 0
 -10-16 12:43:27.403442 7f493b4a9780  3 client.4110 ll_getattr 1.head
 -10-16 12:43:27.403474 7f493b4a9780 10 client.4110 _getattr mask pAsLsXsFs issued=1
 -10-16 12:43:27.403478 7f493b4a9780 10 client.4110 fill_stat on 1 snap/devhead mode 040755 mtime 2012-10-16 12:42:04.740872 ctime 2012-10-16 12:42:04.740872
 -10-16 12:43:27.403487 7f493b4a9780  3 client.4110 ll_getattr 1.head = 0
 -10-16 12:43:27.403513 7f493b4a9780  3 client.4110 ll_lookup 1.head .Trash
 -10-16 12:43:27.403574 7f493b4a9780 10 client.4110 _lookup on #1/.Trash
 -10-16 12:43:27.403595 7f493b4a9780 20 client.4110 choose_target_mds starting with req->inode 1.head(ref=2 cap_refs={} open={} mode=40755 size=0 mtime=2012-10-16 12:42:04.740872 caps=pAsLsXsFs(1=pAsLsXsFs) 0x2257d80)
 -10-16 12:43:27.403622 7f493b4a9780 20 client.4110 choose_target_mds inode dir hash is 2 on .Trash => 571883718
 -10-16 12:43:27.403627 7f493b4a9780 20 client.4110 choose_target_mds 1.head(ref=2 cap_refs={} open={} mode=40755 size=0 mtime=2012-10-16 12:42:04.740872 caps=pAsLsXsFs(1=pAsLsXsFs) 0x2257d80) is_hash=1 hash=571883718
 -10-16 12:43:27.403645 7f493b4a9780 10 client.4110 choose_target_mds from caps on inode 1.head(ref=2 cap_refs={} open={} mode=40755 size=0 mtime=2012-10-16 12:42:04.740872 caps=pAsLsXsFs(1=pAsLsXsFs) 0x2257d80)
 -10-16 12:43:27.403656 7f493b4a9780 20 client.4110 mds is 1
 -10-16 12:43:27.403676 7f493b4a9780 10 client.4110 send_request rebuilding request 2 for mds.1
 -10-16 12:43:27.403701 7f493b4a9780 20 client.4110 encode_cap_releases enter (req: 0x2283580, mds: 1)
 -10-16 12:43:27.403706 7f493b4a9780 20 client.4110 send_request set sent_stamp to 2012-10-16 12:43:27.403706
 -10-16 12:43:27.403721 7f493b4a9780 10 client.4110 send_request client_request(unknown.0:2 lookup #1/.Trash) v1 to mds.1
 -10-16 12:43:27.403801 7f493b4a9780 20 client.4110 awaiting reply|forward|kick on 0x7fffa2bb90d0
 -10-16 12:43:27.404787 7f4936906700 20 client.4110 handle_client_reply got a reply. Safe:1 tid 2
 -10-16 12:43:27.404795 7f4936906700 10 client.4110 insert_trace from 2012-10-16 12:43:27.403706 mds.1 is_target=0 is_dentry=0
 -10-16 12:43:27.404802 7f4936906700 10 client.4110 insert_trace -- no trace
 -10-16 12:43:27.404807 7f4936906700 20 client.4110 handle_client_reply signalling caller 0x7fffa2bb90d0
 -10-16 12:43:27.404810 7f4936906700 20 client.4110 handle_client_reply awaiting kickback on tid 2 0x7f49369056d0
 -10-16 12:43:27.404817 7f493b4a9780 20 client.4110 sendrecv kickback on tid 2 0x7f49369056d0
 -10-16 12:43:27.404823 7f493b4a9780 20 client.4110 lat 0.001116
 -10-16 12:43:27.404840 7f493b4a9780 10 client.4110 _lookup res is -2
 -10-16 12:43:27.404844 7f493b4a9780 10 client.4110 _lookup 1.head(ref=2 cap_refs={} open={} mode=40755 size=0 mtime=2012-10-16 12:42:04.740872 caps=pAsLsXsFs(1=pAsLsXsFs) 0x2257d80) .Trash = -2
 -10-16 12:43:27.404865 7f493b4a9780  3 client.4110 ll_lookup 1.head .Trash -> -2 (0)
 -10-16 12:43:27.404987 7f493b4a9780  3 client.4110 ll_getattr 1.head
 -10-16 12:43:27.404996 7f493b4a9780 10 client.4110 _getattr mask pAsLsXsFs issued=1
 -10-16 12:43:27.405000 7f493b4a9780 10 client.4110 fill_stat on 1 snap/devhead mode 040755 mtime 2012-10-16 12:42:04.740872 ctime 2012-10-16 12:42:04.740872
 -10-16 12:43:27.405008 7f493b4a9780  3 client.4110 ll_getattr 1.head = 0
 -10-16 12:43:27.405029 7f493b4a9780  3 client.4110 ll_lookup 1.head .Trash-1000
 -10-16 12:43:27.405050 7f493b4a9780 10 client.4110 _lookup on #1/.Trash-1000
 -10-16 12:43:27.405059 7f493b4a9780 20 client.4110 choose_target_mds starting with req->inode 1.head(ref=2 cap_refs={} open={} mode=40755 size=0 mtime=2012-10-16 12:42:04.740872 caps=pAsLsXsFs(1=pAsLsXsFs) 0x2257d80)
 -10-16 12:43:27.405073 7f493b4a9780 20 client.4110 choose_target_mds inode dir hash is 2 on .Trash-1000 => 792943375
 -10-16 12:43:27.405076 7f493b4a9780 20 client.4110 choose_target_mds 1.head(ref=2 cap_refs={} open={} mode=40755 size=0 mtime=2012-10-16 12:42:04.740872 caps=pAsLsXsFs(1=pAsLsXsFs) 0x2257d80) is_hash=1 hash=792943375
 -10-16 12:43:27.405089 7f493b4a9780 10 client.4110 choose_target_mds from caps on inode 1.head(ref=2 cap_refs={} open={} mode=40755 size=0 mtime=2012-10-16 12:42:04.740872 caps=pAsLsXsFs(1=pAsLsXsFs) 0x2257d80)
 -10-16 12:43:27.405099 7f493b4a9780 20 client.4110 mds is 1
 -10-16 12:43:27.405108 7f493b4a9780 10 client.4110 send_request rebuilding request 3 for mds.1
 -10-16 12:43:27.405117 7f493b4a9780 20 client.4110 encode_cap_releases enter (req: 0x22832c0, mds: 1)
 -10-16 12:43:27.405122 7f493b4a9780 20 client.4110 send_request set sent_stamp to 2012-10-16 12:43:27.405121
 -10-16 12:43:27.405135 7f493b4a9780 10 client.4110 send_request client_request(unknown.0:3 lookup #1/.Trash-1000) v1 to mds.1
 -10-16 12:43:27.405170 7f493b4a9780 20 client.4110 awaiting reply|forward|kick on 0x7fffa2bb90d0
 -10-16 12:43:27.405686 7f4936906700 10 client.4110 handle_client_request tid 3 fwd 1 to mds.0, resending to 0
 -10-16 12:43:27.405701 7f493b4a9780 10 client.4110 choose_target_mds resend_mds specified as mds.0
 -10-16 12:43:27.405705 7f493b4a9780 20 client.4110 mds is 0
 -10-16 12:43:27.405718 7f493b4a9780 10 client.4110 opening session to mds.0
 -10-16 12:43:27.405835 7f493b4a9780 10 client.4110 waiting for session to mds.0 to open
 -10-16 12:43:27.406493 7f4936906700 10 client.4110 ms_handle_connect on 127.0.0.1:6803/17748
 -10-16 12:43:27.412215 7f4936906700 10 client.4110 handle_client_session client_session(open) v1 from mds.0
 -10-16 12:43:27.412232 7f4936906700 10 client.4110 renew_caps mds.0
 -10-16 12:43:27.412288 7f4936906700 10 client.4110 connect_mds_targets for mds.0
 -10-16 12:43:27.412325 7f493b4a9780 10 client.4110 send_request rebuilding request 3 for mds.0
 -10-16 12:43:27.412339 7f493b4a9780 20 client.4110 encode_cap_releases enter (req: 0x22832c0, mds: 0)
 -10-16 12:43:27.412343 7f493b4a9780 20 client.4110 send_request set sent_stamp to 2012-10-16 12:43:27.412342
 -10-16 12:43:27.412348 7f493b4a9780 10 client.4110 send_request client_request(unknown.0:3 lookup #1/.Trash-1000) v1 to mds.0
 -10-16 12:43:27.412371 7f493b4a9780 20 client.4110 awaiting reply|forward|kick on 0x7fffa2bb90d0
 -10-16 12:43:27.412760 7f4936906700 10 client.4110 handle_client_session client_session(renewcaps seq 1) v1 from mds.0
 -10-16 12:43:27.413752 7f4936906700 20 client.4110 handle_client_reply got a reply. Safe:1 tid 3
 -10-16 12:43:27.413756 7f4936906700 10 client.4110 insert_trace from 2012-10-16 12:43:27.412342 mds.0 is_target=0 is_dentry=0
 -10-16 12:43:27.413762 7f4936906700 10 client.4110 insert_trace -- no trace
 -10-16 12:43:27.413765 7f4936906700 20 client.4110 handle_client_reply signalling caller 0x7fffa2bb90d0
 -10-16 12:43:27.413768 7f4936906700 20 client.4110 handle_client_reply awaiting kickback on tid 3 0x7f49369056d0
 -10-16 12:43:27.413773 7f493b4a9780 20 client.4110 sendrecv kickback on tid 3 0x7f49369056d0
 -10-16 12:43:27.413779 7f493b4a9780 20 client.4110 lat 0.001436
 -10-16 12:43:27.413789 7f493b4a9780 10 client.4110 _lookup res is -2
 -10-16 12:43:27.413792 7f493b4a9780 10 client.4110 _lookup 1.head(ref=2 cap_refs={} open={} mode=40755 size=0 mtime=2012-10-16 12:42:04.740872 caps=pAsLsXsFs(1=pAsLsXsFs) 0x2257d80) .Trash-1000 = -2
 -10-16 12:43:27.413811 7f493b4a9780  3 client.4110 ll_lookup 1.head .Trash-1000 -> -2 (0)
 -10-16 12:43:28.384017 7f4937908700 10 client.4110 renew_caps()
 -10-16 12:43:28.384084 7f4937908700 15 client.4110 renew_caps requesting from mds.0
 -10-16 12:43:28.384133 7f4937908700 10 client.4110 renew_caps mds.0
 -10-16 12:43:28.384454 7f4937908700 15 client.4110 renew_caps requesting from mds.1
 -10-16 12:43:28.384510 7f4937908700 10 client.4110 renew_caps mds.1
 -10-16 12:43:28.386821 7f4936906700 10 client.4110 handle_client_session client_session(renewcaps seq 2) v1 from mds.0
 -10-16 12:43:28.387091 7f4936906700 10 client.4110 handle_client_session client_session(renewcaps seq 2) v1 from mds.1
 -10-16 12:43:30.286909 7f493b4a9780  3 client.4110 ll_getattr 1.head
 -10-16 12:43:30.286993 7f493b4a9780 10 client.4110 _getattr mask pAsLsXsFs issued=1
 -10-16 12:43:30.287022 7f493b4a9780 10 client.4110 fill_stat on 1 snap/devhead mode 040755 mtime 2012-10-16 12:42:04.740872 ctime 2012-10-16 12:42:04.740872
 -10-16 12:43:30.287123 7f493b4a9780  3 client.4110 ll_getattr 1.head = 0
 -10-16 12:43:30.287223 7f493b4a9780  3 client.4110 ll_getattr 1.head
 -10-16 12:43:30.287260 7f493b4a9780 10 client.4110 _getattr mask pAsLsXsFs issued=1
 -10-16 12:43:30.287282 7f493b4a9780 10 client.4110 fill_stat on 1 snap/devhead mode 040755 mtime 2012-10-16 12:42:04.740872 ctime 2012-10-16 12:42:04.740872
 -10-16 12:43:30.287325 7f493b4a9780  3 client.4110 ll_getattr 1.head = 0
 -10-16 12:43:48.386789 7f4937908700 10 client.4110 renew_caps()
 -10-16 12:43:48.386834 7f4937908700 15 client.4110 renew_caps requesting from mds.0
 -10-16 12:43:48.386861 7f4937908700 10 client.4110 renew_caps mds.0
 -10-16 12:43:48.387024 7f4937908700 15 client.4110 renew_caps requesting from mds.1
 -10-16 12:43:48.387182 7f4937908700 10 client.4110 renew_caps mds.1
 -10-16 12:43:48.388982 7f4936906700 10 client.4110 handle_client_session client_session(renewcaps seq 3) v1 from mds.0
 -10-16 12:43:48.389381 7f4936906700 10 client.4110 handle_client_session client_session(renewcaps seq 3) v1 from mds.1
 -10-16 12:44:08.389444 7f4937908700 10 client.4110 renew_caps()
 -10-16 12:44:08.389643 7f4937908700 15 client.4110 renew_caps requesting from mds.0
 -10-16 12:44:08.389692 7f4937908700 10 client.4110 renew_caps mds.0
 -10-16 12:44:08.389784 7f4937908700 15 client.4110 renew_caps requesting from mds.1
 -10-16 12:44:08.389822 7f4937908700 10 client.4110 renew_caps mds.1
 -10-16 12:44:08.391563 7f4936906700 10 client.4110 handle_client_session client_session(renewcaps seq 4) v1 from mds.0
 -10-16 12:44:08.391647 7f4936906700 10 client.4110 handle_client_session client_session(renewcaps seq 4) v1 from mds.1
 -10-16 12:44:21.518299 7f493b4a9780  3 client.4110 ll_getattr 1.head
 -10-16 12:44:21.518380 7f493b4a9780 10 client.4110 _getattr mask pAsLsXsFs issued=1
 -10-16 12:44:21.518395 7f493b4a9780 10 client.4110 fill_stat on 1 snap/devhead mode 040755 mtime 2012-10-16 12:42:04.740872 ctime 2012-10-16 12:42:04.740872
 -10-16 12:44:21.518420 7f493b4a9780  3 client.4110 ll_getattr 1.head = 0
 -10-16 12:44:21.518458 7f493b4a9780  3 client.4110 ll_getattr 1.head
 -10-16 12:44:21.518471 7f493b4a9780 10 client.4110 _getattr mask pAsLsXsFs issued=1
 -10-16 12:44:21.518480 7f493b4a9780 10 client.4110 fill_stat on 1 snap/devhead mode 040755 mtime 2012-10-16 12:42:04.740872 ctime 2012-10-16 12:42:04.740872
 -10-16 12:44:21.518497 7f493b4a9780  3 client.4110 ll_getattr 1.head = 0
 -10-16 12:44:21.518528 7f493b4a9780  3 client.4110 ll_lookup 1.head foo
 -10-16 12:44:21.518571 7f493b4a9780 10 client.4110 _lookup on #1/foo
 -10-16 12:44:21.518622 7f493b4a9780 20 client.4110 choose_target_mds starting with req->inode 1.head(ref=2 cap_refs={} open={} mode=40755 size=0 mtime=2012-10-16 12:42:04.740872 caps=pAsLsXsFs(1=pAsLsXsFs) 0x2257d80)
 -10-16 12:44:21.518707 7f493b4a9780 20 client.4110 choose_target_mds inode dir hash is 2 on foo => 2143417350
 -10-16 12:44:21.518737 7f493b4a9780 20 client.4110 choose_target_mds 1.head(ref=2 cap_refs={} open={} mode=40755 size=0 mtime=2012-10-16 12:42:04.740872 caps=pAsLsXsFs(1=pAsLsXsFs) 0x2257d80) is_hash=1 hash=2143417350
 -10-16 12:44:21.518769 7f493b4a9780 10 client.4110 choose_target_mds from caps on inode 1.head(ref=2 cap_refs={} open={} mode=40755 size=0 mtime=2012-10-16 12:42:04.740872 caps=pAsLsXsFs(1=pAsLsXsFs) 0x2257d80)
 -10-16 12:44:21.518794 7f493b4a9780 20 client.4110 mds is 1
 -10-16 12:44:21.518810 7f493b4a9780 10 client.4110 send_request rebuilding request 4 for mds.1
 -10-16 12:44:21.518831 7f493b4a9780 20 client.4110 encode_cap_releases enter (req: 0x2283840, mds: 1)
 -10-16 12:44:21.518843 7f493b4a9780 20 client.4110 send_request set sent_stamp to 2012-10-16 12:44:21.518842
 -10-16 12:44:21.518859 7f493b4a9780 10 client.4110 send_request client_request(unknown.0:4 lookup #1/foo) v1 to mds.1
 -10-16 12:44:21.518971 7f493b4a9780 20 client.4110 awaiting reply|forward|kick on 0x7fffa2bb90d0
 -10-16 12:44:21.520469 7f4936906700 10 client.4110 handle_client_request tid 4 fwd 1 to mds.0, resending to 0
 -10-16 12:44:21.520511 7f493b4a9780 10 client.4110 choose_target_mds resend_mds specified as mds.0
 -10-16 12:44:21.520525 7f493b4a9780 20 client.4110 mds is 0
 -10-16 12:44:21.520552 7f493b4a9780 10 client.4110 send_request rebuilding request 4 for mds.0
 -10-16 12:44:21.520586 7f493b4a9780 20 client.4110 encode_cap_releases enter (req: 0x2283840, mds: 0)
 -10-16 12:44:21.520598 7f493b4a9780 20 client.4110 send_request set sent_stamp to 2012-10-16 12:44:21.520597
 -10-16 12:44:21.520622 7f493b4a9780 10 client.4110 send_request client_request(unknown.0:4 lookup #1/foo) v1 to mds.0
 -10-16 12:44:21.520728 7f493b4a9780 20 client.4110 awaiting reply|forward|kick on 0x7fffa2bb90d0
 -10-16 12:44:21.523207 7f4936906700 20 client.4110 handle_client_reply got a reply. Safe:1 tid 4
 -10-16 12:44:21.523223 7f4936906700 10 client.4110 insert_trace from 2012-10-16 12:44:21.520597 mds.0 is_target=0 is_dentry=1
 -10-16 12:44:21.523248 7f4936906700 10 client.4110  features 0x7fffff
 -10-16 12:44:21.523255 7f4936906700 10 client.4110 update_snap_trace len 48
 -10-16 12:44:21.523274 7f4934cff700  0 -- 127.0.0.1:0/17998 >> 127.0.0.1:6803/17748 pipe(0x2259900 sd=6 :38061 pgs=6 cs=1 l=0).fault, initiating reconnect
 -10-16 12:44:21.523303 7f4936906700 10 client.4110 update_snap_trace snaprealm(1 nref=3 c=0 seq=1 parent=0 my_snaps=[] cached_snapc=1=[]) seq 1 <= 1 and same parent, SKIPPING
 -10-16 12:44:21.523346 7f4936906700 10 client.4110  hrm  is_target=0 is_dentry=1
 -10-16 12:44:21.523483 7f4936906700 12 client.4110 add_update_inode had 1.head(ref=2 cap_refs={} open={} mode=40755 size=0 mtime=2012-10-16 12:42:04.740872 caps=pAsLsXsFs(1=pAsLsXsFs) 0x2257d80) caps pAsLsXsFs
 -10-16 12:44:21.523620 7f4936906700 10 client.4110 add_update_cap issued - -> pAsLsXsFs from mds.0 on 1.head(ref=2 cap_refs={} open={} mode=40755 size=0 mtime=2012-10-16 12:42:04.740872 caps=pAsLsXsFs(0=pAsLsXsFs,1=pAsLsXsFs) 0x2257d80)
 -10-16 12:44:21.523693 7f4936906700 20 client.4110 got dirfrag map for 1 frag * to mds 0
 -10-16 12:44:21.523806 7f4936906700 20 client.4110 handle_client_reply signalling caller 0x7fffa2bb90d0
 -10-16 12:44:21.523871 7f4936906700 20 client.4110 handle_client_reply awaiting kickback on tid 4 0x7f49369056d0
 -10-16 12:44:21.523912 7f493b4a9780 20 client.4110 sendrecv kickback on tid 4 0x7f49369056d0
 -10-16 12:44:21.523928 7f493b4a9780 20 client.4110 lat 0.003326
 -10-16 12:44:21.523965 7f493b4a9780 10 client.4110 _lookup res is -2
 -10-16 12:44:21.523985 7f493b4a9780 10 client.4110 _lookup 1.head(ref=2 cap_refs={} open={} mode=40755 size=0 mtime=2012-10-16 12:42:04.740872 caps=pAsLsXsFs(0=pAsLsXsFs,1=pAsLsXsFs) 0x2257d80) foo = -2
 -10-16 12:44:21.524077 7f493b4a9780  3 client.4110 ll_lookup 1.head foo -> -2 (0)
 -10-16 12:44:21.524287 7f493b4a9780  3 client.4110 ll_getattr 1.head
 -10-16 12:44:21.524328 7f493b4a9780 10 client.4110 _getattr mask pAsLsXsFs issued=1
 -10-16 12:44:21.524355 7f493b4a9780 10 client.4110 fill_stat on 1 snap/devhead mode 040755 mtime 2012-10-16 12:42:04.740872 ctime 2012-10-16 12:42:04.740872
 -10-16 12:44:21.524430 7f493b4a9780  3 client.4110 ll_getattr 1.head = 0
 -10-16 12:44:21.524537 7f493b4a9780  3 client.4110 ll_create 1.head foo 0100644 33345, uid 0, gid 0
 -10-16 12:44:21.524576 7f493b4a9780  3 client.4110 _mknod(1 foo, 0100644, 0, uid 0, gid 0)
 -10-16 12:44:21.524648 7f493b4a9780 20 client.4110 get_or_create 1.head(ref=2 cap_refs={} open={} mode=40755 size=0 mtime=2012-10-16 12:42:04.740872 caps=pAsLsXsFs(0=pAsLsXsFs,1=pAsLsXsFs) 0x2257d80) name foo
 -10-16 12:44:21.524846 7f493b4a9780 15 client.4110 link dir 0x2257d80 'foo' to inode 0 dn 0x22be150 (new dn)
 -10-16 12:44:21.524878 7f493b4a9780 20 client.4110 choose_target_mds starting with req->inode 1.head(ref=3 cap_refs={} open={} mode=40755 size=0 mtime=2012-10-16 12:42:04.740872 caps=pAsLsXsFs(0=pAsLsXsFs,1=pAsLsXsFs) 0x2257d80)
 -10-16 12:44:21.524967 7f493b4a9780 20 client.4110 choose_target_mds inode dir hash is 2 on foo => 2143417350
 -10-16 12:44:21.524981 7f493b4a9780 20 client.4110 choose_target_mds 1.head(ref=3 cap_refs={} open={} mode=40755 size=0 mtime=2012-10-16 12:42:04.740872 caps=pAsLsXsFs(0=pAsLsXsFs,1=pAsLsXsFs) 0x2257d80) is_hash=1 hash=2143417350
 -10-16 12:44:21.525060 7f493b4a9780 10 client.4110 choose_target_mds from caps on inode 1.head(ref=3 cap_refs={} open={} mode=40755 size=0 mtime=2012-10-16 12:42:04.740872 caps=pAsLsXsFs(0=pAsLsXsFs,1=pAsLsXsFs) 0x2257d80)
 -10-16 12:44:21.525136 7f493b4a9780 20 client.4110 mds is 0
 -10-16 12:44:21.525164 7f493b4a9780 10 client.4110 send_request rebuilding request 5 for mds.0
 -10-16 12:44:21.525213 7f493b4a9780 20 client.4110 encode_cap_releases enter (req: 0x2283580, mds: 0)
 -10-16 12:44:21.525233 7f493b4a9780 20 client.4110 encode_dentry_release enter(dn:0x22be150)
 -10-16 12:44:21.525248 7f493b4a9780 20 client.4110 encode_inode_release enter(in:1.head(ref=3 cap_refs={} open={} mode=40755 size=0 mtime=2012-10-16 12:42:04.740872 caps=pAsLsXsFs(0=pAsLsXsFs,1=pAsLsXsFs) 0x2257d80), req:0x2283580 mds:0, drop:256, unless:512, have:, force:1)
 -10-16 12:44:21.525380 7f493b4a9780 20 client.4110 send_request set sent_stamp to 2012-10-16 12:44:21.525377
 -10-16 12:44:21.525419 7f493b4a9780 10 client.4110 send_request client_request(unknown.0:5 mknod #1/foo) v1 to mds.0
 -10-16 12:44:21.525710 7f4936906700 10 client.4110 ms_handle_connect on 127.0.0.1:6803/17748
 -10-16 12:44:21.525835 7f493b4a9780 20 client.4110 awaiting reply|forward|kick on 0x7fffa2bb9370
 -10-16 12:44:21.526042 7f4934bfe700  0 -- 127.0.0.1:0/17998 >> 127.0.0.1:6803/17748 pipe(0x2259900 sd=6 :38063 pgs=7 cs=3 l=0).reader got old message 7 <= 7 0x228b000 client_reply(???:4 = -2 No such file or directory) v1, discarding
 -10-16 12:44:21.532592 7f4936906700 10 client.4110  mds.1 seq now 1
 -10-16 12:44:21.532612 7f4936906700  5 client.4110 handle_cap_grant on in 1 mds.1 seq 2 caps now pAsLsXs was pAsLsXsFs
 -10-16 12:44:21.532629 7f4936906700 10 client.4110 update_inode_file_bits 1.head(ref=3 cap_refs={} open={} mode=40755 size=0 mtime=2012-10-16 12:42:04.740872 caps=pAsLsXsFs(0=pAsLsXs,1=pAsLsXsFs) 0x2257d80) pAsLsXsFs mtime 2012-10-16 12:42:04.740872
 -10-16 12:44:21.532658 7f4936906700 10 client.4110   revocation of Fs
 -10-16 12:44:21.532667 7f4936906700 10 client.4110 check_caps on 1.head(ref=3 cap_refs={} open={} mode=40755 size=0 mtime=2012-10-16 12:42:04.740872 caps=pAsLsXs(0=pAsLsXs,1=pAsLsXs) 0x2257d80) wanted - used - is_delayed=1
 -10-16 12:44:21.532694 7f4936906700 10 client.4110  cap mds.0 issued pAsLsXs implemented pAsLsXs revoking -
 -10-16 12:44:21.532702 7f4936906700 10 client.4110  cap mds.1 issued pAsLsXs implemented pAsLsXsFs revoking Fs
 -10-16 12:44:21.532708 7f4936906700 10 client.4110 completed revocation of Fs
 -10-16 12:44:21.532715 7f4936906700 10 client.4110 send_cap 1.head(ref=3 cap_refs={} open={} mode=40755 size=0 mtime=2012-10-16 12:42:04.740872 caps=pAsLsXs(0=pAsLsXs,1=pAsLsXs) 0x2257d80) mds.1 seq 2 used - want - flush - retain pAsLsXs held pAsLsXsFs revoking Fs dropping -
 -10-16 12:44:21.555330 7f4936906700 10 client.4110  mds.0 seq now 1
 -10-16 12:44:21.555343 7f4936906700  5 client.4110 handle_caps don't have vino 10000000000.head, dropping
 -10-16 12:44:21.559207 7f4936906700 20 client.4110 handle_client_reply got a reply. Safe:1 tid 5
 -10-16 12:44:21.559220 7f4936906700 10 client.4110 insert_trace from 2012-10-16 12:44:21.525377 mds.0 is_target=1 is_dentry=1
 -10-16 12:44:21.559234 7f4936906700 10 client.4110  features 0x7fffff
 -10-16 12:44:21.559241 7f4936906700 10 client.4110 update_snap_trace len 48
 -10-16 12:44:21.559256 7f4936906700 10 client.4110 update_snap_trace snaprealm(1 nref=3 c=0 seq=1 parent=0 my_snaps=[] cached_snapc=1=[]) seq 1 <= 1 and same parent, SKIPPING
 -10-16 12:44:21.559285 7f4936906700 10 client.4110  hrm  is_target=1 is_dentry=1
 -10-16 12:44:21.559335 7f4936906700 12 client.4110 add_update_inode adding 10000000000.head(ref=0 cap_refs={} open={} mode=100000 size=0 mtime=0.000000 caps=- objectset[10000000000 ts 0/0 objects 0 dirty_or_tx 0] 0x2258680) caps pAsxLsXsxFsxcrwb
 -10-16 12:44:21.559379 7f4936906700 10 client.4110 update_inode_file_bits 10000000000.head(ref=0 cap_refs={} open={} mode=100644 size=0 mtime=0.000000 caps=- objectset[10000000000 ts 0/0 objects 0 dirty_or_tx 0] 0x2258680) - mtime 2012-10-16 12:44:21.542963
 -10-16 12:44:21.559429 7f4936906700 15 client.4110 add_update_cap first one, opened snaprealm 0x2289c30
 -10-16 12:44:21.559439 7f4936906700 10 client.4110 add_update_cap issued - -> pAsxLsXsxFsxcrwb from mds.0 on 10000000000.head(ref=0 cap_refs={} open={} mode=100644 size=0 mtime=2012-10-16 12:44:21.542963 caps=pAsxLsXsxFsxcrwb(0=pAsxLsXsxFsxcrwb) objectset[10000000000 ts 0/0 objects 0 dirty_or_tx 0] 0x2258680)
 -10-16 12:44:21.559494 7f4936906700 12 client.4110 add_update_inode had 1.head(ref=3 cap_refs={} open={} mode=40755 size=0 mtime=2012-10-16 12:42:04.740872 caps=pAsLsXs(0=pAsLsXs,1=pAsLsXs) 0x2257d80) caps pAsLsXs
 -10-16 12:44:21.559548 7f4936906700 20 client.4110  dir hash is 2
 -10-16 12:44:21.559555 7f4936906700 10 client.4110 update_inode_file_bits 1.head(ref=3 cap_refs={} open={} mode=40755 size=0 mtime=2012-10-16 12:42:04.740872 caps=pAsLsXs(0=pAsLsXs,1=pAsLsXs) 0x2257d80) pAsLsXs mtime 2012-10-16 12:44:21.542963
 -10-16 12:44:21.559617 7f4936906700 10 client.4110 add_update_cap issued pAsLsXs -> pAsLsXs from mds.0 on 1.head(ref=3 cap_refs={} open={} mode=40755 size=0 mtime=2012-10-16 12:44:21.542963 caps=pAsLsXs(0=pAsLsXs,1=pAsLsXs) 0x2257d80)
 -10-16 12:44:21.559656 7f4936906700 20 client.4110 got dirfrag map for 1 frag * to mds 0
 -10-16 12:44:21.559685 7f4936906700 12 client.4110 insert_dentry_inode 'foo' vino 10000000000.head in dir 1.head dn 0x22be150
 -10-16 12:44:21.559695 7f4936906700 15 client.4110 link dir 0x2257d80 'foo' to inode 0x2258680 dn 0x22be150 (old dn)
 -10-16 12:44:21.559710 7f4936906700 20 client.4110 link  inode 0x2258680 parents now 0x22be150
 -10-16 12:44:21.559719 7f4936906700 15 client.4110  setting dn offset to 2
 -10-16 12:44:21.559723 7f4936906700 10 client.4110 got dentry lease on foo dur 30000ms ttl 2012-10-16 12:44:51.525377
 -10-16 12:44:21.559741 7f4936906700 20 client.4110 handle_client_reply signalling caller 0x7fffa2bb9370
 -10-16 12:44:21.559747 7f4936906700 20 client.4110 handle_client_reply awaiting kickback on tid 5 0x7f49369056d0
 -10-16 12:44:21.559763 7f493b4a9780 20 client.4110 sendrecv kickback on tid 5 0x7f49369056d0
 -10-16 12:44:21.559778 7f493b4a9780 20 client.4110 lat 0.034398
 -10-16 12:44:21.559808 7f493b4a9780 20 client.4110 trim_cache size 1 max 16384
 -10-16 12:44:21.559823 7f493b4a9780  3 client.4110 mknod(#1/foo, 0100644) = 0
 -10-16 12:44:21.559863 7f493b4a9780 20 client.4110 choose_target_mds starting with req->inode 10000000000.head(ref=1 cap_refs={} open={2=1} mode=100644 size=0 mtime=2012-10-16 12:44:21.542963 caps=pAsxLsXsxFsxcrwb(0=pAsxLsXsxFsxcrwb) objectset[10000000000 ts 0/0 objects 0 dirty_or_tx 0] parents=0x22be150 0x2258680)
 -10-16 12:44:21.559886 7f493b4a9780 20 client.4110 choose_target_mds 10000000000.head(ref=1 cap_refs={} open={2=1} mode=100644 size=0 mtime=2012-10-16 12:44:21.542963 caps=pAsxLsXsxFsxcrwb(0=pAsxLsXsxFsxcrwb) objectset[10000000000 ts 0/0 objects 0 dirty_or_tx 0] parents=0x22be150 0x2258680) is_hash=0 hash=0
 -10-16 12:44:21.559911 7f493b4a9780 10 client.4110 choose_target_mds from caps on inode 10000000000.head(ref=1 cap_refs={} open={2=1} mode=100644 size=0 mtime=2012-10-16 12:44:21.542963 caps=pAsxLsXsxFsxcrwb(0=pAsxLsXsxFsxcrwb) objectset[10000000000 ts 0/0 objects 0 dirty_or_tx 0] parents=0x22be150 0x2258680)
 -10-16 12:44:21.559936 7f493b4a9780 20 client.4110 mds is 0
 -10-16 12:44:21.559950 7f493b4a9780 10 client.4110 send_request rebuilding request 6 for mds.0
 -10-16 12:44:21.559963 7f493b4a9780 20 client.4110 encode_cap_releases enter (req: 0x2283000, mds: 0)
 -10-16 12:44:21.559969 7f493b4a9780 20 client.4110 send_request set sent_stamp to 2012-10-16 12:44:21.559968
 -10-16 12:44:21.559978 7f493b4a9780 10 client.4110 send_request client_request(unknown.0:6 open #10000000000) v1 to mds.0
 -10-16 12:44:21.560028 7f493b4a9780 20 client.4110 awaiting reply|forward|kick on 0x7fffa2bb94a0
 -10-16 12:44:21.565227 7f4936906700 20 client.4110 handle_client_reply got a reply. Safe:0 tid 6
 -10-16 12:44:21.565265 7f4936906700 10 client.4110 insert_trace from 2012-10-16 12:44:21.559968 mds.0 is_target=1 is_dentry=0
 -10-16 12:44:21.565287 7f4936906700 10 client.4110  features 0x7fffff
 -10-16 12:44:21.565294 7f4936906700 10 client.4110 update_snap_trace len 48
 -10-16 12:44:21.565316 7f4936906700 10 client.4110 update_snap_trace snaprealm(1 nref=4 c=0 seq=1 parent=0 my_snaps=[] cached_snapc=1=[]) seq 1 <= 1 and same parent, SKIPPING
 -10-16 12:44:21.565347 7f4936906700 10 client.4110  hrm  is_target=1 is_dentry=0
 -10-16 12:44:21.565387 7f4936906700 12 client.4110 add_update_inode had 10000000000.head(ref=1 cap_refs={} open={2=1} mode=100644 size=0 mtime=2012-10-16 12:44:21.542963 caps=pAsxLsXsxFsxcrwb(0=pAsxLsXsxFsxcrwb) objectset[10000000000 ts 0/0 objects 0 dirty_or_tx 0] parents=0x22be150 0x2258680) caps pAsxLsXsxFsxcrwb
 -10-16 12:44:21.565463 7f4936906700 10 client.4110 update_inode_file_bits 10000000000.head(ref=1 cap_refs={} open={2=1} mode=100644 size=0 mtime=2012-10-16 12:44:21.542963 caps=pAsxLsXsxFsxcrwb(0=pAsxLsXsxFsxcrwb) objectset[10000000000 ts 0/0 objects 0 dirty_or_tx 0] parents=0x22be150 0x2258680) pAsxLsXsxFsxcrwb mtime 2012-10-16 12:44:21.562248
 -10-16 12:44:21.565545 7f4936906700 10 client.4110 add_update_cap issued pAsxLsXsxFsxcrwb -> pAsxLsXsxFsxcrwb from mds.0 on 10000000000.head(ref=1 cap_refs={} open={2=1} mode=100644 size=0 mtime=2012-10-16 12:44:21.562248 caps=pAsxLsXsxFsxcrwb(0=pAsxLsXsxFsxcrwb) objectset[10000000000 ts 0/0 objects 0 dirty_or_tx 0] parents=0x22be150 0x2258680)
 -10-16 12:44:21.565617 7f4936906700 20 client.4110 handle_client_reply signalling caller 0x7fffa2bb94a0
 -10-16 12:44:21.565627 7f4936906700 20 client.4110 handle_client_reply awaiting kickback on tid 6 0x7f49369056d0
 -10-16 12:44:21.565648 7f493b4a9780 20 client.4110 sendrecv kickback on tid 6 0x7f49369056d0
 -10-16 12:44:21.565668 7f493b4a9780 20 client.4110 lat 0.005696
 -10-16 12:44:21.565707 7f493b4a9780 10 client.4110 _create_fh 10000000000 mode 2
 -10-16 12:44:21.565711 7f493b4a9780 20 client.4110 trim_cache size 1 max 16384
 -10-16 12:44:21.565715 7f493b4a9780 10 client.4110 fill_stat on 10000000000 snap/devhead mode 0100644 mtime 2012-10-16 12:44:21.562248 ctime 2012-10-16 12:44:21.562248
 -10-16 12:44:21.565729 7f493b4a9780 20 client.4110 _ll_get 0x2258680 10000000000 -> 1
 -10-16 12:44:21.565733 7f493b4a9780  3 client.4110 ll_create 1.head foo 0100644 33345 = 0 (0x2253320 10000000000)
 -10-16 12:44:21.565789 7f493b4a9780  3 client.4110 ll_getattr 10000000000.head
 -10-16 12:44:21.565801 7f493b4a9780 10 client.4110 _getattr mask pAsLsXsFs issued=1
 -10-16 12:44:21.565807 7f493b4a9780 10 client.4110 fill_stat on 10000000000 snap/devhead mode 0100644 mtime 2012-10-16 12:44:21.562248 ctime 2012-10-16 12:44:21.562248
 -10-16 12:44:21.565819 7f493b4a9780  3 client.4110 ll_getattr 10000000000.head = 0
 -10-16 12:44:21.565919 7f493b4a9780  3 client.4110 ll_getxattr 10000000000.head security.capability size 0
 -10-16 12:44:21.565939 7f493b4a9780 10 client.4110 _getattr mask Xs issued=1
 -10-16 12:44:21.565960 7f493b4a9780  3 client.4110 _getxattr(10000000000, "security.capability", 0) = -61
 -10-16 12:44:21.565983 7f493b4a9780  3 client.4110 ll_write 0x2253320 10000000000 0~4
 -10-16 12:44:21.565995 7f493b4a9780 10 client.4110 cur file size is 0
 -10-16 12:44:21.566006 7f493b4a9780 10 client.4110 wanted_max_size 0 -> 4
 -10-16 12:44:21.566016 7f493b4a9780 10 client.4110 check_caps on 10000000000.head(ref=3 cap_refs={} open={2=1} mode=100644 size=0 mtime=2012-10-16 12:44:21.562248 caps=pAsxLsXsxFsxcrwb(0=pAsxLsXsxFsxcrwb) objectset[10000000000 ts 0/0 objects 0 dirty_or_tx 0] parents=0x22be150 0x2258680) wanted pAsxXsxFxwb used - is_delayed=0
 -10-16 12:44:21.566042 7f493b4a9780 10 client.4110 cap_delay_requeue on 10000000000.head(ref=3 cap_refs={} open={2=1} mode=100644 size=0 mtime=2012-10-16 12:44:21.562248 caps=pAsxLsXsxFsxcrwb(0=pAsxLsXsxFsxcrwb) objectset[10000000000 ts 0/0 objects 0 dirty_or_tx 0] parents=0x22be150 0x2258680)
 -10-16 12:44:21.566068 7f493b4a9780 10 client.4110  cap mds.0 issued pAsxLsXsxFsxcrwb implemented pAsxLsXsxFsxcrwb revoking -
 -10-16 12:44:21.566078 7f493b4a9780 10 client.4110 delaying cap release
 -10-16 12:44:21.566082 7f493b4a9780 10 client.4110 get_caps 10000000000.head(ref=3 cap_refs={} open={2=1} mode=100644 size=0 mtime=2012-10-16 12:44:21.562248 caps=pAsxLsXsxFsxcrwb(0=pAsxLsXsxFsxcrwb) objectset[10000000000 ts 0/0 objects 0 dirty_or_tx 0] parents=0x22be150 0x2258680) have pAsxLsXsxFsxcrwb need Fw want Fb but not Fb revoking -
 -10-16 12:44:21.566112 7f493b4a9780 10 client.4110  snaprealm snaprealm(1 nref=3 c=0 seq=1 parent=0 my_snaps=[] cached_snapc=1=[])
 -10-16 12:44:21.566123 7f493b4a9780  5 client.4110 get_cap_ref got first FILE_BUFFER ref on 10000000000.head(ref=3 cap_refs={4096=1,8192=0} open={2=1} mode=100644 size=0 mtime=2012-10-16 12:44:21.562248 caps=pAsxLsXsxFsxcrwb(0=pAsxLsXsxFsxcrwb) objectset[10000000000 ts 0/0 objects 0 dirty_or_tx 0] parents=0x22be150 0x2258680)
 -10-16 12:44:21.566301 7f493b4a9780 10 client.4110 mark_caps_dirty 10000000000.head(ref=4 cap_refs={4096=1,8192=1} open={2=1} mode=100644 size=4 mtime=2012-10-16 12:44:21.562248 caps=pAsxLsXsxFsxcrwb(0=pAsxLsXsxFsxcrwb) objectset[10000000000 ts 0/0 objects 1 dirty_or_tx 4] parents=0x22be150 0x2258680) - -> Fw
 -10-16 12:44:21.566323 7f493b4a9780  7 client.4110 wrote to 4, extending file size
 -10-16 12:44:21.566330 7f493b4a9780 10 client.4110 mark_caps_dirty 10000000000.head(ref=5 cap_refs={4096=1,8192=1} open={2=1} mode=100644 size=4 mtime=2012-10-16 12:44:21.566329 caps=pAsxLsXsxFsxcrwb(0=pAsxLsXsxFsxcrwb) dirty_caps=Fw objectset[10000000000 ts 0/0 objects 1 dirty_or_tx 4] parents=0x22be150 0x2258680) Fw -> Fw
 -10-16 12:44:21.566364 7f493b4a9780  3 client.4110 ll_write 0x2253320 0~4 = 4
 -10-16 12:44:21.566395 7f493b4a9780  3 client.4110 ll_release 0x2253320 10000000000
 -10-16 12:44:21.566400 7f493b4a9780  5 client.4110 _release_fh 0x2253320 mode 2 on 10000000000.head(ref=5 cap_refs={4096=0,8192=1} open={2=1} mode=100644 size=4 mtime=2012-10-16 12:44:21.566329 caps=pAsxLsXsxFsxcrwb(0=pAsxLsXsxFsxcrwb) dirty_caps=Fw objectset[10000000000 ts 0/0 objects 1 dirty_or_tx 4] parents=0x22be150 0x2258680)
 -10-16 12:44:21.566426 7f493b4a9780 10 client.4110 _flush 10000000000.head(ref=5 cap_refs={4096=0,8192=1} open={2=0} mode=100644 size=4 mtime=2012-10-16 12:44:21.566329 caps=pAsxLsXsxFsxcrwb(0=pAsxLsXsxFsxcrwb) dirty_caps=Fw objectset[10000000000 ts 0/0 objects 1 dirty_or_tx 4] parents=0x22be150 0x2258680)
 -10-16 12:44:21.566742 7f493b4a9780 10 client.4110 check_caps on 10000000000.head(ref=6 cap_refs={4096=0,8192=1} open={2=0} mode=100644 size=4 mtime=2012-10-16 12:44:21.566329 caps=pAsxLsXsxFsxcrwb(0=pAsxLsXsxFsxcrwb) dirty_caps=Fw objectset[10000000000 ts 0/0 objects 1 dirty_or_tx 4] parents=0x22be150 0x2258680) wanted Fxb used Fb is_delayed=0
 -10-16 12:44:21.566771 7f493b4a9780 10 client.4110 cap_delay_requeue on 10000000000.head(ref=6 cap_refs={4096=0,8192=1} open={2=0} mode=100644 size=4 mtime=2012-10-16 12:44:21.566329 caps=pAsxLsXsxFsxcrwb(0=pAsxLsXsxFsxcrwb) dirty_caps=Fw objectset[10000000000 ts 0/0 objects 1 dirty_or_tx 4] parents=0x22be150 0x2258680)
 -10-16 12:44:21.566801 7f493b4a9780 10 client.4110  cap mds.0 issued pAsxLsXsxFsxcrwb implemented pAsxLsXsxFsxcrwb revoking -
 -10-16 12:44:21.566809 7f493b4a9780 10 client.4110 delaying cap release
 -10-16 12:44:21.566812 7f493b4a9780 10 client.4110 put_inode on 10000000000.head(ref=6 cap_refs={4096=0,8192=1} open={2=0} mode=100644 size=4 mtime=2012-10-16 12:44:21.566329 caps=pAsxLsXsxFsxcrwb(0=pAsxLsXsxFsxcrwb) dirty_caps=Fw objectset[10000000000 ts 0/0 objects 1 dirty_or_tx 4] parents=0x22be150 0x2258680)
 -10-16 12:44:21.568696 7f4936906700 10 client.4110 ms_handle_connect on 127.0.0.1:6800/17725
 -10-16 12:44:21.574541 7f4936906700 10 client.4110 put_inode on 10000000000.head(ref=5 cap_refs={4096=0,8192=1} open={2=0} mode=100644 size=4 mtime=2012-10-16 12:44:21.566329 caps=pAsxLsXsxFsxcrwb(0=pAsxLsXsxFsxcrwb) dirty_caps=Fw objectset[10000000000 ts 0/0 objects 1 dirty_or_tx 0] parents=0x22be150 0x2258680)
 -10-16 12:44:21.574585 7f4936906700 10 client.4110 _flushed 10000000000.head(ref=4 cap_refs={4096=0,8192=1} open={2=0} mode=100644 size=4 mtime=2012-10-16 12:44:21.566329 caps=pAsxLsXsxFsxcrwb(0=pAsxLsXsxFsxcrwb) dirty_caps=Fw objectset[10000000000 ts 0/0 objects 1 dirty_or_tx 0] parents=0x22be150 0x2258680)
 -10-16 12:44:21.574620 7f4936906700 10 client.4110 _invalidate_inode_cache 10000000000.head(ref=4 cap_refs={1024=0,4096=0,8192=1} open={2=0} mode=100644 size=4 mtime=2012-10-16 12:44:21.566329 caps=pAsxLsXsxFsxcrwb(0=pAsxLsXsxFsxcrwb) dirty_caps=Fw objectset[10000000000 ts 0/0 objects 1 dirty_or_tx 0] parents=0x22be150 0x2258680)
 -10-16 12:44:21.574682 7f4936906700 10 client.4110 check_caps on 10000000000.head(ref=4 cap_refs={1024=0,4096=0,8192=0} open={2=0} mode=100644 size=4 mtime=2012-10-16 12:44:21.566329 caps=pAsxLsXsxFsxcrwb(0=pAsxLsXsxFsxcrwb) dirty_caps=Fw objectset[10000000000 ts 0/0 objects 0 dirty_or_tx 0] parents=0x22be150 0x2258680) wanted - used - is_delayed=0
 -10-16 12:44:21.574714 7f4936906700 10 client.4110 cap_delay_requeue on 10000000000.head(ref=4 cap_refs={1024=0,4096=0,8192=0} open={2=0} mode=100644 size=4 mtime=2012-10-16 12:44:21.566329 caps=pAsxLsXsxFsxcrwb(0=pAsxLsXsxFsxcrwb) dirty_caps=Fw objectset[10000000000 ts 0/0 objects 0 dirty_or_tx 0] parents=0x22be150 0x2258680)
 -10-16 12:44:21.574742 7f4936906700 10 client.4110  cap mds.0 issued pAsxLsXsxFsxcrwb implemented pAsxLsXsxFsxcrwb revoking -
 -10-16 12:44:21.574752 7f4936906700 10 client.4110 delaying cap release
 -10-16 12:44:21.574756 7f4936906700  5 client.4110 put_cap_ref dropped last FILE_BUFFER ref on 10000000000.head(ref=4 cap_refs={1024=0,4096=0,8192=0} open={2=0} mode=100644 size=4 mtime=2012-10-16 12:44:21.566329 caps=pAsxLsXsxFsxcrwb(0=pAsxLsXsxFsxcrwb) dirty_caps=Fw objectset[10000000000 ts 0/0 objects 0 dirty_or_tx 0] parents=0x22be150 0x2258680)
 -10-16 12:44:21.574782 7f4936906700 10 client.4110 put_inode on 10000000000.head(ref=4 cap_refs={1024=0,4096=0,8192=0} open={2=0} mode=100644 size=4 mtime=2012-10-16 12:44:21.566329 caps=pAsxLsXsxFsxcrwb(0=pAsxLsXsxFsxcrwb) dirty_caps=Fw objectset[10000000000 ts 0/0 objects 0 dirty_or_tx 0] parents=0x22be150 0x2258680)
 -10-16 12:44:24.427074 7f4936906700 20 client.4110 handle_client_reply got a reply. Safe:1 tid 6
 -10-16 12:44:24.427120 7f4936906700 10 client.4110 insert_trace from 2012-10-16 12:44:21.559968 mds.0 is_target=0 is_dentry=0
 -10-16 12:44:24.427152 7f4936906700 10 client.4110 insert_trace -- no trace
 -10-16 12:44:24.428738 7f4936906700 10 client.4110  mds.0 seq now 2
 -10-16 12:44:24.428788 7f4936906700  5 client.4110 handle_cap_grant on in 10000000000 mds.0 seq 3 caps now pAsxLsXsxFsxcrwb was pAsxLsXsxFsxcrwb
 -10-16 12:44:24.428847 7f4936906700 10 client.4110 update_inode_file_bits 10000000000.head(ref=3 cap_refs={1024=0,4096=0,8192=0} open={2=0} mode=100644 size=4 mtime=2012-10-16 12:44:21.566329 caps=pAsxLsXsxFsxcrwb(0=pAsxLsXsxFsxcrwb) dirty_caps=Fw objectset[10000000000 ts 0/0 objects 0 dirty_or_tx 0] parents=0x22be150 0x2258680) pAsxLsXsxFsxcrwb mtime 2012-10-16 12:44:21.562248
 -10-16 12:44:24.428987 7f4936906700 10 client.4110   caps unchanged at pAsxLsXsxFsxcrwb
 -10-16 12:44:24.459391 7f4936906700  1 client.4110 handle_mds_map epoch 12
 -10-16 12:44:27.391732 7f4937908700 10 client.4110 check_caps on 10000000000.head(ref=3 cap_refs={1024=0,4096=0,8192=0} open={2=0} mode=100644 size=4 mtime=2012-10-16 12:44:21.566329 caps=pAsxLsXsxFsxcrwb(0=pAsxLsXsxFsxcrwb) dirty_caps=Fw objectset[10000000000 ts 0/0 objects 0 dirty_or_tx 0] parents=0x22be150 0x2258680) wanted - used - is_delayed=1
 -10-16 12:44:27.391880 7f4937908700 10 client.4110  cap mds.0 issued pAsxLsXsxFsxcrwb implemented pAsxLsXsxFsxcrwb revoking -
 -10-16 12:44:27.391916 7f4937908700 10 client.4110 mark_caps_flushing Fw 10000000000.head(ref=3 cap_refs={1024=0,4096=0,8192=0} open={2=0} mode=100644 size=4 mtime=2012-10-16 12:44:21.566329 caps=pAsxLsXsxFsxcrwb(0=pAsxLsXsxFsxcrwb) dirty_caps=Fw objectset[10000000000 ts 0/0 objects 0 dirty_or_tx 0] parents=0x22be150 0x2258680)
 -10-16 12:44:27.392004 7f4937908700 10 client.4110 send_cap 10000000000.head(ref=3 cap_refs={1024=0,4096=0,8192=0} open={2=0} mode=100644 size=4 mtime=2012-10-16 12:44:21.566329 caps=pAsxLsXsxFsxcrwb(0=pAsxLsXsxFsxcrwb) flushing_caps=Fw objectset[10000000000 ts 0/0 objects 0 dirty_or_tx 0] parents=0x22be150 0x2258680) mds.0 seq 3 used - want - flush Fw retain pAsLsXsFs held pAsxLsXsxFsxcrwb revoking - dropping AxXxFxcrwb
 -10-16 12:44:27.392156 7f4937908700 15 client.4110 auth cap, setting max_size = 4
 -10-16 12:44:27.544828 7f493b4a9780  3 client.4110 ll_getattr 1.head
 -10-16 12:44:27.544903 7f493b4a9780 10 client.4110 _getattr mask pAsLsXsFs issued=0
 -10-16 12:44:27.544970 7f493b4a9780 20 client.4110 choose_target_mds starting with req->inode 1.head(ref=3 cap_refs={} open={} mode=40755 size=0 mtime=2012-10-16 12:44:21.542963 caps=pAsLsXs(0=pAsLsXs,1=pAsLsXs) 0x2257d80)
 -10-16 12:44:27.545038 7f493b4a9780 20 client.4110 choose_target_mds 1.head(ref=3 cap_refs={} open={} mode=40755 size=0 mtime=2012-10-16 12:44:21.542963 caps=pAsLsXs(0=pAsLsXs,1=pAsLsXs) 0x2257d80) is_hash=0 hash=0
 -10-16 12:44:27.545088 7f493b4a9780 10 client.4110 choose_target_mds from caps on inode 1.head(ref=3 cap_refs={} open={} mode=40755 size=0 mtime=2012-10-16 12:44:21.542963 caps=pAsLsXs(0=pAsLsXs,1=pAsLsXs) 0x2257d80)
 -10-16 12:44:27.545132 7f493b4a9780 20 client.4110 mds is 0
 -10-16 12:44:27.545158 7f493b4a9780 10 client.4110 send_request rebuilding request 7 for mds.0
 -10-16 12:44:27.545186 7f493b4a9780 20 client.4110 encode_cap_releases enter (req: 0x2283b00, mds: 0)
 -10-16 12:44:27.545195 7f493b4a9780 20 client.4110 send_request set sent_stamp to 2012-10-16 12:44:27.545194
 -10-16 12:44:27.545217 7f493b4a9780 10 client.4110 send_request client_request(unknown.0:7 getattr pAsLsXsFs #1) v1 to mds.0
 -10-16 12:44:27.545350 7f493b4a9780 20 client.4110 awaiting reply|forward|kick on 0x7fffa2bb9420
 -10-16 12:44:27.556439 7f4936906700 20 client.4110 handle_client_reply got a reply. Safe:1 tid 7
 -10-16 12:44:27.556446 7f4936906700 10 client.4110 insert_trace from 2012-10-16 12:44:27.545194 mds.0 is_target=1 is_dentry=0
 -10-16 12:44:27.556465 7f4936906700 10 client.4110  features 0x7fffff
 -10-16 12:44:27.556469 7f4936906700 10 client.4110 update_snap_trace len 48
 -10-16 12:44:27.556483 7f4936906700 10 client.4110 update_snap_trace snaprealm(1 nref=4 c=0 seq=1 parent=0 my_snaps=[] cached_snapc=1=[]) seq 1 <= 1 and same parent, SKIPPING
 -10-16 12:44:27.556499 7f4936906700 10 client.4110  hrm  is_target=1 is_dentry=0
 -10-16 12:44:27.556519 7f4936906700 12 client.4110 add_update_inode had 1.head(ref=3 cap_refs={} open={} mode=40755 size=0 mtime=2012-10-16 12:44:21.542963 caps=pAsLsXs(0=pAsLsXs,1=pAsLsXs) 0x2257d80) caps pAsLsXsFs
 -10-16 12:44:27.556553 7f4936906700 20 client.4110  dir hash is 2
 -10-16 12:44:27.556558 7f4936906700 10 client.4110 update_inode_file_bits 1.head(ref=3 cap_refs={} open={} mode=40755 size=0 mtime=2012-10-16 12:44:21.542963 caps=pAsLsXs(0=pAsLsXs,1=pAsLsXs) 0x2257d80) pAsLsXs mtime 2012-10-16 12:44:21.542963
 -10-16 12:44:27.556594 7f4936906700 10 client.4110 add_update_cap issued pAsLsXs -> pAsLsXsFs from mds.0 on 1.head(ref=3 cap_refs={} open={} mode=40755 size=0 mtime=2012-10-16 12:44:21.542963 caps=pAsLsXsFs(0=pAsLsXsFs,1=pAsLsXs) 0x2257d80)
 -10-16 12:44:27.556629 7f4936906700 20 client.4110 handle_client_reply signalling caller 0x7fffa2bb9420
 -10-16 12:44:27.556634 7f4936906700 20 client.4110 handle_client_reply awaiting kickback on tid 7 0x7f49369056d0
 -10-16 12:44:27.556642 7f493b4a9780 20 client.4110 sendrecv kickback on tid 7 0x7f49369056d0
 -10-16 12:44:27.556648 7f493b4a9780 20 client.4110 lat 0.011453
 -10-16 12:44:27.556661 7f493b4a9780 10 client.4110 _getattr result=0
 -10-16 12:44:27.556666 7f493b4a9780 10 client.4110 fill_stat on 1 snap/devhead mode 040755 mtime 2012-10-16 12:44:21.542963 ctime 2012-10-16 12:44:21.542963
 -10-16 12:44:27.556690 7f493b4a9780  3 client.4110 ll_getattr 1.head = 0
 -10-16 12:44:27.556904 7f493b4a9780  3 client.4110 ll_lookup 1.head foo
 -10-16 12:44:27.556921 7f493b4a9780 20 client.4110 _lookup have dn foo mds.0 ttl 2012-10-16 12:44:51.525377 seq 2
 -10-16 12:44:27.556938 7f493b4a9780 10 client.4110 _lookup 1.head(ref=3 cap_refs={} open={} mode=40755 size=0 mtime=2012-10-16 12:44:21.542963 caps=pAsLsXsFs(0=pAsLsXsFs,1=pAsLsXs) 0x2257d80) foo = 10000000000.head(ref=3 cap_refs={1024=0,4096=0,8192=0} open={2=0} mode=100644 size=4 mtime=2012-10-16 12:44:21.566329 caps=pAsLsXsFs(0=pAsLsXsFs) flushing_caps=Fw objectset[10000000000 ts 0/0 objects 0 dirty_or_tx 0] parents=0x22be150 0x2258680)
 -10-16 12:44:27.556981 7f493b4a9780 10 client.4110 fill_stat on 10000000000 snap/devhead mode 0100644 mtime 2012-10-16 12:44:21.566329 ctime 2012-10-16 12:44:21.562248
 -10-16 12:44:27.556993 7f493b4a9780 20 client.4110 _ll_get 0x2258680 10000000000 -> 2
 -10-16 12:44:27.556997 7f493b4a9780  3 client.4110 ll_lookup 1.head foo -> 0 (10000000000)
 -10-16 12:44:27.557065 7f493b4a9780  3 client.4110 ll_getattr 10000000000.head
 -10-16 12:44:27.557076 7f493b4a9780 10 client.4110 _getattr mask pAsLsXsFs issued=1
 -10-16 12:44:27.557081 7f493b4a9780 10 client.4110 fill_stat on 10000000000 snap/devhead mode 0100644 mtime 2012-10-16 12:44:21.566329 ctime 2012-10-16 12:44:21.562248
 -10-16 12:44:27.557094 7f493b4a9780  3 client.4110 ll_getattr 10000000000.head = 0
 -10-16 12:44:27.557133 7f493b4a9780  3 client.4110 ll_getattr 1.head
 -10-16 12:44:27.557142 7f493b4a9780 10 client.4110 _getattr mask pAsLsXsFs issued=1
 -10-16 12:44:27.557147 7f493b4a9780 10 client.4110 fill_stat on 1 snap/devhead mode 040755 mtime 2012-10-16 12:44:21.542963 ctime 2012-10-16 12:44:21.542963
 -10-16 12:44:27.557162 7f493b4a9780  3 client.4110 ll_getattr 1.head = 0
 -10-16 12:44:27.557184 7f493b4a9780  3 client.4110 ll_lookup 1.head foo
 -10-16 12:44:27.557194 7f493b4a9780 20 client.4110 _lookup have dn foo mds.0 ttl 2012-10-16 12:44:51.525377 seq 2
 -10-16 12:44:27.557203 7f493b4a9780 10 client.4110 _lookup 1.head(ref=3 cap_refs={} open={} mode=40755 size=0 mtime=2012-10-16 12:44:21.542963 caps=pAsLsXsFs(0=pAsLsXsFs,1=pAsLsXs) 0x2257d80) foo = 10000000000.head(ref=3 cap_refs={1024=0,4096=0,8192=0} open={2=0} mode=100644 size=4 mtime=2012-10-16 12:44:21.566329 caps=pAsLsXsFs(0=pAsLsXsFs) flushing_caps=Fw objectset[10000000000 ts 0/0 objects 0 dirty_or_tx 0] parents=0x22be150 0x2258680)
 -10-16 12:44:27.557229 7f493b4a9780 10 client.4110 fill_stat on 10000000000 snap/devhead mode 0100644 mtime 2012-10-16 12:44:21.566329 ctime 2012-10-16 12:44:21.562248
 -10-16 12:44:27.557239 7f493b4a9780 20 client.4110 _ll_get 0x2258680 10000000000 -> 3
 -10-16 12:44:27.557241 7f493b4a9780  3 client.4110 ll_lookup 1.head foo -> 0 (10000000000)
 -10-16 12:44:27.557263 7f493b4a9780  3 client.4110 ll_setattr 10000000000.head mask 1
 -10-16 12:44:27.557272 7f493b4a9780 10 client.4110 _setattr mask 1 issued pAsLsXsFs
 -10-16 12:44:27.557296 7f493b4a9780 20 client.4110 choose_target_mds starting with req->inode 10000000000.head(ref=3 cap_refs={1024=0,4096=0,8192=0} open={2=0} mode=100644 size=4 mtime=2012-10-16 12:44:21.566329 caps=pAsLsXsFs(0=pAsLsXsFs) flushing_caps=Fw objectset[10000000000 ts 0/0 objects 0 dirty_or_tx 0] parents=0x22be150 0x2258680)
 -10-16 12:44:27.557313 7f493b4a9780 20 client.4110 choose_target_mds 10000000000.head(ref=3 cap_refs={1024=0,4096=0,8192=0} open={2=0} mode=100644 size=4 mtime=2012-10-16 12:44:21.566329 caps=pAsLsXsFs(0=pAsLsXsFs) flushing_caps=Fw objectset[10000000000 ts 0/0 objects 0 dirty_or_tx 0] parents=0x22be150 0x2258680) is_hash=0 hash=0
 -10-16 12:44:27.557332 7f493b4a9780 10 client.4110 choose_target_mds from caps on inode 10000000000.head(ref=3 cap_refs={1024=0,4096=0,8192=0} open={2=0} mode=100644 size=4 mtime=2012-10-16 12:44:21.566329 caps=pAsLsXsFs(0=pAsLsXsFs) flushing_caps=Fw objectset[10000000000 ts 0/0 objects 0 dirty_or_tx 0] parents=0x22be150 0x2258680)
 -10-16 12:44:27.557359 7f493b4a9780 20 client.4110 mds is 0
 -10-16 12:44:27.557371 7f493b4a9780 10 client.4110 send_request rebuilding request 8 for mds.0
 -10-16 12:44:27.557383 7f493b4a9780 20 client.4110 encode_cap_releases enter (req: 0x22832c0, mds: 0)
 -10-16 12:44:27.557385 7f493b4a9780 20 client.4110 encode_inode_release enter(in:10000000000.head(ref=3 cap_refs={1024=0,4096=0,8192=0} open={2=0} mode=100644 size=4 mtime=2012-10-16 12:44:21.566329 caps=pAsLsXsFs(0=pAsLsXsFs) flushing_caps=Fw objectset[10000000000 ts 0/0 objects 0 dirty_or_tx 0] parents=0x22be150 0x2258680), req:0x22832c0 mds:0, drop:4, unless:0, have:, force:0)
 -10-16 12:44:27.557410 7f493b4a9780 20 client.4110 send_request set sent_stamp to 2012-10-16 12:44:27.557410
 -10-16 12:44:27.557416 7f493b4a9780 10 client.4110 send_request client_request(unknown.0:8 setattr mode=064330242 #10000000000) v1 to mds.0
 -10-16 12:44:27.557453 7f493b4a9780 20 client.4110 awaiting reply|forward|kick on 0x7fffa2bb93c0
 -10-16 12:44:27.560016 7f4936906700 20 client.4110 handle_client_reply got a reply. Safe:0 tid 8
 -10-16 12:44:27.560023 7f4936906700 10 client.4110 insert_trace from 2012-10-16 12:44:27.557410 mds.0 is_target=1 is_dentry=0
 -10-16 12:44:27.560030 7f4936906700 10 client.4110  features 0x7fffff
 -10-16 12:44:27.560034 7f4936906700 10 client.4110 update_snap_trace len 48
 -10-16 12:44:27.560044 7f4936906700 10 client.4110 update_snap_trace snaprealm(1 nref=4 c=0 seq=1 parent=0 my_snaps=[] cached_snapc=1=[]) seq 1 <= 1 and same parent, SKIPPING
 -10-16 12:44:27.560058 7f4936906700 10 client.4110  hrm  is_target=1 is_dentry=0
 -10-16 12:44:27.560075 7f4936906700 12 client.4110 add_update_inode had 10000000000.head(ref=3 cap_refs={1024=0,4096=0,8192=0} open={2=0} mode=100644 size=4 mtime=2012-10-16 12:44:21.566329 caps=pLsXsFs(0=pLsXsFs) flushing_caps=Fw objectset[10000000000 ts 0/0 objects 0 dirty_or_tx 0] parents=0x22be150 0x2258680) caps pAsLsXsFsxcrwb
 -10-16 12:44:27.560107 7f4936906700 10 client.4110 update_inode_file_bits 10000000000.head(ref=3 cap_refs={1024=0,4096=0,8192=0} open={2=0} mode=100644 size=4 mtime=2012-10-16 12:44:21.566329 caps=pLsXsFs(0=pLsXsFs) flushing_caps=Fw objectset[10000000000 ts 0/0 objects 0 dirty_or_tx 0] parents=0x22be150 0x2258680) pAxLsXsxFsxcrwb mtime 2012-10-16 12:44:21.566329
 -10-16 12:44:27.560144 7f4936906700 10 client.4110 add_update_cap issued pLsXsFs -> pAsLsXsFsxcrwb from mds.0 on 10000000000.head(ref=3 cap_refs={1024=0,4096=0,8192=0} open={2=0} mode=100644 size=4 mtime=2012-10-16 12:44:21.566329 caps=pAsLsXsFsxcrwb(0=pAsLsXsFsxcrwb) flushing_caps=Fw objectset[10000000000 ts 0/0 objects 0 dirty_or_tx 0] parents=0x22be150 0x2258680)
 -10-16 12:44:27.560183 7f4936906700 20 client.4110 handle_client_reply signalling caller 0x7fffa2bb93c0
 -10-16 12:44:27.560188 7f4936906700 20 client.4110 handle_client_reply awaiting kickback on tid 8 0x7f49369056d0
 -10-16 12:44:27.560195 7f493b4a9780 20 client.4110 sendrecv kickback on tid 8 0x7f49369056d0
 -10-16 12:44:27.560201 7f493b4a9780 20 client.4110 lat 0.002790
 -10-16 12:44:27.560210 7f493b4a9780 10 client.4110 _setattr result=0
 -10-16 12:44:27.560213 7f493b4a9780 10 client.4110 fill_stat on 10000000000 snap/devhead mode 0100644 mtime 2012-10-16 12:44:21.566329 ctime 2012-10-16 12:44:27.559216
 -10-16 12:44:27.560223 7f493b4a9780  3 client.4110 ll_setattr 10000000000.head = 0
 -10-16 12:44:27.562863 7f4936906700 10 client.4110  mds.0 seq now 3
 -10-16 12:44:27.562878 7f4936906700  5 client.4110 handle_cap_flush_ack mds.0 cleaned Fw on 10000000000.head(ref=3 cap_refs={1024=0,4096=0,8192=0} open={2=0} mode=100644 size=4 mtime=2012-10-16 12:44:21.566329 caps=pAsLsXsFsxcrwb(0=pAsLsXsFsxcrwb) flushing_caps=Fw objectset[10000000000 ts 0/0 objects 0 dirty_or_tx 0] parents=0x22be150 0x2258680) with Fw
 -10-16 12:44:27.562912 7f4936906700  5 client.4110   flushing_caps Fw -> -
 -10-16 12:44:27.562916 7f4936906700 10 client.4110  10000000000.head(ref=3 cap_refs={1024=0,4096=0,8192=0} open={2=0} mode=100644 size=4 mtime=2012-10-16 12:44:21.566329 caps=pAsLsXsFsxcrwb(0=pAsLsXsFsxcrwb) objectset[10000000000 ts 0/0 objects 0 dirty_or_tx 0] parents=0x22be150 0x2258680) !flushing
 -10-16 12:44:27.562948 7f4936906700 10 client.4110 put_inode on 10000000000.head(ref=3 cap_refs={1024=0,4096=0,8192=0} open={2=0} mode=100644 size=4 mtime=2012-10-16 12:44:21.566329 caps=pAsLsXsFsxcrwb(0=pAsLsXsFsxcrwb) objectset[10000000000 ts 0/0 objects 0 dirty_or_tx 0] parents=0x22be150 0x2258680)
 -10-16 12:44:27.563488 7f4936906700 10 client.4110  mds.0 seq now 4
 -10-16 12:44:27.563496 7f4936906700  5 client.4110 handle_cap_grant on in 10000000000 mds.0 seq 4 caps now pAsLsXsFsxcrwb was pAsLsXsFsxcrwb
 -10-16 12:44:27.563505 7f4936906700 10 client.4110 update_inode_file_bits 10000000000.head(ref=2 cap_refs={1024=0,4096=0,8192=0} open={2=0} mode=100644 size=4 mtime=2012-10-16 12:44:21.566329 caps=pAsLsXsFsxcrwb(0=pAsLsXsFsxcrwb) objectset[10000000000 ts 0/0 objects 0 dirty_or_tx 0] parents=0x22be150 0x2258680) pAsxLsXsxFsxcrwb mtime 2012-10-16 12:44:21.566329
 -10-16 12:44:27.563537 7f4936906700 10 client.4110   caps unchanged at pAsLsXsFsxcrwb
 -10-16 12:44:28.391839 7f4937908700 10 client.4110 renew_caps()
 -10-16 12:44:28.391879 7f4937908700 15 client.4110 renew_caps requesting from mds.0
 -10-16 12:44:28.391900 7f4937908700 10 client.4110 renew_caps mds.0
 -10-16 12:44:28.392018 7f4937908700 15 client.4110 renew_caps requesting from mds.1
 -10-16 12:44:28.392032 7f4937908700 10 client.4110 renew_caps mds.1
 -10-16 12:44:28.393603 7f4936906700 10 client.4110 handle_client_session client_session(renewcaps seq 5) v1 from mds.1
 -10-16 12:44:28.393755 7f4936906700 10 client.4110 handle_client_session client_session(renewcaps seq 5) v1 from mds.0
 -10-16 12:44:29.428008 7f4936906700 20 client.4110 handle_client_reply got a reply. Safe:1 tid 8
 -10-16 12:44:29.428030 7f4936906700 10 client.4110 insert_trace from 2012-10-16 12:44:27.557410 mds.0 is_target=0 is_dentry=0
 -10-16 12:44:29.428094 7f4936906700 10 client.4110 insert_trace -- no trace
 -10-16 12:44:31.568803 7f493b4a9780  3 client.4110 ll_getattr 1.head
 -10-16 12:44:31.568869 7f493b4a9780 10 client.4110 _getattr mask pAsLsXsFs issued=1
 -10-16 12:44:31.568891 7f493b4a9780 10 client.4110 fill_stat on 1 snap/devhead mode 040755 mtime 2012-10-16 12:44:21.542963 ctime 2012-10-16 12:44:21.542963
 -10-16 12:44:31.568933 7f493b4a9780  3 client.4110 ll_getattr 1.head = 0
 -10-16 12:44:31.569028 7f493b4a9780  3 client.4110 ll_lookup 1.head foo
 -10-16 12:44:31.569064 7f493b4a9780 20 client.4110 _lookup have dn foo mds.0 ttl 2012-10-16 12:44:51.525377 seq 2
 -10-16 12:44:31.569102 7f493b4a9780 10 client.4110 _lookup 1.head(ref=3 cap_refs={} open={} mode=40755 size=0 mtime=2012-10-16 12:44:21.542963 caps=pAsLsXsFs(0=pAsLsXsFs,1=pAsLsXs) 0x2257d80) foo = 10000000000.head(ref=2 cap_refs={1024=0,4096=0,8192=0} open={2=0} mode=100644 size=4 mtime=2012-10-16 12:44:21.566329 caps=pAsLsXsFsxcrwb(0=pAsLsXsFsxcrwb) objectset[10000000000 ts 0/0 objects 0 dirty_or_tx 0] parents=0x22be150 0x2258680)
 -10-16 12:44:31.569209 7f493b4a9780 10 client.4110 fill_stat on 10000000000 snap/devhead mode 0100644 mtime 2012-10-16 12:44:21.566329 ctime 2012-10-16 12:44:27.559216
 -10-16 12:44:31.569236 7f493b4a9780 20 client.4110 _ll_get 0x2258680 10000000000 -> 4
 -10-16 12:44:31.569245 7f493b4a9780  3 client.4110 ll_lookup 1.head foo -> 0 (10000000000)
 -10-16 12:44:31.569344 7f493b4a9780  3 client.4110 ll_getattr 10000000000.head
 -10-16 12:44:31.569369 7f493b4a9780 10 client.4110 _getattr mask pAsLsXsFs issued=1
 -10-16 12:44:31.569392 7f493b4a9780 10 client.4110 fill_stat on 10000000000 snap/devhead mode 0100644 mtime 2012-10-16 12:44:21.566329 ctime 2012-10-16 12:44:27.559216
 -10-16 12:44:31.569422 7f493b4a9780  3 client.4110 ll_getattr 10000000000.head = 0
 -10-16 12:44:31.569516 7f493b4a9780  3 client.4110 ll_getattr 1.head
 -10-16 12:44:31.569544 7f493b4a9780 10 client.4110 _getattr mask pAsLsXsFs issued=1
 -10-16 12:44:31.569558 7f493b4a9780 10 client.4110 fill_stat on 1 snap/devhead mode 040755 mtime 2012-10-16 12:44:21.542963 ctime 2012-10-16 12:44:21.542963
 -10-16 12:44:31.569588 7f493b4a9780  3 client.4110 ll_getattr 1.head = 0
 -10-16 12:44:31.569661 7f493b4a9780  3 client.4110 ll_lookup 1.head foo
 -10-16 12:44:31.569687 7f493b4a9780 20 client.4110 _lookup have dn foo mds.0 ttl 2012-10-16 12:44:51.525377 seq 2
 -10-16 12:44:31.569720 7f493b4a9780 10 client.4110 _lookup 1.head(ref=3 cap_refs={} open={} mode=40755 size=0 mtime=2012-10-16 12:44:21.542963 caps=pAsLsXsFs(0=pAsLsXsFs,1=pAsLsXs) 0x2257d80) foo = 10000000000.head(ref=2 cap_refs={1024=0,4096=0,8192=0} open={2=0} mode=100644 size=4 mtime=2012-10-16 12:44:21.566329 caps=pAsLsXsFsxcrwb(0=pAsLsXsFsxcrwb) objectset[10000000000 ts 0/0 objects 0 dirty_or_tx 0] parents=0x22be150 0x2258680)
 -10-16 12:44:31.569815 7f493b4a9780 10 client.4110 fill_stat on 10000000000 snap/devhead mode 0100644 mtime 2012-10-16 12:44:21.566329 ctime 2012-10-16 12:44:27.559216
 -10-16 12:44:31.569838 7f493b4a9780 20 client.4110 _ll_get 0x2258680 10000000000 -> 5
 -10-16 12:44:31.569845 7f493b4a9780  3 client.4110 ll_lookup 1.head foo -> 0 (10000000000)
 -10-16 12:44:31.569939 7f493b4a9780  3 client.4110 ll_setattr 10000000000.head mask 1
 -10-16 12:44:31.569966 7f493b4a9780 10 client.4110 _setattr mask 1 issued pAsLsXsFsxcrwb
 -10-16 12:44:31.570045 7f493b4a9780 20 client.4110 choose_target_mds starting with req->inode 10000000000.head(ref=2 cap_refs={1024=0,4096=0,8192=0} open={2=0} mode=100644 size=4 mtime=2012-10-16 12:44:21.566329 caps=pAsLsXsFsxcrwb(0=pAsLsXsFsxcrwb) objectset[10000000000 ts 0/0 objects 0 dirty_or_tx 0] parents=0x22be150 0x2258680)
 -10-16 12:44:31.570114 7f493b4a9780 20 client.4110 choose_target_mds 10000000000.head(ref=2 cap_refs={1024=0,4096=0,8192=0} open={2=0} mode=100644 size=4 mtime=2012-10-16 12:44:21.566329 caps=pAsLsXsFsxcrwb(0=pAsLsXsFsxcrwb) objectset[10000000000 ts 0/0 objects 0 dirty_or_tx 0] parents=0x22be150 0x2258680) is_hash=0 hash=0
 -10-16 12:44:31.570167 7f493b4a9780 10 client.4110 choose_target_mds from caps on inode 10000000000.head(ref=2 cap_refs={1024=0,4096=0,8192=0} open={2=0} mode=100644 size=4 mtime=2012-10-16 12:44:21.566329 caps=pAsLsXsFsxcrwb(0=pAsLsXsFsxcrwb) objectset[10000000000 ts 0/0 objects 0 dirty_or_tx 0] parents=0x22be150 0x2258680)
 -10-16 12:44:31.570215 7f493b4a9780 20 client.4110 mds is 0
 -10-16 12:44:31.570239 7f493b4a9780 10 client.4110 send_request rebuilding request 9 for mds.0
 -10-16 12:44:31.570268 7f493b4a9780 20 client.4110 encode_cap_releases enter (req: 0x22848c0, mds: 0)
 -10-16 12:44:31.570275 7f493b4a9780 20 client.4110 encode_inode_release enter(in:10000000000.head(ref=2 cap_refs={1024=0,4096=0,8192=0} open={2=0} mode=100644 size=4 mtime=2012-10-16 12:44:21.566329 caps=pAsLsXsFsxcrwb(0=pAsLsXsFsxcrwb) objectset[10000000000 ts 0/0 objects 0 dirty_or_tx 0] parents=0x22be150 0x2258680), req:0x22848c0 mds:0, drop:4, unless:0, have:, force:0)
 -10-16 12:44:31.570352 7f493b4a9780 20 client.4110 send_request set sent_stamp to 2012-10-16 12:44:31.570350
 -10-16 12:44:31.570369 7f493b4a9780 10 client.4110 send_request client_request(unknown.0:9 setattr mode=064331882 #10000000000) v1 to mds.0
 -10-16 12:44:31.570504 7f493b4a9780 20 client.4110 awaiting reply|forward|kick on 0x7fffa2bb93c0
 -10-16 12:44:31.577106 7f4936906700 20 client.4110 handle_client_reply got a reply. Safe:0 tid 9
 -10-16 12:44:31.577135 7f4936906700 10 client.4110 insert_trace from 2012-10-16 12:44:31.570350 mds.0 is_target=1 is_dentry=0
 -10-16 12:44:31.577162 7f4936906700 10 client.4110  features 0x7fffff
 -10-16 12:44:31.577174 7f4936906700 10 client.4110 update_snap_trace len 48
 -10-16 12:44:31.577210 7f4936906700 10 client.4110 update_snap_trace snaprealm(1 nref=4 c=0 seq=1 parent=0 my_snaps=[] cached_snapc=1=[]) seq 1 <= 1 and same parent, SKIPPING
 -10-16 12:44:31.577255 7f4936906700 10 client.4110  hrm  is_target=1 is_dentry=0
 -10-16 12:44:31.577315 7f4936906700 12 client.4110 add_update_inode had 10000000000.head(ref=2 cap_refs={1024=0,4096=0,8192=0} open={2=0} mode=100644 size=4 mtime=2012-10-16 12:44:21.566329 caps=pLsXsFsxcrwb(0=pLsXsFsxcrwb) objectset[10000000000 ts 0/0 objects 0 dirty_or_tx 0] parents=0x22be150 0x2258680) caps pAsLsXsFsxcrwb
 -10-16 12:44:31.577436 7f4936906700 10 client.4110 update_inode_file_bits 10000000000.head(ref=2 cap_refs={1024=0,4096=0,8192=0} open={2=0} mode=100644 size=4 mtime=2012-10-16 12:44:21.566329 caps=pLsXsFsxcrwb(0=pLsXsFsxcrwb) objectset[10000000000 ts 0/0 objects 0 dirty_or_tx 0] parents=0x22be150 0x2258680) pAxLsXsxFsxcrwb mtime 2012-10-16 12:44:21.566329
 -10-16 12:44:31.577577 7f4936906700 10 client.4110 add_update_cap issued pLsXsFsxcrwb -> pAsLsXsFsxcrwb from mds.0 on 10000000000.head(ref=2 cap_refs={1024=0,4096=0,8192=0} open={2=0} mode=100644 size=4 mtime=2012-10-16 12:44:21.566329 caps=pAsLsXsFsxcrwb(0=pAsLsXsFsxcrwb) objectset[10000000000 ts 0/0 objects 0 dirty_or_tx 0] parents=0x22be150 0x2258680)
 -10-16 12:44:31.577713 7f4936906700 20 client.4110 handle_client_reply signalling caller 0x7fffa2bb93c0
 -10-16 12:44:31.577751 7f4936906700 20 client.4110 handle_client_reply awaiting kickback on tid 9 0x7f49369056d0
 -10-16 12:44:31.577786 7f493b4a9780 20 client.4110 sendrecv kickback on tid 9 0x7f49369056d0
 -10-16 12:44:31.577800 7f493b4a9780 20 client.4110 lat 0.007446
 -10-16 12:44:31.577837 7f493b4a9780 10 client.4110 _setattr result=0
 -10-16 12:44:31.577850 7f493b4a9780 10 client.4110 fill_stat on 10000000000 snap/devhead mode 0100644 mtime 2012-10-16 12:44:21.566329 ctime 2012-10-16 12:44:31.574307
 -10-16 12:44:31.577895 7f493b4a9780  3 client.4110 ll_setattr 10000000000.head = 0
 -10-16 12:44:33.914151 7f493b4a9780  3 client.4110 ll_getattr 1.head
 -10-16 12:44:33.914211 7f493b4a9780 10 client.4110 _getattr mask pAsLsXsFs issued=1
 -10-16 12:44:33.914233 7f493b4a9780 10 client.4110 fill_stat on 1 snap/devhead mode 040755 mtime 2012-10-16 12:44:21.542963 ctime 2012-10-16 12:44:21.542963
 -10-16 12:44:33.914270 7f493b4a9780  3 client.4110 ll_getattr 1.head = 0
 -10-16 12:44:33.914356 7f493b4a9780  3 client.4110 ll_lookup 1.head foo
 -10-16 12:44:33.914388 7f493b4a9780 20 client.4110 _lookup have dn foo mds.0 ttl 2012-10-16 12:44:51.525377 seq 2
 -10-16 12:44:33.914442 7f493b4a9780 10 client.4110 _lookup 1.head(ref=3 cap_refs={} open={} mode=40755 size=0 mtime=2012-10-16 12:44:21.542963 caps=pAsLsXsFs(0=pAsLsXsFs,1=pAsLsXs) 0x2257d80) foo = 10000000000.head(ref=2 cap_refs={1024=0,4096=0,8192=0} open={2=0} mode=100644 size=4 mtime=2012-10-16 12:44:21.566329 caps=pAsLsXsFsxcrwb(0=pAsLsXsFsxcrwb) objectset[10000000000 ts 0/0 objects 0 dirty_or_tx 0] parents=0x22be150 0x2258680)
 -10-16 12:44:33.914549 7f493b4a9780 10 client.4110 fill_stat on 10000000000 snap/devhead mode 0100644 mtime 2012-10-16 12:44:21.566329 ctime 2012-10-16 12:44:31.574307
 -10-16 12:44:33.914577 7f493b4a9780 20 client.4110 _ll_get 0x2258680 10000000000 -> 6
 -10-16 12:44:33.914584 7f493b4a9780  3 client.4110 ll_lookup 1.head foo -> 0 (10000000000)
 -10-16 12:44:33.914653 7f493b4a9780  3 client.4110 ll_getattr 10000000000.head
 -10-16 12:44:33.914675 7f493b4a9780 10 client.4110 _getattr mask pAsLsXsFs issued=1
 -10-16 12:44:33.914686 7f493b4a9780 10 client.4110 fill_stat on 10000000000 snap/devhead mode 0100644 mtime 2012-10-16 12:44:21.566329 ctime 2012-10-16 12:44:31.574307
 -10-16 12:44:33.914714 7f493b4a9780  3 client.4110 ll_getattr 10000000000.head = 0
 -10-16 12:44:33.914810 7f493b4a9780  3 client.4110 ll_getattr 1.head
 -10-16 12:44:33.914832 7f493b4a9780 10 client.4110 _getattr mask pAsLsXsFs issued=1
 -10-16 12:44:33.914844 7f493b4a9780 10 client.4110 fill_stat on 1 snap/devhead mode 040755 mtime 2012-10-16 12:44:21.542963 ctime 2012-10-16 12:44:21.542963
 -10-16 12:44:33.914875 7f493b4a9780  3 client.4110 ll_getattr 1.head = 0
 -10-16 12:44:33.914936 7f493b4a9780  3 client.4110 ll_lookup 1.head foo
 -10-16 12:44:33.914963 7f493b4a9780 20 client.4110 _lookup have dn foo mds.0 ttl 2012-10-16 12:44:51.525377 seq 2
 -10-16 12:44:33.914997 7f493b4a9780 10 client.4110 _lookup 1.head(ref=3 cap_refs={} open={} mode=40755 size=0 mtime=2012-10-16 12:44:21.542963 caps=pAsLsXsFs(0=pAsLsXsFs,1=pAsLsXs) 0x2257d80) foo = 10000000000.head(ref=2 cap_refs={1024=0,4096=0,8192=0} open={2=0} mode=100644 size=4 mtime=2012-10-16 12:44:21.566329 caps=pAsLsXsFsxcrwb(0=pAsLsXsFsxcrwb) objectset[10000000000 ts 0/0 objects 0 dirty_or_tx 0] parents=0x22be150 0x2258680)
 -10-16 12:44:33.915145 7f493b4a9780 10 client.4110 fill_stat on 10000000000 snap/devhead mode 0100644 mtime 2012-10-16 12:44:21.566329 ctime 2012-10-16 12:44:31.574307
 -10-16 12:44:33.915171 7f493b4a9780 20 client.4110 _ll_get 0x2258680 10000000000 -> 7
 -10-16 12:44:33.915178 7f493b4a9780  3 client.4110 ll_lookup 1.head foo -> 0 (10000000000)
 -10-16 12:44:33.915285 7f493b4a9780  3 client.4110 ll_getxattr 10000000000.head security.selinux size 255
 -10-16 12:44:33.915297 7f493b4a9780 10 client.4110 _getattr mask Xs issued=1
 -10-16 12:44:33.915302 7f493b4a9780  3 client.4110 _getxattr(10000000000, "security.selinux", 255) = -61
 -10-16 12:44:33.915346 7f493b4a9780  3 client.4110 ll_getattr 1.head
 -10-16 12:44:33.915373 7f493b4a9780 10 client.4110 _getattr mask pAsLsXsFs issued=1
 -10-16 12:44:33.915392 7f493b4a9780 10 client.4110 fill_stat on 1 snap/devhead mode 040755 mtime 2012-10-16 12:44:21.542963 ctime 2012-10-16 12:44:21.542963
 -10-16 12:44:33.915428 7f493b4a9780  3 client.4110 ll_getattr 1.head = 0
 -10-16 12:44:33.915469 7f493b4a9780  3 client.4110 ll_lookup 1.head foo
 -10-16 12:44:33.915478 7f493b4a9780 20 client.4110 _lookup have dn foo mds.0 ttl 2012-10-16 12:44:51.525377 seq 2
 -10-16 12:44:33.915494 7f493b4a9780 10 client.4110 _lookup 1.head(ref=3 cap_refs={} open={} mode=40755 size=0 mtime=2012-10-16 12:44:21.542963 caps=pAsLsXsFs(0=pAsLsXsFs,1=pAsLsXs) 0x2257d80) foo = 10000000000.head(ref=2 cap_refs={1024=0,4096=0,8192=0} open={2=0} mode=100644 size=4 mtime=2012-10-16 12:44:21.566329 caps=pAsLsXsFsxcrwb(0=pAsLsXsFsxcrwb) objectset[10000000000 ts 0/0 objects 0 dirty_or_tx 0] parents=0x22be150 0x2258680)
 -10-16 12:44:33.915523 7f493b4a9780 10 client.4110 fill_stat on 10000000000 snap/devhead mode 0100644 mtime 2012-10-16 12:44:21.566329 ctime 2012-10-16 12:44:31.574307
 -10-16 12:44:33.915560 7f493b4a9780 20 client.4110 _ll_get 0x2258680 10000000000 -> 8
 -10-16 12:44:33.915568 7f493b4a9780  3 client.4110 ll_lookup 1.head foo -> 0 (10000000000)
 -10-16 12:44:33.915628 7f493b4a9780  3 client.4110 ll_getxattr 10000000000.head system.posix_acl_access size 0
 -10-16 12:44:33.915634 7f493b4a9780 10 client.4110 _getattr mask Xs issued=1
 -10-16 12:44:33.915638 7f493b4a9780  3 client.4110 _getxattr(10000000000, "system.posix_acl_access", 0) = -61
 -10-16 12:44:33.915656 7f493b4a9780  3 client.4110 ll_getattr 1.head
 -10-16 12:44:33.915662 7f493b4a9780 10 client.4110 _getattr mask pAsLsXsFs issued=1
 -10-16 12:44:33.915666 7f493b4a9780 10 client.4110 fill_stat on 1 snap/devhead mode 040755 mtime 2012-10-16 12:44:21.542963 ctime 2012-10-16 12:44:21.542963
 -10-16 12:44:33.915678 7f493b4a9780  3 client.4110 ll_getattr 1.head = 0
 -10-16 12:44:33.915696 7f493b4a9780  3 client.4110 ll_lookup 1.head foo
 -10-16 12:44:33.915703 7f493b4a9780 20 client.4110 _lookup have dn foo mds.0 ttl 2012-10-16 12:44:51.525377 seq 2
 -10-16 12:44:33.915711 7f493b4a9780 10 client.4110 _lookup 1.head(ref=3 cap_refs={} open={} mode=40755 size=0 mtime=2012-10-16 12:44:21.542963 caps=pAsLsXsFs(0=pAsLsXsFs,1=pAsLsXs) 0x2257d80) foo = 10000000000.head(ref=2 cap_refs={1024=0,4096=0,8192=0} open={2=0} mode=100644 size=4 mtime=2012-10-16 12:44:21.566329 caps=pAsLsXsFsxcrwb(0=pAsLsXsFsxcrwb) objectset[10000000000 ts 0/0 objects 0 dirty_or_tx 0] parents=0x22be150 0x2258680)
 -10-16 12:44:33.915768 7f493b4a9780 10 client.4110 fill_stat on 10000000000 snap/devhead mode 0100644 mtime 2012-10-16 12:44:21.566329 ctime 2012-10-16 12:44:31.574307
 -10-16 12:44:33.915793 7f493b4a9780 20 client.4110 _ll_get 0x2258680 10000000000 -> 9
 -10-16 12:44:33.915800 7f493b4a9780  3 client.4110 ll_lookup 1.head foo -> 0 (10000000000)
 -10-16 12:44:33.915871 7f493b4a9780  3 client.4110 ll_getxattr 10000000000.head system.posix_acl_default size 0
 -10-16 12:44:33.915887 7f493b4a9780 10 client.4110 _getattr mask Xs issued=1
 -10-16 12:44:33.915893 7f493b4a9780  3 client.4110 _getxattr(10000000000, "system.posix_acl_default", 0) = -61
 -10-16 12:44:34.435238 7f4936906700 20 client.4110 handle_client_reply got a reply. Safe:1 tid 9
 -10-16 12:44:34.435289 7f4936906700 10 client.4110 insert_trace from 2012-10-16 12:44:31.570350 mds.0 is_target=0 is_dentry=0
 -10-16 12:44:34.435362 7f4936906700 10 client.4110 insert_trace -- no trace
 -10-16 12:44:48.394635 7f4937908700 10 client.4110 renew_caps()
 -10-16 12:44:48.394685 7f4937908700 15 client.4110 renew_caps requesting from mds.0
 -10-16 12:44:48.394718 7f4937908700 10 client.4110 renew_caps mds.0
 -10-16 12:44:48.394912 7f4937908700 15 client.4110 renew_caps requesting from mds.1
 -10-16 12:44:48.394953 7f4937908700 10 client.4110 renew_caps mds.1
 -10-16 12:44:48.397037 7f4936906700 10 client.4110 handle_client_session client_session(renewcaps seq 6) v1 from mds.0
 -10-16 12:44:48.397379 7f4936906700 10 client.4110 handle_client_session client_session(renewcaps seq 6) v1 from mds.1
 -10-16 12:44:55.672314 7f493b4a9780  3 client.4110 ll_getattr 1.head
 -10-16 12:44:55.672377 7f493b4a9780 10 client.4110 _getattr mask pAsLsXsFs issued=1
 -10-16 12:44:55.672399 7f493b4a9780 10 client.4110 fill_stat on 1 snap/devhead mode 040755 mtime 2012-10-16 12:44:21.542963 ctime 2012-10-16 12:44:21.542963
 -10-16 12:44:55.672438 7f493b4a9780  3 client.4110 ll_getattr 1.head = 0
 -10-16 12:44:55.672523 7f493b4a9780  3 client.4110 ll_lookup 1.head foo
 -10-16 12:44:55.672556 7f493b4a9780 20 client.4110 _lookup have dn foo mds.0 ttl 2012-10-16 12:44:51.525377 seq 2
 -10-16 12:44:55.672619 7f493b4a9780 10 client.4110 _lookup on #1/foo
 -10-16 12:44:55.672648 7f493b4a9780 20 client.4110 choose_target_mds starting with req->inode 1.head(ref=3 cap_refs={} open={} mode=40755 size=0 mtime=2012-10-16 12:44:21.542963 caps=pAsLsXsFs(0=pAsLsXsFs,1=pAsLsXs) 0x2257d80)
 -10-16 12:44:55.672708 7f493b4a9780 20 client.4110 choose_target_mds inode dir hash is 2 on foo => 2143417350
 -10-16 12:44:55.672717 7f493b4a9780 20 client.4110 choose_target_mds 1.head(ref=3 cap_refs={} open={} mode=40755 size=0 mtime=2012-10-16 12:44:21.542963 caps=pAsLsXsFs(0=pAsLsXsFs,1=pAsLsXs) 0x2257d80) is_hash=1 hash=2143417350
 -10-16 12:44:55.672766 7f493b4a9780 10 client.4110 choose_target_mds from caps on inode 1.head(ref=3 cap_refs={} open={} mode=40755 size=0 mtime=2012-10-16 12:44:21.542963 caps=pAsLsXsFs(0=pAsLsXsFs,1=pAsLsXs) 0x2257d80)
 -10-16 12:44:55.672811 7f493b4a9780 20 client.4110 mds is 0
 -10-16 12:44:55.672836 7f493b4a9780 10 client.4110 send_request rebuilding request 10 for mds.0
 -10-16 12:44:55.672867 7f493b4a9780 20 client.4110 encode_cap_releases enter (req: 0x2284600, mds: 0)
 -10-16 12:44:55.672877 7f493b4a9780 20 client.4110 send_request set sent_stamp to 2012-10-16 12:44:55.672876
 -10-16 12:44:55.672898 7f493b4a9780 10 client.4110 send_request client_request(unknown.0:10 lookup #1/foo) v1 to mds.0
 -10-16 12:44:55.673021 7f493b4a9780 20 client.4110 awaiting reply|forward|kick on 0x7fffa2bb90d0
 -10-16 12:44:55.677467 7f4936906700 20 client.4110 handle_client_reply got a reply. Safe:1 tid 10
 -10-16 12:44:55.677481 7f4936906700 10 client.4110 insert_trace from 2012-10-16 12:44:55.672876 mds.0 is_target=1 is_dentry=1
 -10-16 12:44:55.677500 7f4936906700 10 client.4110  features 0x7fffff
 -10-16 12:44:55.677514 7f4936906700 10 client.4110 update_snap_trace len 48
 -10-16 12:44:55.677537 7f4936906700 10 client.4110 update_snap_trace snaprealm(1 nref=4 c=0 seq=1 parent=0 my_snaps=[] cached_snapc=1=[]) seq 1 <= 1 and same parent, SKIPPING
 -10-16 12:44:55.677564 7f4936906700 10 client.4110  hrm  is_target=1 is_dentry=1
 -10-16 12:44:55.677654 7f4936906700 12 client.4110 add_update_inode had 10000000000.head(ref=2 cap_refs={1024=0,4096=0,8192=0} open={2=0} mode=100644 size=4 mtime=2012-10-16 12:44:21.566329 caps=pAsLsXsFsxcrwb(0=pAsLsXsFsxcrwb) objectset[10000000000 ts 0/0 objects 0 dirty_or_tx 0] parents=0x22be150 0x2258680) caps pAsLsXsFsxcrwb
 -10-16 12:44:55.677738 7f4936906700 10 client.4110 update_inode_file_bits 10000000000.head(ref=2 cap_refs={1024=0,4096=0,8192=0} open={2=0} mode=100644 size=4 mtime=2012-10-16 12:44:21.566329 caps=pAsLsXsFsxcrwb(0=pAsLsXsFsxcrwb) objectset[10000000000 ts 0/0 objects 0 dirty_or_tx 0] parents=0x22be150 0x2258680) pAsxLsXsxFsxcrwb mtime 2012-10-16 12:44:21.566329
 -10-16 12:44:55.677829 7f4936906700 10 client.4110 add_update_cap issued pAsLsXsFsxcrwb -> pAsLsXsFsxcrwb from mds.0 on 10000000000.head(ref=2 cap_refs={1024=0,4096=0,8192=0} open={2=0} mode=100644 size=4 mtime=2012-10-16 12:44:21.566329 caps=pAsLsXsFsxcrwb(0=pAsLsXsFsxcrwb) objectset[10000000000 ts 0/0 objects 0 dirty_or_tx 0] parents=0x22be150 0x2258680)
 -10-16 12:44:55.677898 7f4936906700 12 client.4110 add_update_inode had 1.head(ref=3 cap_refs={} open={} mode=40755 size=0 mtime=2012-10-16 12:44:21.542963 caps=pAsLsXsFs(0=pAsLsXsFs,1=pAsLsXs) 0x2257d80) caps pAsLsXsFs
 -10-16 12:44:55.677953 7f4936906700 20 client.4110  dir hash is 2
 -10-16 12:44:55.677959 7f4936906700 10 client.4110 update_inode_file_bits 1.head(ref=3 cap_refs={} open={} mode=40755 size=0 mtime=2012-10-16 12:44:21.542963 caps=pAsLsXsFs(0=pAsLsXsFs,1=pAsLsXs) 0x2257d80) pAsLsXsFs mtime 2012-10-16 12:44:21.542963
 -10-16 12:44:55.678030 7f4936906700 10 client.4110 add_update_cap issued pAsLsXsFs -> pAsLsXsFs from mds.0 on 1.head(ref=3 cap_refs={} open={} mode=40755 size=0 mtime=2012-10-16 12:44:21.542963 caps=pAsLsXsFs(0=pAsLsXsFs,1=pAsLsXs) 0x2257d80)
 -10-16 12:44:55.678083 7f4936906700 20 client.4110 got dirfrag map for 1 frag * to mds 0
 -10-16 12:44:55.678123 7f4936906700 12 client.4110 insert_dentry_inode 'foo' vino 10000000000.head in dir 1.head dn 0x22be150
 -10-16 12:44:55.678140 7f4936906700 12 client.4110  had dentry foo with correct vino 10000000000.head
 -10-16 12:44:55.678161 7f4936906700 20 client.4110 handle_client_reply signalling caller 0x7fffa2bb90d0
 -10-16 12:44:55.678172 7f4936906700 20 client.4110 handle_client_reply awaiting kickback on tid 10 0x7f49369056d0
 -10-16 12:44:55.678200 7f493b4a9780 20 client.4110 sendrecv kickback on tid 10 0x7f49369056d0
 -10-16 12:44:55.678222 7f493b4a9780 20 client.4110 lat 0.005343
 -10-16 12:44:55.678259 7f493b4a9780 10 client.4110 _lookup res is 0
 -10-16 12:44:55.678276 7f493b4a9780 10 client.4110 _lookup 1.head(ref=3 cap_refs={} open={} mode=40755 size=0 mtime=2012-10-16 12:44:21.542963 caps=pAsLsXsFs(0=pAsLsXsFs,1=pAsLsXs) 0x2257d80) foo = 10000000000.head(ref=2 cap_refs={1024=0,4096=0,8192=0} open={2=0} mode=100644 size=4 mtime=2012-10-16 12:44:21.566329 caps=pAsLsXsFsxcrwb(0=pAsLsXsFsxcrwb) objectset[10000000000 ts 0/0 objects 0 dirty_or_tx 0] parents=0x22be150 0x2258680)
 -10-16 12:44:55.678399 7f493b4a9780 10 client.4110 fill_stat on 10000000000 snap/devhead mode 0100644 mtime 2012-10-16 12:44:21.566329 ctime 2012-10-16 12:44:31.574307
 -10-16 12:44:55.678435 7f493b4a9780 20 client.4110 _ll_get 0x2258680 10000000000 -> 10
 -10-16 12:44:55.678448 7f493b4a9780  3 client.4110 ll_lookup 1.head foo -> 0 (10000000000)
 -10-16 12:44:55.678596 7f493b4a9780  3 client.4110 ll_getattr 10000000000.head
 -10-16 12:44:55.678635 7f493b4a9780 10 client.4110 _getattr mask pAsLsXsFs issued=1
 -10-16 12:44:55.678656 7f493b4a9780 10 client.4110 fill_stat on 10000000000 snap/devhead mode 0100644 mtime 2012-10-16 12:44:21.566329 ctime 2012-10-16 12:44:31.574307
 -10-16 12:44:55.678687 7f493b4a9780  3 client.4110 ll_getattr 10000000000.head = 0
 -10-16 12:44:55.678789 7f493b4a9780  3 client.4110 ll_getattr 1.head
 -10-16 12:44:55.678825 7f493b4a9780 10 client.4110 _getattr mask pAsLsXsFs issued=1
 -10-16 12:44:55.678846 7f493b4a9780 10 client.4110 fill_stat on 1 snap/devhead mode 040755 mtime 2012-10-16 12:44:21.542963 ctime 2012-10-16 12:44:21.542963
 -10-16 12:44:55.678888 7f493b4a9780  3 client.4110 ll_getattr 1.head = 0
 -10-16 12:44:55.678957 7f493b4a9780  3 client.4110 ll_lookup 1.head foo
 -10-16 12:44:55.678997 7f493b4a9780 20 client.4110 _lookup have dn foo mds.0 ttl 2012-10-16 12:44:51.525377 seq 2
 -10-16 12:44:55.679029 7f493b4a9780 10 client.4110 _lookup 1.head(ref=3 cap_refs={} open={} mode=40755 size=0 mtime=2012-10-16 12:44:21.542963 caps=pAsLsXsFs(0=pAsLsXsFs,1=pAsLsXs) 0x2257d80) foo = 10000000000.head(ref=2 cap_refs={1024=0,4096=0,8192=0} open={2=0} mode=100644 size=4 mtime=2012-10-16 12:44:21.566329 caps=pAsLsXsFsxcrwb(0=pAsLsXsFsxcrwb) objectset[10000000000 ts 0/0 objects 0 dirty_or_tx 0] parents=0x22be150 0x2258680)
 -10-16 12:44:55.679212 7f493b4a9780 10 client.4110 fill_stat on 10000000000 snap/devhead mode 0100644 mtime 2012-10-16 12:44:21.566329 ctime 2012-10-16 12:44:31.574307
 -10-16 12:44:55.679277 7f493b4a9780 20 client.4110 _ll_get 0x2258680 10000000000 -> 11
 -10-16 12:44:55.679286 7f493b4a9780  3 client.4110 ll_lookup 1.head foo -> 0 (10000000000)
 -10-16 12:44:55.679372 7f493b4a9780  3 client.4110 ll_setattr 10000000000.head mask 1
 -10-16 12:44:55.679403 7f493b4a9780 10 client.4110 _setattr mask 1 issued pAsLsXsFsxcrwb
 -10-16 12:44:55.679456 7f493b4a9780 20 client.4110 choose_target_mds starting with req->inode 10000000000.head(ref=2 cap_refs={1024=0,4096=0,8192=0} open={2=0} mode=100644 size=4 mtime=2012-10-16 12:44:21.566329 caps=pAsLsXsFsxcrwb(0=pAsLsXsFsxcrwb) objectset[10000000000 ts 0/0 objects 0 dirty_or_tx 0] parents=0x22be150 0x2258680)
 -10-16 12:44:55.679519 7f493b4a9780 20 client.4110 choose_target_mds 10000000000.head(ref=2 cap_refs={1024=0,4096=0,8192=0} open={2=0} mode=100644 size=4 mtime=2012-10-16 12:44:21.566329 caps=pAsLsXsFsxcrwb(0=pAsLsXsFsxcrwb) objectset[10000000000 ts 0/0 objects 0 dirty_or_tx 0] parents=0x22be150 0x2258680) is_hash=0 hash=0
 -10-16 12:44:55.679577 7f493b4a9780 10 client.4110 choose_target_mds from caps on inode 10000000000.head(ref=2 cap_refs={1024=0,4096=0,8192=0} open={2=0} mode=100644 size=4 mtime=2012-10-16 12:44:21.566329 caps=pAsLsXsFsxcrwb(0=pAsLsXsFsxcrwb) objectset[10000000000 ts 0/0 objects 0 dirty_or_tx 0] parents=0x22be150 0x2258680)
 -10-16 12:44:55.679632 7f493b4a9780 20 client.4110 mds is 0
 -10-16 12:44:55.679655 7f493b4a9780 10 client.4110 send_request rebuilding request 11 for mds.0
 -10-16 12:44:55.679680 7f493b4a9780 20 client.4110 encode_cap_releases enter (req: 0x2284340, mds: 0)
 -10-16 12:44:55.679689 7f493b4a9780 20 client.4110 encode_inode_release enter(in:10000000000.head(ref=2 cap_refs={1024=0,4096=0,8192=0} open={2=0} mode=100644 size=4 mtime=2012-10-16 12:44:21.566329 caps=pAsLsXsFsxcrwb(0=pAsLsXsFsxcrwb) objectset[10000000000 ts 0/0 objects 0 dirty_or_tx 0] parents=0x22be150 0x2258680), req:0x2284340 mds:0, drop:4, unless:0, have:, force:0)
 -10-16 12:44:55.679768 7f493b4a9780 20 client.4110 send_request set sent_stamp to 2012-10-16 12:44:55.679767
 -10-16 12:44:55.679789 7f493b4a9780 10 client.4110 send_request client_request(unknown.0:11 setattr mode=064330242 #10000000000) v1 to mds.0
 -10-16 12:44:55.679894 7f493b4a9780 20 client.4110 awaiting reply|forward|kick on 0x7fffa2bb93c0
 -10-16 12:44:55.685951 7f4936906700 20 client.4110 handle_client_reply got a reply. Safe:0 tid 11
 -10-16 12:44:55.685980 7f4936906700 10 client.4110 insert_trace from 2012-10-16 12:44:55.679767 mds.0 is_target=1 is_dentry=0
 -10-16 12:44:55.686101 7f4936906700 10 client.4110  features 0x7fffff
 -10-16 12:44:55.686119 7f4936906700 10 client.4110 update_snap_trace len 48
 -10-16 12:44:55.686149 7f4936906700 10 client.4110 update_snap_trace snaprealm(1 nref=4 c=0 seq=1 parent=0 my_snaps=[] cached_snapc=1=[]) seq 1 <= 1 and same parent, SKIPPING
 -10-16 12:44:55.686189 7f4936906700 10 client.4110  hrm  is_target=1 is_dentry=0
 -10-16 12:44:55.686242 7f4936906700 12 client.4110 add_update_inode had 10000000000.head(ref=2 cap_refs={1024=0,4096=0,8192=0} open={2=0} mode=100644 size=4 mtime=2012-10-16 12:44:21.566329 caps=pLsXsFsxcrwb(0=pLsXsFsxcrwb) objectset[10000000000 ts 0/0 objects 0 dirty_or_tx 0] parents=0x22be150 0x2258680) caps pAsLsXsFsxcrwb
 -10-16 12:44:55.686363 7f4936906700 10 client.4110 update_inode_file_bits 10000000000.head(ref=2 cap_refs={1024=0,4096=0,8192=0} open={2=0} mode=100644 size=4 mtime=2012-10-16 12:44:21.566329 caps=pLsXsFsxcrwb(0=pLsXsFsxcrwb) objectset[10000000000 ts 0/0 objects 0 dirty_or_tx 0] parents=0x22be150 0x2258680) pAxLsXsxFsxcrwb mtime 2012-10-16 12:44:21.566329
 -10-16 12:44:55.686493 7f4936906700 10 client.4110 add_update_cap issued pLsXsFsxcrwb -> pAsLsXsFsxcrwb from mds.0 on 10000000000.head(ref=2 cap_refs={1024=0,4096=0,8192=0} open={2=0} mode=100644 size=4 mtime=2012-10-16 12:44:21.566329 caps=pAsLsXsFsxcrwb(0=pAsLsXsFsxcrwb) objectset[10000000000 ts 0/0 objects 0 dirty_or_tx 0] parents=0x22be150 0x2258680)
 -10-16 12:44:55.686635 7f4936906700 20 client.4110 handle_client_reply signalling caller 0x7fffa2bb93c0
 -10-16 12:44:55.686654 7f4936906700 20 client.4110 handle_client_reply awaiting kickback on tid 11 0x7f49369056d0
 -10-16 12:44:55.686733 7f493b4a9780 20 client.4110 sendrecv kickback on tid 11 0x7f49369056d0
 -10-16 12:44:55.686754 7f493b4a9780 20 client.4110 lat 0.006984
 -10-16 12:44:55.686797 7f493b4a9780 10 client.4110 _setattr result=0
 -10-16 12:44:55.686809 7f493b4a9780 10 client.4110 fill_stat on 10000000000 snap/devhead mode 0100644 mtime 2012-10-16 12:44:21.566329 ctime 2012-10-16 12:44:55.683293
 -10-16 12:44:55.686871 7f493b4a9780  3 client.4110 ll_setattr 10000000000.head = 0
 -10-16 12:44:57.625345 7f493b4a9780  3 client.4110 ll_getattr 1.head
 -10-16 12:44:57.625405 7f493b4a9780 10 client.4110 _getattr mask pAsLsXsFs issued=1
 -10-16 12:44:57.625434 7f493b4a9780 10 client.4110 fill_stat on 1 snap/devhead mode 040755 mtime 2012-10-16 12:44:21.542963 ctime 2012-10-16 12:44:21.542963
 -10-16 12:44:57.625491 7f493b4a9780  3 client.4110 ll_getattr 1.head = 0
 -10-16 12:44:57.625590 7f493b4a9780  3 client.4110 ll_lookup 1.head foo
 -10-16 12:44:57.625625 7f493b4a9780 20 client.4110 _lookup have dn foo mds.0 ttl 2012-10-16 12:44:51.525377 seq 2
 -10-16 12:44:57.625647 7f493b4a9780 10 client.4110 _lookup 1.head(ref=3 cap_refs={} open={} mode=40755 size=0 mtime=2012-10-16 12:44:21.542963 caps=pAsLsXsFs(0=pAsLsXsFs,1=pAsLsXs) 0x2257d80) foo = 10000000000.head(ref=2 cap_refs={1024=0,4096=0,8192=0} open={2=0} mode=100644 size=4 mtime=2012-10-16 12:44:21.566329 caps=pAsLsXsFsxcrwb(0=pAsLsXsFsxcrwb) objectset[10000000000 ts 0/0 objects 0 dirty_or_tx 0] parents=0x22be150 0x2258680)
 -10-16 12:44:57.625756 7f493b4a9780 10 client.4110 fill_stat on 10000000000 snap/devhead mode 0100644 mtime 2012-10-16 12:44:21.566329 ctime 2012-10-16 12:44:55.683293
 -10-16 12:44:57.625781 7f493b4a9780 20 client.4110 _ll_get 0x2258680 10000000000 -> 12
 -10-16 12:44:57.625788 7f493b4a9780  3 client.4110 ll_lookup 1.head foo -> 0 (10000000000)
 -10-16 12:44:57.625861 7f493b4a9780  3 client.4110 ll_getattr 10000000000.head
 -10-16 12:44:57.625882 7f493b4a9780 10 client.4110 _getattr mask pAsLsXsFs issued=1
 -10-16 12:44:57.625896 7f493b4a9780 10 client.4110 fill_stat on 10000000000 snap/devhead mode 0100644 mtime 2012-10-16 12:44:21.566329 ctime 2012-10-16 12:44:55.683293
 -10-16 12:44:57.625923 7f493b4a9780  3 client.4110 ll_getattr 10000000000.head = 0
 -10-16 12:44:57.626005 7f493b4a9780  3 client.4110 ll_getattr 1.head
 -10-16 12:44:57.626029 7f493b4a9780 10 client.4110 _getattr mask pAsLsXsFs issued=1
 -10-16 12:44:57.626041 7f493b4a9780 10 client.4110 fill_stat on 1 snap/devhead mode 040755 mtime 2012-10-16 12:44:21.542963 ctime 2012-10-16 12:44:21.542963
 -10-16 12:44:57.626090 7f493b4a9780  3 client.4110 ll_getattr 1.head = 0
 -10-16 12:44:57.626164 7f493b4a9780  3 client.4110 ll_lookup 1.head foo
 -10-16 12:44:57.626191 7f493b4a9780 20 client.4110 _lookup have dn foo mds.0 ttl 2012-10-16 12:44:51.525377 seq 2
 -10-16 12:44:57.626210 7f493b4a9780 10 client.4110 _lookup 1.head(ref=3 cap_refs={} open={} mode=40755 size=0 mtime=2012-10-16 12:44:21.542963 caps=pAsLsXsFs(0=pAsLsXsFs,1=pAsLsXs) 0x2257d80) foo = 10000000000.head(ref=2 cap_refs={1024=0,4096=0,8192=0} open={2=0} mode=100644 size=4 mtime=2012-10-16 12:44:21.566329 caps=pAsLsXsFsxcrwb(0=pAsLsXsFsxcrwb) objectset[10000000000 ts 0/0 objects 0 dirty_or_tx 0] parents=0x22be150 0x2258680)
 -10-16 12:44:57.626302 7f493b4a9780 10 client.4110 fill_stat on 10000000000 snap/devhead mode 0100644 mtime 2012-10-16 12:44:21.566329 ctime 2012-10-16 12:44:55.683293
 -10-16 12:44:57.626328 7f493b4a9780 20 client.4110 _ll_get 0x2258680 10000000000 -> 13
 -10-16 12:44:57.626336 7f493b4a9780  3 client.4110 ll_lookup 1.head foo -> 0 (10000000000)
 -10-16 12:44:57.626410 7f493b4a9780  3 client.4110 ll_getxattr 10000000000.head security.selinux size 255
 -10-16 12:44:57.626437 7f493b4a9780 10 client.4110 _getattr mask Xs issued=1
 -10-16 12:44:57.626450 7f493b4a9780  3 client.4110 _getxattr(10000000000, "security.selinux", 255) = -61
 -10-16 12:44:57.626528 7f493b4a9780  3 client.4110 ll_getattr 1.head
 -10-16 12:44:57.626552 7f493b4a9780 10 client.4110 _getattr mask pAsLsXsFs issued=1
 -10-16 12:44:57.626565 7f493b4a9780 10 client.4110 fill_stat on 1 snap/devhead mode 040755 mtime 2012-10-16 12:44:21.542963 ctime 2012-10-16 12:44:21.542963
 -10-16 12:44:57.626594 7f493b4a9780  3 client.4110 ll_getattr 1.head = 0
 -10-16 12:44:57.626655 7f493b4a9780  3 client.4110 ll_lookup 1.head foo
 -10-16 12:44:57.626684 7f493b4a9780 20 client.4110 _lookup have dn foo mds.0 ttl 2012-10-16 12:44:51.525377 seq 2
 -10-16 12:44:57.626704 7f493b4a9780 10 client.4110 _lookup 1.head(ref=3 cap_refs={} open={} mode=40755 size=0 mtime=2012-10-16 12:44:21.542963 caps=pAsLsXsFs(0=pAsLsXsFs,1=pAsLsXs) 0x2257d80) foo = 10000000000.head(ref=2 cap_refs={1024=0,4096=0,8192=0} open={2=0} mode=100644 size=4 mtime=2012-10-16 12:44:21.566329 caps=pAsLsXsFsxcrwb(0=pAsLsXsFsxcrwb) objectset[10000000000 ts 0/0 objects 0 dirty_or_tx 0] parents=0x22be150 0x2258680)
 -10-16 12:44:57.626808 7f493b4a9780 10 client.4110 fill_stat on 10000000000 snap/devhead mode 0100644 mtime 2012-10-16 12:44:21.566329 ctime 2012-10-16 12:44:55.683293
 -10-16 12:44:57.626835 7f493b4a9780 20 client.4110 _ll_get 0x2258680 10000000000 -> 14
 -10-16 12:44:57.626844 7f493b4a9780  3 client.4110 ll_lookup 1.head foo -> 0 (10000000000)
 -10-16 12:44:57.626921 7f493b4a9780  3 client.4110 ll_getxattr 10000000000.head system.posix_acl_access size 0
 -10-16 12:44:57.626948 7f493b4a9780 10 client.4110 _getattr mask Xs issued=1
 -10-16 12:44:57.626959 7f493b4a9780  3 client.4110 _getxattr(10000000000, "system.posix_acl_access", 0) = -61
 -10-16 12:44:57.627013 7f493b4a9780  3 client.4110 ll_getattr 1.head
 -10-16 12:44:57.627071 7f493b4a9780 10 client.4110 _getattr mask pAsLsXsFs issued=1
 -10-16 12:44:57.627091 7f493b4a9780 10 client.4110 fill_stat on 1 snap/devhead mode 040755 mtime 2012-10-16 12:44:21.542963 ctime 2012-10-16 12:44:21.542963
 -10-16 12:44:57.627123 7f493b4a9780  3 client.4110 ll_getattr 1.head = 0
 -10-16 12:44:57.627187 7f493b4a9780  3 client.4110 ll_lookup 1.head foo
 -10-16 12:44:57.627222 7f493b4a9780 20 client.4110 _lookup have dn foo mds.0 ttl 2012-10-16 12:44:51.525377 seq 2
 -10-16 12:44:57.627245 7f493b4a9780 10 client.4110 _lookup 1.head(ref=3 cap_refs={} open={} mode=40755 size=0 mtime=2012-10-16 12:44:21.542963 caps=pAsLsXsFs(0=pAsLsXsFs,1=pAsLsXs) 0x2257d80) foo = 10000000000.head(ref=2 cap_refs={1024=0,4096=0,8192=0} open={2=0} mode=100644 size=4 mtime=2012-10-16 12:44:21.566329 caps=pAsLsXsFsxcrwb(0=pAsLsXsFsxcrwb) objectset[10000000000 ts 0/0 objects 0 dirty_or_tx 0] parents=0x22be150 0x2258680)
 -10-16 12:44:57.627340 7f493b4a9780 10 client.4110 fill_stat on 10000000000 snap/devhead mode 0100644 mtime 2012-10-16 12:44:21.566329 ctime 2012-10-16 12:44:55.683293
 -10-16 12:44:57.627366 7f493b4a9780 20 client.4110 _ll_get 0x2258680 10000000000 -> 15
 -10-16 12:44:57.627376 7f493b4a9780  3 client.4110 ll_lookup 1.head foo -> 0 (10000000000)
 -10-16 12:44:57.627448 7f493b4a9780  3 client.4110 ll_getxattr 10000000000.head system.posix_acl_default size 0
 -10-16 12:44:57.627475 7f493b4a9780 10 client.4110 _getattr mask Xs issued=1
 -10-16 12:44:57.627487 7f493b4a9780  3 client.4110 _getxattr(10000000000, "system.posix_acl_default", 0) = -61
 -10-16 12:44:59.432930 7f4936906700 20 client.4110 handle_client_reply got a reply. Safe:1 tid 11
 -10-16 12:44:59.432952 7f4936906700 10 client.4110 insert_trace from 2012-10-16 12:44:55.679767 mds.0 is_target=0 is_dentry=0
 -10-16 12:44:59.432983 7f4936906700 10 client.4110 insert_trace -- no trace
 -10-16 12:45:06.478204 7f493b4a9780  3 client.4110 ll_getattr 1.head
 -10-16 12:45:06.478284 7f493b4a9780 10 client.4110 _getattr mask pAsLsXsFs issued=1
 -10-16 12:45:06.478316 7f493b4a9780 10 client.4110 fill_stat on 1 snap/devhead mode 040755 mtime 2012-10-16 12:44:21.542963 ctime 2012-10-16 12:44:21.542963
 -10-16 12:45:06.478404 7f493b4a9780  3 client.4110 ll_getattr 1.head = 0
 -10-16 12:45:06.478493 7f493b4a9780  3 client.4110 ll_getattr 1.head
 -10-16 12:45:06.478523 7f493b4a9780 10 client.4110 _getattr mask pAsLsXsFs issued=1
 -10-16 12:45:06.478544 7f493b4a9780 10 client.4110 fill_stat on 1 snap/devhead mode 040755 mtime 2012-10-16 12:44:21.542963 ctime 2012-10-16 12:44:21.542963
 -10-16 12:45:06.478589 7f493b4a9780  3 client.4110 ll_getattr 1.head = 0
 -10-16 12:45:06.478664 7f493b4a9780  3 client.4110 ll_lookup 1.head foo
 -10-16 12:45:06.478705 7f493b4a9780 20 client.4110 _lookup have dn foo mds.0 ttl 2012-10-16 12:44:51.525377 seq 2
 -10-16 12:45:06.478737 7f493b4a9780 10 client.4110 _lookup 1.head(ref=3 cap_refs={} open={} mode=40755 size=0 mtime=2012-10-16 12:44:21.542963 caps=pAsLsXsFs(0=pAsLsXsFs,1=pAsLsXs) 0x2257d80) foo = 10000000000.head(ref=2 cap_refs={1024=0,4096=0,8192=0} open={2=0} mode=100644 size=4 mtime=2012-10-16 12:44:21.566329 caps=pAsLsXsFsxcrwb(0=pAsLsXsFsxcrwb) objectset[10000000000 ts 0/0 objects 0 dirty_or_tx 0] parents=0x22be150 0x2258680)
 -10-16 12:45:06.478934 7f493b4a9780 10 client.4110 fill_stat on 10000000000 snap/devhead mode 0100644 mtime 2012-10-16 12:44:21.566329 ctime 2012-10-16 12:44:55.683293
 -10-16 12:45:06.478982 7f493b4a9780 20 client.4110 _ll_get 0x2258680 10000000000 -> 16
 -10-16 12:45:06.478995 7f493b4a9780  3 client.4110 ll_lookup 1.head foo -> 0 (10000000000)
 -10-16 12:45:06.479107 7f493b4a9780  3 client.4110 ll_getattr 10000000000.head
 -10-16 12:45:06.479138 7f493b4a9780 10 client.4110 _getattr mask pAsLsXsFs issued=1
 -10-16 12:45:06.479158 7f493b4a9780 10 client.4110 fill_stat on 10000000000 snap/devhead mode 0100644 mtime 2012-10-16 12:44:21.566329 ctime 2012-10-16 12:44:55.683293
 -10-16 12:45:06.479201 7f493b4a9780  3 client.4110 ll_getattr 10000000000.head = 0
 -10-16 12:45:06.479330 7f493b4a9780  3 client.4110 ll_open 10000000000.head 33793
 -10-16 12:45:06.479437 7f493b4a9780 20 client.4110 choose_target_mds starting with req->inode 10000000000.head(ref=2 cap_refs={1024=0,4096=0,8192=0} open={2=1} mode=100644 size=4 mtime=2012-10-16 12:44:21.566329 caps=pAsLsXsFsxcrwb(0=pAsLsXsFsxcrwb) objectset[10000000000 ts 0/0 objects 0 dirty_or_tx 0] parents=0x22be150 0x2258680)
 -10-16 12:45:06.479553 7f493b4a9780 20 client.4110 choose_target_mds 10000000000.head(ref=2 cap_refs={1024=0,4096=0,8192=0} open={2=1} mode=100644 size=4 mtime=2012-10-16 12:44:21.566329 caps=pAsLsXsFsxcrwb(0=pAsLsXsFsxcrwb) objectset[10000000000 ts 0/0 objects 0 dirty_or_tx 0] parents=0x22be150 0x2258680) is_hash=0 hash=0
 -10-16 12:45:06.479653 7f493b4a9780 10 client.4110 choose_target_mds from caps on inode 10000000000.head(ref=2 cap_refs={1024=0,4096=0,8192=0} open={2=1} mode=100644 size=4 mtime=2012-10-16 12:44:21.566329 caps=pAsLsXsFsxcrwb(0=pAsLsXsFsxcrwb) objectset[10000000000 ts 0/0 objects 0 dirty_or_tx 0] parents=0x22be150 0x2258680)
 -10-16 12:45:06.479762 7f493b4a9780 20 client.4110 mds is 0
 -10-16 12:45:06.479801 7f493b4a9780 10 client.4110 send_request rebuilding request 12 for mds.0
 -10-16 12:45:06.479847 7f493b4a9780 20 client.4110 encode_cap_releases enter (req: 0x2284080, mds: 0)
 -10-16 12:45:06.479865 7f493b4a9780 20 client.4110 send_request set sent_stamp to 2012-10-16 12:45:06.479861
 -10-16 12:45:06.479899 7f493b4a9780 10 client.4110 send_request client_request(unknown.0:12 open #10000000000) v1 to mds.0
 -10-16 12:45:06.480076 7f493b4a9780 20 client.4110 awaiting reply|forward|kick on 0x7fffa2bb95c0
 -10-16 12:45:06.483849 7f4936906700 10 client.4110  mds.0 seq now 5
 -10-16 12:45:06.483861 7f4936906700  5 client.4110 handle_cap_grant on in 10000000000 mds.0 seq 8 caps now pAsxLsXsxFsxcrwb was pAsLsXsFsxcrwb
 -10-16 12:45:06.483877 7f4936906700 10 client.4110 update_inode_file_bits 10000000000.head(ref=2 cap_refs={1024=0,4096=0,8192=0} open={2=1} mode=100644 size=4 mtime=2012-10-16 12:44:21.566329 caps=pAsLsXsFsxcrwb(0=pAsLsXsFsxcrwb) objectset[10000000000 ts 0/0 objects 0 dirty_or_tx 0] parents=0x22be150 0x2258680) pAsxLsXsxFsxcrwb mtime 2012-10-16 12:44:21.566329
 -10-16 12:45:06.483913 7f4936906700 10 client.4110   grant, new caps are AxXx
 -10-16 12:45:06.484853 7f4936906700 20 client.4110 handle_client_reply got a reply. Safe:1 tid 12
 -10-16 12:45:06.484859 7f4936906700 10 client.4110 insert_trace from 2012-10-16 12:45:06.479861 mds.0 is_target=1 is_dentry=0
 -10-16 12:45:06.484868 7f4936906700 10 client.4110  features 0x7fffff
 -10-16 12:45:06.484871 7f4936906700 10 client.4110 update_snap_trace len 48
 -10-16 12:45:06.484906 7f4936906700 10 client.4110 update_snap_trace snaprealm(1 nref=4 c=0 seq=1 parent=0 my_snaps=[] cached_snapc=1=[]) seq 1 <= 1 and same parent, SKIPPING
 -10-16 12:45:06.484922 7f4936906700 10 client.4110  hrm  is_target=1 is_dentry=0
 -10-16 12:45:06.484942 7f4936906700 12 client.4110 add_update_inode had 10000000000.head(ref=2 cap_refs={1024=0,4096=0,8192=0} open={2=1} mode=100644 size=4 mtime=2012-10-16 12:44:21.566329 caps=pAsxLsXsxFsxcrwb(0=pAsxLsXsxFsxcrwb) objectset[10000000000 ts 0/0 objects 0 dirty_or_tx 0] parents=0x22be150 0x2258680) caps pAsxLsXsxFsxcrwb
 -10-16 12:45:06.484983 7f4936906700 10 client.4110 update_inode_file_bits 10000000000.head(ref=2 cap_refs={1024=0,4096=0,8192=0} open={2=1} mode=100644 size=4 mtime=2012-10-16 12:44:21.566329 caps=pAsxLsXsxFsxcrwb(0=pAsxLsXsxFsxcrwb) objectset[10000000000 ts 0/0 objects 0 dirty_or_tx 0] parents=0x22be150 0x2258680) pAsxLsXsxFsxcrwb mtime 2012-10-16 12:44:21.566329
 -10-16 12:45:06.485021 7f4936906700 10 client.4110 add_update_cap issued pAsxLsXsxFsxcrwb -> pAsxLsXsxFsxcrwb from mds.0 on 10000000000.head(ref=2 cap_refs={1024=0,4096=0,8192=0} open={2=1} mode=100644 size=4 mtime=2012-10-16 12:44:21.566329 caps=pAsxLsXsxFsxcrwb(0=pAsxLsXsxFsxcrwb) objectset[10000000000 ts 0/0 objects 0 dirty_or_tx 0] parents=0x22be150 0x2258680)
 -10-16 12:45:06.485057 7f4936906700 20 client.4110 handle_client_reply signalling caller 0x7fffa2bb95c0
 -10-16 12:45:06.485062 7f4936906700 20 client.4110 handle_client_reply awaiting kickback on tid 12 0x7f49369056d0
 -10-16 12:45:06.485070 7f493b4a9780 20 client.4110 sendrecv kickback on tid 12 0x7f49369056d0
 -10-16 12:45:06.485077 7f493b4a9780 20 client.4110 lat 0.005215
 -10-16 12:45:06.485096 7f493b4a9780 10 client.4110 _create_fh 10000000000 mode 2
 -10-16 12:45:06.485100 7f493b4a9780 20 client.4110 trim_cache size 1 max 16384
 -10-16 12:45:06.485103 7f493b4a9780  3 client.4110 ll_open 10000000000.head 33793 = 0 (0x2253320)
 -10-16 12:45:06.485163 7f493b4a9780  3 client.4110 ll_getxattr 10000000000.head security.capability size 0
 -10-16 12:45:06.485175 7f493b4a9780 10 client.4110 _getattr mask Xs issued=1
 -10-16 12:45:06.485183 7f493b4a9780  3 client.4110 _getxattr(10000000000, "security.capability", 0) = -61
 -10-16 12:45:06.485222 7f493b4a9780  3 client.4110 ll_write 0x2253320 10000000000 4~4
 -10-16 12:45:06.485231 7f493b4a9780 10 client.4110 cur file size is 4
 -10-16 12:45:06.485240 7f493b4a9780 10 client.4110 wanted_max_size 4 -> 8
 -10-16 12:45:06.485247 7f493b4a9780 10 client.4110 check_caps on 10000000000.head(ref=3 cap_refs={1024=0,4096=0,8192=0} open={2=1} mode=100644 size=4 mtime=2012-10-16 12:44:21.566329 caps=pAsxLsXsxFsxcrwb(0=pAsxLsXsxFsxcrwb) objectset[10000000000 ts 0/0 objects 0 dirty_or_tx 0] parents=0x22be150 0x2258680) wanted pAsxXsxFxwb used - is_delayed=0
 -10-16 12:45:06.485280 7f493b4a9780 10 client.4110 cap_delay_requeue on 10000000000.head(ref=3 cap_refs={1024=0,4096=0,8192=0} open={2=1} mode=100644 size=4 mtime=2012-10-16 12:44:21.566329 caps=pAsxLsXsxFsxcrwb(0=pAsxLsXsxFsxcrwb) objectset[10000000000 ts 0/0 objects 0 dirty_or_tx 0] parents=0x22be150 0x2258680)
 -10-16 12:45:06.485305 7f493b4a9780 10 client.4110  cap mds.0 issued pAsxLsXsxFsxcrwb implemented pAsxLsXsxFsxcrwb revoking -
 -10-16 12:45:06.485315 7f493b4a9780 10 client.4110 send_cap 10000000000.head(ref=3 cap_refs={1024=0,4096=0,8192=0} open={2=1} mode=100644 size=4 mtime=2012-10-16 12:44:21.566329 caps=pAsxLsXsxFsxcrwb(0=pAsxLsXsxFsxcrwb) objectset[10000000000 ts 0/0 objects 0 dirty_or_tx 0] parents=0x22be150 0x2258680) mds.0 seq 9 used - want pAsxXsxFxwb flush - retain pAsxLsxXsxFsxcrwbl held pAsxLsXsxFsxcrwb revoking - dropping -
 -10-16 12:45:06.485355 7f493b4a9780 15 client.4110 auth cap, setting max_size = 8
 -10-16 12:45:06.485406 7f493b4a9780 10 client.4110 waiting on max_size, endoff 8 max_size 0
 -10-16 12:45:06.492460 7f4936906700 10 client.4110  mds.0 seq now 6
 -10-16 12:45:06.492476 7f4936906700  5 client.4110 handle_cap_grant on in 10000000000 mds.0 seq 9 caps now pAsxLsXsxFsxcrwb was pAsxLsXsxFsxcrwb
 -10-16 12:45:06.492494 7f4936906700 10 client.4110 update_inode_file_bits 10000000000.head(ref=3 cap_refs={1024=0,4096=0,8192=0} open={2=1} mode=100644 size=4 mtime=2012-10-16 12:44:21.566329 caps=pAsxLsXsxFsxcrwb(0=pAsxLsXsxFsxcrwb) objectset[10000000000 ts 0/0 objects 0 dirty_or_tx 0] parents=0x22be150 0x2258680) pAsxLsXsxFsxcrwb mtime 2012-10-16 12:44:21.566329
 -10-16 12:45:06.492530 7f4936906700 10 client.4110 max_size 0 -> 4194304
 -10-16 12:45:06.492535 7f4936906700 10 client.4110   caps unchanged at pAsxLsXsxFsxcrwb
 -10-16 12:45:06.492565 7f493b4a9780 10 client.4110 get_caps 10000000000.head(ref=3 cap_refs={1024=0,4096=0,8192=0} open={2=1} mode=100644 size=4 mtime=2012-10-16 12:44:21.566329 caps=pAsxLsXsxFsxcrwb(0=pAsxLsXsxFsxcrwb) objectset[10000000000 ts 0/0 objects 0 dirty_or_tx 0] parents=0x22be150 0x2258680) have pAsxLsXsxFsxcrwb need Fw want Fb but not Fb revoking -
 -10-16 12:45:06.492662 7f493b4a9780 10 client.4110  snaprealm snaprealm(1 nref=3 c=0 seq=1 parent=0 my_snaps=[] cached_snapc=1=[])
 -10-16 12:45:06.492698 7f493b4a9780  5 client.4110 get_cap_ref got first FILE_BUFFER ref on 10000000000.head(ref=3 cap_refs={1024=0,4096=1,8192=0} open={2=1} mode=100644 size=4 mtime=2012-10-16 12:44:21.566329 caps=pAsxLsXsxFsxcrwb(0=pAsxLsXsxFsxcrwb) objectset[10000000000 ts 0/0 objects 0 dirty_or_tx 0] parents=0x22be150 0x2258680)
 -10-16 12:45:06.492941 7f493b4a9780 10 client.4110 mark_caps_dirty 10000000000.head(ref=4 cap_refs={1024=0,4096=1,8192=1} open={2=1} mode=100644 size=8 mtime=2012-10-16 12:44:21.566329 caps=pAsxLsXsxFsxcrwb(0=pAsxLsXsxFsxcrwb) objectset[10000000000 ts 0/0 objects 1 dirty_or_tx 4] parents=0x22be150 0x2258680) - -> Fw
 -10-16 12:45:06.492972 7f493b4a9780  7 client.4110 wrote to 8, extending file size
 -10-16 12:45:06.492975 7f493b4a9780 10 client.4110 mark_caps_dirty 10000000000.head(ref=5 cap_refs={1024=0,4096=1,8192=1} open={2=1} mode=100644 size=8 mtime=2012-10-16 12:45:06.492975 caps=pAsxLsXsxFsxcrwb(0=pAsxLsXsxFsxcrwb) dirty_caps=Fw objectset[10000000000 ts 0/0 objects 1 dirty_or_tx 4] parents=0x22be150 0x2258680) Fw -> Fw
 -10-16 12:45:06.493009 7f493b4a9780  3 client.4110 ll_write 0x2253320 4~4 = 4
 -10-16 12:45:06.493219 7f493b4a9780  3 client.4110 ll_release 0x2253320 10000000000
 -10-16 12:45:06.493228 7f493b4a9780  5 client.4110 _release_fh 0x2253320 mode 2 on 10000000000.head(ref=5 cap_refs={1024=0,4096=0,8192=1} open={2=1} mode=100644 size=8 mtime=2012-10-16 12:45:06.492975 caps=pAsxLsXsxFsxcrwb(0=pAsxLsXsxFsxcrwb) dirty_caps=Fw objectset[10000000000 ts 0/0 objects 1 dirty_or_tx 4] parents=0x22be150 0x2258680)
 -10-16 12:45:06.493260 7f493b4a9780 10 client.4110 _flush 10000000000.head(ref=5 cap_refs={1024=0,4096=0,8192=1} open={2=0} mode=100644 size=8 mtime=2012-10-16 12:45:06.492975 caps=pAsxLsXsxFsxcrwb(0=pAsxLsXsxFsxcrwb) dirty_caps=Fw objectset[10000000000 ts 0/0 objects 1 dirty_or_tx 4] parents=0x22be150 0x2258680)
 -10-16 12:45:06.493626 7f493b4a9780 10 client.4110 check_caps on 10000000000.head(ref=6 cap_refs={1024=0,4096=0,8192=1} open={2=0} mode=100644 size=8 mtime=2012-10-16 12:45:06.492975 caps=pAsxLsXsxFsxcrwb(0=pAsxLsXsxFsxcrwb) dirty_caps=Fw objectset[10000000000 ts 0/0 objects 1 dirty_or_tx 4] parents=0x22be150 0x2258680) wanted Fxb used Fb is_delayed=0
 -10-16 12:45:06.493658 7f493b4a9780 10 client.4110 cap_delay_requeue on 10000000000.head(ref=6 cap_refs={1024=0,4096=0,8192=1} open={2=0} mode=100644 size=8 mtime=2012-10-16 12:45:06.492975 caps=pAsxLsXsxFsxcrwb(0=pAsxLsXsxFsxcrwb) dirty_caps=Fw objectset[10000000000 ts 0/0 objects 1 dirty_or_tx 4] parents=0x22be150 0x2258680)
 -10-16 12:45:06.493684 7f493b4a9780 10 client.4110  cap mds.0 issued pAsxLsXsxFsxcrwb implemented pAsxLsXsxFsxcrwb revoking -
 -10-16 12:45:06.493694 7f493b4a9780 10 client.4110 delaying cap release
 -10-16 12:45:06.493697 7f493b4a9780 10 client.4110 put_inode on 10000000000.head(ref=6 cap_refs={1024=0,4096=0,8192=1} open={2=0} mode=100644 size=8 mtime=2012-10-16 12:45:06.492975 caps=pAsxLsXsxFsxcrwb(0=pAsxLsXsxFsxcrwb) dirty_caps=Fw objectset[10000000000 ts 0/0 objects 1 dirty_or_tx 4] parents=0x22be150 0x2258680)
 -10-16 12:45:06.498281 7f4936906700 10 client.4110 put_inode on 10000000000.head(ref=5 cap_refs={1024=0,4096=0,8192=1} open={2=0} mode=100644 size=8 mtime=2012-10-16 12:45:06.492975 caps=pAsxLsXsxFsxcrwb(0=pAsxLsXsxFsxcrwb) dirty_caps=Fw objectset[10000000000 ts 0/0 objects 1 dirty_or_tx 0] parents=0x22be150 0x2258680)
 -10-16 12:45:06.498316 7f4936906700 10 client.4110 _flushed 10000000000.head(ref=4 cap_refs={1024=0,4096=0,8192=1} open={2=0} mode=100644 size=8 mtime=2012-10-16 12:45:06.492975 caps=pAsxLsXsxFsxcrwb(0=pAsxLsXsxFsxcrwb) dirty_caps=Fw objectset[10000000000 ts 0/0 objects 1 dirty_or_tx 0] parents=0x22be150 0x2258680)
 -10-16 12:45:06.498345 7f4936906700 10 client.4110 _invalidate_inode_cache 10000000000.head(ref=4 cap_refs={1024=0,4096=0,8192=1} open={2=0} mode=100644 size=8 mtime=2012-10-16 12:45:06.492975 caps=pAsxLsXsxFsxcrwb(0=pAsxLsXsxFsxcrwb) dirty_caps=Fw objectset[10000000000 ts 0/0 objects 1 dirty_or_tx 0] parents=0x22be150 0x2258680)
 -10-16 12:45:06.498404 7f4936906700 10 client.4110 check_caps on 10000000000.head(ref=4 cap_refs={1024=0,4096=0,8192=0} open={2=0} mode=100644 size=8 mtime=2012-10-16 12:45:06.492975 caps=pAsxLsXsxFsxcrwb(0=pAsxLsXsxFsxcrwb) dirty_caps=Fw objectset[10000000000 ts 0/0 objects 0 dirty_or_tx 0] parents=0x22be150 0x2258680) wanted - used - is_delayed=0
 -10-16 12:45:06.498425 7f4936906700 10 client.4110 cap_delay_requeue on 10000000000.head(ref=4 cap_refs={1024=0,4096=0,8192=0} open={2=0} mode=100644 size=8 mtime=2012-10-16 12:45:06.492975 caps=pAsxLsXsxFsxcrwb(0=pAsxLsXsxFsxcrwb) dirty_caps=Fw objectset[10000000000 ts 0/0 objects 0 dirty_or_tx 0] parents=0x22be150 0x2258680)
 -10-16 12:45:06.498451 7f4936906700 10 client.4110  cap mds.0 issued pAsxLsXsxFsxcrwb implemented pAsxLsXsxFsxcrwb revoking -
 -10-16 12:45:06.498461 7f4936906700 10 client.4110 delaying cap release
 -10-16 12:45:06.498465 7f4936906700  5 client.4110 put_cap_ref dropped last FILE_BUFFER ref on 10000000000.head(ref=4 cap_refs={1024=0,4096=0,8192=0} open={2=0} mode=100644 size=8 mtime=2012-10-16 12:45:06.492975 caps=pAsxLsXsxFsxcrwb(0=pAsxLsXsxFsxcrwb) dirty_caps=Fw objectset[10000000000 ts 0/0 objects 0 dirty_or_tx 0] parents=0x22be150 0x2258680)
 -10-16 12:45:06.498489 7f4936906700 10 client.4110 put_inode on 10000000000.head(ref=4 cap_refs={1024=0,4096=0,8192=0} open={2=0} mode=100644 size=8 mtime=2012-10-16 12:45:06.492975 caps=pAsxLsXsxFsxcrwb(0=pAsxLsXsxFsxcrwb) dirty_caps=Fw objectset[10000000000 ts 0/0 objects 0 dirty_or_tx 0] parents=0x22be150 0x2258680)
 -10-16 12:45:08.397416 7f4937908700 10 client.4110 renew_caps()
 -10-16 12:45:08.397464 7f4937908700 15 client.4110 renew_caps requesting from mds.0
 -10-16 12:45:08.397491 7f4937908700 10 client.4110 renew_caps mds.0
 -10-16 12:45:08.397641 7f4937908700 15 client.4110 renew_caps requesting from mds.1
 -10-16 12:45:08.397680 7f4937908700 10 client.4110 renew_caps mds.1
 -10-16 12:45:08.399918 7f4936906700 10 client.4110 handle_client_session client_session(renewcaps seq 7) v1 from mds.0
 -10-16 12:45:08.400076 7f4936906700 10 client.4110 handle_client_session client_session(renewcaps seq 7) v1 from mds.1
 -10-16 12:45:09.065781 7f493b4a9780  3 client.4110 ll_getattr 1.head
 -10-16 12:45:09.065841 7f493b4a9780 10 client.4110 _getattr mask pAsLsXsFs issued=1
 -10-16 12:45:09.065862 7f493b4a9780 10 client.4110 fill_stat on 1 snap/devhead mode 040755 mtime 2012-10-16 12:44:21.542963 ctime 2012-10-16 12:44:21.542963
 -10-16 12:45:09.065930 7f493b4a9780  3 client.4110 ll_getattr 1.head = 0
 -10-16 12:45:09.066160 7f493b4a9780  3 client.4110 ll_lookup 1.head foo
 -10-16 12:45:09.066222 7f493b4a9780 20 client.4110 _lookup have dn foo mds.0 ttl 2012-10-16 12:44:51.525377 seq 2
 -10-16 12:45:09.066260 7f493b4a9780 10 client.4110 _lookup 1.head(ref=3 cap_refs={} open={} mode=40755 size=0 mtime=2012-10-16 12:44:21.542963 caps=pAsLsXsFs(0=pAsLsXsFs,1=pAsLsXs) 0x2257d80) foo = 10000000000.head(ref=3 cap_refs={1024=0,4096=0,8192=0} open={2=0} mode=100644 size=8 mtime=2012-10-16 12:45:06.492975 caps=pAsxLsXsxFsxcrwb(0=pAsxLsXsxFsxcrwb) dirty_caps=Fw objectset[10000000000 ts 0/0 objects 0 dirty_or_tx 0] parents=0x22be150 0x2258680)
 -10-16 12:45:09.066412 7f493b4a9780 10 client.4110 fill_stat on 10000000000 snap/devhead mode 0100644 mtime 2012-10-16 12:45:06.492975 ctime 2012-10-16 12:44:55.683293
 -10-16 12:45:09.066455 7f493b4a9780 20 client.4110 _ll_get 0x2258680 10000000000 -> 17
 -10-16 12:45:09.066469 7f493b4a9780  3 client.4110 ll_lookup 1.head foo -> 0 (10000000000)
 -10-16 12:45:09.066559 7f493b4a9780  3 client.4110 ll_getattr 10000000000.head
 -10-16 12:45:09.066596 7f493b4a9780 10 client.4110 _getattr mask pAsLsXsFs issued=1
 -10-16 12:45:09.066617 7f493b4a9780 10 client.4110 fill_stat on 10000000000 snap/devhead mode 0100644 mtime 2012-10-16 12:45:06.492975 ctime 2012-10-16 12:44:55.683293
 -10-16 12:45:09.066662 7f493b4a9780  3 client.4110 ll_getattr 10000000000.head = 0
 -10-16 12:45:09.066755 7f493b4a9780  3 client.4110 ll_getattr 1.head
 -10-16 12:45:09.066785 7f493b4a9780 10 client.4110 _getattr mask pAsLsXsFs issued=1
 -10-16 12:45:09.066805 7f493b4a9780 10 client.4110 fill_stat on 1 snap/devhead mode 040755 mtime 2012-10-16 12:44:21.542963 ctime 2012-10-16 12:44:21.542963
 -10-16 12:45:09.066847 7f493b4a9780  3 client.4110 ll_getattr 1.head = 0
 -10-16 12:45:09.066916 7f493b4a9780  3 client.4110 ll_lookup 1.head foo
 -10-16 12:45:09.066961 7f493b4a9780 20 client.4110 _lookup have dn foo mds.0 ttl 2012-10-16 12:44:51.525377 seq 2
 -10-16 12:45:09.066988 7f493b4a9780 10 client.4110 _lookup 1.head(ref=3 cap_refs={} open={} mode=40755 size=0 mtime=2012-10-16 12:44:21.542963 caps=pAsLsXsFs(0=pAsLsXsFs,1=pAsLsXs) 0x2257d80) foo = 10000000000.head(ref=3 cap_refs={1024=0,4096=0,8192=0} open={2=0} mode=100644 size=8 mtime=2012-10-16 12:45:06.492975 caps=pAsxLsXsxFsxcrwb(0=pAsxLsXsxFsxcrwb) dirty_caps=Fw objectset[10000000000 ts 0/0 objects 0 dirty_or_tx 0] parents=0x22be150 0x2258680)
 -10-16 12:45:09.067172 7f493b4a9780 10 client.4110 fill_stat on 10000000000 snap/devhead mode 0100644 mtime 2012-10-16 12:45:06.492975 ctime 2012-10-16 12:44:55.683293
 -10-16 12:45:09.067214 7f493b4a9780 20 client.4110 _ll_get 0x2258680 10000000000 -> 18
 -10-16 12:45:09.067227 7f493b4a9780  3 client.4110 ll_lookup 1.head foo -> 0 (10000000000)
 -10-16 12:45:09.067348 7f493b4a9780  3 client.4110 ll_getxattr 10000000000.head security.selinux size 255
 -10-16 12:45:09.067379 7f493b4a9780 10 client.4110 _getattr mask Xs issued=1
 -10-16 12:45:09.067404 7f493b4a9780  3 client.4110 _getxattr(10000000000, "security.selinux", 255) = -61
 -10-16 12:45:09.067582 7f493b4a9780  3 client.4110 ll_getattr 1.head
 -10-16 12:45:09.067624 7f493b4a9780 10 client.4110 _getattr mask pAsLsXsFs issued=1
 -10-16 12:45:09.067649 7f493b4a9780 10 client.4110 fill_stat on 1 snap/devhead mode 040755 mtime 2012-10-16 12:44:21.542963 ctime 2012-10-16 12:44:21.542963
 -10-16 12:45:09.067693 7f493b4a9780  3 client.4110 ll_getattr 1.head = 0
 -10-16 12:45:09.067816 7f493b4a9780  3 client.4110 ll_lookup 1.head foo
 -10-16 12:45:09.067853 7f493b4a9780 20 client.4110 _lookup have dn foo mds.0 ttl 2012-10-16 12:44:51.525377 seq 2
 -10-16 12:45:09.067882 7f493b4a9780 10 client.4110 _lookup 1.head(ref=3 cap_refs={} open={} mode=40755 size=0 mtime=2012-10-16 12:44:21.542963 caps=pAsLsXsFs(0=pAsLsXsFs,1=pAsLsXs) 0x2257d80) foo = 10000000000.head(ref=3 cap_refs={1024=0,4096=0,8192=0} open={2=0} mode=100644 size=8 mtime=2012-10-16 12:45:06.492975 caps=pAsxLsXsxFsxcrwb(0=pAsxLsXsxFsxcrwb) dirty_caps=Fw objectset[10000000000 ts 0/0 objects 0 dirty_or_tx 0] parents=0x22be150 0x2258680)
 -10-16 12:45:09.068014 7f493b4a9780 10 client.4110 fill_stat on 10000000000 snap/devhead mode 0100644 mtime 2012-10-16 12:45:06.492975 ctime 2012-10-16 12:44:55.683293
 -10-16 12:45:09.068058 7f493b4a9780 20 client.4110 _ll_get 0x2258680 10000000000 -> 19
 -10-16 12:45:09.068072 7f493b4a9780  3 client.4110 ll_lookup 1.head foo -> 0 (10000000000)
 -10-16 12:45:09.068164 7f493b4a9780  3 client.4110 ll_getxattr 10000000000.head system.posix_acl_access size 0
 -10-16 12:45:09.068197 7f493b4a9780 10 client.4110 _getattr mask Xs issued=1
 -10-16 12:45:09.068216 7f493b4a9780  3 client.4110 _getxattr(10000000000, "system.posix_acl_access", 0) = -61
 -10-16 12:45:09.068284 7f493b4a9780  3 client.4110 ll_getattr 1.head
 -10-16 12:45:09.068310 7f493b4a9780 10 client.4110 _getattr mask pAsLsXsFs issued=1
 -10-16 12:45:09.068330 7f493b4a9780 10 client.4110 fill_stat on 1 snap/devhead mode 040755 mtime 2012-10-16 12:44:21.542963 ctime 2012-10-16 12:44:21.542963
 -10-16 12:45:09.068376 7f493b4a9780  3 client.4110 ll_getattr 1.head = 0
 -10-16 12:45:09.068434 7f493b4a9780  3 client.4110 ll_lookup 1.head foo
 -10-16 12:45:09.068490 7f493b4a9780 20 client.4110 _lookup have dn foo mds.0 ttl 2012-10-16 12:44:51.525377 seq 2
 -10-16 12:45:09.068518 7f493b4a9780 10 client.4110 _lookup 1.head(ref=3 cap_refs={} open={} mode=40755 size=0 mtime=2012-10-16 12:44:21.542963 caps=pAsLsXsFs(0=pAsLsXsFs,1=pAsLsXs) 0x2257d80) foo = 10000000000.head(ref=3 cap_refs={1024=0,4096=0,8192=0} open={2=0} mode=100644 size=8 mtime=2012-10-16 12:45:06.492975 caps=pAsxLsXsxFsxcrwb(0=pAsxLsXsxFsxcrwb) dirty_caps=Fw objectset[10000000000 ts 0/0 objects 0 dirty_or_tx 0] parents=0x22be150 0x2258680)
 -10-16 12:45:09.068666 7f493b4a9780 10 client.4110 fill_stat on 10000000000 snap/devhead mode 0100644 mtime 2012-10-16 12:45:06.492975 ctime 2012-10-16 12:44:55.683293
 -10-16 12:45:09.068707 7f493b4a9780 20 client.4110 _ll_get 0x2258680 10000000000 -> 20
 -10-16 12:45:09.068720 7f493b4a9780  3 client.4110 ll_lookup 1.head foo -> 0 (10000000000)
 -10-16 12:45:09.068799 7f493b4a9780  3 client.4110 ll_getxattr 10000000000.head system.posix_acl_default size 0
 -10-16 12:45:09.068831 7f493b4a9780 10 client.4110 _getattr mask Xs issued=1
 -10-16 12:45:09.068849 7f493b4a9780  3 client.4110 _getxattr(10000000000, "system.posix_acl_default", 0) = -61
 -10-16 12:45:12.398043 7f4937908700 10 client.4110 check_caps on 10000000000.head(ref=3 cap_refs={1024=0,4096=0,8192=0} open={2=0} mode=100644 size=8 mtime=2012-10-16 12:45:06.492975 caps=pAsxLsXsxFsxcrwb(0=pAsxLsXsxFsxcrwb) dirty_caps=Fw objectset[10000000000 ts 0/0 objects 0 dirty_or_tx 0] parents=0x22be150 0x2258680) wanted - used - is_delayed=1
 -10-16 12:45:12.398255 7f4937908700 10 client.4110  cap mds.0 issued pAsxLsXsxFsxcrwb implemented pAsxLsXsxFsxcrwb revoking -
 -10-16 12:45:12.398312 7f4937908700 10 client.4110 mark_caps_flushing Fw 10000000000.head(ref=3 cap_refs={1024=0,4096=0,8192=0} open={2=0} mode=100644 size=8 mtime=2012-10-16 12:45:06.492975 caps=pAsxLsXsxFsxcrwb(0=pAsxLsXsxFsxcrwb) dirty_caps=Fw objectset[10000000000 ts 0/0 objects 0 dirty_or_tx 0] parents=0x22be150 0x2258680)
 -10-16 12:45:12.398441 7f4937908700 10 client.4110 send_cap 10000000000.head(ref=3 cap_refs={1024=0,4096=0,8192=0} open={2=0} mode=100644 size=8 mtime=2012-10-16 12:45:06.492975 caps=pAsxLsXsxFsxcrwb(0=pAsxLsXsxFsxcrwb) flushing_caps=Fw objectset[10000000000 ts 0/0 objects 0 dirty_or_tx 0] parents=0x22be150 0x2258680) mds.0 seq 9 used - want - flush Fw retain pAsLsXsFs held pAsxLsXsxFsxcrwb revoking - dropping AxXxFxcrwb
 -10-16 12:45:12.398636 7f4937908700 15 client.4110 auth cap, setting max_size = 0
 -10-16 12:45:14.429506 7f4936906700 10 client.4110  mds.0 seq now 7
 -10-16 12:45:14.429544 7f4936906700  5 client.4110 handle_cap_flush_ack mds.0 cleaned Fw on 10000000000.head(ref=3 cap_refs={1024=0,4096=0,8192=0} open={2=0} mode=100644 size=8 mtime=2012-10-16 12:45:06.492975 caps=pAsLsXsFs(0=pAsLsXsFs) flushing_caps=Fw objectset[10000000000 ts 0/0 objects 0 dirty_or_tx 0] parents=0x22be150 0x2258680) with Fw
 -10-16 12:45:14.429655 7f4936906700  5 client.4110   flushing_caps Fw -> -
 -10-16 12:45:14.429673 7f4936906700 10 client.4110  10000000000.head(ref=3 cap_refs={1024=0,4096=0,8192=0} open={2=0} mode=100644 size=8 mtime=2012-10-16 12:45:06.492975 caps=pAsLsXsFs(0=pAsLsXsFs) objectset[10000000000 ts 0/0 objects 0 dirty_or_tx 0] parents=0x22be150 0x2258680) !flushing
 -10-16 12:45:14.429755 7f4936906700 10 client.4110 put_inode on 10000000000.head(ref=3 cap_refs={1024=0,4096=0,8192=0} open={2=0} mode=100644 size=8 mtime=2012-10-16 12:45:06.492975 caps=pAsLsXsFs(0=pAsLsXsFs) objectset[10000000000 ts 0/0 objects 0 dirty_or_tx 0] parents=0x22be150 0x2258680)
 -10-16 12:45:28.400444 7f4937908700 10 client.4110 renew_caps()
 -10-16 12:45:28.400495 7f4937908700 15 client.4110 renew_caps requesting from mds.0
 -10-16 12:45:28.400529 7f4937908700 10 client.4110 renew_caps mds.0
 -10-16 12:45:28.400722 7f4937908700 15 client.4110 renew_caps requesting from mds.1
 -10-16 12:45:28.400762 7f4937908700 10 client.4110 renew_caps mds.1
 -10-16 12:45:28.403013 7f4936906700 10 client.4110 handle_client_session client_session(renewcaps seq 8) v1 from mds.0
 -10-16 12:45:28.403285 7f4936906700 10 client.4110 handle_client_session client_session(renewcaps seq 8) v1 from mds.1
 -10-16 12:45:48.403450 7f4937908700 10 client.4110 renew_caps()
 -10-16 12:45:48.403502 7f4937908700 15 client.4110 renew_caps requesting from mds.0
 -10-16 12:45:48.403537 7f4937908700 10 client.4110 renew_caps mds.0
 -10-16 12:45:48.403752 7f4937908700 15 client.4110 renew_caps requesting from mds.1
 -10-16 12:45:48.403803 7f4937908700 10 client.4110 renew_caps mds.1
 -10-16 12:45:48.405664 7f4936906700 10 client.4110 handle_client_session client_session(renewcaps seq 9) v1 from mds.1
 -10-16 12:45:48.405835 7f4936906700 10 client.4110 handle_client_session client_session(renewcaps seq 9) v1 from mds.0
 -10-16 12:46:08.406184 7f4937908700 10 client.4110 renew_caps()
 -10-16 12:46:08.406232 7f4937908700 15 client.4110 renew_caps requesting from mds.0
 -10-16 12:46:08.406255 7f4937908700 10 client.4110 renew_caps mds.0
 -10-16 12:46:08.406402 7f4937908700 15 client.4110 renew_caps requesting from mds.1
 -10-16 12:46:08.406426 7f4937908700 10 client.4110 renew_caps mds.1
 -10-16 12:46:08.408717 7f4936906700 10 client.4110 handle_client_session client_session(renewcaps seq 10) v1 from mds.1
 -10-16 12:46:08.408915 7f4936906700 10 client.4110 handle_client_session client_session(renewcaps seq 10) v1 from mds.0
 -10-16 12:46:11.517104 7f493b4a9780  3 client.4110 ll_getattr 1.head
 -10-16 12:46:11.517164 7f493b4a9780 10 client.4110 _getattr mask pAsLsXsFs issued=1
 -10-16 12:46:11.517196 7f493b4a9780 10 client.4110 fill_stat on 1 snap/devhead mode 040755 mtime 2012-10-16 12:44:21.542963 ctime 2012-10-16 12:44:21.542963
 -10-16 12:46:11.517253 7f493b4a9780  3 client.4110 ll_getattr 1.head = 0
 -10-16 12:46:11.517347 7f493b4a9780  3 client.4110 ll_getattr 1.head
 -10-16 12:46:11.517389 7f493b4a9780 10 client.4110 _getattr mask pAsLsXsFs issued=1
 -10-16 12:46:11.517408 7f493b4a9780 10 client.4110 fill_stat on 1 snap/devhead mode 040755 mtime 2012-10-16 12:44:21.542963 ctime 2012-10-16 12:44:21.542963
 -10-16 12:46:11.517451 7f493b4a9780  3 client.4110 ll_getattr 1.head = 0
 -10-16 12:46:13.089217 7f493b4a9780  3 client.4110 ll_forget 10000000000.head 20
 -10-16 12:46:13.089288 7f493b4a9780 20 client.4110 _ll_put 0x2258680 10000000000 20 -> 0
 -10-16 12:46:13.089304 7f493b4a9780 10 client.4110 put_inode on 10000000000.head(ref=2 cap_refs={1024=0,4096=0,8192=0} open={2=0} mode=100644 size=8 mtime=2012-10-16 12:45:06.492975 caps=pAsLsXsFs(0=pAsLsXsFs) objectset[10000000000 ts 0/0 objects 0 dirty_or_tx 0] parents=0x22be150 0x2258680)
 -10-16 12:46:13.089669 7f493b4a9780  3 client.4110 ll_forget 1.head 1
 -10-16 12:46:13.090877 7f493b4a9780  2 client.4110 unmounting
 -10-16 12:46:13.090931 7f493b4a9780 10 client.4110 put_inode on 1.head(ref=3 cap_refs={} open={} mode=40755 size=0 mtime=2012-10-16 12:44:21.542963 caps=pAsLsXsFs(0=pAsLsXsFs,1=pAsLsXs) 0x2257d80)
 -10-16 12:46:13.091024 7f493b4a9780 10 client.4110 _ll_drop_pins
 -10-16 12:46:13.091114 7f493b4a9780 20 client.4110 _ll_put 0x2257d80 1 1 -> 0
 -10-16 12:46:13.091129 7f493b4a9780 10 client.4110 put_inode on 1.head(ref=2 cap_refs={} open={} mode=40755 size=0 mtime=2012-10-16 12:44:21.542963 caps=pAsLsXsFs(0=pAsLsXsFs,1=pAsLsXs) 0x2257d80)
 -10-16 12:46:13.091193 7f493b4a9780 10 client.4110 _flush 10000000000.head(ref=2 cap_refs={1024=0,4096=0,8192=0} open={2=0} mode=100644 size=8 mtime=2012-10-16 12:45:06.492975 caps=pAsLsXsFs(0=pAsLsXsFs) objectset[10000000000 ts 0/0 objects 0 dirty_or_tx 0] parents=0x22be150 0x2258680)
 -10-16 12:46:13.091245 7f493b4a9780 10 client.4110  nothing to flush
 -10-16 12:46:13.091250 7f493b4a9780 10 client.4110 put_inode on 10000000000.head(ref=2 cap_refs={1024=0,4096=0,8192=0} open={2=0} mode=100644 size=8 mtime=2012-10-16 12:45:06.492975 caps=pAsLsXsFs(0=pAsLsXsFs) objectset[10000000000 ts 0/0 objects 0 dirty_or_tx 0] parents=0x22be150 0x2258680)
 -10-16 12:46:13.091359 7f493b4a9780 10 client.4110 _flush 1.head(ref=2 cap_refs={1024=0} open={} mode=40755 size=0 mtime=2012-10-16 12:44:21.542963 caps=pAsLsXsFs(0=pAsLsXsFs,1=pAsLsXs) 0x2257d80)
 -10-16 12:46:13.091432 7f493b4a9780 10 client.4110  nothing to flush
 -10-16 12:46:13.091440 7f493b4a9780 10 client.4110 put_inode on 1.head(ref=2 cap_refs={1024=0} open={} mode=40755 size=0 mtime=2012-10-16 12:44:21.542963 caps=pAsLsXsFs(0=pAsLsXsFs,1=pAsLsXs) 0x2257d80)
 -10-16 12:46:13.091514 7f493b4a9780 10 client.4110 flush_caps
 -10-16 12:46:13.091532 7f493b4a9780 10 client.4110 check_caps on 1.head(ref=1 cap_refs={1024=0} open={} mode=40755 size=0 mtime=2012-10-16 12:44:21.542963 caps=pAsLsXsFs(0=pAsLsXsFs,1=pAsLsXs) 0x2257d80) wanted - used - is_delayed=1
 -10-16 12:46:13.091646 7f493b4a9780 10 client.4110  cap mds.0 issued pAsLsXsFs implemented pAsLsXsFs revoking -
 -10-16 12:46:13.091674 7f493b4a9780 10 client.4110 send_cap 1.head(ref=1 cap_refs={1024=0} open={} mode=40755 size=0 mtime=2012-10-16 12:44:21.542963 caps=pAsLsXsFs(0=pAsLsXsFs,1=pAsLsXs) 0x2257d80) mds.0 seq 4 used - want - flush - retain p held pAsLsXsFs revoking - dropping AsLsXsFs
 -10-16 12:46:13.091796 7f493b4a9780 15 client.4110 auth cap, setting max_size = 0
 -10-16 12:46:13.091972 7f493b4a9780 10 client.4110  cap mds.1 issued pAsLsXs implemented pAsLsXs revoking -
 -10-16 12:46:13.092009 7f493b4a9780 10 client.4110 send_cap 1.head(ref=1 cap_refs={1024=0} open={} mode=40755 size=0 mtime=2012-10-16 12:44:21.542963 caps=pAsLsXs(0=p,1=pAsLsXs) 0x2257d80) mds.1 seq 2 used - want - flush - retain p held pAsLsXs revoking - dropping AsLsXs
 -10-16 12:46:13.092259 7f493b4a9780 10 client.4110 check_caps on 10000000000.head(ref=1 cap_refs={1024=0,4096=0,8192=0} open={2=0} mode=100644 size=8 mtime=2012-10-16 12:45:06.492975 caps=pAsLsXsFs(0=pAsLsXsFs) objectset[10000000000 ts 0/0 objects 0 dirty_or_tx 0] parents=0x22be150 0x2258680) wanted - used - is_delayed=1
 -10-16 12:46:13.092388 7f493b4a9780 10 client.4110  cap mds.0 issued pAsLsXsFs implemented pAsxLsXsxFsxcrwb revoking AxXxFxcrwb
 -10-16 12:46:13.092426 7f493b4a9780 10 client.4110 completed revocation of AxXxFxcrwb
 -10-16 12:46:13.092441 7f493b4a9780 10 client.4110 send_cap 10000000000.head(ref=1 cap_refs={1024=0,4096=0,8192=0} open={2=0} mode=100644 size=8 mtime=2012-10-16 12:45:06.492975 caps=pAsLsXsFs(0=pAsLsXsFs) objectset[10000000000 ts 0/0 objects 0 dirty_or_tx 0] parents=0x22be150 0x2258680) mds.0 seq 9 used - want - flush - retain p held pAsxLsXsxFsxcrwb revoking AxXxFxcrwb dropping AsLsXsFs
 -10-16 12:46:13.092563 7f493b4a9780 15 client.4110 auth cap, setting max_size = 0
 -10-16 12:46:13.092700 7f493b4a9780 10 client.4110 wait_sync_caps want 2 (last is 2, 0 total flushing)
 -10-16 12:46:13.092723 7f493b4a9780 20 client.4110 trim_cache size 1 max 0
 -10-16 12:46:13.092736 7f493b4a9780 15 client.4110 trim_dentry unlinking dn foo in dir 1
 -10-16 12:46:13.092747 7f493b4a9780 15 client.4110 unlink dir 0x2257d80 'foo' dn 0x22be150 inode 0x2258680
 -10-16 12:46:13.092776 7f493b4a9780 20 client.4110 unlink  inode 0x2258680 parents now
 -10-16 12:46:13.092786 7f493b4a9780 10 client.4110 put_inode on 10000000000.head(ref=1 cap_refs={1024=0,4096=0,8192=0} open={2=0} mode=100644 size=8 mtime=2012-10-16 12:45:06.492975 caps=p(0=p) objectset[10000000000 ts 0/0 objects 0 dirty_or_tx 0] 0x2258680)
 -10-16 12:46:13.092854 7f493b4a9780 10 client.4110 remove_cap mds.0 on 10000000000.head(ref=0 cap_refs={1024=0,4096=0,8192=0} open={2=0} mode=100644 size=8 mtime=2012-10-16 12:45:06.492975 caps=p(0=p) objectset[10000000000 ts 0/0 objects 0 dirty_or_tx 0] 0x2258680)
 -10-16 12:46:13.092967 7f493b4a9780 15 client.4110 remove_cap last one, closing snaprealm 0x2289c30
 -10-16 12:46:13.092982 7f493b4a9780 10 client.4110 put_inode deleting 10000000000.head(ref=0 cap_refs={1024=0,4096=0,8192=0} open={2=0} mode=100644 size=8 mtime=2012-10-16 12:45:06.492975 caps=- objectset[10000000000 ts 0/0 objects 0 dirty_or_tx 0] 0x2258680)
 -10-16 12:46:13.093105 7f493b4a9780 15 client.4110 close_dir dir 0x22be1c0 on 0x2257d80
 -10-16 12:46:13.093125 7f493b4a9780 10 client.4110 put_inode on 1.head(ref=1 cap_refs={1024=0} open={} mode=40755 size=0 mtime=2012-10-16 12:44:21.542963 caps=p(0=p,1=p) 0x2257d80)
 -10-16 12:46:13.093196 7f493b4a9780 10 client.4110 remove_cap mds.0 on 1.head(ref=0 cap_refs={1024=0} open={} mode=40755 size=0 mtime=2012-10-16 12:44:21.542963 caps=p(0=p,1=p) 0x2257d80)
 -10-16 12:46:13.093276 7f493b4a9780 10 client.4110 remove_cap mds.1 on 1.head(ref=0 cap_refs={1024=0} open={} mode=40755 size=0 mtime=2012-10-16 12:44:21.542963 caps=p(1=p) 0x2257d80)
 -10-16 12:46:13.093356 7f493b4a9780 15 client.4110 remove_cap last one, closing snaprealm 0x2289c30
 -10-16 12:46:13.093368 7f493b4a9780 10 client.4110 put_inode deleting 1.head(ref=0 cap_refs={1024=0} open={} mode=40755 size=0 mtime=2012-10-16 12:44:21.542963 caps=- 0x2257d80)
 -10-16 12:46:13.093441 7f493b4a9780  2 client.4110 sending client_session close to mds.0 seq 7
 -10-16 12:46:13.093541 7f493b4a9780  2 client.4110 sending client_session close to mds.1 seq 1
 -10-16 12:46:13.093649 7f493b4a9780  2 client.4110 waiting for 2 mds sessions to close
 -10-16 12:46:13.113118 7f4936906700 10 client.4110 handle_client_session client_session(close) v1 from mds.1
 -10-16 12:46:13.113132 7f4936906700 10 client.4110 kick_requests for mds.1
 -10-16 12:46:13.113166 7f4936906700 10 client.4110 unmounting: trim pass, size was 0+0
 -10-16 12:46:13.113172 7f4936906700 20 client.4110 trim_cache size 0 max 0
 -10-16 12:46:13.113176 7f4936906700 10 client.4110 unmounting: trim pass, cache now empty, waking unmount()
 -10-16 12:46:13.113186 7f493b4a9780  2 client.4110 waiting for 1 mds sessions to close
 -10-16 12:46:13.113631 7f4936906700 10 client.4110 handle_client_session client_session(close) v1 from mds.0
 -10-16 12:46:13.113640 7f4936906700 10 client.4110 kick_requests for mds.0
 -10-16 12:46:13.113659 7f4936906700 10 client.4110 unmounting: trim pass, size was 0+0
 -10-16 12:46:13.113663 7f4936906700 20 client.4110 trim_cache size 0 max 0
 -10-16 12:46:13.113666 7f4936906700 10 client.4110 unmounting: trim pass, cache now empty, waking unmount()
 -10-16 12:46:13.113702 7f493b4a9780  2 client.4110 unmounted.
 -10-16 12:46:13.113709 7f493b4a9780  1 client.4110 shutdown
 -10-16 12:46:13.114426 7f493b4a9780 20 client.4110 trim_cache size 0 max 0

« Previous
1
…
3
4
5
Next »

(5-5/5)

Project

General

Profile

Ceph » CephFS

Bug #3301 » client.admin.log