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