Ceph » CephFS

I chased this down a bit of a ways but there's a lot to look through.
This log is output from testceph with client debug 20.
In particular, the program has already created and opened the directory 'readdir_r_test' and then opens the file 'opened_file' (search for 'ceph_open').
Then it calls 'readdir_r'
Either there's a bug or I'm not calling the API correctly.
My patch to testceph.cc shows how I'm calling it in the samba vfs module.

2011-05-13 06:13:57.067364 7f04341ec720 client7107 open enter(readdir_r_test/opened_file, 64,438) =
2011-05-13 06:13:57.067371 7f04341ec720 client7107 path_walk readdir_r_test/opened_file
2011-05-13 06:13:57.067385 7f04341ec720 client7107 0 1.head( cap_refs={} open={} ref=3 caps=pAsLsXs mode=40755 mtime=2011-05-13 06:13:56.968093) readdir_r_test
2011-05-13 06:13:57.067393 7f04341ec720 client7107 _lookup have dn readdir_r_test mds-1 ttl 0.000000 seq 0
2011-05-13 06:13:57.067402 7f04341ec720 client7107 _lookup on #1/readdir_r_test
2011-05-13 06:13:57.067410 7f04341ec720 client7107 dir hash is 2 on readdir_r_test => 2444911409
2011-05-13 06:13:57.067417 7f04341ec720 client7107 choose_target_mds 0x7f0420001f40 is_hash=1 hash=2444911409
2011-05-13 06:13:57.067422 7f04341ec720 client7107 choose_target_mds from caps
2011-05-13 06:13:57.067427 7f04341ec720 client7107 mds is 0
2011-05-13 06:13:57.067433 7f04341ec720 client7107 send_request rebuilding request 29 for mds0
2011-05-13 06:13:57.067440 7f04341ec720 client7107 encode_cap_releases enter (req: 0x1338890, mds: 0)
2011-05-13 06:13:57.067447 7f04341ec720 client7107 send_request set sent_stamp to 2011-05-13 06:13:57.067445
2011-05-13 06:13:57.067455 7f04341ec720 client7107 send_request client_request(unknown0:29 lookup #1/readdir_r_test) v1 to mds0
2011-05-13 06:13:57.067467 7f04341ec720 client7107 awaiting reply|forward|kick on 0x7fff637de5e0
2011-05-13 06:13:57.067922 7f0430d89710 client7107 handle_client_reply got a reply. Safe:1 tid 29
2011-05-13 06:13:57.067938 7f0430d89710 client7107 insert_trace from 2011-05-13 06:13:57.067445 mds0 is_target=1 is_dentry=1
2011-05-13 06:13:57.067944 7f0430d89710 client7107 features 0x1fa
2011-05-13 06:13:57.067949 7f0430d89710 client7107 update_snap_trace len 48
2011-05-13 06:13:57.067957 7f0430d89710 client7107 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
2011-05-13 06:13:57.067963 7f0430d89710 client7107 hrm is_target=1 is_dentry=1
2011-05-13 06:13:57.067984 7f0430d89710 client7107 add_update_inode had 100000015cd.head( cap_refs={} open={} ref=2 caps=pAsxLsXsxFsx mode=40777 mtime=2011-05-13 06:13:57.007942 parent=0x1338f10) caps pAsxLsXsxFsx
2011-05-13 06:13:57.068006 7f0430d89710 client7107 add_update_cap issued pAsxLsXsxFsx > pAsxLsXsxFsx from mds0 on 100000015cd.head( cap_refs={} open={} ref=2 caps=pAsxLsXsxFsx mode=40777 mtime=2011-05-13 06:13:57.007942 parent=0x1338f10)
2011-05-13 06:13:57.068021 7f0430d89710 client7107 add_update_inode had 1.head( cap_refs={} open={} ref=3 caps=pAsLsXs mode=40755 mtime=2011-05-13 06:13:56.968093) caps pAsLsXs
2011-05-13 06:13:57.068029 7f0430d89710 client7107 dir hash is 2
2011-05-13 06:13:57.068042 7f0430d89710 client7107 update_inode_file_bits 1.head( cap_refs={} open={} ref=3 caps=pAsLsXs mode=40755 mtime=2011-05-13 06:13:56.968093) pAsLsXs mtime 2011-05-13 06:13:56.968093
2011-05-13 06:13:57.068059 7f0430d89710 client7107 add_update_cap issued pAsLsXs -> pAsLsXs from mds0 on 1.head( cap_refs={} open={} ref=3 caps=pAsLsXs mode=40755 mtime=2011-05-13 06:13:56.968093)
2011-05-13 06:13:57.068066 7f0430d89710 client7107 got dirfrag map for 1 frag * to mds 0
2011-05-13 06:13:57.068073 7f0430d89710 client7107 insert_dentry_inode readdir_r_test vino 100000015cd.head in dir 1.head
2011-05-13 06:13:57.068079 7f0430d89710 client7107 had dentry readdir_r_test with correct vino 100000015cd.head
2011-05-13 06:13:57.068086 7f0430d89710 client7107 handle_client_reply signalling caller 0x7fff637de5e0
2011-05-13 06:13:57.068097 7f0430d89710 client7107 handle_client_reply awaiting kickback on tid 29 0x7f0430d885d0
2011-05-13 06:13:57.068142 7f04341ec720 client7107 sendrecv kickback on tid 29 0x7f0430d885d0
2011-05-13 06:13:57.068151 7f04341ec720 client7107 lat 0.000705
2011-05-13 06:13:57.068161 7f04341ec720 client7107 _lookup res is 0
2011-05-13 06:13:57.068181 7f04341ec720 client7107 _lookup 1.head( cap_refs={} open={} ref=3 caps=pAsLsXs mode=40755 mtime=2011-05-13 06:13:56.968093) readdir_r_test = 100000015cd.head( cap_refs={} open={} ref=2 caps=pAsxLsXsxFsx mode=40777 mtime=2011-05-13 06:13:57.007942 parent=0x1338f10)
2011-05-13 06:13:57.068195 7f04341ec720 client7107 1 100000015cd.head( cap_refs={} open={} ref=2 caps=pAsxLsXsxFsx mode=40777 mtime=2011-05-13 06:13:57.007942 parent=0x1338f10) opened_file
2011-05-13 06:13:57.068206 7f04341ec720 client7107 _lookup on #100000015cd/opened_file
2011-05-13 06:13:57.068215 7f04341ec720 client7107 dir hash is 2 on opened_file => 433343845
2011-05-13 06:13:57.068221 7f04341ec720 client7107 choose_target_mds 0x7f0420002d50 is_hash=1 hash=433343845
2011-05-13 06:13:57.068226 7f04341ec720 client7107 choose_target_mds from caps
2011-05-13 06:13:57.068231 7f04341ec720 client7107 mds is 0
2011-05-13 06:13:57.068237 7f04341ec720 client7107 send_request rebuilding request 30 for mds0
2011-05-13 06:13:57.068244 7f04341ec720 client7107 encode_cap_releases enter (req: 0x1338b60, mds: 0)
2011-05-13 06:13:57.068251 7f04341ec720 client7107 send_request set sent_stamp to 2011-05-13 06:13:57.068249
2011-05-13 06:13:57.068259 7f04341ec720 client7107 send_request client_request(unknown0:30 lookup #100000015cd/opened_file) v1 to mds0
2011-05-13 06:13:57.068272 7f04341ec720 client7107 awaiting reply|forward|kick on 0x7fff637de5e0
2011-05-13 06:13:57.068614 7f0430d89710 client7107 handle_client_reply got a reply. Safe:1 tid 30
2011-05-13 06:13:57.068630 7f0430d89710 client7107 insert_trace from 2011-05-13 06:13:57.068249 mds0 is_target=0 is_dentry=1
2011-05-13 06:13:57.068635 7f0430d89710 client7107 features 0x1fa
2011-05-13 06:13:57.068640 7f0430d89710 client7107 update_snap_trace len 48
2011-05-13 06:13:57.068649 7f0430d89710 client7107 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
2011-05-13 06:13:57.068655 7f0430d89710 client7107 hrm is_target=0 is_dentry=1
2011-05-13 06:13:57.068675 7f0430d89710 client7107 add_update_inode had 100000015cd.head( cap_refs={} open={} ref=2 caps=pAsxLsXsxFsx mode=40777 mtime=2011-05-13 06:13:57.007942 parent=0x1338f10) caps pAsxLsXsxFsx
2011-05-13 06:13:57.068696 7f0430d89710 client7107 add_update_cap issued pAsxLsXsxFsx -> pAsxLsXsxFsx from mds0 on 100000015cd.head( cap_refs={} open={} ref=2 caps=pAsxLsXsxFsx mode=40777 mtime=2011-05-13 06:13:57.007942 parent=0x1338f10)
2011-05-13 06:13:57.068703 7f0430d89710 client7107 got dirfrag map for 100000015cd frag * to mds -1
2011-05-13 06:13:57.068710 7f0430d89710 client7107 handle_client_reply signalling caller 0x7fff637de5e0
2011-05-13 06:13:57.068720 7f0430d89710 client7107 handle_client_reply awaiting kickback on tid 30 0x7f0430d885d0
2011-05-13 06:13:57.068734 7f04341ec720 client7107 sendrecv kickback on tid 30 0x7f0430d885d0
2011-05-13 06:13:57.068743 7f04341ec720 client7107 lat 0.000492
2011-05-13 06:13:57.068750 7f04341ec720 client7107 _lookup res is -2
2011-05-13 06:13:57.068765 7f04341ec720 client7107 _lookup 100000015cd.head( cap_refs={} open={} ref=2 caps=pAsxLsXsxFsx mode=40777 mtime=2011-05-13 06:13:57.007942 parent=0x1338f10) opened_file = -2
2011-05-13 06:13:57.068775 7f04341ec720 client7107 path_walk readdir_r_test
2011-05-13 06:13:57.068786 7f04341ec720 client7107 0 1.head( cap_refs={} open={} ref=3 caps=pAsLsXs mode=40755 mtime=2011-05-13 06:13:56.968093) readdir_r_test
2011-05-13 06:13:57.068794 7f04341ec720 client7107 _lookup have dn readdir_r_test mds-1 ttl 0.000000 seq 0
2011-05-13 06:13:57.068803 7f04341ec720 client7107 _lookup on #1/readdir_r_test
2011-05-13 06:13:57.068811 7f04341ec720 client7107 dir hash is 2 on readdir_r_test => 2444911409
2011-05-13 06:13:57.068818 7f04341ec720 client7107 choose_target_mds 0x7f0420001f40 is_hash=1 hash=2444911409
2011-05-13 06:13:57.068823 7f04341ec720 client7107 choose_target_mds from caps
2011-05-13 06:13:57.068846 7f04341ec720 client7107 mds is 0
2011-05-13 06:13:57.068854 7f04341ec720 client7107 send_request rebuilding request 31 for mds0
2011-05-13 06:13:57.068861 7f04341ec720 client7107 encode_cap_releases enter (req: 0x1338890, mds: 0)
2011-05-13 06:13:57.068868 7f04341ec720 client7107 send_request set sent_stamp to 2011-05-13 06:13:57.068866
2011-05-13 06:13:57.068876 7f04341ec720 client7107 send_request client_request(unknown0:31 lookup #1/readdir_r_test) v1 to mds0
2011-05-13 06:13:57.068889 7f04341ec720 client7107 awaiting reply|forward|kick on 0x7fff637de5e0
2011-05-13 06:13:57.069274 7f0430d89710 client7107 handle_client_reply got a reply. Safe:1 tid 31
2011-05-13 06:13:57.069290 7f0430d89710 client7107 insert_trace from 2011-05-13 06:13:57.068866 mds0 is_target=1 is_dentry=1
2011-05-13 06:13:57.069296 7f0430d89710 client7107 features 0x1fa
2011-05-13 06:13:57.069301 7f0430d89710 client7107 update_snap_trace len 48
2011-05-13 06:13:57.069309 7f0430d89710 client7107 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
2011-05-13 06:13:57.069316 7f0430d89710 client7107 hrm is_target=1 is_dentry=1
2011-05-13 06:13:57.069337 7f0430d89710 client7107 add_update_inode had 100000015cd.head( cap_refs={} open={} ref=2 caps=pAsxLsXsxFsx mode=40777 mtime=2011-05-13 06:13:57.007942 parent=0x1338f10) caps pAsxLsXsxFsx
2011-05-13 06:13:57.069359 7f0430d89710 client7107 add_update_cap issued pAsxLsXsxFsx -> pAsxLsXsxFsx from mds0 on 100000015cd.head( cap_refs={} open={} ref=2 caps=pAsxLsXsxFsx mode=40777 mtime=2011-05-13 06:13:57.007942 parent=0x1338f10)
2011-05-13 06:13:57.069373 7f0430d89710 client7107 add_update_inode had 1.head( cap_refs={} open={} ref=3 caps=pAsLsXs mode=40755 mtime=2011-05-13 06:13:56.968093) caps pAsLsXs
2011-05-13 06:13:57.069380 7f0430d89710 client7107 dir hash is 2
2011-05-13 06:13:57.069393 7f0430d89710 client7107 update_inode_file_bits 1.head( cap_refs={} open={} ref=3 caps=pAsLsXs mode=40755 mtime=2011-05-13 06:13:56.968093) pAsLsXs mtime 2011-05-13 06:13:56.968093
2011-05-13 06:13:57.069410 7f0430d89710 client7107 add_update_cap issued pAsLsXs -> pAsLsXs from mds0 on 1.head( cap_refs={} open={} ref=3 caps=pAsLsXs mode=40755 mtime=2011-05-13 06:13:56.968093)
2011-05-13 06:13:57.069417 7f0430d89710 client7107 got dirfrag map for 1 frag * to mds 0
2011-05-13 06:13:57.069424 7f0430d89710 client7107 insert_dentry_inode readdir_r_test vino 100000015cd.head in dir 1.head
2011-05-13 06:13:57.069430 7f0430d89710 client7107 had dentry readdir_r_test with correct vino 100000015cd.head
2011-05-13 06:13:57.069437 7f0430d89710 client7107 handle_client_reply signalling caller 0x7fff637de5e0
2011-05-13 06:13:57.069446 7f0430d89710 client7107 handle_client_reply awaiting kickback on tid 31 0x7f0430d885d0
2011-05-13 06:13:57.069460 7f04341ec720 client7107 sendrecv kickback on tid 31 0x7f0430d885d0
2011-05-13 06:13:57.069469 7f04341ec720 client7107 lat 0.000601
2011-05-13 06:13:57.069477 7f04341ec720 client7107 _lookup res is 0
2011-05-13 06:13:57.069496 7f04341ec720 client7107 _lookup 1.head( cap_refs={} open={} ref=3 caps=pAsLsXs mode=40755 mtime=2011-05-13 06:13:56.968093) readdir_r_test = 100000015cd.head( cap_refs={} open={} ref=2 caps=pAsxLsXsxFsx mode=40777 mtime=2011-05-13 06:13:57.007942 parent=0x1338f10)
2011-05-13 06:13:57.069505 7f04341ec720 client7107 _create(100000015cd opened_file, 0666)
2011-05-13 06:13:57.069524 7f04341ec720 client7107 dir hash is 2 on opened_file => 433343845
2011-05-13 06:13:57.069532 7f04341ec720 client7107 choose_target_mds 0x7f0420002d50 is_hash=1 hash=433343845
2011-05-13 06:13:57.069537 7f04341ec720 client7107 choose_target_mds from caps
2011-05-13 06:13:57.069542 7f04341ec720 client7107 mds is 0
2011-05-13 06:13:57.069548 7f04341ec720 client7107 send_request rebuilding request 32 for mds0
2011-05-13 06:13:57.069555 7f04341ec720 client7107 encode_cap_releases enter (req: 0x1338b60, mds: 0)
2011-05-13 06:13:57.069560 7f04341ec720 client7107 encode_dentry_release enter(dn:0x1330ae0)
2011-05-13 06:13:57.069574 7f04341ec720 client7107 encode_inode_release enter(in:100000015cd.head( cap_refs={} open={} ref=3 caps=pAsxLsXsxFsx mode=40777 mtime=2011-05-13 06:13:57.007942 parent=0x1338f10), req:0x1338b60 mds:0, drop:256, unless:512, have:, force:1)
2011-05-13 06:13:57.069585 7f04341ec720 client7107 send_request set sent_stamp to 2011-05-13 06:13:57.069583
2011-05-13 06:13:57.069593 7f04341ec720 client7107 send_request client_request(unknown0:32 create #100000015cd/opened_file) v1 to mds0
2011-05-13 06:13:57.069606 7f04341ec720 client7107 awaiting reply|forward|kick on 0x7fff637de7c0
2011-05-13 06:13:57.070072 7f0430d89710 client7107 mds0 seq now 11
2011-05-13 06:13:57.070096 7f0430d89710 client7107 handle_cap_grant on in 100000015cd mds0 seq 7 caps now pAsLsXsxFsx was pAsxLsXsxFsx
2011-05-13 06:13:57.070116 7f0430d89710 client7107 update_inode_file_bits 100000015cd.head( cap_refs={} open={} ref=3 caps=pAsxLsXsxFsx mode=40777 mtime=2011-05-13 06:13:57.007942 parent=0x1338f10) pAsxLsXsxFsx mtime 2011-05-13 06:13:57.007942
2011-05-13 06:13:57.070125 7f0430d89710 client7107 revocation of Ax
2011-05-13 06:13:57.070139 7f0430d89710 client7107 check_caps on 100000015cd.head( cap_refs={} open={} ref=3 caps=pAsLsXsxFsx mode=40777 mtime=2011-05-13 06:13:57.007942 parent=0x1338f10) wanted - used - is_delayed=1
2011-05-13 06:13:57.070154 7f0430d89710 client7107 cap mds0 issued pAsLsXsxFsx implemented pAsxLsXsxFsx revoking Ax
2011-05-13 06:13:57.070161 7f0430d89710 client7107 completed revocation of Ax
2011-05-13 06:13:57.070167 7f0430d89710 client7107 flushing -
2011-05-13 06:13:57.070189 7f0430d89710 client7107 send_cap 100000015cd.head( cap_refs={} open={} ref=3 caps=pAsLsXsxFsx mode=40777 mtime=2011-05-13 06:13:57.007942 parent=0x1338f10) mds0 seq 7 used - want - flush - retain pAsLsXsFs held pAsxLsXsxFsx revoking Ax dropping XxFx
2011-05-13 06:13:57.073359 7f0430d89710 client7107 handle_client_reply got a reply. Safe:0 tid 32
2011-05-13 06:13:57.073388 7f0430d89710 client7107 insert_trace from 2011-05-13 06:13:57.069583 mds0 is_target=1 is_dentry=1
2011-05-13 06:13:57.073394 7f0430d89710 client7107 features 0x1fa
2011-05-13 06:13:57.073400 7f0430d89710 client7107 update_snap_trace len 48
2011-05-13 06:13:57.073411 7f0430d89710 client7107 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
2011-05-13 06:13:57.073417 7f0430d89710 client7107 hrm is_target=1 is_dentry=1
2011-05-13 06:13:57.073443 7f0430d89710 client7107 add_update_inode adding 100000015ce.head( cap_refs={} open={} ref=0 caps= mode=100000 mtime=0.000000) caps pAsxLsXsxFscr
2011-05-13 06:13:57.073455 7f0430d89710 client7107 update_inode_file_bits 100000015ce.head( cap_refs={} open={} ref=0 caps=- mode=100666 mtime=0.000000) - mtime 2011-05-13 06:13:57.015188
2011-05-13 06:13:57.073463 7f0430d89710 client7107 add_update_cap first one, opened snaprealm 0x7f0420006e60
2011-05-13 06:13:57.073482 7f0430d89710 client7107 add_update_cap issued - > pAsxLsXsxFscr from mds0 on 100000015ce.head( cap_refs={} open={} ref=0 caps=pAsxLsXsxFscr mode=100666 mtime=2011-05-13 06:13:57.015188)
2011-05-13 06:13:57.073500 7f0430d89710 client7107 add_update_inode had 100000015cd.head( cap_refs={} open={} ref=3 caps=pAsLsXsFs mode=40777 mtime=2011-05-13 06:13:57.007942 parent=0x1338f10) caps pAsLsXsxFsx
2011-05-13 06:13:57.073506 7f0430d89710 client7107 dir hash is 2
2011-05-13 06:13:57.073521 7f0430d89710 client7107 update_inode_file_bits 100000015cd.head( cap_refs={} open={} ref=3 caps=pAsLsXsFs mode=40777 mtime=2011-05-13 06:13:57.007942 parent=0x1338f10) pAsLsXsFs mtime 2011-05-13 06:13:57.015188
2011-05-13 06:13:57.073541 7f0430d89710 client7107 add_update_cap issued pAsLsXsFs -> pAsLsXsxFsx from mds0 on 100000015cd.head( cap_refs={} open={} ref=3 caps=pAsLsXsxFsx mode=40777 mtime=2011-05-13 06:13:57.015188 parent=0x1338f10)
2011-05-13 06:13:57.073548 7f0430d89710 client7107 got dirfrag map for 100000015cd frag * to mds -1
2011-05-13 06:13:57.073558 7f0430d89710 client7107 insert_dentry_inode opened_file vino 100000015ce.head in dir 100000015cd.head
2011-05-13 06:13:57.073564 7f0430d89710 client7107 had vino 100000015ce.head unlinked, linking
2011-05-13 06:13:57.073570 7f0430d89710 client7107 setting dn offset to 2
2011-05-13 06:13:57.073577 7f0430d89710 client7107 handle_client_reply signalling caller 0x7fff637de7c0
2011-05-13 06:13:57.073587 7f0430d89710 client7107 handle_client_reply awaiting kickback on tid 32 0x7f0430d885d0
2011-05-13 06:13:57.073602 7f04341ec720 client7107 sendrecv kickback on tid 32 0x7f0430d885d0
2011-05-13 06:13:57.073614 7f04341ec720 client7107 lat 0.004029
2011-05-13 06:13:57.073628 7f04341ec720 client7107 _lookup have dn opened_file mds-1 ttl 0.000000 seq 0
2011-05-13 06:13:57.073652 7f04341ec720 client7107 _lookup 100000015cd.head( cap_refs={} open={} ref=3 caps=pAsLsXsxFsx mode=40777 mtime=2011-05-13 06:13:57.015188 parent=0x1338f10) opened_file = 100000015ce.head( cap_refs={} open={} ref=1 caps=pAsxLsXsxFscr mode=100666 mtime=2011-05-13 06:13:57.015188 parent=0x1330ae0)
2011-05-13 06:13:57.073664 7f04341ec720 client7107 _create_fh 100000015ce mode 1
2011-05-13 06:13:57.073672 7f04341ec720 client7107 create(#100000015cd/opened_file, 0666 layout 0 0 0 0 -1) = 0
2011-05-13 06:13:57.073682 7f04341ec720 client7107 open exit(readdir_r_test/opened_file, 64) = 11
ceph_open: success
2011-05-13 06:13:57.073727 7f04341ec720 client7107 readdir_r_cb 100000015cd.head( cap_refs={} open={} ref=3 caps=pAsLsXsxFsx mode=40777 mtime=2011-05-13 06:13:57.015188 parent=0x1338f10) offset 0 frag * fragpos 0 at_end=0
2011-05-13 06:13:57.073734 7f04341ec720 client7107 including .
2011-05-13 06:13:57.073749 7f04341ec720 client7107 fill_dirent '.' -> 100000015cd type 4 w/ next_off 1
2011-05-13 06:13:57.073759 7f04341ec720 client7107 fill_stat on 100000015cd snap/devhead mode 040777 mtime 2011-05-13 06:13:57.015188 ctime 2011-05-13 06:13:57.015188
2011-05-13 06:13:57.073765 7f04341ec720 client7107 including ..
2011-05-13 06:13:57.073770 7f04341ec720 client7107 fill_dirent '..' -> 100000015cd type 4 w/ next_off 2
2011-05-13 06:13:57.073779 7f04341ec720 client7107 fill_stat on 100000015cd snap/devhead mode 040777 mtime 2011-05-13 06:13:57.015188 ctime 2011-05-13 06:13:57.015188
ceph_readdir_r: fail, returned: -1
2011-05-13 06:13:57.073802 7f04341ec720 client7107 unmounting
2011-05-13 06:13:57.073809 7f04341ec720 client7107 waiting on 2 requests
2011-05-13 06:13:57.096541 7f0430d89710 client7107 handle_client_reply got a reply. Safe:1 tid 27
2011-05-13 06:13:57.096568 7f0430d89710 client7107 insert_trace from 2011-05-13 06:13:57.064945 mds0 is_target=0 is_dentry=0
2011-05-13 06:13:57.096574 7f0430d89710 client7107 insert_trace - no trace
2011-05-13 06:13:57.096590 7f0430d89710 client7107 unmounting: trim pass, size was 3+4
2011-05-13 06:13:57.096597 7f0430d89710 client7107 unmounting: trim pass, size still 3+4
2011-05-13 06:13:57.096609 7f0430d89710 client7107 dump_inode: inode 1 ref 3 dir 0x13338a0
2011-05-13 06:13:57.096614 7f0430d89710 client7107 dir size 2
2011-05-13 06:13:57.096620 7f0430d89710 client7107 dn barfile ref 0
2011-05-13 06:13:57.096625 7f0430d89710 client7107 dump_inode: inode 100000015cc ref 2 dir 0
2011-05-13 06:13:57.096631 7f0430d89710 client7107 dn readdir_r_test ref 1
2011-05-13 06:13:57.096637 7f0430d89710 client7107 dump_inode: inode 100000015cd ref 3 dir 0x1338e10
2011-05-13 06:13:57.096642 7f0430d89710 client7107 dir size 1
2011-05-13 06:13:57.096647 7f0430d89710 client7107 dn opened_file ref 0
2011-05-13 06:13:57.096652 7f0430d89710 client7107 dump_inode: inode 100000015ce ref 2 dir 0
2011-05-13 06:13:57.096671 7f0430d89710 client7107 dump_cache: inode 100000015cd.head ref 3 dir 0x1338e10 100000015cd.head( cap_refs={} open={} ref=3 caps=pAsLsXsxFsx mode=40777 mtime=2011-05-13 06:13:57.015188 parent=0x1338f10)
2011-05-13 06:13:57.096677 7f0430d89710 client7107 dir size 1
2011-05-13 06:13:57.096689 7f0430d89710 client7107 dump_cache: inode 1.head ref 3 dir 0x13338a0 1.head( cap_refs={} open={} ref=3 caps=pAsLsXs mode=40755 mtime=2011-05-13 06:13:56.968093)
2011-05-13 06:13:57.096695 7f0430d89710 client7107 dir size 2
2011-05-13 06:13:57.096708 7f0430d89710 client7107 dump_cache: inode 100000015ce.head ref 2 dir 0 100000015ce.head( cap_refs={} open={1=1} ref=2 caps=pAsxLsXsxFscr mode=100666 mtime=2011-05-13 06:13:57.015188 parent=0x1330ae0)
2011-05-13 06:13:57.096722 7f0430d89710 client7107 dump_cache: inode 100000015cc.head ref 2 dir 0 100000015cc.head( cap_refs={} open={1=1} ref=2 caps=pAsxLsXsFscr mode=100666 mtime=2011-05-13 06:13:56.968093 parent=0x1333820)
2011-05-13 06:13:57.096736 7f04341ec720 client7107 waiting on 1 requests
2011-05-13 06:13:57.236599 7f0430d89710 client7107 handle_client_reply got a reply. Safe:1 tid 32
2011-05-13 06:13:57.236630 7f0430d89710 client7107 insert_trace from 2011-05-13 06:13:57.069583 mds0 is_target=0 is_dentry=0
2011-05-13 06:13:57.236636 7f0430d89710 client7107 insert_trace -- no trace
2011-05-13 06:13:57.236653 7f0430d89710 client7107 unmounting: trim pass, size was 3+4
2011-05-13 06:13:57.236660 7f0430d89710 client7107 unmounting: trim pass, size still 3+4
2011-05-13 06:13:57.236667 7f0430d89710 client7107 dump_inode: inode 1 ref 3 dir 0x13338a0
2011-05-13 06:13:57.236672 7f0430d89710 client7107 dir size 2
2011-05-13 06:13:57.236678 7f0430d89710 client7107 dn barfile ref 0
2011-05-13 06:13:57.236683 7f0430d89710 client7107 dump_inode: inode 100000015cc ref 2 dir 0
2011-05-13 06:13:57.236689 7f0430d89710 client7107 dn readdir_r_test ref 1
2011-05-13 06:13:57.236694 7f0430d89710 client7107 dump_inode: inode 100000015cd ref 3 dir 0x1338e10
2011-05-13 06:13:57.236700 7f0430d89710 client7107 dir size 1
2011-05-13 06:13:57.236705 7f0430d89710 client7107 dn opened_file ref 0
2011-05-13 06:13:57.236710 7f0430d89710 client7107 dump_inode: inode 100000015ce ref 2 dir 0
2011-05-13 06:13:57.236731 7f0430d89710 client7107 dump_cache: inode 100000015cd.head ref 3 dir 0x1338e10 100000015cd.head( cap_refs={} open={} ref=3 caps=pAsLsXsxFsx mode=40777 mtime=2011-05-13 06:13:57.015188 parent=0x1338f10)
2011-05-13 06:13:57.236737 7f0430d89710 client7107 dir size 1
2011-05-13 06:13:57.236749 7f0430d89710 client7107 dump_cache: inode 1.head ref 3 dir 0x13338a0 1.head( cap_refs={} open={} ref=3 caps=pAsLsXs mode=40755 mtime=2011-05-13 06:13:56.968093)
2011-05-13 06:13:57.236755 7f0430d89710 client7107 dir size 2
2011-05-13 06:13:57.236769 7f0430d89710 client7107 dump_cache: inode 100000015ce.head ref 2 dir 0 100000015ce.head( cap_refs={} open={1=1} ref=2 caps=pAsxLsXsxFscr mode=100666 mtime=2011-05-13 06:13:57.015188 parent=0x1330ae0)
2011-05-13 06:13:57.236783 7f0430d89710 client7107 dump_cache: inode 100000015cc.head ref 2 dir 0 100000015cc.head( cap_refs={} open={1=1} ref=2 caps=pAsxLsXsFscr mode=100666 mtime=2011-05-13 06:13:56.968093 parent=0x1333820)
Warning: Some files were not closed prior to unmounting;
Ceph is closing them now.
2011-05-13 06:13:57.236848 7f04341ec720 client7107 _release 0x132f3a0 mode 1 on 100000015cc.head( cap_refs={} open={1=1} ref=2 caps=pAsxLsXsFscr mode=100666 mtime=2011-05-13 06:13:56.968093 parent=0x1333820)
2011-05-13 06:13:57.236871 7f04341ec720 client7107 check_caps on 100000015cc.head( cap_refs={} open={1=0} ref=2 caps=pAsxLsXsFscr mode=100666 mtime=2011-05-13 06:13:56.968093 parent=0x1333820) wanted - used - is_delayed=0
2011-05-13 06:13:57.236888 7f04341ec720 client7107 cap_delay_requeue on 100000015cc.head( cap_refs={} open={1=0} ref=2 caps=pAsxLsXsFscr mode=100666 mtime=2011-05-13 06:13:56.968093 parent=0x1333820)
2011-05-13 06:13:57.236903 7f04341ec720 client7107 cap mds0 issued pAsxLsXsFscr implemented pAsxLsXsFscr revoking -
2011-05-13 06:13:57.236910 7f04341ec720 client7107 flushing -
2011-05-13 06:13:57.236933 7f04341ec720 client7107 send_cap 100000015cc.head( cap_refs={} open={1=0} ref=2 caps=pAsxLsXsFscr mode=100666 mtime=2011-05-13 06:13:56.968093 parent=0x1333820) mds0 seq 8 used - want - flush - retain p held pAsxLsXsFscr revoking - dropping AsxLsXsFscr
2011-05-13 06:13:57.236967 7f04341ec720 client7107 _release 0x13381a0 mode 1 on 100000015ce.head( cap_refs={} open={1=1} ref=2 caps=pAsxLsXsxFscr mode=100666 mtime=2011-05-13 06:13:57.015188 parent=0x1330ae0)
2011-05-13 06:13:57.236982 7f04341ec720 client7107 check_caps on 100000015ce.head( cap_refs={} open={1=0} ref=2 caps=pAsxLsXsxFscr mode=100666 mtime=2011-05-13 06:13:57.015188 parent=0x1330ae0) wanted - used - is_delayed=0
2011-05-13 06:13:57.236997 7f04341ec720 client7107 cap_delay_requeue on 100000015ce.head( cap_refs={} open={1=0} ref=2 caps=pAsxLsXsxFscr mode=100666 mtime=2011-05-13 06:13:57.015188 parent=0x1330ae0)
2011-05-13 06:13:57.237012 7f04341ec720 client7107 cap mds0 issued pAsxLsXsxFscr implemented pAsxLsXsxFscr revoking -
2011-05-13 06:13:57.237019 7f04341ec720 client7107 flushing -
2011-05-13 06:13:57.237041 7f04341ec720 client7107 send_cap 100000015ce.head( cap_refs={} open={1=0} ref=2 caps=pAsxLsXsxFscr mode=100666 mtime=2011-05-13 06:13:57.015188 parent=0x1330ae0) mds0 seq 1 used - want - flush - retain p held pAsxLsXsxFscr revoking - dropping AsxLsXsxFscr
2011-05-13 06:13:57.237075 7f04341ec720 client7107 _ll_drop_pins
2011-05-13 06:13:57.237086 7f04341ec720 client7107 _ll_put 0x7f0420001f40 1 1 -> 0
2011-05-13 06:13:57.237092 7f04341ec720 client7107 trim_cache unlinking dn opened_file in dir 100000015cd
2011-05-13 06:13:57.237104 7f04341ec720 client7107 remove_cap mds0 on 100000015ce.head( cap_refs={} open={1=0} ref=0 caps=p mode=100666 mtime=2011-05-13 06:13:57.015188)
2011-05-13 06:13:57.237114 7f04341ec720 client7107 remove_cap last one, closing snaprealm 0x7f0420006e60
2011-05-13 06:13:57.237127 7f04341ec720 client7107 trim_cache unlinking dn barfile in dir 1
2011-05-13 06:13:57.237138 7f04341ec720 client7107 remove_cap mds0 on 100000015cc.head( cap_refs={} open={1=0} ref=0 caps=p mode=100666 mtime=2011-05-13 06:13:56.968093)
2011-05-13 06:13:57.237144 7f04341ec720 client7107 remove_cap last one, closing snaprealm 0x7f0420006e60
2011-05-13 06:13:57.237154 7f04341ec720 client7107 trim_cache unlinking dn readdir_r_test in dir 1
2011-05-13 06:13:57.237177 7f04341ec720 client7107 remove_cap mds0 on 1.head( cap_refs={} open={} ref=0 caps=pAsLsXs mode=40755 mtime=2011-05-13 06:13:56.968093)
2011-05-13 06:13:57.237185 7f04341ec720 client7107 remove_cap last one, closing snaprealm 0x7f0420006e60
2011-05-13 06:13:57.237214 7f04341ec720 client7107 _flush 100000015cd.head( cap_refs={1024=0} open={} ref=2 caps=pAsLsXsxFsx mode=40777 mtime=2011-05-13 06:13:57.015188)
2011-05-13 06:13:57.237228 7f04341ec720 client7107 flush_caps
2011-05-13 06:13:57.237244 7f04341ec720 client7107 check_caps on 100000015cd.head( cap_refs={1024=0,8192=0} open={} ref=1 caps=pAsLsXsxFsx mode=40777 mtime=2011-05-13 06:13:57.015188) wanted - used - is_delayed=1
2011-05-13 06:13:57.237259 7f04341ec720 client7107 cap mds0 issued pAsLsXsxFsx implemented pAsLsXsxFsx revoking -
2011-05-13 06:13:57.237295 7f04341ec720 client7107 flushing -
2011-05-13 06:13:57.237318 7f04341ec720 client7107 send_cap 100000015cd.head( cap_refs={1024=0,8192=0} open={} ref=1 caps=pAsLsXsxFsx mode=40777 mtime=2011-05-13 06:13:57.015188) mds0 seq 8 used - want - flush - retain p held pAsLsXsxFsx revoking - dropping AsLsXsxFsx
2011-05-13 06:13:57.237339 7f04341ec720 client7107 wait_sync_caps want 0 (last is 0, 0 total flushing)
2011-05-13 06:13:57.237348 7f04341ec720 client7107 cache still has 0+1 items, waiting (for caps to release?)
2011-05-13 06:13:57.237359 7f04341ec720 client7107 dump_cache: inode 100000015cd.head ref 1 dir 0 100000015cd.head( cap_refs={1024=0,8192=0} open={} ref=1 caps=p mode=40777 mtime=2011-05-13 06:13:57.015188)
2011-05-13 06:14:57.015498 7f0430d89710 client7107 handle_client_session client_session(stale seq 11) v1
2011-05-13 06:14:57.015527 7f0430d89710 client7107 renew_caps mds0
2011-05-13 06:14:57.015550 7f0430d89710 client7107 unmounting: trim pass, size was 0+1
2011-05-13 06:14:57.015557 7f0430d89710 client7107 unmounting: trim pass, size still 0+1
2011-05-13 06:14:57.015574 7f0430d89710 client7107 dump_cache: inode 100000015cd.head ref 1 dir 0 100000015cd.head( cap_refs={1024=0,8192=0} open={} ref=1 caps=p mode=40777 mtime=2011-05-13 06:13:57.015188)
2011-05-13 06:14:57.015915 7f0430d89710 client7107 handle_client_session client_session(renewcaps seq 2) v1
2011-05-13 06:14:57.015934 7f0430d89710 client7107 unmounting: trim pass, size was 0+1
2011-05-13 06:14:57.015940 7f0430d89710 client7107 unmounting: trim pass, size still 0+1
2011-05-13 06:14:57.015953 7f0430d89710 client7107 dump_cache: inode 100000015cd.head ref 1 dir 0 100000015cd.head( cap_refs={1024=0,8192=0} open={} ref=1 caps=p mode=40777 mtime=2011-05-13 06:13:57.015188)