Hey Pete, I don't have a solution for you, but I included some comments that should clear up a couple of things.
Bart. On Dec 17, 2007 11:41 AM, Pete Wyckoff <[EMAIL PROTECTED]> wrote: > 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. > I think there may be an error in the debug message that tells what was successfully found in the cache. The lookup-ncache.sm 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. > > 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, > 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. > then tries to look up segment "3" in /1, which won't be there. 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. > > 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 >
_______________________________________________ Pvfs2-developers mailing list [email protected] http://www.beowulf-underground.org/mailman/listinfo/pvfs2-developers
