We have an abusive file/dir create/remove script that led me to find
this repeatable problem, with CVS head.
Start 1 server, both meta + data. This is stock pvfs, no OSD code
here. 40k is a 40*1024 byte file of zeroes on NFS.
ib30$ pvfs2-mkdir -p /pvfs/1/2/3
ib30$ pvfs2-cp 40k /pvfs/1/2/3/a
ib30$ pvfs2-cp 40k /pvfs/1/2/3/b
ib30$ pvfs2-rm /pvfs/1/2/3/a /pvfs/1/2/3/b
PVFS_sys_lookup: No such file or directory (error class: 0)
Here's a verbose dump of that last command. The rm code takes two
trips through the loop, one for each file to remove. There are
differences in the two lookups. The second time through hits on the
directory /1/2/3, which makes sense since the first time it looked
it up successfully.
But after finding this in the cache, it goes to the completion
function and claims it only resolved 1 segment. (Grep for the
second occurrence of lookup_segment_lookup_comp_fn below.)
Shouldn't this be 3, since it found all three dirs at once in the
cache? Then it goes to get the attrs for /1, which weren't present,
then tries to look up segment "3" in /1, which won't be there.
Can someone who understands the ncache stuff figure out what is
going wrong? (fs.conf at the very end, if needed.) Thanks,
-- Pete
[D 13:30:21.531138] PINT_do_request_commit: commit node 0x7fffbc409410
[D 13:30:21.531901] node stored at 0
[D 13:30:21.531909] clearing tree
[D 13:30:21.531953] PINT_do_request_commit: commit node 0x7fffbc409410
[D 13:30:21.531959] node stored at 0
[D 13:30:21.531965] clearing tree
[D 13:30:21.532119] client_op_state_get_machine 300
[D 13:30:21.532132] PINT_client_state_machine_post smcb 0x6135a0, op:
PVFS_CLIENT_JOB_TIMER
[D 13:30:21.532158] Posted PVFS_CLIENT_JOB_TIMER (-1) (waiting for
test)(-1073741839)
[D 13:30:21.532186] BMI_tcp_initialize: Initializing TCP/IP module.
[D 13:30:21.532207] BMI_tcp_initialize: TCP/IP module successfully initialized.
[D 13:30:21.532238] client_op_state_get_machine 19
[D 13:30:21.532247] PINT_client_state_machine_post smcb 0x6143c0, op:
PVFS_SYS_FS_ADD
[D 13:30:21.532254] get_config state: server_get_config_setup_msgpair
[D 13:30:21.532265] (0x6143c0) msgpairarray state: init (1 msgpair(s))
[D 13:30:21.532273] msgpairarray_post: sm 0x6143c0 2 total message(s) with 2
incomplete
[D 13:30:21.532305] msgpairarray_post: sm 0x6143c0 msgpair 0: posting recv
[D 13:30:21.532314] BMI_post_recv: addr: 6374272, offset: 0x614df0, size:
16416, tag: 1
[D 13:30:21.532349] msgpairarray_post: sm 0x6143c0 msgpair 0: posting send
[D 13:30:21.532358] BMI_post_sendunexpected_list: addr: 6374272, count: 1,
total_size: 24, tag: 1
[D 13:30:21.532364] element 0: offset: 0x614dd0, size: 24
[D 13:30:21.532376] Default socket buffers send:-1 receive:-1
[D 13:30:21.532383] Setting socket buffer size for send:0 receive:0
[D 13:30:21.532389] Reread socket buffers send:-1 receive:-1
[D 13:30:21.532417] Default socket buffers send:16384 receive:87380
[D 13:30:21.532423] Setting socket buffer size for send:0 receive:0
[D 13:30:21.532429] Reread socket buffers send:16384 receive:87380
[D 13:30:21.532434] tcp_sock_init: Connect: socket=4, hostname=ib29, port=3334
[D 13:30:21.533712] Posted PVFS_SYS_FS_ADD (5) (waiting for test)(-1073741839)
[D 13:30:21.533812] work_on_send_op: Sent: 24 bytes of data.
[D 13:30:21.533827] BMI_testcontext completing: 6395632
[D 13:30:21.533840] sm control op 19
[D 13:30:21.533847] msgpairarray_complete: sm 0x6143c0 status_user_tag 1
msgarray_count 1
[D 13:30:21.533853] msgpairarray: 1 operations remain
[D 13:30:21.534016] tcp_do_work_recv: Reading header for new op.
[D 13:30:21.534025] tcp_do_work_recv: Received new message; mode: 4.
[D 13:30:21.534031] tcp_do_work_recv: tag: 1
[D 13:30:21.534042] BMI_testcontext completing: 6393680
[D 13:30:21.534049] sm control op 19
[D 13:30:21.534055] msgpairarray_complete: sm 0x6143c0 status_user_tag 0
msgarray_count 1
[D 13:30:21.534061] msgpairarray: all operations complete
[D 13:30:21.534066] (0x6143c0) msgpairarray state: completion_fn
[D 13:30:21.534085] msgpairarray_completion_fn: sm 0x6143c0 msgpair 0 marked
complete
[D 13:30:21.534506] [BMI CONTROL]: BMI_set_info: set_info: 0 option: 11
[D 13:30:21.534516] [BMI CONTROL]: BMI_set_info: set_info: 0 option: 12
[D 13:30:21.534531] PINT_server_config_mgr_add_config: adding config 0x614cc0
[D 13:30:21.534539] mapped fs_id 42 => config 0x614cc0
[D 13:30:21.534550] Set min handle recycle time to 360 seconds
[D 13:30:21.534556] Reloading handle mappings for fs_id 42
[D 13:30:21.534577] client_state_machine_terminate smcb 0x6143c0
[D 13:30:21.534584] add smcb 0x6143c0 to completion list
[D 13:30:21.534591] PINT_sys_release: id 5
[D 13:30:21.534614] PVFS_sys_ref_lookup entered
[D 13:30:21.534621] PVFS_isys_ref_lookup entered
[D 13:30:21.534628] client_op_state_get_machine 11
[D 13:30:21.534637] initialize_context called
[D 13:30:21.534645] original pathname is: 1/2/3
[D 13:30:21.534651] cur_seg_name[0]: 1
[D 13:30:21.534656] pathname is: 1
[D 13:30:21.534662] *seg_remaining is: 1/2/3
[D 13:30:21.534668] cur_seg_name[1]: 2
[D 13:30:21.534673] pathname is: 1/2
[D 13:30:21.534680] *seg_remaining is: 3
[D 13:30:21.534685] cur_seg_name[2]: 3
[D 13:30:21.534691] pathname is: 1/2/3
[D 13:30:21.534696] lookup got: 1/2/3 (parent 2000000)
[D 13:30:21.534702] PINT_client_state_machine_post smcb 0x6143c0, op:
PVFS_SYS_LOOKUP
[D 13:30:21.534722] lookup state: lookup_init
[D 13:30:21.534729] ncache: get_cached_entry(): [1/2/3]
[D 13:30:21.534736] ncache: miss: name=[1/2/3]
[D 13:30:21.534744] lookup state: lookup_segment_lookup_setup_msgpair
[D 13:30:21.534750] Looking up segment 1/2/3 under handle 2000000
[D 13:30:21.534761] lookup_ncache state: lookup
[D 13:30:21.534769] lookup_ncache state: lookup_ncache_lookup on segment [1]
[D 13:30:21.534774] ncache: get_cached_entry(): [1]
[D 13:30:21.534780] ncache: miss: name=[1]
[D 13:30:21.534785] *** ncache clean miss on 1/2/3.
[D 13:30:21.534791] (0x6143c0) msgpairarray state: init (1 msgpair(s))
[D 13:30:21.534797] msgpairarray_post: sm 0x6143c0 2 total message(s) with 2
incomplete
[D 13:30:21.534813] msgpairarray_post: sm 0x6143c0 msgpair 0: posting recv
[D 13:30:21.534820] BMI_post_recv: addr: 6374272, offset: 0x61a2b0, size: 8224,
tag: 2
[D 13:30:21.534833] msgpairarray_post: sm 0x6143c0 msgpair 0: posting send
[D 13:30:21.534840] BMI_post_sendunexpected_list: addr: 6374272, count: 1,
total_size: 60, tag: 2
[D 13:30:21.534846] element 0: offset: 0x616aa0, size: 60
[D 13:30:21.534858] BMI_tcp_post_send_generic: Sent: 60 bytes of data.
[D 13:30:21.534866] Posted PVFS_SYS_LOOKUP (8) (waiting for test)(-1073741839)
[D 13:30:21.535046] tcp_do_work_recv: Reading header for new op.
[D 13:30:21.535053] tcp_do_work_recv: Received new message; mode: 4.
[D 13:30:21.535059] tcp_do_work_recv: tag: 2
[D 13:30:21.535067] BMI_testcontext completing: 6384880
[D 13:30:21.535074] sm control op 11
[D 13:30:21.535080] msgpairarray_complete: sm 0x6143c0 status_user_tag 0
msgarray_count 1
[D 13:30:21.535086] msgpairarray: all operations complete
[D 13:30:21.535092] (0x6143c0) msgpairarray state: completion_fn
[D 13:30:21.535103] lookup_segment_lookup_comp_fn
[D 13:30:21.535109] - Resolved 3 segments
[D 13:30:21.535118] *** ncache update on 1 target (2999996|42) parent
(2000000|42)
[D 13:30:21.535125] ncache: update(): name [1]
[D 13:30:21.535133] ncache: update(): return=0
[D 13:30:21.535139] *** ncache update on 2 target (2999994|42) parent
(2999996|42)
[D 13:30:21.535145] ncache: update(): name [2]
[D 13:30:21.535151] ncache: update(): return=0
[D 13:30:21.535157] *** ncache update on 3 target (2999992|42) parent
(2999994|42)
[D 13:30:21.535163] ncache: update(): name [3]
[D 13:30:21.535169] ncache: update(): return=0
[D 13:30:21.535176] msgpairarray_completion_fn: sm 0x6143c0 msgpair 0 marked
complete
[D 13:30:21.535182] lookup state: lookup_segment_verify_attr_present
[D 13:30:21.535188] -- we have the attrs for 3
[D 13:30:21.535194] lookup state: lookup_segment_check_attr_type
[D 13:30:21.535200] lookup state: lookup_context_check_completion
[D 13:30:21.535206] lookup state: lookup_cleanup
[D 13:30:21.535212] Freeing segment 1
[D 13:30:21.535217] Freeing remaining segment 1/2/3
[D 13:30:21.535223] Freeing segment 2
[D 13:30:21.535228] Freeing remaining segment 3
[D 13:30:21.535233] Freeing segment 3
[D 13:30:21.535240] All contexts finalized
[D 13:30:21.535245] Lookup resolved segment 1/2/3 to 2999992
[D 13:30:21.535251] client_state_machine_terminate smcb 0x6143c0
[D 13:30:21.535256] add smcb 0x6143c0 to completion list
[D 13:30:21.535262] PINT_sys_release: id 8
[D 13:30:21.535271] PVFS_sys_remove entered
[D 13:30:21.535278] PVFS_isys_remove entered
[D 13:30:21.535286] client_op_state_get_machine 1
[D 13:30:21.535293] Trying to remove entry a under 2999992,42
[D 13:30:21.535299] PINT_client_state_machine_post smcb 0x616aa0, op:
PVFS_SYS_REMOVE
[D 13:30:21.535305] remove state: init
[D 13:30:21.535311] remove state: rmdirent_setup_msgpair
[D 13:30:21.535317] - doing RMDIRENT on a under 2999992,42
[D 13:30:21.535325] (0x616aa0) msgpairarray state: init (1 msgpair(s))
[D 13:30:21.535331] msgpairarray_post: sm 0x616aa0 2 total message(s) with 2
incomplete
[D 13:30:21.535339] msgpairarray_post: sm 0x616aa0 msgpair 0: posting recv
[D 13:30:21.535345] BMI_post_recv: addr: 6374272, offset: 0x614db0, size: 24,
tag: 3
[D 13:30:21.535361] msgpairarray_post: sm 0x616aa0 msgpair 0: posting send
[D 13:30:21.535381] BMI_post_sendunexpected_list: addr: 6374272, count: 1,
total_size: 44, tag: 3
[D 13:30:21.535388] element 0: offset: 0x616b50, size: 44
[D 13:30:21.535398] BMI_tcp_post_send_generic: Sent: 44 bytes of data.
[D 13:30:21.535406] Posted PVFS_SYS_REMOVE (11) (waiting for test)(-1073741839)
[D 13:30:21.536975] tcp_do_work_recv: Reading header for new op.
[D 13:30:21.536983] tcp_do_work_recv: Received new message; mode: 4.
[D 13:30:21.536988] tcp_do_work_recv: tag: 3
[D 13:30:21.536995] BMI_testcontext completing: 6374592
[D 13:30:21.537003] sm control op 1
[D 13:30:21.537009] msgpairarray_complete: sm 0x616aa0 status_user_tag 0
msgarray_count 1
[D 13:30:21.537014] msgpairarray: all operations complete
[D 13:30:21.537020] (0x616aa0) msgpairarray state: completion_fn
[D 13:30:21.537027] remove_rmdirent_comp_fn: metafile handle = 2999990
[D 13:30:21.537033] msgpairarray_completion_fn: sm 0x616aa0 msgpair 0 marked
complete
[D 13:30:21.537041] getattr_acache_lookup: handle 2999990 fsid 42
[D 13:30:21.537047] acache: get_cached_entry(): H=2999990
[D 13:30:21.537053] acache: miss: H=2999990
[D 13:30:21.537059] acache: clean acache miss: [2999990]
[D 13:30:21.537065] (0x616f80) getattr_object_getattr_setup_msgpair
[D 13:30:21.537074] (0x616aa0) msgpairarray state: init (1 msgpair(s))
[D 13:30:21.537081] msgpairarray_post: sm 0x616aa0 2 total message(s) with 2
incomplete
[D 13:30:21.537089] msgpairarray_post: sm 0x616aa0 msgpair 0: posting recv
[D 13:30:21.537096] BMI_post_recv: addr: 6374272, offset: 0x61a2b0, size: 9280,
tag: 4
[D 13:30:21.537107] msgpairarray_post: sm 0x616aa0 msgpair 0: posting send
[D 13:30:21.537114] BMI_post_sendunexpected_list: addr: 6374272, count: 1,
total_size: 40, tag: 4
[D 13:30:21.537120] element 0: offset: 0x6197c0, size: 40
[D 13:30:21.537130] BMI_tcp_post_send_generic: Sent: 40 bytes of data.
[D 13:30:21.537272] tcp_do_work_recv: Reading header for new op.
[D 13:30:21.537279] tcp_do_work_recv: Received new message; mode: 4.
[D 13:30:21.537284] tcp_do_work_recv: tag: 4
[D 13:30:21.537292] BMI_testcontext completing: 6374336
[D 13:30:21.537299] sm control op 1
[D 13:30:21.537305] msgpairarray_complete: sm 0x616aa0 status_user_tag 0
msgarray_count 1
[D 13:30:21.537311] msgpairarray: all operations complete
[D 13:30:21.537316] (0x616aa0) msgpairarray state: completion_fn
[D 13:30:21.537327] getattr_object_getattr_comp_fn called
[D 13:30:21.537334] getattr_object_getattr_comp_fn: 1 datafiles.
[D 13:30:21.537341] msgpairarray_completion_fn: sm 0x616aa0 msgpair 0 marked
complete
[D 13:30:21.537349] acache: update(): H=2999990
[D 13:30:21.537355] acache: update(): attr_status=0, size_status=-1073741858
[D 13:30:21.537362] acache: update(): return=0
[D 13:30:21.537368] trying to add object reference to acache
[D 13:30:21.537375] (0x616f80) getattr state: getattr_cleanup
[D 13:30:21.537382] remove_getattr_analyze_results: must remove 1 datafiles
[D 13:30:21.537388] remove state: datafile_remove_setup_msgpair
[D 13:30:21.537393] datafile_remove: removing handle 1000000
[D 13:30:21.537401] mapped handle 1000000 to server 6374272
[D 13:30:21.537407] (0x616aa0) msgpairarray state: init (1 msgpair(s))
[D 13:30:21.537413] msgpairarray_post: sm 0x616aa0 2 total message(s) with 2
incomplete
[D 13:30:21.537421] msgpairarray_post: sm 0x616aa0 msgpair 0: posting recv
[D 13:30:21.537427] BMI_post_recv: addr: 6374272, offset: 0x6177a0, size: 16,
tag: 5
[D 13:30:21.537438] msgpairarray_post: sm 0x616aa0 msgpair 0: posting send
[D 13:30:21.537445] BMI_post_sendunexpected_list: addr: 6374272, count: 1,
total_size: 36, tag: 5
[D 13:30:21.537451] element 0: offset: 0x6197c0, size: 36
[D 13:30:21.537461] BMI_tcp_post_send_generic: Sent: 36 bytes of data.
[D 13:30:21.537933] tcp_do_work_recv: Reading header for new op.
[D 13:30:21.537941] tcp_do_work_recv: Received new message; mode: 4.
[D 13:30:21.537946] tcp_do_work_recv: tag: 5
[D 13:30:21.537953] BMI_testcontext completing: 6376064
[D 13:30:21.537961] sm control op 1
[D 13:30:21.537967] msgpairarray_complete: sm 0x616aa0 status_user_tag 0
msgarray_count 1
[D 13:30:21.537985] msgpairarray: all operations complete
[D 13:30:21.537991] (0x616aa0) msgpairarray state: completion_fn
[D 13:30:21.537998] msgpairarray_completion_fn: sm 0x616aa0 msgpair 0 marked
complete
[D 13:30:21.538004] remove state: object_remove_setup_msgpair
[D 13:30:21.538011] (0x616aa0) msgpairarray state: init (1 msgpair(s))
[D 13:30:21.538017] msgpairarray_post: sm 0x616aa0 2 total message(s) with 2
incomplete
[D 13:30:21.538025] msgpairarray_post: sm 0x616aa0 msgpair 0: posting recv
[D 13:30:21.538031] BMI_post_recv: addr: 6374272, offset: 0x614ca0, size: 16,
tag: 6
[D 13:30:21.538042] msgpairarray_post: sm 0x616aa0 msgpair 0: posting send
[D 13:30:21.538049] BMI_post_sendunexpected_list: addr: 6374272, count: 1,
total_size: 36, tag: 6
[D 13:30:21.538055] element 0: offset: 0x6177a0, size: 36
[D 13:30:21.538065] BMI_tcp_post_send_generic: Sent: 36 bytes of data.
[D 13:30:21.539263] tcp_do_work_recv: Reading header for new op.
[D 13:30:21.539270] tcp_do_work_recv: Received new message; mode: 4.
[D 13:30:21.539276] tcp_do_work_recv: tag: 6
[D 13:30:21.539283] BMI_testcontext completing: 6376320
[D 13:30:21.539290] sm control op 1
[D 13:30:21.539296] msgpairarray_complete: sm 0x616aa0 status_user_tag 0
msgarray_count 1
[D 13:30:21.539301] msgpairarray: all operations complete
[D 13:30:21.539307] (0x616aa0) msgpairarray state: completion_fn
[D 13:30:21.539313] msgpairarray_completion_fn: sm 0x616aa0 msgpair 0 marked
complete
[D 13:30:21.539320] remove state: helper cleanup
[D 13:30:21.539326] acache: invalidate(): H=2999990
[D 13:30:21.539355] remove_check_error_code got Success (0)
[D 13:30:21.539362] remove state: cleanup
[D 13:30:21.539368] ncache: invalidate(): entry=a
[D 13:30:21.539374] client_state_machine_terminate smcb 0x616aa0
[D 13:30:21.539379] add smcb 0x616aa0 to completion list
[D 13:30:21.539385] PINT_sys_release: id 11
[D 13:30:21.539394] PVFS_sys_ref_lookup entered
[D 13:30:21.539400] PVFS_isys_ref_lookup entered
[D 13:30:21.539407] client_op_state_get_machine 11
[D 13:30:21.539414] initialize_context called
[D 13:30:21.539420] original pathname is: 1/2/3
[D 13:30:21.539426] cur_seg_name[0]: 1
[D 13:30:21.539431] pathname is: 1
[D 13:30:21.539437] *seg_remaining is: 1/2/3
[D 13:30:21.539442] cur_seg_name[1]: 2
[D 13:30:21.539448] pathname is: 1/2
[D 13:30:21.539453] *seg_remaining is: 3
[D 13:30:21.539459] cur_seg_name[2]: 3
[D 13:30:21.539464] pathname is: 1/2/3
[D 13:30:21.539470] lookup got: 1/2/3 (parent 2000000)
[D 13:30:21.539476] PINT_client_state_machine_post smcb 0x616aa0, op:
PVFS_SYS_LOOKUP
[D 13:30:21.539482] lookup state: lookup_init
[D 13:30:21.539487] ncache: get_cached_entry(): [1/2/3]
[D 13:30:21.539492] ncache: miss: name=[1/2/3]
[D 13:30:21.539498] lookup state: lookup_segment_lookup_setup_msgpair
[D 13:30:21.539504] Looking up segment 1/2/3 under handle 2000000
[D 13:30:21.539511] lookup_ncache state: lookup
[D 13:30:21.539516] lookup_ncache state: lookup_ncache_lookup on segment [1]
[D 13:30:21.539522] ncache: get_cached_entry(): [1]
[D 13:30:21.539527] ncache: status=0, entry_status=0
[D 13:30:21.539532] ncache: copying out ref.
[D 13:30:21.539537] *** ncache hit on 1/2/3 (2999996|42)!
[D 13:30:21.539543] lookup_segment_lookup_comp_fn
[D 13:30:21.539548] - Resolved 1 segments
[D 13:30:21.539554] lookup state: lookup_segment_verify_attr_present
[D 13:30:21.539559] -- NO attrs for 1
[D 13:30:21.539564] getattr_acache_lookup: handle 2999996 fsid 42
[D 13:30:21.539570] acache: get_cached_entry(): H=2999996
[D 13:30:21.539575] acache: miss: H=2999996
[D 13:30:21.539581] acache: clean acache miss: [2999996]
[D 13:30:21.539586] (0x616f80) getattr_object_getattr_setup_msgpair
[D 13:30:21.539593] (0x616aa0) msgpairarray state: init (1 msgpair(s))
[D 13:30:21.539599] msgpairarray_post: sm 0x616aa0 2 total message(s) with 2
incomplete
[D 13:30:21.539607] msgpairarray_post: sm 0x616aa0 msgpair 0: posting recv
[D 13:30:21.539614] BMI_post_recv: addr: 6374272, offset: 0x61a2b0, size: 9280,
tag: 7
[D 13:30:21.539625] msgpairarray_post: sm 0x616aa0 msgpair 0: posting send
[D 13:30:21.539644] BMI_post_sendunexpected_list: addr: 6374272, count: 1,
total_size: 40, tag: 7
[D 13:30:21.539651] element 0: offset: 0x618ee0, size: 40
[D 13:30:21.539661] BMI_tcp_post_send_generic: Sent: 40 bytes of data.
[D 13:30:21.539668] Posted PVFS_SYS_LOOKUP (20) (waiting for test)(-1073741839)
[D 13:30:21.539773] tcp_do_work_recv: Reading header for new op.
[D 13:30:21.539781] tcp_do_work_recv: Received new message; mode: 4.
[D 13:30:21.539786] tcp_do_work_recv: tag: 7
[D 13:30:21.539793] BMI_testcontext completing: 6374336
[D 13:30:21.539801] sm control op 11
[D 13:30:21.539807] msgpairarray_complete: sm 0x616aa0 status_user_tag 0
msgarray_count 1
[D 13:30:21.539812] msgpairarray: all operations complete
[D 13:30:21.539818] (0x616aa0) msgpairarray state: completion_fn
[D 13:30:21.539824] getattr_object_getattr_comp_fn called
[D 13:30:21.539829] getattr comp_fn [0x616fb8] dfile_count = 0 dist_name_len =
0 dist_params_len = 0
[D 13:30:21.539836] msgpairarray_completion_fn: sm 0x616aa0 msgpair 0 marked
complete
[D 13:30:21.539842] acache: update(): H=2999996
[D 13:30:21.539848] acache: update(): attr_status=0, size_status=-1073741858
[D 13:30:21.539855] acache: update(): return=0
[D 13:30:21.539860] trying to add object reference to acache
[D 13:30:21.539866] (0x616f80) getattr state: getattr_cleanup
[D 13:30:21.539871] lookup state: lookup_segment_check_attr_type
[D 13:30:21.539877] lookup state: lookup_context_check_completion
[D 13:30:21.539883] lookup state: lookup_segment_lookup_setup_msgpair
[D 13:30:21.539888] Looking up segment 3 under handle 2999996
[D 13:30:21.539895] lookup_ncache state: lookup
[D 13:30:21.539901] lookup_ncache state: lookup_ncache_lookup on segment [3]
[D 13:30:21.539906] ncache: get_cached_entry(): [3]
[D 13:30:21.539912] ncache: miss: name=[3]
[D 13:30:21.539917] *** ncache clean miss on 3.
[D 13:30:21.539923] (0x616aa0) msgpairarray state: init (1 msgpair(s))
[D 13:30:21.539928] msgpairarray_post: sm 0x616aa0 2 total message(s) with 2
incomplete
[D 13:30:21.539937] msgpairarray_post: sm 0x616aa0 msgpair 0: posting recv
[D 13:30:21.539943] BMI_post_recv: addr: 6374272, offset: 0x61a2b0, size: 8224,
tag: 8
[D 13:30:21.539954] msgpairarray_post: sm 0x616aa0 msgpair 0: posting send
[D 13:30:21.539961] BMI_post_sendunexpected_list: addr: 6374272, count: 1,
total_size: 52, tag: 8
[D 13:30:21.539967] element 0: offset: 0x6143c0, size: 52
[D 13:30:21.539977] BMI_tcp_post_send_generic: Sent: 52 bytes of data.
[D 13:30:21.540099] tcp_do_work_recv: Reading header for new op.
[D 13:30:21.540107] tcp_do_work_recv: Received new message; mode: 4.
[D 13:30:21.540112] tcp_do_work_recv: tag: 8
[D 13:30:21.540120] BMI_testcontext completing: 6374880
[D 13:30:21.540127] sm control op 11
[D 13:30:21.540132] msgpairarray_complete: sm 0x616aa0 status_user_tag 0
msgarray_count 1
[D 13:30:21.540138] msgpairarray: all operations complete
[D 13:30:21.540144] (0x616aa0) msgpairarray state: completion_fn
[D 13:30:21.540149] lookup_segment_lookup_comp_fn
[D 13:30:21.540155] msgpairarray_completion_fn: sm 0x616aa0 msgpair 0 marked
complete
[D 13:30:21.540162] lookup state: lookup_segment_lookup_failure
[D 13:30:21.540167] lookup state: lookup_cleanup
[D 13:30:21.540173] Freeing segment 1
[D 13:30:21.540178] Freeing remaining segment 1/2/3
[D 13:30:21.540183] Freeing segment 2
[D 13:30:21.540188] Freeing remaining segment 3
[D 13:30:21.540193] Freeing segment 3
[D 13:30:21.540200] All contexts finalized
[D 13:30:21.540206] Lookup failed to resolve 1/2/3: No such file or directory
[D 13:30:21.540212] client_state_machine_terminate smcb 0x616aa0
[D 13:30:21.540217] add smcb 0x616aa0 to completion list
[D 13:30:21.540223] PINT_sys_release: id 20
PVFS_sys_lookup: No such file or directory (error class: 0)
[D 13:30:21.540320] BMI_tcp_finalize: TCP/IP module finalized.
And fs.conf. Root handle really is 2e7 with fsid 42.
<Defaults>
UnexpectedRequests 50
EventLogging none
LogStamp usec
BMIModules bmi_tcp
FlowModules flowproto_multiqueue
PerfUpdateInterval 1000
ServerJobBMITimeoutSecs 30
ServerJobFlowTimeoutSecs 30
ClientJobBMITimeoutSecs 300
ClientJobFlowTimeoutSecs 300
ClientRetryLimit 5
ClientRetryDelayMilliSecs 2000
StorageSpace /tmp/pbstmp.4361/storage
LogFile /tmp/pbstmp.4361/pvfs2.log
</Defaults>
<Aliases>
Alias ib29 tcp://ib29:3334
</Aliases>
<Filesystem>
Name pvfs2-fs
ID 42
<DataHandleRanges>
Range ib29 1000000-1999999
</DataHandleRanges>
<MetaHandleRanges>
Range ib29 2000000-2999999
</MetaHandleRanges>
RootHandle 2000000
<StorageHints>
TroveSyncMeta no
TroveSyncData no
ImmediateCompletion yes
CoalescingHighWatermark infinity
CoalescingLowWatermark 1
TroveMethod dbpf
</StorageHints>
FlowBufferSizeBytes 16777216
</Filesystem>
_______________________________________________
Pvfs2-developers mailing list
[email protected]
http://www.beowulf-underground.org/mailman/listinfo/pvfs2-developers
