[Pvfs2-developers] server flow post
Scott Atchley
atchley at myri.com
Fri Jan 12 09:02:22 EST 2007
On Jan 12, 2007, at 8:09 AM, Scott Atchley wrote:
> On Jan 11, 2007, at 5:43 PM, Sam Lang wrote:
>
>> In any case, Scott it might be worth it to try this patch and see
>> if we're able to post operations for expected messages before
>> they're received.
>>
>> -sam
>
> The server aborts with:
>
> [D 08:08:18.429878] PVFS2 Server version
> 2.6.1pre1-2007-01-11-200834 starting.
> pvfs2-server: src/server/io.sm:357: io_check_write_completion:
> Assertion `s_op->u.io.flow_done || s_op->u.io.positive_ack_done'
> failed.
>
> Scott
The verbose output of the entire pvfs2-cp up to the abort:
[D 01/12 09:01] PINT_decode
[D 01/12 09:01] lebf_decode_req
[D 01/12 09:01] (0x81934a8) getconfig (prelude sm) state: req_sched
[A 01/12 09:01] atchley.softies at mx://fog34:0:0 H=0 S=0x81934a8:
getconfig: request
[A 01/12 09:01] atchley.softies at mx://fog34:0:0 H=0 S=0x81934a8:
getconfig: start
[D 01/12 09:01] (0x81934a8) getconfig (prelude sm) state:
getattr_if_needed
[D 01/12 09:01] PVFS operation "getconfig" got attr mask 127
(attr_uid_valid? yes, attr_owner = 0, credentials_uid = 8175)
(attr_gid_valid? yes, attr_group = 0, credentials.gid = 1001)
[D 01/12 09:01] Final permission check for "getconfig" set error code
to 0
[D 01/12 09:01] (0x81934a8) getconfig (prelude sm) state: perm_check
(status = 0)
[D 01/12 09:01] (0x81934a8) getconfig (FR sm) state: release:
(error_code = 0)
[D 01/12 09:01] (0x81934a8) getconfig (FR sm) state: send_resp
(status = 0)
[D 01/12 09:01] PINT_encode
[D 01/12 09:01] encode_common
[D 01/12 09:01] lebf_encode_resp
[D 01/12 09:01] BMI_post_send_list: addr: 178, count: 1, total_size:
880, tag: 1
[D 01/12 09:01] element 0: offset: 0xb58b4008, size: 880
[D 01/12 09:01] (0x81934a8) getconfig (FR sm) state: cleanup
[A 01/12 09:01] atchley.softies at mx://fog34:0:0 H=0 S=0x81934a8:
getconfig: finish (Success)
[D 01/12 09:01] PINT_encode_release
[D 01/12 09:01] lebf_encode_rel
[D 01/12 09:01] PINT_decode_release
[D 01/12 09:01] lebf_decode_rel
[D 01/12 09:01] PINT_decode
[D 01/12 09:01] lebf_decode_req
[D 01/12 09:01] (0x81944f0) lookup_path (prelude sm) state: req_sched
[A 01/12 09:01] atchley.softies at mx://fog34:0:0 H=1048576 S=0x81944f0:
lookup_path: request
[D 01/12 09:01] REQ SCHED POSTING, handle: 1048576, queue_element:
0xb3e02a98
[D 01/12 09:01] REQ SCHED SCHEDULING, handle: 1048576, queue_element:
0xb3e02a98
[A 01/12 09:01] atchley.softies at mx://fog34:0:0 H=1048576 S=0x81944f0:
lookup_path: start
[D 01/12 09:01] (0x81944f0) lookup_path (prelude sm) state:
getattr_if_needed
[D 01/12 09:01] About to retrieve attributes for handle 1048576
[D 01/12 09:01] dspace_getattr fast path attr cache hit on 1048576
(dfile_count=0 | dist_size=0 | data_size=0)
[D 01/12 09:01] PVFS operation "lookup_path" got attr mask 127
(attr_uid_valid? yes, attr_owner = 8175, credentials_uid =
8175)
(attr_gid_valid? yes, attr_group = 1001, credentials.gid =
1001)
[D 01/12 09:01] Final permission check for "lookup_path" set error
code to 0
[D 01/12 09:01] (0x81944f0) lookup_path (prelude sm) state:
perm_check (status = 0)
[D 01/12 09:01] dspace_getattr fast path attr cache hit on 1048576
(dfile_count=0 | dist_size=0 | data_size=0)
[D 01/12 09:01] attrs = (owner = 8175, group = 1001, perms = 777,
type = 4)
[D 01/12 09:01] - check_mode called ---
(uid=8175,gid=1001,access_type=1)
[D 01/12 09:01] - object attributes --- (uid=8175,gid=1001,mode=511)
[D 01/12 09:01] - checking if uid (8175) is root ...
[D 01/12 09:01] - no
[D 01/12 09:01] - checking if owner (8175) matches uid (8175)...
[D 01/12 09:01] - yes
[D 01/12 09:01] - checking if permissions (511) allows access type
(1) for user...
[D 01/12 09:01] - yes
[D 01/12 09:01] object is a directory; will be looking for handle
for segment "test" in a bit
[D 01/12 09:01] reading dirent handle value from handle 1048576
[D 01/12 09:01] *** Trove KeyVal Read of de
[D 01/12 09:01] dbpf_cache_elem_lookup: cache elem matching 1048576
returned (num_elems=1)
[D 01/12 09:01] op_queue add: 0xb3e09e30
[D 01/12 09:01] [DBPF THREAD]: [KEYVAL -1]: -13
[D 01/12 09:01] [DBPF THREAD]: STARTING TROVE SERVICE ROUTINE
(KEYVAL_READ)
[D 01/12 09:01] dbpf_cache_elem_lookup: cache elem matching 1048576
returned (num_elems=1)
[D 01/12 09:01] ** CANNOT cache data retrieved (key is de)
[D 01/12 09:01] [DBPF THREAD]: FINISHED TROVE SERVICE ROUTINE
(KEYVAL_READ) (ret: 1)
[D 01/12 09:01] op_queue add: 0xb3e09e30
[D 01/12 09:01] reading from dirent handle = 4, segment = test (len=4)
[D 01/12 09:01] *** Trove KeyVal Read of test
[D 01/12 09:01] op_queue add: 0xb3e09e30
[D 01/12 09:01] [DBPF THREAD]: [KEYVAL -1]: -14
[D 01/12 09:01] [DBPF THREAD]: STARTING TROVE SERVICE ROUTINE
(KEYVAL_READ)
[D 01/12 09:01] warning: keyval read error on handle 4 and key= test
(DB_NOTFOUND: No matching key/data pair found)
[D 01/12 09:01] [DBPF THREAD]: FINISHED TROVE SERVICE ROUTINE
(KEYVAL_READ) (ret: -1073742082)
[D 01/12 09:01] op_queue add: 0xb3e09e30
[D 01/12 09:01] sending 'error' response with 0 handle(s) and 0 attr
(s)
[A 01/12 09:01] atchley.softies at mx://fog34:0:0 H=1048576 S=0x81944f0:
lookup_path: path: test, lookup failed
[D 01/12 09:01] (0x81944f0) lookup_path (FR sm) state: release:
(error_code = -1073742082)
[D 01/12 09:01] REQ SCHED RELEASING, handle: 1048576, queue_element:
0xb3e02a98
[D 01/12 09:01] (0x81944f0) lookup_path (FR sm) state: send_resp
(status = -1073741826)
[D 01/12 09:01] PINT_encode
[D 01/12 09:01] encode_common
[D 01/12 09:01] lebf_encode_resp
[D 01/12 09:01] BMI_post_send_list: addr: 178, count: 1, total_size:
32, tag: 2
[D 01/12 09:01] element 0: offset: 0xb58b4008, size: 32
[D 01/12 09:01] (0x81944f0) lookup_path (FR sm) state: cleanup
[A 01/12 09:01] atchley.softies at mx://fog34:0:0 H=1048576 S=0x81944f0:
lookup_path: finish (No such file or directory)
[D 01/12 09:01] PINT_encode_release
[D 01/12 09:01] lebf_encode_rel
[D 01/12 09:01] PINT_decode_release
[D 01/12 09:01] lebf_decode_rel
[D 01/12 09:01] PINT_decode
[D 01/12 09:01] lebf_decode_req
[D 01/12 09:01] (0x8195538) getattr (prelude sm) state: req_sched
[A 01/12 09:01] atchley.softies at mx://fog34:0:0 H=1048576 S=0x8195538:
getattr: request
[D 01/12 09:01] REQ SCHED POSTING, handle: 1048576, queue_element:
0xb3e02ba0
[D 01/12 09:01] REQ SCHED SCHEDULING, handle: 1048576, queue_element:
0xb3e02ba0
[A 01/12 09:01] atchley.softies at mx://fog34:0:0 H=1048576 S=0x8195538:
getattr: start
[D 01/12 09:01] (0x8195538) getattr (prelude sm) state:
getattr_if_needed
[D 01/12 09:01] About to retrieve attributes for handle 1048576
[D 01/12 09:01] dspace_getattr fast path attr cache hit on 1048576
(dfile_count=0 | dist_size=0 | data_size=0)
[D 01/12 09:01] PVFS operation "getattr" got attr mask 127
(attr_uid_valid? yes, attr_owner = 8175, credentials_uid =
8175)
(attr_gid_valid? yes, attr_group = 1001, credentials.gid =
1001)
[D 01/12 09:01] Final permission check for "getattr" set error code to 0
[D 01/12 09:01] (0x8195538) getattr (prelude sm) state: perm_check
(status = 0)
[D 01/12 09:01] No version found! Using mtime 1168610456
[A 01/12 09:01] atchley.softies at mx://fog34:0:0 H=1048576 S=0x8195538:
getattr: type: directory
[D 01/12 09:01] getattr: dirent_count not needed.
[D 01/12 09:01] getattr: dfile_count needed.
[D 01/12 09:01] *** Trove KeyVal Read of de
[D 01/12 09:01] dbpf_cache_elem_lookup: cache elem matching 1048576
returned (num_elems=1)
[D 01/12 09:01] op_queue add: 0xb3e09d70
[D 01/12 09:01] [DBPF THREAD]: [KEYVAL -1]: -15
[D 01/12 09:01] [DBPF THREAD]: STARTING TROVE SERVICE ROUTINE
(KEYVAL_READ)
[D 01/12 09:01] dbpf_cache_elem_lookup: cache elem matching 1048576
returned (num_elems=1)
[D 01/12 09:01] ** CANNOT cache data retrieved (key is de)
[D 01/12 09:01] [DBPF THREAD]: FINISHED TROVE SERVICE ROUTINE
(KEYVAL_READ) (ret: 1)
[D 01/12 09:01] op_queue add: 0xb3e09d70
[D 01/12 09:01] trying to getxattr of
user.pvfs2.dist_name,user.pvfs2.dist_params,user.pvfs2.num_dfiles of
dir handle (coll_id = 1318064247, handle = 1048576
[D 01/12 09:01] op_queue add: 0xb3e0c2d0
[D 01/12 09:01] [DBPF THREAD]: [KEYVAL -1]: -16
[D 01/12 09:01] [DBPF THREAD]: STARTING TROVE SERVICE ROUTINE
(KEYVAL_READ_LIST)
[D 01/12 09:01] keyval get user.pvfs2.dist_name failed with error
DB_NOTFOUND: No matching key/data pair found
[D 01/12 09:01] keyval get user.pvfs2.dist_params failed with error
DB_NOTFOUND: No matching key/data pair found
[D 01/12 09:01] keyval get user.pvfs2.num_dfiles failed with error
DB_NOTFOUND: No matching key/data pair found
[D 01/12 09:01] [DBPF THREAD]: FINISHED TROVE SERVICE ROUTINE
(KEYVAL_READ_LIST) (ret: -1073742082)
[D 01/12 09:01] op_queue add: 0xb3e0c2d0
[D 01/12 09:01] getattr: job status code = -1073742082
[D 01/12 09:01] getattr: dir hint dfile_count: 0
[D 01/12 09:01] - RETURNING retrieved attrs: [owner = 8175, group = 1001
perms = 777, type = 4, atime = 1168610456, mtime = 1168610456
ctime = 1168610456, dist_size = 0]
[D 01/12 09:01] server returning dirent_count = 0 dfile_count = 0
dist_name_len = 0 dist_params_len = 0
[D 01/12 09:01] @ End DIRECTORY attributes: sending status 0 (error = 0)
[D 01/12 09:01] (0x8195538) getattr (FR sm) state: release:
(error_code = 0)
[D 01/12 09:01] REQ SCHED RELEASING, handle: 1048576, queue_element:
0xb3e02ba0
[D 01/12 09:01] (0x8195538) getattr (FR sm) state: send_resp (status
= 0)
[D 01/12 09:01] PINT_encode
[D 01/12 09:01] encode_common
[D 01/12 09:01] lebf_encode_resp
[D 01/12 09:01] BMI_post_send_list: addr: 178, count: 1, total_size:
108, tag: 3
[D 01/12 09:01] element 0: offset: 0xb58b4008, size: 108
[D 01/12 09:01] (0x8195538) getattr (FR sm) state: cleanup
[A 01/12 09:01] atchley.softies at mx://fog34:0:0 H=1048576 S=0x8195538:
getattr: finish (Success)
[D 01/12 09:01] PINT_encode_release
[D 01/12 09:01] lebf_encode_rel
[D 01/12 09:01] PINT_decode_release
[D 01/12 09:01] lebf_decode_rel
[D 01/12 09:01] PINT_decode
[D 01/12 09:01] lebf_decode_req
[D 01/12 09:01] (0x8196580) create (prelude sm) state: req_sched
[A 01/12 09:01] atchley.softies at mx://fog34:0:0 H=0 S=0x8196580:
create: request
[A 01/12 09:01] atchley.softies at mx://fog34:0:0 H=0 S=0x8196580:
create: start
[D 01/12 09:01] (0x8196580) create (prelude sm) state: getattr_if_needed
[D 01/12 09:01] PVFS operation "create" got attr mask 127
(attr_uid_valid? yes, attr_owner = 0, credentials_uid = 8175)
(attr_gid_valid? yes, attr_group = 0, credentials.gid = 1001)
[D 01/12 09:01] Final permission check for "create" set error code to 0
[D 01/12 09:01] (0x8196580) create (prelude sm) state: perm_check
(status = 0)
[D 01/12 09:01] op_queue add: 0xb3e09e30
[D 01/12 09:01] [SYNC_COALESCE]: enqueue called
[D 01/12 09:01] [SYNC_COALESCE]: enqueue 1 counter sync:1 non_sync:0
[D 01/12 09:01] [SYNC_COALESCE]: dequeue called
[D 01/12 09:01] [SYNC_COALESCE]: dequeue 1 counter sync:0 non_sync:0
[D 01/12 09:01] [DBPF THREAD]: STARTING TROVE SERVICE ROUTINE
(DSPACE_CREATE)
[D 01/12 09:01] [1 extents] -- new_handle is 1048578 (cur_extent is 4
- 2147483650)
[D 01/12 09:01] dbpf_attr_cache_insert: inserting 1048578 (b_size is 0)
[D 01/12 09:01] [DBPF THREAD]: FINISHED TROVE SERVICE ROUTINE
(DSPACE_CREATE) (ret: 1)
[D 01/12 09:01] [SYNC_COALESCE]: sync_coalesce called, handle: 0, cid: 0
[D 01/12 09:01] [SYNC_COALESCE]: sync_context: 0x80ef060
[D 01/12 09:01] [SYNC_COALESCE]: sync context type is DSPACE
[D 01/12 09:01] [SYNC_COALESCE]: high or low watermark reached:
coalesced: 0
queued: 0
[D 01/12 09:01] [SYNC_COALESCE]: syncing now!
[D 01/12 09:01] [SYNC_COALESCE]: coalesce 1 sync start in
coalesce_queue:0 pending:0
[D 01/12 09:01] [SYNC_COALESCE]: coalesce 1 sync stop
[D 01/12 09:01] [SYNC_COALESCE]: moving op 0xb3e09e30 with handle: 0
to completion queue
[D 01/12 09:01] op_queue add: 0xb3e09e30
[D 01/12 09:01] Handle created: 1048578
[A 01/12 09:01] atchley.softies at mx://fog34:0:0 H=0 S=0x8196580:
create: new handle: 1048578, type metafile.
[D 01/12 09:01] (0x8196580) create (FR sm) state: release:
(error_code = 0)
[D 01/12 09:01] (0x8196580) create (FR sm) state: send_resp (status = 0)
[D 01/12 09:01] PINT_encode
[D 01/12 09:01] encode_common
[D 01/12 09:01] lebf_encode_resp
[D 01/12 09:01] BMI_post_send_list: addr: 178, count: 1, total_size:
24, tag: 4
[D 01/12 09:01] element 0: offset: 0xb58b4008, size: 24
[D 01/12 09:01] (0x8196580) create (FR sm) state: cleanup
[A 01/12 09:01] atchley.softies at mx://fog34:0:0 H=0 S=0x8196580:
create: finish (Success)
[D 01/12 09:01] PINT_encode_release
[D 01/12 09:01] lebf_encode_rel
[D 01/12 09:01] PINT_decode_release
[D 01/12 09:01] lebf_decode_rel
[D 01/12 09:01] PINT_decode
[D 01/12 09:01] lebf_decode_req
[D 01/12 09:01] (0x81975c8) create (prelude sm) state: req_sched
[A 01/12 09:01] atchley.softies at mx://fog34:0:0 H=0 S=0x81975c8:
create: request
[A 01/12 09:01] atchley.softies at mx://fog34:0:0 H=0 S=0x81975c8:
create: start
[D 01/12 09:01] (0x81975c8) create (prelude sm) state: getattr_if_needed
[D 01/12 09:01] PVFS operation "create" got attr mask 127
(attr_uid_valid? yes, attr_owner = 0, credentials_uid = 8175)
(attr_gid_valid? yes, attr_group = 0, credentials.gid = 1001)
[D 01/12 09:01] Final permission check for "create" set error code to 0
[D 01/12 09:01] (0x81975c8) create (prelude sm) state: perm_check
(status = 0)
[D 01/12 09:01] op_queue add: 0xb3e09e30
[D 01/12 09:01] [SYNC_COALESCE]: enqueue called
[D 01/12 09:01] [SYNC_COALESCE]: enqueue 1 counter sync:1 non_sync:0
[D 01/12 09:01] [SYNC_COALESCE]: dequeue called
[D 01/12 09:01] [SYNC_COALESCE]: dequeue 1 counter sync:0 non_sync:0
[D 01/12 09:01] [DBPF THREAD]: STARTING TROVE SERVICE ROUTINE
(DSPACE_CREATE)
[D 01/12 09:01] [1 extents] -- new_handle is 4294967291 (cur_extent
is 2147483651 - 4294967297)
[D 01/12 09:01] dbpf_attr_cache_insert: inserting 4294967291 (b_size
is 0)
[D 01/12 09:01] [DBPF THREAD]: FINISHED TROVE SERVICE ROUTINE
(DSPACE_CREATE) (ret: 1)
[D 01/12 09:01] [SYNC_COALESCE]: sync_coalesce called, handle: 0, cid: 0
[D 01/12 09:01] [SYNC_COALESCE]: sync_context: 0x80ef060
[D 01/12 09:01] [SYNC_COALESCE]: sync context type is DSPACE
[D 01/12 09:01] [SYNC_COALESCE]: high or low watermark reached:
coalesced: 0
queued: 0
[D 01/12 09:01] [SYNC_COALESCE]: syncing now!
[D 01/12 09:01] [SYNC_COALESCE]: coalesce 1 sync start in
coalesce_queue:0 pending:0
[D 01/12 09:01] [SYNC_COALESCE]: coalesce 1 sync stop
[D 01/12 09:01] [SYNC_COALESCE]: moving op 0xb3e09e30 with handle: 0
to completion queue
[D 01/12 09:01] op_queue add: 0xb3e09e30
[D 01/12 09:01] Handle created: 4294967291
[A 01/12 09:01] atchley.softies at mx://fog34:0:0 H=0 S=0x81975c8:
create: new handle: 4294967291, type datafile.
[D 01/12 09:01] (0x81975c8) create (FR sm) state: release:
(error_code = 0)
[D 01/12 09:01] (0x81975c8) create (FR sm) state: send_resp (status = 0)
[D 01/12 09:01] PINT_encode
[D 01/12 09:01] encode_common
[D 01/12 09:01] lebf_encode_resp
[D 01/12 09:01] BMI_post_send_list: addr: 178, count: 1, total_size:
24, tag: 5
[D 01/12 09:01] element 0: offset: 0xb58b4008, size: 24
[D 01/12 09:01] (0x81975c8) create (FR sm) state: cleanup
[A 01/12 09:01] atchley.softies at mx://fog34:0:0 H=0 S=0x81975c8:
create: finish (Success)
[D 01/12 09:01] PINT_encode_release
[D 01/12 09:01] lebf_encode_rel
[D 01/12 09:01] PINT_decode_release
[D 01/12 09:01] lebf_decode_rel
[D 01/12 09:01] PINT_decode
[D 01/12 09:01] lebf_decode_req
[D 01/12 09:01] (0x8198610) setattr (prelude sm) state: req_sched
[A 01/12 09:01] atchley.softies at mx://fog34:0:0 H=1048578 S=0x8198610:
setattr: request
[D 01/12 09:01] REQ SCHED POSTING, handle: 1048578, queue_element:
0xb3e02be8
[D 01/12 09:01] REQ SCHED SCHEDULING, handle: 1048578, queue_element:
0xb3e02be8
[A 01/12 09:01] atchley.softies at mx://fog34:0:0 H=1048578 S=0x8198610:
setattr: start
[D 01/12 09:01] (0x8198610) setattr (prelude sm) state:
getattr_if_needed
[D 01/12 09:01] About to retrieve attributes for handle 1048578
[D 01/12 09:01] dspace_getattr fast path attr cache hit on 1048578
(dfile_count=0 | dist_size=0 | data_size=0)
[D 01/12 09:01] PVFS operation "setattr" got attr mask 127
(attr_uid_valid? yes, attr_owner = 0, credentials_uid = 8175)
(attr_gid_valid? yes, attr_group = 0, credentials.gid = 1001)
[D 01/12 09:01] Final permission check for "setattr" set error code to 0
[D 01/12 09:01] (0x8198610) setattr (prelude sm) state: perm_check
(status = 0)
[D 01/12 09:01] attrs read from dspace:
[owner = 0, group = 0, perms = 0, type = 1]
[D 01/12 09:01] attrs read from request:
[owner = 8175, group = 1001, perms = 644, type = 1]
[D 01/12 09:01] handle 1048578 refers to a metafile
[D 01/12 09:01] *** dspace has dfile count 0 and req has dfile count 1
[D 01/12 09:01] *** dspace has dist size 0 and req has dist size 48
[D 01/12 09:01] *** using dfile_count of 1
[D 01/12 09:01] *** using dist_size of 48
[D 01/12 09:01] request has dfile_count of 1 | dspace has 1
[D 01/12 09:01] metafile has 1 datafiles associated with it
[D 01/12 09:01] writing dh [1048578,1318064247,len 8]
[D 01/12 09:01] op_queue add: 0xb3e09e30
[D 01/12 09:01] [SYNC_COALESCE]: enqueue called
[D 01/12 09:01] [SYNC_COALESCE]: enqueue 0 counter sync:0 non_sync:1
[D 01/12 09:01] [SYNC_COALESCE]: dequeue called
[D 01/12 09:01] [SYNC_COALESCE]: dequeue 0 counter sync:0 non_sync:0
[D 01/12 09:01] [DBPF THREAD]: [KEYVAL -1]: -17
[D 01/12 09:01] [DBPF THREAD]: STARTING TROVE SERVICE ROUTINE
(KEYVAL_WRITE)
[D 01/12 09:01] dbpf_keyval_write_op_svc: handle: 1048578, key: dh
[D 01/12 09:01] keyval_db->put(handle= 1048578, key= dh (3)) size=11
[D 01/12 09:01] *** Trove KeyVal Write of dh
[D 01/12 09:01] dbpf_cache_elem_lookup: cache elem matching 1048578
returned (num_elems=3)
[D 01/12 09:01] dbpf_cache_elem_lookup: cache elem matching 1048578
returned (num_elems=3)
[D 01/12 09:01] Setting data 0xb3e02bd8 based on key 1048578 and
key_str dh (data_sz=8)
[D 01/12 09:01] *** cached keyval data written (key is dh)
[D 01/12 09:01] [DBPF THREAD]: FINISHED TROVE SERVICE ROUTINE
(KEYVAL_WRITE) (ret: 1)
[D 01/12 09:01] [SYNC_COALESCE]: sync_coalesce called, handle:
1048578, cid: 0
[D 01/12 09:01] [SYNC_COALESCE]: sync not needed, moving to
completion queue: 1048578
[D 01/12 09:01] op_queue add: 0xb3e09e30
[D 01/12 09:01] metafile distribution size = 48
[D 01/12 09:01] writing md [1048578,1318064247,len 48]
[D 01/12 09:01] op_queue add: 0xb3e0ef58
[D 01/12 09:01] [SYNC_COALESCE]: enqueue called
[D 01/12 09:01] [SYNC_COALESCE]: enqueue 0 counter sync:1 non_sync:0
[D 01/12 09:01] [SYNC_COALESCE]: dequeue called
[D 01/12 09:01] [SYNC_COALESCE]: dequeue 0 counter sync:0 non_sync:0
[D 01/12 09:01] [DBPF THREAD]: [KEYVAL -1]: -18
[D 01/12 09:01] [DBPF THREAD]: STARTING TROVE SERVICE ROUTINE
(KEYVAL_WRITE)
[D 01/12 09:01] dbpf_keyval_write_op_svc: handle: 1048578, key: md
[D 01/12 09:01] keyval_db->put(handle= 1048578, key= md (3)) size=11
[D 01/12 09:01] *** Trove KeyVal Write of md
[D 01/12 09:01] dbpf_cache_elem_lookup: cache elem matching 1048578
returned (num_elems=3)
[D 01/12 09:01] dbpf_cache_elem_lookup: cache elem matching 1048578
returned (num_elems=3)
[D 01/12 09:01] ** CANNOT cache data written (key is md)
[D 01/12 09:01] [DBPF THREAD]: FINISHED TROVE SERVICE ROUTINE
(KEYVAL_WRITE) (ret: 1)
[D 01/12 09:01] [SYNC_COALESCE]: sync_coalesce called, handle:
1048578, cid: 0
[D 01/12 09:01] [SYNC_COALESCE]: sync_context: 0x80eef20
[D 01/12 09:01] [SYNC_COALESCE]: sync context type is KEYVAL
[D 01/12 09:01] [SYNC_COALESCE]: high or low watermark reached:
coalesced: 0
queued: 0
[D 01/12 09:01] [SYNC_COALESCE]: syncing now!
[D 01/12 09:01] [SYNC_COALESCE]: coalesce 0 sync start in
coalesce_queue:0 pending:0
[D 01/12 09:01] [SYNC_COALESCE]: coalesce 0 sync stop
[D 01/12 09:01] [SYNC_COALESCE]: moving op 0xb3e0ef58 with handle:
1048578 to completion queue
[D 01/12 09:01] op_queue add: 0xb3e0ef58
[D 01/12 09:01] request has dfile_count of 1 | dspace has 1
[D 01/12 09:01] writing count of 1 to disk
[D 01/12 09:01] WRITING attrs: [owner = 8175, group = 1001
perms = 644, type = 1, atime = 1168610468, mtime = 0
ctime = 1168610468 | dfile_count = 1 | dist_size = 48]
[D 01/12 09:01] op_queue add: 0xb3e0ef58
[D 01/12 09:01] [SYNC_COALESCE]: enqueue called
[D 01/12 09:01] [SYNC_COALESCE]: enqueue 1 counter sync:1 non_sync:0
[D 01/12 09:01] [SYNC_COALESCE]: dequeue called
[D 01/12 09:01] [SYNC_COALESCE]: dequeue 1 counter sync:0 non_sync:0
[D 01/12 09:01] [DBPF THREAD]: STARTING TROVE SERVICE ROUTINE
(DSPACE_SETATTR)
[D 01/12 09:01] dbpf_cache_elem_lookup: cache elem matching 1048578
returned (num_elems=3)
[D 01/12 09:01] Updating cached attributes for key 1048578
[D 01/12 09:01] [DBPF THREAD]: FINISHED TROVE SERVICE ROUTINE
(DSPACE_SETATTR) (ret: 1)
[D 01/12 09:01] [SYNC_COALESCE]: sync_coalesce called, handle:
1048578, cid: 0
[D 01/12 09:01] [SYNC_COALESCE]: sync_context: 0x80ef060
[D 01/12 09:01] [SYNC_COALESCE]: sync context type is DSPACE
[D 01/12 09:01] [SYNC_COALESCE]: high or low watermark reached:
coalesced: 0
queued: 0
[D 01/12 09:01] [SYNC_COALESCE]: syncing now!
[D 01/12 09:01] [SYNC_COALESCE]: coalesce 1 sync start in
coalesce_queue:0 pending:0
[D 01/12 09:01] [SYNC_COALESCE]: coalesce 1 sync stop
[D 01/12 09:01] [SYNC_COALESCE]: moving op 0xb3e0ef58 with handle:
1048578 to completion queue
[D 01/12 09:01] op_queue add: 0xb3e0ef58
[D 01/12 09:01] (0x8198610) setattr (FR sm) state: release:
(error_code = 0)
[D 01/12 09:01] REQ SCHED RELEASING, handle: 1048578, queue_element:
0xb3e02be8
[D 01/12 09:01] (0x8198610) setattr (FR sm) state: send_resp (status
= 0)
[D 01/12 09:01] PINT_encode
[D 01/12 09:01] encode_common
[D 01/12 09:01] lebf_encode_resp
[D 01/12 09:01] BMI_post_send_list: addr: 178, count: 1, total_size:
16, tag: 6
[D 01/12 09:01] element 0: offset: 0xb58b4008, size: 16
[D 01/12 09:01] (0x8198610) setattr (FR sm) state: cleanup
[A 01/12 09:01] atchley.softies at mx://fog34:0:0 H=1048578 S=0x8198610:
setattr: finish (Success)
[D 01/12 09:01] PINT_encode_release
[D 01/12 09:01] lebf_encode_rel
[D 01/12 09:01] PINT_decode_release
[D 01/12 09:01] lebf_decode_rel
[D 01/12 09:01] PINT_decode
[D 01/12 09:01] lebf_decode_req
[D 01/12 09:01] (0x8199658) crdirent (prelude sm) state: req_sched
[A 01/12 09:01] atchley.softies at mx://fog34:0:0 H=1048576 S=0x8199658:
crdirent: request
[D 01/12 09:01] REQ SCHED POSTING, handle: 1048576, queue_element:
0xb3e02ba0
[D 01/12 09:01] REQ SCHED SCHEDULING, handle: 1048576, queue_element:
0xb3e02ba0
[A 01/12 09:01] atchley.softies at mx://fog34:0:0 H=1048576 S=0x8199658:
crdirent: start
[D 01/12 09:01] (0x8199658) crdirent (prelude sm) state:
getattr_if_needed
[D 01/12 09:01] About to retrieve attributes for handle 1048576
[D 01/12 09:01] dspace_getattr fast path attr cache hit on 1048576
(dfile_count=0 | dist_size=0 | data_size=0)
[D 01/12 09:01] PVFS operation "crdirent" got attr mask 127
(attr_uid_valid? yes, attr_owner = 8175, credentials_uid =
8175)
(attr_gid_valid? yes, attr_group = 1001, credentials.gid =
1001)
[D 01/12 09:01] - check_mode called ---
(uid=8175,gid=1001,access_type=2)
[D 01/12 09:01] - object attributes --- (uid=8175,gid=1001,mode=511)
[D 01/12 09:01] - checking if uid (8175) is root ...
[D 01/12 09:01] - no
[D 01/12 09:01] - checking if owner (8175) matches uid (8175)...
[D 01/12 09:01] - yes
[D 01/12 09:01] - checking if permissions (511) allows access type
(2) for user...
[D 01/12 09:01] - yes
[D 01/12 09:01] - check_mode called ---
(uid=8175,gid=1001,access_type=1)
[D 01/12 09:01] - object attributes --- (uid=8175,gid=1001,mode=511)
[D 01/12 09:01] - checking if uid (8175) is root ...
[D 01/12 09:01] - no
[D 01/12 09:01] - checking if owner (8175) matches uid (8175)...
[D 01/12 09:01] - yes
[D 01/12 09:01] - checking if permissions (511) allows access type
(1) for user...
[D 01/12 09:01] - yes
[D 01/12 09:01] Final permission check for "crdirent" set error code
to 0
[D 01/12 09:01] (0x8199658) crdirent (prelude sm) state: perm_check
(status = 0)
[A 01/12 09:01] atchley.softies at mx://fog34:0:0 H=1048576 S=0x8199658:
crdirent: crdirent entry: test points to 1048578
[D 01/12 09:01] got crdirent for test (with handle 1048578) in 1048576
[D 01/12 09:01] *** Trove KeyVal Read of de
[D 01/12 09:01] dbpf_cache_elem_lookup: cache elem matching 1048576
returned (num_elems=3)
[D 01/12 09:01] op_queue add: 0xb3e09e30
[D 01/12 09:01] [DBPF THREAD]: [KEYVAL -1]: -19
[D 01/12 09:01] [DBPF THREAD]: STARTING TROVE SERVICE ROUTINE
(KEYVAL_READ)
[D 01/12 09:01] dbpf_cache_elem_lookup: cache elem matching 1048576
returned (num_elems=3)
[D 01/12 09:01] ** CANNOT cache data retrieved (key is de)
[D 01/12 09:01] [DBPF THREAD]: FINISHED TROVE SERVICE ROUTINE
(KEYVAL_READ) (ret: 1)
[D 01/12 09:01] op_queue add: 0xb3e09e30
[D 01/12 09:01] writing new directory entry for test (handle =
1048578) to dirdata dspace 4
[D 01/12 09:01] op_queue add: 0xb3e09e30
[D 01/12 09:01] [SYNC_COALESCE]: enqueue called
[D 01/12 09:01] [SYNC_COALESCE]: enqueue 0 counter sync:1 non_sync:0
[D 01/12 09:01] [SYNC_COALESCE]: dequeue called
[D 01/12 09:01] [SYNC_COALESCE]: dequeue 0 counter sync:0 non_sync:0
[D 01/12 09:01] [DBPF THREAD]: [KEYVAL -1]: -20
[D 01/12 09:01] [DBPF THREAD]: STARTING TROVE SERVICE ROUTINE
(KEYVAL_WRITE)
[D 01/12 09:01] dbpf_keyval_write_op_svc: handle: 4, key: test
[D 01/12 09:01] keyval_db->put(handle= 4, key= test (5)) size=13
[D 01/12 09:01] *** Trove KeyVal Write of test
[D 01/12 09:01] [DBPF KEYVAL]: handle_info count increment: handle:
4, value: 1
[D 01/12 09:01] [DBPF THREAD]: FINISHED TROVE SERVICE ROUTINE
(KEYVAL_WRITE) (ret: 1)
[D 01/12 09:01] [SYNC_COALESCE]: sync_coalesce called, handle: 4, cid: 0
[D 01/12 09:01] [SYNC_COALESCE]: sync_context: 0x80eef20
[D 01/12 09:01] [SYNC_COALESCE]: sync context type is KEYVAL
[D 01/12 09:01] [SYNC_COALESCE]: high or low watermark reached:
coalesced: 0
queued: 0
[D 01/12 09:01] [SYNC_COALESCE]: syncing now!
[D 01/12 09:01] [SYNC_COALESCE]: coalesce 0 sync start in
coalesce_queue:0 pending:0
[D 01/12 09:01] [SYNC_COALESCE]: coalesce 0 sync stop
[D 01/12 09:01] [SYNC_COALESCE]: moving op 0xb3e09e30 with handle: 4
to completion queue
[D 01/12 09:01] op_queue add: 0xb3e09e30
[D 01/12 09:01] op_queue add: 0xb3e09e30
[D 01/12 09:01] [SYNC_COALESCE]: enqueue called
[D 01/12 09:01] [SYNC_COALESCE]: enqueue 1 counter sync:1 non_sync:0
[D 01/12 09:01] [SYNC_COALESCE]: dequeue called
[D 01/12 09:01] [SYNC_COALESCE]: dequeue 1 counter sync:0 non_sync:0
[D 01/12 09:01] [DBPF THREAD]: STARTING TROVE SERVICE ROUTINE
(DSPACE_SETATTR)
[D 01/12 09:01] dbpf_cache_elem_lookup: cache elem matching 1048576
returned (num_elems=3)
[D 01/12 09:01] Updating cached attributes for key 1048576
[D 01/12 09:01] [DBPF THREAD]: FINISHED TROVE SERVICE ROUTINE
(DSPACE_SETATTR) (ret: 1)
[D 01/12 09:01] [SYNC_COALESCE]: sync_coalesce called, handle:
1048576, cid: 0
[D 01/12 09:01] [SYNC_COALESCE]: sync_context: 0x80ef060
[D 01/12 09:01] [SYNC_COALESCE]: sync context type is DSPACE
[D 01/12 09:01] [SYNC_COALESCE]: high or low watermark reached:
coalesced: 0
queued: 0
[D 01/12 09:01] [SYNC_COALESCE]: syncing now!
[D 01/12 09:01] [SYNC_COALESCE]: coalesce 1 sync start in
coalesce_queue:0 pending:0
[D 01/12 09:01] [SYNC_COALESCE]: coalesce 1 sync stop
[D 01/12 09:01] [SYNC_COALESCE]: moving op 0xb3e09e30 with handle:
1048576 to completion queue
[D 01/12 09:01] op_queue add: 0xb3e09e30
[D 01/12 09:01] (0x8199658) crdirent (FR sm) state: release:
(error_code = 0)
[D 01/12 09:01] REQ SCHED RELEASING, handle: 1048576, queue_element:
0xb3e02ba0
[D 01/12 09:01] (0x8199658) crdirent (FR sm) state: send_resp (status
= 0)
[D 01/12 09:01] PINT_encode
[D 01/12 09:01] encode_common
[D 01/12 09:01] lebf_encode_resp
[D 01/12 09:01] BMI_post_send_list: addr: 178, count: 1, total_size:
16, tag: 7
[D 01/12 09:01] element 0: offset: 0xb58b4008, size: 16
[D 01/12 09:01] (0x8199658) crdirent (FR sm) state: cleanup
[A 01/12 09:01] atchley.softies at mx://fog34:0:0 H=1048576 S=0x8199658:
crdirent: finish (Success)
[D 01/12 09:01] PINT_encode_release
[D 01/12 09:01] lebf_encode_rel
[D 01/12 09:01] PINT_decode_release
[D 01/12 09:01] lebf_decode_rel
[D 01/12 09:01] PINT_decode
[D 01/12 09:01] lebf_decode_req
[D 01/12 09:01] (0x819a6a0) io (prelude sm) state: req_sched
[A 01/12 09:01] atchley.softies at mx://fog34:0:0 H=4294967291
S=0x819a6a0: io: request
[D 01/12 09:01] REQ SCHED POSTING, handle: 4294967291, queue_element:
0xb3e02930
[D 01/12 09:01] REQ SCHED SCHEDULING, handle: 4294967291,
queue_element: 0xb3e02930
[A 01/12 09:01] atchley.softies at mx://fog34:0:0 H=4294967291
S=0x819a6a0: io: start
[D 01/12 09:01] (0x819a6a0) io (prelude sm) state: getattr_if_needed
[D 01/12 09:01] About to retrieve attributes for handle 4294967291
[D 01/12 09:01] dspace_getattr fast path attr cache hit on 4294967291
(dfile_count=0 | dist_size=0 | data_size=0)
[D 01/12 09:01] PVFS operation "io" got attr mask 127
(attr_uid_valid? yes, attr_owner = 0, credentials_uid = 8175)
(attr_gid_valid? yes, attr_group = 0, credentials.gid = 1001)
[D 01/12 09:01] Final permission check for "io" set error code to 0
[D 01/12 09:01] (0x819a6a0) io (prelude sm) state: perm_check (status
= 0)
[D 01/12 09:01] PINT_encode
[D 01/12 09:01] encode_common
[D 01/12 09:01] lebf_encode_resp
[D 01/12 09:01] BMI_post_send_list: addr: 178, count: 1, total_size:
24, tag: 8
[D 01/12 09:01] element 0: offset: 0xb58b4008, size: 24
[D 01/12 09:01] flow: fsize: 0, server_nr: 0, server_ct: 1
[D 01/12 09:01] file_req_offset: 0, aggregate_size: 52428800,
handle: 4294967291
[D 01/12 09:01] io_start_flow() issuing flow to write data.
[D 01/12 09:01] PINT_New_request_state
[D 01/12 09:01] flowproto posting 0xb3e0ff88
[D 01/12 09:01] flowproto-multiqueue forcing trove_write_callback_fn.
[D 01/12 09:01] flowproto-multiqueue trove_write_callback_fn,
error_code: 0, flow: 0xb3e0ff88.
[D 01/12 09:01]
=========================================================
[D 01/12 09:01] PINT_process_request
[D 01/12 09:01] tiling 52428801 copies
[D 01/12 09:01] Do seq of 0 ne 1 st 1 nb 0 ub 1 lb 0 as 1 co 0
[D 01/12 09:01] lvl 0 el 0 blk 0 by 0
Early expected message length 1048576 tag 8 match 0xe000000100000008
[D 01/12 09:01] to 0 ta 0 fi 52428800
[D 01/12 09:01] basic type or contiguous data
[D 01/12 09:01] Request disp
[D 01/12 09:01] contig_offset = 0 contig_size = 52428801
lvl_flag = 1
[D 01/12 09:01] calling distribute
[D 01/12 09:01] PINT_distribute
[D 01/12 09:01] of 0 sz 52428800 ix 0 sm 64 by 0 bm
1048576 fsz 0 exfl 1
[D 01/12 09:01] begin iteration loff: 0
[D 01/12 09:01] segment exceeds byte limit
[D 01/12 09:01] file being extended
[D 01/12 09:01] process a segment
[D 01/12 09:01] of 0 sz 1048576
[D 01/12 09:01] add a segment 0
[D 01/12 09:01] end iteration
[D 01/12 09:01] done with segments or bytes
[D 01/12 09:01] of 1048576 sz 51380224 sg 1
sm 64 by 1048576 bm 1048576
[D 01/12 09:01] next loff: 1048576 next poff:
1048576
[D 01/12 09:01] return value 1048576
[D 01/12 09:01] finished
[D 01/12 09:01] retval = 1048576
[D 01/12 09:01] exiting distribute returned less than expected
[D 01/12 09:01] done sg 1 sm 64 by 1048576 bm 1048576 ta 0 to
1048576 fo 52428800 eof 0
[D 01/12 09:01]
=========================================================
[D 01/12 09:01] BMI_post_recv: addr: 178, offset: 0xb59b5008, size:
1048576, tag: 8
[D 01/12 09:01] flowproto posted 0xb3e0ff88
[D 01/12 09:01] Job flows in progress (post time): 1
pvfs2-server: src/server/io.sm:357: io_check_write_completion:
Assertion `s_op->u.io.flow_done || s_op->u.io.positive_ack_done' failed.
More information about the Pvfs2-developers
mailing list