Pete Wyckoff wrote:
I would like to get the full list involved. Can you make a more
concise trace for them. Do something like the following:
cd /tmp
service pvfs2 start
/usr/local/bin/pvfs2-set-debugmask -m /u/data1 verbose
pvfs2-mkdir /u/data1/foo
/usr/local/bin/pvfs2-set-debugmask -m /u/data1 none
service pvfs2 stop
Hey Pete,
I'm attaching the log generated when running those commands to this email.
Can you also give me:
- the ./configure line you used to build, including any CC= or
CFLAGS= that may have been set in your environment
- gcc --version
- uname -a
- cat /etc/redhat-release (if you have one, or equivalent)
- /lib/libc.so.6 (makes it say its version number, or equivalent)
./configure --enable-redhat24 --disable-nptl-workaround
--with-kernel24=/usr/src/linux-2.4
--with-ib=/usr/local/ibgd/driver/infinihost/
gcc (GCC) 3.2.3 20030502 (Red Hat Linux 3.2.3-54)
Linux scn1 2.4.21-40.ELsmp #1 SMP Thu Feb 2 22:13:55 EST 2006 x86_64
x86_64 x86_64 GNU/Linux
Red Hat Enterprise Linux ES release 3 (Taroon Update 7)
libc-2.3.2.so <- Note that this is a 64-bit version so it *should* be
using the one in /lib64
If you need anything else just let me know.
Thanks again for all of your help with this!
-Lee
No clue what is going on at the server for so long, and so evenly a
multiple of 10ms, but we'll figure it out. All I can guess now is
these 10ms timeout periods in src/io/job/job.c:
do_one_work_cycle_all(10);
and maybe a broken thread scheduler?
-- Pete
--
Lee S. Whatley, Contractor
NAVOCEANO MSRC
Lockheed Martin Space Operations - Stennis Programs
1001 Balch Boulevard
Stennis Space Center, MS 39522
Phone: 228-688-4999 DSN: 828-4999
[D 14:45:52.542961] PVFS2 Server version 1.4.1pre1-2006-05-22-144949 starting.
[D 14:45:52.552961] Passing ib://scn1-ib0:3334 as BMI listen address.
[D 14:45:52.552961] BMI_ib_initialize: init.
[D 14:45:52.572962] BMI_ib_initialize: built pd 5a4e80.
[D 14:45:52.572962] BMI_ib_initialize: max 16256 completion queue entries.
[D 14:45:52.572962] BMI_ib_initialize: asking for 1024 completion queue entries.
[D 14:45:52.572962] BMI_ib_initialize: done.
[D 14:45:52.642963] dbpf_thread_function started
[D 14:45:52.642963] dbpf_thread_initialize: initialized
[D 14:45:52.672964] collection lookup: version is 0.1.2
[D 14:45:52.672964] - set handle re-use timeout to 360 seconds (ret=0)
[D 14:45:52.872968] File system pvfs2-fs1 using handles:
4-2147483650,2147483651-4294967297
[D 14:45:52.872968] Sync on metadata update for pvfs2-fs1: yes
[D 14:45:52.872968] Sync on I/O data update for pvfs2-fs1: no
[D 14:45:52.872968] Storage Init Complete (aio-threaded)
[D 14:45:52.872968] 1 filesystem(s) initialized
[D 14:45:52.872968] Initialization completed successfully.
[D 14:46:00.543141] post_rr: 11.0.0.1:53360 bh 0.
[D 14:46:00.543141] post_rr: 11.0.0.1:53360 bh 1.
[D 14:46:00.543141] post_rr: 11.0.0.1:53360 bh 2.
[D 14:46:00.543141] post_rr: 11.0.0.1:53360 bh 3.
[D 14:46:00.543141] post_rr: 11.0.0.1:53360 bh 4.
[D 14:46:00.543141] post_rr: 11.0.0.1:53360 bh 5.
[D 14:46:00.543141] post_rr: 11.0.0.1:53360 bh 6.
[D 14:46:00.543141] post_rr: 11.0.0.1:53360 bh 7.
[D 14:46:00.543141] post_rr: 11.0.0.1:53360 bh 8.
[D 14:46:00.543141] post_rr: 11.0.0.1:53360 bh 9.
[D 14:46:00.543141] post_rr: 11.0.0.1:53360 bh 10.
[D 14:46:00.543141] post_rr: 11.0.0.1:53360 bh 11.
[D 14:46:00.543141] post_rr: 11.0.0.1:53360 bh 12.
[D 14:46:00.543141] post_rr: 11.0.0.1:53360 bh 13.
[D 14:46:00.543141] post_rr: 11.0.0.1:53360 bh 14.
[D 14:46:00.543141] post_rr: 11.0.0.1:53360 bh 15.
[D 14:46:00.543141] post_rr: 11.0.0.1:53360 bh 16.
[D 14:46:00.543141] post_rr: 11.0.0.1:53360 bh 17.
[D 14:46:00.543141] post_rr: 11.0.0.1:53360 bh 18.
[D 14:46:00.543141] post_rr: 11.0.0.1:53360 bh 19.
[D 14:46:00.543141] ib_tcp_server_check_new_connections: accepted new
connection 11.0.0.1:53360 at server.
[D 14:46:00.543141] check_cq: found something.
[D 14:46:00.543141] check_cq: found len 40 at 11.0.0.1:53360 my bufnum 0 type
MSG_EAGER_SENDUNEXPECTED.
[D 14:46:00.543141] encourage_recv_incoming: incoming msg type
MSG_EAGER_SENDUNEXPECTED.
[D 14:46:00.543141] encourage_recv_incoming: recv eager unexpected my bufnum 0
his bufnum 0 len 40.
[D 14:46:00.543141] encourage_recv_incoming: new rq 0x892e70 now
RQ_EAGER_WAITING_USER_TESTUNEXPECTED.
[D 14:46:00.543141] BMI_ib_testunexpected: found waiting testunexpected.
[D 14:46:00.543141] post_rr: 11.0.0.1:53360 bh 0.
[D 14:46:00.543141] post_sr_ack: 11.0.0.1:53360 his buf 0 wr 0/8191.
[D 14:46:00.543141] (0x8183c0) getconfig (prelude sm) state: req_sched
[D 14:46:00.543141] (0x8183c0) getconfig (prelude sm) state: getattr_if_needed
[D 14:46:00.543141] (0x8183c0) getconfig (prelude sm) state: perm_check (status
= 0)
[D 14:46:00.543141] (0x8183c0) getconfig state: init
[D 14:46:00.543141] (0x8183c0) getconfig (FR sm) state: release: (error_code =
0)
[D 14:46:00.543141] (0x8183c0) getconfig (FR sm) state: send_resp (status = 0)
[D 14:46:00.543141] ib_mem_register: buf 0x892f30 len 32808.
[D 14:46:00.543141] BMI_post_send_list: addr: 65, count: 1, total_size: 1016
[D 14:46:00.543141] element 0: offset: 0x892f30, size: 1016
[D 14:46:00.543141] BMI_ib_post_send_list: listlen 1 tag 1.
[D 14:46:00.543141] generic_post_send: new sq 0x89af60.
[D 14:46:00.543141] encourage_send_waiting_buffer: sq 0x89af60.
[D 14:46:00.543141] post_rr_ack: 11.0.0.1:53360 bh 0.
[D 14:46:00.543141] post_sr: 11.0.0.1:53360 bh 0 len 1032 wr 0/8191.
[D 14:46:00.543141] encourage_send_waiting_buffer: sq 0x89af60 sent EAGER now
SQ_WAITING_EAGER_ACK.
[D 14:46:00.543141] check_cq: found something.
[D 14:46:00.543141] check_cq: ack message 11.0.0.1:53360 my bufnum 0.
[D 14:46:00.543141] check_cq: sq 0x89af60 SQ_WAITING_EAGER_ACK ->
SQ_WAITING_USER_TEST.
[D 14:46:00.543141] test_sq: sq 0x89af60 completed 1016 to 11.0.0.1:53360.
[D 14:46:00.543141] BMI_testcontext completing: 69
[D 14:46:00.543141] (0x8183c0) getconfig (FR sm) state: cleanup
[D 14:46:00.543141] ib_mem_deregister: buf 0x892f30 len 32808 lkey 693b9100
rkey 693b9100.
[D 14:46:00.543141] (0x8183c0) getconfig state: cleanup
[D 14:46:00.543141] check_cq: found something.
[D 14:46:00.543141] check_cq: found len 56 at 11.0.0.1:53360 my bufnum 1 type
MSG_EAGER_SENDUNEXPECTED.
[D 14:46:00.543141] encourage_recv_incoming: incoming msg type
MSG_EAGER_SENDUNEXPECTED.
[D 14:46:00.543141] encourage_recv_incoming: recv eager unexpected my bufnum 1
his bufnum 1 len 56.
[D 14:46:00.543141] encourage_recv_incoming: new rq 0x8183c0 now
RQ_EAGER_WAITING_USER_TESTUNEXPECTED.
[D 14:46:00.543141] BMI_ib_testunexpected: found waiting testunexpected.
[D 14:46:00.543141] post_rr: 11.0.0.1:53360 bh 1.
[D 14:46:00.543141] post_sr_ack: 11.0.0.1:53360 his buf 1 wr 1/8191.
[D 14:46:00.543141] (0x819a00) mgmt_setparam (prelude sm) state: req_sched
[D 14:46:00.543141] (0x819a00) mgmt_setparam (prelude sm) state:
getattr_if_needed
[D 14:46:00.543141] (0x819a00) mgmt_setparam (prelude sm) state: perm_check
(status = 0)
[D 14:46:00.543141] (0x819a00) mgmt_setparam state: work
[D 14:46:00.543141] (0x819a00) mgmt_setparam (FR sm) state: release:
(error_code = 0)
[D 14:46:00.543141] (0x819a00) mgmt_setparam (FR sm) state: send_resp (status =
0)
[D 14:46:00.543141] BMI_post_send_list: addr: 65, count: 1, total_size: 24
[D 14:46:00.543141] element 0: offset: 0x892f10, size: 24
[D 14:46:00.543141] BMI_ib_post_send_list: listlen 1 tag 2.
[D 14:46:00.543141] generic_post_send: new sq 0x8183c0.
[D 14:46:00.543141] encourage_send_waiting_buffer: sq 0x8183c0.
[D 14:46:00.543141] post_rr_ack: 11.0.0.1:53360 bh 1.
[D 14:46:00.543141] post_sr: 11.0.0.1:53360 bh 1 len 40 wr 1/8191.
[D 14:46:00.543141] encourage_send_waiting_buffer: sq 0x8183c0 sent EAGER now
SQ_WAITING_EAGER_ACK.
[D 14:46:00.543141] check_cq: found something.
[D 14:46:00.543141] check_cq: ack message 11.0.0.1:53360 my bufnum 1.
[D 14:46:00.543141] check_cq: sq 0x8183c0 SQ_WAITING_EAGER_ACK ->
SQ_WAITING_USER_TEST.
[D 14:46:00.543141] check_cq: found something.
[D 14:46:00.543141] check_cq: found len 8 at 11.0.0.1:53360 my bufnum 2 type
MSG_BYE.
[D 14:46:00.543141] encourage_recv_incoming: incoming msg type MSG_BYE.
[D 14:46:00.543141] encourage_recv_incoming: recv BYE my bufnum 2 len 8.
[D 14:46:00.543141] ib_close_connection: closing connection to 11.0.0.1:53360.
[D 14:46:00.543141] ib_close_connection: refcnt non-zero 1, delaying free.
[D 14:46:00.543141] test_sq: sq 0x8183c0 completed 24 to 11.0.0.1:53360.
[D 14:46:00.543141] ib_close_connection: closing connection to 11.0.0.1:53360.
[D 14:46:00.553142] BMI_testcontext completing: 76
[D 14:46:00.553142] (0x819a00) mgmt_setparam (FR sm) state: cleanup
[A 14:46:00.553142] root.root@(unconnected) H=0 S=0x819a00: mgmt_setparam:
finish (Success)
[D 14:46:00.553142] (0x819a00) mgmt_setparam state: cleanup
[D 14:46:00.553142] - setparam returning 0
[D 14:46:05.663257] post_rr: 11.0.0.1:53361 bh 0.
[D 14:46:05.663257] post_rr: 11.0.0.1:53361 bh 1.
[D 14:46:05.663257] post_rr: 11.0.0.1:53361 bh 2.
[D 14:46:05.663257] post_rr: 11.0.0.1:53361 bh 3.
[D 14:46:05.663257] post_rr: 11.0.0.1:53361 bh 4.
[D 14:46:05.663257] post_rr: 11.0.0.1:53361 bh 5.
[D 14:46:05.663257] post_rr: 11.0.0.1:53361 bh 6.
[D 14:46:05.663257] post_rr: 11.0.0.1:53361 bh 7.
[D 14:46:05.663257] post_rr: 11.0.0.1:53361 bh 8.
[D 14:46:05.663257] post_rr: 11.0.0.1:53361 bh 9.
[D 14:46:05.663257] post_rr: 11.0.0.1:53361 bh 10.
[D 14:46:05.663257] post_rr: 11.0.0.1:53361 bh 11.
[D 14:46:05.663257] post_rr: 11.0.0.1:53361 bh 12.
[D 14:46:05.663257] post_rr: 11.0.0.1:53361 bh 13.
[D 14:46:05.663257] post_rr: 11.0.0.1:53361 bh 14.
[D 14:46:05.663257] post_rr: 11.0.0.1:53361 bh 15.
[D 14:46:05.663257] post_rr: 11.0.0.1:53361 bh 16.
[D 14:46:05.663257] post_rr: 11.0.0.1:53361 bh 17.
[D 14:46:05.663257] post_rr: 11.0.0.1:53361 bh 18.
[D 14:46:05.663257] post_rr: 11.0.0.1:53361 bh 19.
[D 14:46:05.663257] ib_tcp_server_check_new_connections: accepted new
connection 11.0.0.1:53361 at server.
[D 14:46:05.663257] check_cq: found something.
[D 14:46:05.663257] check_cq: found len 40 at 11.0.0.1:53361 my bufnum 0 type
MSG_EAGER_SENDUNEXPECTED.
[D 14:46:05.663257] encourage_recv_incoming: incoming msg type
MSG_EAGER_SENDUNEXPECTED.
[D 14:46:05.663257] encourage_recv_incoming: recv eager unexpected my bufnum 0
his bufnum 0 len 40.
[D 14:46:05.663257] encourage_recv_incoming: new rq 0x892bc0 now
RQ_EAGER_WAITING_USER_TESTUNEXPECTED.
[D 14:46:05.663257] BMI_ib_testunexpected: found waiting testunexpected.
[D 14:46:05.663257] post_rr: 11.0.0.1:53361 bh 0.
[D 14:46:05.663257] post_sr_ack: 11.0.0.1:53361 his buf 0 wr 0/8191.
[D 14:46:05.663257] (0x81aba0) getconfig (prelude sm) state: req_sched
[A 14:46:05.663257] [EMAIL PROTECTED]:53361 H=0 S=0x81aba0: getconfig: request
[A 14:46:05.673257] [EMAIL PROTECTED]:53361 H=0 S=0x81aba0: getconfig: start
[D 14:46:05.673257] (0x81aba0) getconfig (prelude sm) state: getattr_if_needed
[D 14:46:05.673257] PVFS operation "getconfig" got attr mask 127
(attr_uid_valid? yes, attr_owner = 0, credentials_uid = 0)
(attr_gid_valid? yes, attr_group = 0, credentials.gid = 0)
[D 14:46:05.673257] Final permission check for "getconfig" set error code to 0
[D 14:46:05.673257] (0x81aba0) getconfig (prelude sm) state: perm_check (status
= 0)
[D 14:46:05.673257] (0x81aba0) getconfig state: init
[D 14:46:05.673257] (0x81aba0) getconfig (FR sm) state: release: (error_code =
0)
[D 14:46:05.673257] (0x81aba0) getconfig (FR sm) state: send_resp (status = 0)
[D 14:46:05.673257] ib_mem_register: buf 0x89c210 len 32808.
[D 14:46:05.673257] BMI_post_send_list: addr: 86, count: 1, total_size: 1016
[D 14:46:05.673257] element 0: offset: 0x89c210, size: 1016
[D 14:46:05.673257] BMI_ib_post_send_list: listlen 1 tag 1.
[D 14:46:05.673257] generic_post_send: new sq 0x892bc0.
[D 14:46:05.673257] encourage_send_waiting_buffer: sq 0x892bc0.
[D 14:46:05.673257] post_rr_ack: 11.0.0.1:53361 bh 0.
[D 14:46:05.673257] post_sr: 11.0.0.1:53361 bh 0 len 1032 wr 0/8191.
[D 14:46:05.673257] encourage_send_waiting_buffer: sq 0x892bc0 sent EAGER now
SQ_WAITING_EAGER_ACK.
[D 14:46:05.673257] check_cq: found something.
[D 14:46:05.673257] check_cq: ack message 11.0.0.1:53361 my bufnum 0.
[D 14:46:05.673257] check_cq: sq 0x892bc0 SQ_WAITING_EAGER_ACK ->
SQ_WAITING_USER_TEST.
[D 14:46:05.673257] test_sq: sq 0x892bc0 completed 1016 to 11.0.0.1:53361.
[D 14:46:05.673257] BMI_testcontext completing: 90
[D 14:46:05.673257] (0x81aba0) getconfig (FR sm) state: cleanup
[A 14:46:05.673257] [EMAIL PROTECTED]:53361 H=0 S=0x81aba0: getconfig: finish
(Success)
[D 14:46:05.673257] ib_mem_deregister: buf 0x89c210 len 32808 lkey 813b9800
rkey 813b9800.
[D 14:46:05.673257] (0x81aba0) getconfig state: cleanup
[D 14:46:05.673257] check_cq: found something.
[D 14:46:05.673257] check_cq: found len 56 at 11.0.0.1:53361 my bufnum 1 type
MSG_EAGER_SENDUNEXPECTED.
[D 14:46:05.673257] encourage_recv_incoming: incoming msg type
MSG_EAGER_SENDUNEXPECTED.
[D 14:46:05.673257] encourage_recv_incoming: recv eager unexpected my bufnum 1
his bufnum 1 len 56.
[D 14:46:05.673257] encourage_recv_incoming: new rq 0x892bc0 now
RQ_EAGER_WAITING_USER_TESTUNEXPECTED.
[D 14:46:05.673257] BMI_ib_testunexpected: found waiting testunexpected.
[D 14:46:05.673257] post_rr: 11.0.0.1:53361 bh 1.
[D 14:46:05.673257] post_sr_ack: 11.0.0.1:53361 his buf 1 wr 1/8191.
[D 14:46:05.673257] (0x81bd40) getattr (prelude sm) state: req_sched
[A 14:46:05.673257] [EMAIL PROTECTED]:53361 H=1048576 S=0x81bd40: getattr:
request
[D 14:46:05.673257] REQ SCHED POSTING, handle: 1048576, queue_element: 0x81a3f0
[D 14:46:05.673257] REQ SCHED SCHEDULING, handle: 1048576, queue_element:
0x81a3f0
[A 14:46:05.673257] [EMAIL PROTECTED]:53361 H=1048576 S=0x81bd40: getattr: start
[D 14:46:05.673257] (0x81bd40) getattr (prelude sm) state: getattr_if_needed
[D 14:46:05.673257] About to retrieve attributes for handle 1048576
[D 14:46:05.673257] dbpf_open_cache_get: called
[D 14:46:05.673257] dbpf_open_cache_get: create_flag: 0
[D 14:46:05.673257] dbpf_open_cache_get: resetting entry from free list.
[D 14:46:05.673257] dbpf_open_cache open_fd: opening fd 1048576, create: 0
[D 14:46:05.673257] dbpf_open_cache open_fd: filename:
//pvfs-1/6292076b/bstreams/00000000/00100000.bstream
[D 14:46:05.673257] dbpf_open_cache_get: could not open (ret=-1073742082)
[D 14:46:05.673257] ATTRIB: retrieved attributes from DISK for key 1048576
uid = 0, mode = 511, type = 4, dfile_count = 0, dist_size = 0
b_size = 0, k_size = 2974
[D 14:46:05.673257] dbpf_attr_cache_insert: inserting 1048576 (k_size is 2974 |
b_size is 0)
[D 14:46:05.673257] PVFS operation "getattr" got attr mask 127
(attr_uid_valid? yes, attr_owner = 0, credentials_uid = 0)
(attr_gid_valid? yes, attr_group = 0, credentials.gid = 0)
[D 14:46:05.673257] Final permission check for "getattr" set error code to 0
[D 14:46:05.673257] (0x81bd40) getattr (prelude sm) state: perm_check (status =
0)
[D 14:46:05.673257] (0x81bd40) getattr state: verify_attribs
[D 14:46:05.673257] VERSION is 4932410570953273028, mtime is 1148416328
[A 14:46:05.673257] [EMAIL PROTECTED]:53361 H=1048576 S=0x81bd40: getattr:
type: directory
[D 14:46:05.673257] getattr: dirent_count not needed.
[D 14:46:05.673257] (0x81bd40) getattr state: setup_resp
[D 14:46:05.673257] - RETURNING retrieved attrs: [owner = 0, group = 0
perms = 777, type = 4, atime = 1148416328, mtime = 1148416328
ctime = 1148416328, dfile_count = 0, dist_size = 0]
[D 14:46:05.673257] @ End DIRECTORY attributes: sending status 0 (error = 0)
[D 14:46:05.673257] (0x81bd40) getattr (FR sm) state: release: (error_code = 0)
[D 14:46:05.673257] REQ SCHED RELEASING, handle: 1048576, queue_element:
0x81a3f0
[D 14:46:05.673257] (0x81bd40) getattr (FR sm) state: send_resp (status = 0)
[D 14:46:05.673257] ib_mem_register: buf 0x894ff0 len 9280.
[D 14:46:05.673257] BMI_post_send_list: addr: 86, count: 1, total_size: 64
[D 14:46:05.673257] element 0: offset: 0x894ff0, size: 64
[D 14:46:05.673257] BMI_ib_post_send_list: listlen 1 tag 2.
[D 14:46:05.673257] generic_post_send: new sq 0x892d60.
[D 14:46:05.673257] encourage_send_waiting_buffer: sq 0x892d60.
[D 14:46:05.673257] post_rr_ack: 11.0.0.1:53361 bh 1.
[D 14:46:05.673257] post_sr: 11.0.0.1:53361 bh 1 len 80 wr 1/8191.
[D 14:46:05.673257] encourage_send_waiting_buffer: sq 0x892d60 sent EAGER now
SQ_WAITING_EAGER_ACK.
[D 14:46:05.673257] check_cq: found something.
[D 14:46:05.673257] check_cq: ack message 11.0.0.1:53361 my bufnum 1.
[D 14:46:05.673257] check_cq: sq 0x892d60 SQ_WAITING_EAGER_ACK ->
SQ_WAITING_USER_TEST.
[D 14:46:05.673257] test_sq: sq 0x892d60 completed 64 to 11.0.0.1:53361.
[D 14:46:05.673257] BMI_testcontext completing: 97
[D 14:46:05.673257] (0x81bd40) getattr (FR sm) state: cleanup
[A 14:46:05.673257] [EMAIL PROTECTED]:53361 H=1048576 S=0x81bd40: getattr:
finish (Success)
[D 14:46:05.673257] ib_mem_deregister: buf 0x894ff0 len 9280 lkey e93ba800 rkey
e93ba800.
[D 14:46:05.673257] (0x81bd40) getattr state: getattr_cleanup
[D 14:46:05.673257] check_cq: found something.
[D 14:46:05.673257] check_cq: found len 120 at 11.0.0.1:53361 my bufnum 2 type
MSG_EAGER_SENDUNEXPECTED.
[D 14:46:05.673257] encourage_recv_incoming: incoming msg type
MSG_EAGER_SENDUNEXPECTED.
[D 14:46:05.673257] encourage_recv_incoming: recv eager unexpected my bufnum 2
his bufnum 2 len 120.
[D 14:46:05.673257] encourage_recv_incoming: new rq 0x892d60 now
RQ_EAGER_WAITING_USER_TESTUNEXPECTED.
[D 14:46:05.673257] BMI_ib_testunexpected: found waiting testunexpected.
[D 14:46:05.673257] post_rr: 11.0.0.1:53361 bh 2.
[D 14:46:05.673257] post_sr_ack: 11.0.0.1:53361 his buf 2 wr 2/8191.
[D 14:46:05.673257] (0x81cee0) mkdir (prelude sm) state: req_sched
[A 14:46:05.673257] [EMAIL PROTECTED]:53361 H=0 S=0x81cee0: mkdir: request
[A 14:46:05.673257] [EMAIL PROTECTED]:53361 H=0 S=0x81cee0: mkdir: start
[D 14:46:05.673257] (0x81cee0) mkdir (prelude sm) state: getattr_if_needed
[D 14:46:05.673257] PVFS operation "mkdir" got attr mask 127
(attr_uid_valid? yes, attr_owner = 0, credentials_uid = 0)
(attr_gid_valid? yes, attr_group = 0, credentials.gid = 0)
[D 14:46:05.673257] Final permission check for "mkdir" set error code to 0
[D 14:46:05.673257] (0x81cee0) mkdir (prelude sm) state: perm_check (status = 0)
[D 14:46:05.673257] (0x81cee0) mkdir state: prep_sm
[D 14:46:05.673257] attrs to write: [owner = 0, group = 0, perms = 755]
[D 14:46:05.673257] (0x81cee0) mkdir state: create
[D 14:46:05.673257] creating dspace on coll_id 1653737323
[D 14:46:05.673257] directory handle will be in starting hrange[0] 4-2147483650
[D 14:46:05.673257] [1 extents] -- new_handle is 1055489 (cur_extent is 4 -
2147483650)
[D 14:46:05.673257] dbpf_attr_cache_insert: inserting 1055489 (k_size is 0 |
b_size is 0)
[D 14:46:05.763259] db SYNC called servicing op type DSPACE_CREATE
[D 14:46:05.763259] (0x81cee0) mkdir state: setattrib
[D 14:46:05.763259] *** new directory has handle 1055489
[D 14:46:05.763259] setting directory version to 1148586365
mtime is 0
[D 14:46:05.763259] dbpf_cache_elem_lookup: cache elem matching 1055489
returned (num_elems=2)
[D 14:46:05.763259] Updating cached attributes for key 1055489
[D 14:46:05.833261] db SYNC called servicing op type DSPACE_SETATTR
[D 14:46:05.833261] (0x81cee0) mkdir state: create_dirdata_dspace
[D 14:46:05.833261] creating dspace on coll_id 1653737323
[D 14:46:05.833261] dirdata handle will be in starting hrange[0] 4-2147483650
[D 14:46:05.833261] [1 extents] -- new_handle is 1055485 (cur_extent is 4 -
2147483650)
[D 14:46:05.833261] dbpf_attr_cache_insert: inserting 1055485 (k_size is 0 |
b_size is 0)
[D 14:46:05.933263] db SYNC called servicing op type DSPACE_CREATE
[D 14:46:05.933263] (0x81cee0) mkdir state: write_dirdata_handle
[D 14:46:05.933263] *** new dirdata has handle 1055485
[D 14:46:05.933263] writing dirdata handle (1055485) into parent dir (1055489)
[D 14:46:05.973264] dbpf_cache_elem_lookup: cache elem matching 1055489
returned (num_elems=3)
[D 14:46:05.973264] dbpf_cache_elem_lookup: cache elem matching 1055489
returned (num_elems=3)
[D 14:46:05.973264] Setting data 0x81db48 based on key 1055489 and key_str
dir_ent (data_sz=8)
[D 14:46:05.973264] *** cached keyval data written (key is dir_ent)
[D 14:46:06.033265] db SYNC called servicing op type KEYVAL_WRITE
[D 14:46:06.033265] dbpf_cache_elem_lookup: cache elem matching 1055489
returned (num_elems=3)
[D 14:46:06.033265] dbpf_cache_elem_lookup: cache elem matching 1055489
returned (num_elems=3)
[D 14:46:06.033265] ** CANNOT cache data written (key is dirdata_size)
[D 14:46:06.133268] db SYNC called servicing op type KEYVAL_WRITE
[D 14:46:06.133268] (0x81cee0) mkdir (FR sm) state: release: (error_code = 0)
[D 14:46:06.133268] (0x81cee0) mkdir (FR sm) state: send_resp (status = 0)
[D 14:46:06.133268] BMI_post_send_list: addr: 86, count: 1, total_size: 24
[D 14:46:06.133268] element 0: offset: 0x7f0010, size: 24
[D 14:46:06.133268] BMI_ib_post_send_list: listlen 1 tag 3.
[D 14:46:06.133268] generic_post_send: new sq 0x892d60.
[D 14:46:06.133268] encourage_send_waiting_buffer: sq 0x892d60.
[D 14:46:06.133268] post_rr_ack: 11.0.0.1:53361 bh 2.
[D 14:46:06.133268] post_sr: 11.0.0.1:53361 bh 2 len 40 wr 2/8191.
[D 14:46:06.133268] encourage_send_waiting_buffer: sq 0x892d60 sent EAGER now
SQ_WAITING_EAGER_ACK.
[D 14:46:06.133268] check_cq: found something.
[D 14:46:06.133268] check_cq: ack message 11.0.0.1:53361 my bufnum 2.
[D 14:46:06.133268] check_cq: sq 0x892d60 SQ_WAITING_EAGER_ACK ->
SQ_WAITING_USER_TEST.
[D 14:46:06.133268] test_sq: sq 0x892d60 completed 24 to 11.0.0.1:53361.
[D 14:46:06.133268] BMI_testcontext completing: 109
[D 14:46:06.133268] (0x81cee0) mkdir (FR sm) state: cleanup
[A 14:46:06.133268] [EMAIL PROTECTED]:53361 H=0 S=0x81cee0: mkdir: finish
(Success)
[D 14:46:06.133268] (0x81cee0) mkdir state: cleanup
[D 14:46:06.133268] check_cq: found something.
[D 14:46:06.133268] check_cq: found len 96 at 11.0.0.1:53361 my bufnum 3 type
MSG_EAGER_SENDUNEXPECTED.
[D 14:46:06.133268] encourage_recv_incoming: incoming msg type
MSG_EAGER_SENDUNEXPECTED.
[D 14:46:06.133268] encourage_recv_incoming: recv eager unexpected my bufnum 3
his bufnum 3 len 96.
[D 14:46:06.133268] encourage_recv_incoming: new rq 0x892d60 now
RQ_EAGER_WAITING_USER_TESTUNEXPECTED.
[D 14:46:06.133268] BMI_ib_testunexpected: found waiting testunexpected.
[D 14:46:06.133268] post_rr: 11.0.0.1:53361 bh 3.
[D 14:46:06.133268] post_sr_ack: 11.0.0.1:53361 his buf 3 wr 3/8191.
[D 14:46:06.133268] (0x81e080) crdirent (prelude sm) state: req_sched
[A 14:46:06.133268] [EMAIL PROTECTED]:53361 H=1048576 S=0x81e080: crdirent:
request
[D 14:46:06.133268] REQ SCHED POSTING, handle: 1048576, queue_element: 0x892d60
[D 14:46:06.133268] REQ SCHED SCHEDULING, handle: 1048576, queue_element:
0x892d60
[A 14:46:06.133268] [EMAIL PROTECTED]:53361 H=1048576 S=0x81e080: crdirent:
start
[D 14:46:06.133268] (0x81e080) crdirent (prelude sm) state: getattr_if_needed
[D 14:46:06.133268] About to retrieve attributes for handle 1048576
[D 14:46:06.133268] dspace_getattr fast path attr cache hit on 1048576
(dfile_count=0 | dist_size=0 | data_size=0)
[D 14:46:06.133268] PVFS operation "crdirent" got attr mask 127
(attr_uid_valid? yes, attr_owner = 0, credentials_uid = 0)
(attr_gid_valid? yes, attr_group = 0, credentials.gid = 0)
[D 14:46:06.133268] - check_mode called --- (uid=0,gid=0,access_type=2)
[D 14:46:06.133268] - object attributes --- (uid=0,gid=0,mode=511)
[D 14:46:06.133268] - checking if uid (0) is root ...
[D 14:46:06.133268] - yes
[D 14:46:06.133268] - check_mode called --- (uid=0,gid=0,access_type=1)
[D 14:46:06.133268] - object attributes --- (uid=0,gid=0,mode=511)
[D 14:46:06.133268] - checking if uid (0) is root ...
[D 14:46:06.133268] - yes
[D 14:46:06.143268] Final permission check for "crdirent" set error code to 0
[D 14:46:06.143268] (0x81e080) crdirent (prelude sm) state: perm_check (status
= 0)
[D 14:46:06.143268] (0x81e080) crdirent state: setup_op
[A 14:46:06.143268] [EMAIL PROTECTED]:53361 H=1048576 S=0x81e080: crdirent:
crdirent entry: foo points to 1055489
[D 14:46:06.143268] (0x81e080) crdirent state: validate
[D 14:46:06.143268] got crdirent for foo (with handle 1055489) in 1048576
[D 14:46:06.143268] (0x81e080) crdirent state: read_directory_entry_handle
[D 14:46:06.143268] dbpf_cache_elem_lookup: cache elem matching 1048576
returned (num_elems=3)
[D 14:46:06.143268] dbpf_cache_elem_lookup: cache elem matching 1048576
returned (num_elems=3)
[D 14:46:06.143268] Setting data 0x81ecf0 based on key 1048576 and key_str
dir_ent (data_sz=8)
[D 14:46:06.143268] *** cached keyval data retrieved (key is dir_ent)
[D 14:46:06.143268] (0x81e080) crdirent state: check_exist_directory_entry
[D 14:46:06.143268] checking existence of new directory entry for foo (handle
= 1055489) to dirdata dspace 4
[D 14:46:06.143268] (0x81e080) crdirent state: write_directory_entry
[D 14:46:06.143268] writing new directory entry for foo (handle = 1055489) to
dirdata dspace 4
[D 14:46:06.243270] db SYNC called servicing op type KEYVAL_WRITE
[D 14:46:06.243270] dbpf_cache_elem_lookup: cache elem matching 1048576
returned (num_elems=3)
[D 14:46:06.243270] dbpf_cache_elem_lookup: cache elem matching 1048576
returned (num_elems=3)
[D 14:46:06.243270] ** CANNOT cache data retrieved (key is dirdata_size)
[D 14:46:06.243270] incrementing dirent_count: fsid: 1653737323, handle:
1048576, count: 5
[D 14:46:06.243270] dbpf_cache_elem_lookup: cache elem matching 1048576
returned (num_elems=3)
[D 14:46:06.243270] dbpf_cache_elem_lookup: cache elem matching 1048576
returned (num_elems=3)
[D 14:46:06.243270] ** CANNOT cache data written (key is dirdata_size)
[D 14:46:06.333272] db SYNC called servicing op type KEYVAL_WRITE
[D 14:46:06.333272] (0x81e080) crdirent state: update_directory_entry
[D 14:46:06.333272] updating parent dir version to 4933140874306852312
mtime is 1148586365
[D 14:46:06.333272] dbpf_cache_elem_lookup: cache elem matching 1048576
returned (num_elems=3)
[D 14:46:06.333272] Updating cached attributes for key 1048576
[D 14:46:06.433274] db SYNC called servicing op type DSPACE_SETATTR
[D 14:46:06.433274] (0x81e080) crdirent (FR sm) state: release: (error_code = 0)
[D 14:46:06.433274] REQ SCHED RELEASING, handle: 1048576, queue_element:
0x892d60
[D 14:46:06.433274] (0x81e080) crdirent (FR sm) state: send_resp (status = 0)
[D 14:46:06.433274] BMI_post_send_list: addr: 86, count: 1, total_size: 16
[D 14:46:06.433274] element 0: offset: 0x8194b0, size: 16
[D 14:46:06.433274] BMI_ib_post_send_list: listlen 1 tag 4.
[D 14:46:06.433274] generic_post_send: new sq 0x81a9b0.
[D 14:46:06.433274] encourage_send_waiting_buffer: sq 0x81a9b0.
[D 14:46:06.433274] post_rr_ack: 11.0.0.1:53361 bh 3.
[D 14:46:06.433274] post_sr: 11.0.0.1:53361 bh 3 len 32 wr 3/8191.
[D 14:46:06.433274] encourage_send_waiting_buffer: sq 0x81a9b0 sent EAGER now
SQ_WAITING_EAGER_ACK.
[D 14:46:06.433274] check_cq: found something.
[D 14:46:06.433274] check_cq: ack message 11.0.0.1:53361 my bufnum 3.
[D 14:46:06.433274] check_cq: sq 0x81a9b0 SQ_WAITING_EAGER_ACK ->
SQ_WAITING_USER_TEST.
[D 14:46:06.433274] test_sq: sq 0x81a9b0 completed 16 to 11.0.0.1:53361.
[D 14:46:06.433274] BMI_testcontext completing: 121
[D 14:46:06.433274] (0x81e080) crdirent (FR sm) state: cleanup
[A 14:46:06.433274] [EMAIL PROTECTED]:53361 H=1048576 S=0x81e080: crdirent:
finish (Success)
[D 14:46:06.433274] (0x81e080) crdirent state: cleanup
[D 14:46:06.433274] check_cq: found something.
[D 14:46:06.433274] check_cq: found len 8 at 11.0.0.1:53361 my bufnum 4 type
MSG_BYE.
[D 14:46:06.433274] encourage_recv_incoming: incoming msg type MSG_BYE.
[D 14:46:06.433274] encourage_recv_incoming: recv BYE my bufnum 4 len 8.
[D 14:46:06.433274] ib_close_connection: closing connection to 11.0.0.1:53361.
[D 14:46:11.823396] post_rr: 11.0.0.1:53369 bh 0.
[D 14:46:11.823396] post_rr: 11.0.0.1:53369 bh 1.
[D 14:46:11.823396] post_rr: 11.0.0.1:53369 bh 2.
[D 14:46:11.823396] post_rr: 11.0.0.1:53369 bh 3.
[D 14:46:11.823396] post_rr: 11.0.0.1:53369 bh 4.
[D 14:46:11.823396] post_rr: 11.0.0.1:53369 bh 5.
[D 14:46:11.823396] post_rr: 11.0.0.1:53369 bh 6.
[D 14:46:11.823396] post_rr: 11.0.0.1:53369 bh 7.
[D 14:46:11.823396] post_rr: 11.0.0.1:53369 bh 8.
[D 14:46:11.823396] post_rr: 11.0.0.1:53369 bh 9.
[D 14:46:11.823396] post_rr: 11.0.0.1:53369 bh 10.
[D 14:46:11.823396] post_rr: 11.0.0.1:53369 bh 11.
[D 14:46:11.823396] post_rr: 11.0.0.1:53369 bh 12.
[D 14:46:11.823396] post_rr: 11.0.0.1:53369 bh 13.
[D 14:46:11.823396] post_rr: 11.0.0.1:53369 bh 14.
[D 14:46:11.823396] post_rr: 11.0.0.1:53369 bh 15.
[D 14:46:11.823396] post_rr: 11.0.0.1:53369 bh 16.
[D 14:46:11.823396] post_rr: 11.0.0.1:53369 bh 17.
[D 14:46:11.823396] post_rr: 11.0.0.1:53369 bh 18.
[D 14:46:11.823396] post_rr: 11.0.0.1:53369 bh 19.
[D 14:46:11.823396] ib_tcp_server_check_new_connections: accepted new
connection 11.0.0.1:53369 at server.
[D 14:46:11.823396] check_cq: found something.
[D 14:46:11.823396] check_cq: found len 40 at 11.0.0.1:53369 my bufnum 0 type
MSG_EAGER_SENDUNEXPECTED.
[D 14:46:11.823396] encourage_recv_incoming: incoming msg type
MSG_EAGER_SENDUNEXPECTED.
[D 14:46:11.823396] encourage_recv_incoming: recv eager unexpected my bufnum 0
his bufnum 0 len 40.
[D 14:46:11.823396] encourage_recv_incoming: new rq 0x872860 now
RQ_EAGER_WAITING_USER_TESTUNEXPECTED.
[D 14:46:11.823396] BMI_ib_testunexpected: found waiting testunexpected.
[D 14:46:11.823396] post_rr: 11.0.0.1:53369 bh 0.
[D 14:46:11.823396] post_sr_ack: 11.0.0.1:53369 his buf 0 wr 0/8191.
[D 14:46:11.823396] (0x81f220) getconfig (prelude sm) state: req_sched
[A 14:46:11.823396] [EMAIL PROTECTED]:53369 H=0 S=0x81f220: getconfig: request
[A 14:46:11.823396] [EMAIL PROTECTED]:53369 H=0 S=0x81f220: getconfig: start
[D 14:46:11.823396] (0x81f220) getconfig (prelude sm) state: getattr_if_needed
[D 14:46:11.823396] PVFS operation "getconfig" got attr mask 127
(attr_uid_valid? yes, attr_owner = 0, credentials_uid = 0)
(attr_gid_valid? yes, attr_group = 0, credentials.gid = 0)
[D 14:46:11.823396] Final permission check for "getconfig" set error code to 0
[D 14:46:11.823396] (0x81f220) getconfig (prelude sm) state: perm_check (status
= 0)
[D 14:46:11.823396] (0x81f220) getconfig state: init
[D 14:46:11.823396] (0x81f220) getconfig (FR sm) state: release: (error_code =
0)
[D 14:46:11.823396] (0x81f220) getconfig (FR sm) state: send_resp (status = 0)
[D 14:46:11.823396] ib_mem_register: buf 0x89c210 len 32808.
[D 14:46:11.823396] BMI_post_send_list: addr: 132, count: 1, total_size: 1016
[D 14:46:11.823396] element 0: offset: 0x89c210, size: 1016
[D 14:46:11.823396] BMI_ib_post_send_list: listlen 1 tag 1.
[D 14:46:11.823396] generic_post_send: new sq 0x81a3d0.
[D 14:46:11.823396] encourage_send_waiting_buffer: sq 0x81a3d0.
[D 14:46:11.823396] post_rr_ack: 11.0.0.1:53369 bh 0.
[D 14:46:11.823396] post_sr: 11.0.0.1:53369 bh 0 len 1032 wr 0/8191.
[D 14:46:11.823396] encourage_send_waiting_buffer: sq 0x81a3d0 sent EAGER now
SQ_WAITING_EAGER_ACK.
[D 14:46:11.823396] check_cq: found something.
[D 14:46:11.823396] check_cq: ack message 11.0.0.1:53369 my bufnum 0.
[D 14:46:11.823396] check_cq: sq 0x81a3d0 SQ_WAITING_EAGER_ACK ->
SQ_WAITING_USER_TEST.
[D 14:46:11.823396] test_sq: sq 0x81a3d0 completed 1016 to 11.0.0.1:53369.
[D 14:46:11.823396] BMI_testcontext completing: 136
[D 14:46:11.823396] (0x81f220) getconfig (FR sm) state: cleanup
[A 14:46:11.823396] [EMAIL PROTECTED]:53369 H=0 S=0x81f220: getconfig: finish
(Success)
[D 14:46:11.823396] ib_mem_deregister: buf 0x89c210 len 32808 lkey f13ba800
rkey f13ba800.
[D 14:46:11.823396] (0x81f220) getconfig state: cleanup
[D 14:46:11.823396] check_cq: found something.
[D 14:46:11.823396] check_cq: found len 56 at 11.0.0.1:53369 my bufnum 1 type
MSG_EAGER_SENDUNEXPECTED.
[D 14:46:11.823396] encourage_recv_incoming: incoming msg type
MSG_EAGER_SENDUNEXPECTED.
[D 14:46:11.823396] encourage_recv_incoming: recv eager unexpected my bufnum 1
his bufnum 1 len 56.
[D 14:46:11.823396] encourage_recv_incoming: new rq 0x872860 now
RQ_EAGER_WAITING_USER_TESTUNEXPECTED.
[D 14:46:11.823396] BMI_ib_testunexpected: found waiting testunexpected.
[D 14:46:11.823396] post_rr: 11.0.0.1:53369 bh 1.
[D 14:46:11.823396] post_sr_ack: 11.0.0.1:53369 his buf 1 wr 1/8191.
[D 14:46:11.823396] (0x8203c0) mgmt_setparam (prelude sm) state: req_sched
[A 14:46:11.823396] [EMAIL PROTECTED]:53369 H=0 S=0x8203c0: mgmt_setparam:
request
[A 14:46:11.823396] [EMAIL PROTECTED]:53369 H=0 S=0x8203c0: mgmt_setparam: start
[D 14:46:11.823396] (0x8203c0) mgmt_setparam (prelude sm) state:
getattr_if_needed
[D 14:46:11.823396] PVFS operation "mgmt_setparam" got attr mask 127
(attr_uid_valid? yes, attr_owner = 0, credentials_uid = 0)
(attr_gid_valid? yes, attr_group = 0, credentials.gid = 0)
[D 14:46:11.823396] Final permission check for "mgmt_setparam" set error code
to 0
[D 14:46:11.823396] (0x8203c0) mgmt_setparam (prelude sm) state: perm_check
(status = 0)
[D 14:46:11.823396] (0x8203c0) mgmt_setparam state: work
[E 14:46:16.183494]
PVFS2 server got signal 15 (server_status_flag: 262143)
_______________________________________________
Pvfs2-developers mailing list
[email protected]
http://www.beowulf-underground.org/mailman/listinfo/pvfs2-developers
