Raghavendra G wrote:
On Fri, Apr 2, 2010 at 3:32 PM, Olivier Le Cam
<Olivier.LeCam@xxxxxxxxxxxxxxxxxxxxx
<mailto:Olivier.LeCam@xxxxxxxxxxxxxxxxxxxxx>> wrote:
Hi -
I am evaluating glusterfs for a replacement of an NFS server which
acts as a backend storage for a webcluster, in order to take
advantage of its very interesting features in term of
high-availability and scalability.
That said, I'm experiencing (like everybody in the same situation)
performance issues due to the large number of small files a
webserver have to deal with.
The io-cache translator does not help so much in this situation
because (as far as I understood) the clients always have to check
the mtime of the target file before delivering it in order to known
if the cache is up-to-date. This intensive network traffic is quite
penalizing in term of performance (especially on a Gb-E).
Following to a recent talk on the IRC channel, it came to my mind
that caching lookups could (in this particular situation) greatly
improve the performances.
If you are not very much concerned about file being changed from other
clients while it is being cached, you can set 'cache-timeout' value in
io-cache configuration to some high value, there by increasing the time
intervals at which stat call is sent to server to check whether the file
has changed.
I have observed the GlusterFS code carefully and TBH I haven't been
able to see how/where such a translator could be integrated in.
Would it be possible to get some help? Are other users/developers
already involved in such a development?
If you are just interested in caching stats for beniefit of io-cache,
the same functionality can be achieved by tuning cache-timeout value in
io-cache.
This is not the behaviour I would expected according to the doc: "If the
cached page for a file is greater than 'cache-timeout' seconds old,
io-cache translator forces a re-validation of the page. However the
cached page is verified against the mtime whenever possible and cache is
refreshed. Default is 1 second."
AFAIU, mtime is always verified (whenever possible). As a non native
english spoker I might misunderstood something thougth!
Anyway, I have tested with a cache-timeout of 60 seconds on a client:
according to the debug traces and tcpdump, cat'ing the same file several
times. I have no idea which protocols are involved here but there is
always some traffic between the client and the servers even where cat
issued within the cache interval.
My guess is that file is indeed cached by io-cache but that the client
always stats the server before delivering the file (either from the
cache or the glusterfs).
Debug log attached.
Kind regards,
--
Olivier
================================================================================
Version : glusterfs 3.0.3 built on Mar 24 2010 09:20:49
git: v3.0.2-41-g029062c
Starting Time: 2010-04-04 10:35:07
Command line : /usr/sbin/glusterfs --log-level=NORMAL --volfile=/etc/glusterfs/glusterfs.vol /mnt
PID : 25905
System name : Linux
Nodename : nunki-6
Kernel Release : 2.6.32-trunk-amd64
Hardware Identifier: x86_64
Given volfile:
+------------------------------------------------------------------------------+
1: ## file auto generated by /usr/bin/glusterfs-volgen (mount.vol)
2: # Cmd line:
3: # $ /usr/bin/glusterfs-volgen --name store1 --raid 1 gl1:/export/nunki gl2:/export/nunki
4:
5: # RAID 1
6: # TRANSPORT-TYPE tcp
7: volume gl1-1
8: type protocol/client
9: option transport-type tcp
10: option remote-host 195.221.98.123
11: option transport.socket.nodelay on
12: option transport.remote-port 6996
13: option remote-subvolume brick1
14: end-volume
15:
16: volume gl2-1
17: type protocol/client
18: option transport-type tcp
19: option remote-host 192.168.19.124
20: option transport.socket.nodelay on
21: option transport.remote-port 6996
22: option remote-subvolume brick1
23: end-volume
24:
25: volume mirror-0
26: type cluster/replicate
27: subvolumes gl1-1 gl2-1
28: end-volume
29:
30: volume trace-before
31: type debug/trace
32: subvolumes mirror-0
33: # option include open,close,create,readdir,opendir,closedir
34: # option exclude lookup,read,write
35: option include open,close,create,readdir,opendir,closedir,lookup,read,write,stat
36: end-volume
37:
38: #volume writebehind
39: # type performance/write-behind
40: # option cache-size 4MB
41: # # option flush-behind on # olecam: increasing the performance of handling lots of small files
42: # option enable-trickling-writes false
43: # subvolumes trace-before
44: #end-volume
45:
46: # olecam: not recommanded on Gb-E
47: #volume readahead
48: # type performance/read-ahead
49: # option page-count 4
50: # subvolumes writebehind
51: #end-volume
52:
53: volume iocache
54: type performance/io-cache
55: option cache-size `grep 'MemTotal' /proc/meminfo | awk '{printf "%dMB\n", $2 * 0.2 / 1024}'`
56: # option cache-timeout 1
57: option cache-timeout 60
58: subvolumes trace-before
59: # subvolumes writebehind
60: end-volume
61:
62: volume trace-after
63: type debug/trace
64: subvolumes iocache
65: # option include open,close,create,readdir,opendir,closedir
66: # option exclude lookup,read,write
67: option include open,close,create,readdir,opendir,closedir,lookup,read,write,stat
68: end-volume
69:
70: #volume quickread
71: # type performance/quick-read
72: # option cache-timeout 1
73: # option max-file-size 64kB
74: # subvolumes iocache
75: #end-volume
76:
77: #volume statprefetch
78: # type performance/stat-prefetch
79: # subvolumes quickread
80: #end-volume
81:
+------------------------------------------------------------------------------+
[2010-04-04 10:35:07] W [xlator.c:656:validate_xlator_volume_options] trace-after: option 'include' is deprecated, preferred is 'include-ops', continuing with correction
[2010-04-04 10:35:07] W [xlator.c:656:validate_xlator_volume_options] trace-before: option 'include' is deprecated, preferred is 'include-ops', continuing with correction
[2010-04-04 10:35:07] C [dict.c:1142:data_to_str] dict: @data=(nil)
[2010-04-04 10:35:07] C [dict.c:1142:data_to_str] dict: @data=(nil)
[2010-04-04 10:35:07] W [xlator.c:656:validate_xlator_volume_options] gl2-1: option 'transport.remote-port' is deprecated, preferred is 'remote-port', continuing with correction
[2010-04-04 10:35:07] W [xlator.c:656:validate_xlator_volume_options] gl1-1: option 'transport.remote-port' is deprecated, preferred is 'remote-port', continuing with correction
[2010-04-04 10:35:07] N [glusterfsd.c:1396:main] glusterfs: Successfully started
[2010-04-04 10:35:07] N [client-protocol.c:6246:client_setvolume_cbk] gl1-1: Connected to 195.221.98.123:6996, attached to remote volume 'brick1'.
[2010-04-04 10:35:07] N [afr.c:2627:notify] mirror-0: Subvolume 'gl1-1' came back up; going online.
[2010-04-04 10:35:07] N [client-protocol.c:6246:client_setvolume_cbk] gl2-1: Connected to 192.168.19.124:6996, attached to remote volume 'brick1'.
[2010-04-04 10:35:07] N [client-protocol.c:6246:client_setvolume_cbk] gl2-1: Connected to 192.168.19.124:6996, attached to remote volume 'brick1'.
[2010-04-04 10:35:07] N [fuse-bridge.c:2942:fuse_init] glusterfs-fuse: FUSE inited with protocol versions: glusterfs 7.13 kernel 7.13
[2010-04-04 10:35:07] N [client-protocol.c:6246:client_setvolume_cbk] gl1-1: Connected to 195.221.98.123:6996, attached to remote volume 'brick1'.
[2010-04-04 10:35:27] N [trace.c:1289:trace_lookup] trace-after: 0: (loc {path=/, ino=1})
[2010-04-04 10:35:27] N [trace.c:1289:trace_lookup] trace-before: 0: (loc {path=/, ino=1})
[2010-04-04 10:35:27] N [trace.c:590:trace_lookup_cbk] trace-before: 0: (op_ret=0, ino=1, *buf {st_ino=1, st_mode=40755, st_nlink=30, st_uid=0, st_gid=0, st_size=4096, st_blocks=16, st_atime=[Apr 01 17:00:11], st_mtime=[Apr 01 17:17:42], st_ctime=[Apr 01 17:17:42]}, *postparent {st_ino=1, st_mode=40755, st_nlink=30, st_uid=0, st_gid=0, st_size=4096, st_blocks=16, st_atime=[Apr 01 17:00:11], st_mtime=[Apr 01 17:17:42], st_ctime=[Apr 01 17:17:42]}
[2010-04-04 10:35:27] N [trace.c:590:trace_lookup_cbk] trace-after: 0: (op_ret=0, ino=1, *buf {st_ino=1, st_mode=40755, st_nlink=30, st_uid=0, st_gid=0, st_size=4096, st_blocks=16, st_atime=[Apr 01 17:00:11], st_mtime=[Apr 01 17:17:42], st_ctime=[Apr 01 17:17:42]}, *postparent {st_ino=1, st_mode=40755, st_nlink=30, st_uid=0, st_gid=0, st_size=4096, st_blocks=16, st_atime=[Apr 01 17:00:11], st_mtime=[Apr 01 17:17:42], st_ctime=[Apr 01 17:17:42]}
[2010-04-04 10:35:27] N [trace.c:1289:trace_lookup] trace-after: 2: (loc {path=/, ino=1})
[2010-04-04 10:35:27] N [trace.c:1289:trace_lookup] trace-before: 2: (loc {path=/, ino=1})
[2010-04-04 10:35:27] N [trace.c:590:trace_lookup_cbk] trace-before: 2: (op_ret=0, ino=1, *buf {st_ino=1, st_mode=40755, st_nlink=30, st_uid=0, st_gid=0, st_size=4096, st_blocks=16, st_atime=[Apr 01 17:00:11], st_mtime=[Apr 01 17:17:42], st_ctime=[Apr 01 17:17:42]}, *postparent {st_ino=1, st_mode=40755, st_nlink=30, st_uid=0, st_gid=0, st_size=4096, st_blocks=16, st_atime=[Apr 01 17:00:11], st_mtime=[Apr 01 17:17:42], st_ctime=[Apr 01 17:17:42]}
[2010-04-04 10:35:27] N [trace.c:590:trace_lookup_cbk] trace-after: 2: (op_ret=0, ino=1, *buf {st_ino=1, st_mode=40755, st_nlink=30, st_uid=0, st_gid=0, st_size=4096, st_blocks=16, st_atime=[Apr 01 17:00:11], st_mtime=[Apr 01 17:17:42], st_ctime=[Apr 01 17:17:42]}, *postparent {st_ino=1, st_mode=40755, st_nlink=30, st_uid=0, st_gid=0, st_size=4096, st_blocks=16, st_atime=[Apr 01 17:00:11], st_mtime=[Apr 01 17:17:42], st_ctime=[Apr 01 17:17:42]}
[2010-04-04 10:35:27] N [trace.c:1289:trace_lookup] trace-after: 3: (loc {path=/s, ino=0})
[2010-04-04 10:35:27] N [trace.c:1289:trace_lookup] trace-before: 3: (loc {path=/s, ino=0})
[2010-04-04 10:35:27] N [trace.c:590:trace_lookup_cbk] trace-before: 3: (op_ret=0, ino=0, *buf {st_ino=85983234, st_mode=40755, st_nlink=16, st_uid=0, st_gid=0, st_size=4096, st_blocks=8, st_atime=[Apr 02 22:02:17], st_mtime=[Mar 09 09:31:01], st_ctime=[Apr 02 22:07:37]}, *postparent {st_ino=85983234, st_mode=40755, st_nlink=16, st_uid=0, st_gid=0, st_size=4096, st_blocks=8, st_atime=[Apr 02 22:02:17], st_mtime=[Mar 09 09:31:01], st_ctime=[Apr 02 22:07:37]}
[2010-04-04 10:35:27] N [trace.c:590:trace_lookup_cbk] trace-after: 3: (op_ret=0, ino=0, *buf {st_ino=85983234, st_mode=40755, st_nlink=16, st_uid=0, st_gid=0, st_size=4096, st_blocks=8, st_atime=[Apr 02 22:02:17], st_mtime=[Mar 09 09:31:01], st_ctime=[Apr 02 22:07:37]}, *postparent {st_ino=85983234, st_mode=40755, st_nlink=16, st_uid=0, st_gid=0, st_size=4096, st_blocks=8, st_atime=[Apr 02 22:02:17], st_mtime=[Mar 09 09:31:01], st_ctime=[Apr 02 22:07:37]}
[2010-04-04 10:35:27] N [trace.c:1289:trace_lookup] trace-after: 4: (loc {path=/s/t, ino=0})
[2010-04-04 10:35:27] N [trace.c:1289:trace_lookup] trace-before: 4: (loc {path=/s/t, ino=0})
[2010-04-04 10:35:27] N [trace.c:590:trace_lookup_cbk] trace-before: 4: (op_ret=0, ino=0, *buf {st_ino=11078108, st_mode=40755, st_nlink=10, st_uid=0, st_gid=0, st_size=4096, st_blocks=8, st_atime=[Apr 02 23:02:55], st_mtime=[Jan 27 08:30:02], st_ctime=[Apr 02 23:08:13]}, *postparent {st_ino=11078108, st_mode=40755, st_nlink=10, st_uid=0, st_gid=0, st_size=4096, st_blocks=8, st_atime=[Apr 02 23:02:55], st_mtime=[Jan 27 08:30:02], st_ctime=[Apr 02 23:08:13]}
[2010-04-04 10:35:27] N [trace.c:590:trace_lookup_cbk] trace-after: 4: (op_ret=0, ino=0, *buf {st_ino=11078108, st_mode=40755, st_nlink=10, st_uid=0, st_gid=0, st_size=4096, st_blocks=8, st_atime=[Apr 02 23:02:55], st_mtime=[Jan 27 08:30:02], st_ctime=[Apr 02 23:08:13]}, *postparent {st_ino=11078108, st_mode=40755, st_nlink=10, st_uid=0, st_gid=0, st_size=4096, st_blocks=8, st_atime=[Apr 02 23:02:55], st_mtime=[Jan 27 08:30:02], st_ctime=[Apr 02 23:08:13]}
[2010-04-04 10:35:27] N [trace.c:1289:trace_lookup] trace-after: 5: (loc {path=/s/t/nunki-0-test, ino=0})
[2010-04-04 10:35:27] N [trace.c:1289:trace_lookup] trace-before: 5: (loc {path=/s/t/nunki-0-test, ino=0})
[2010-04-04 10:35:27] N [trace.c:590:trace_lookup_cbk] trace-before: 5: (op_ret=0, ino=0, *buf {st_ino=11196338, st_mode=40755, st_nlink=9, st_uid=0, st_gid=0, st_size=4096, st_blocks=8, st_atime=[Apr 02 23:08:14], st_mtime=[Feb 18 09:51:02], st_ctime=[Apr 02 23:13:34]}, *postparent {st_ino=11196338, st_mode=40755, st_nlink=9, st_uid=0, st_gid=0, st_size=4096, st_blocks=8, st_atime=[Apr 02 23:08:14], st_mtime=[Feb 18 09:51:02], st_ctime=[Apr 02 23:13:34]}
[2010-04-04 10:35:27] N [trace.c:590:trace_lookup_cbk] trace-after: 5: (op_ret=0, ino=0, *buf {st_ino=11196338, st_mode=40755, st_nlink=9, st_uid=0, st_gid=0, st_size=4096, st_blocks=8, st_atime=[Apr 02 23:08:14], st_mtime=[Feb 18 09:51:02], st_ctime=[Apr 02 23:13:34]}, *postparent {st_ino=11196338, st_mode=40755, st_nlink=9, st_uid=0, st_gid=0, st_size=4096, st_blocks=8, st_atime=[Apr 02 23:08:14], st_mtime=[Feb 18 09:51:02], st_ctime=[Apr 02 23:13:34]}
[2010-04-04 10:35:27] N [trace.c:1289:trace_lookup] trace-after: 6: (loc {path=/s/t/nunki-0-test/cgi-bin, ino=0})
[2010-04-04 10:35:27] N [trace.c:1289:trace_lookup] trace-before: 6: (loc {path=/s/t/nunki-0-test/cgi-bin, ino=0})
[2010-04-04 10:35:27] N [trace.c:590:trace_lookup_cbk] trace-before: 6: (op_ret=0, ino=0, *buf {st_ino=13011334, st_mode=40755, st_nlink=2, st_uid=0, st_gid=0, st_size=4096, st_blocks=8, st_atime=[Apr 02 23:08:14], st_mtime=[Mar 22 18:43:28], st_ctime=[Apr 02 23:13:32]}, *postparent {st_ino=13011334, st_mode=40755, st_nlink=2, st_uid=0, st_gid=0, st_size=4096, st_blocks=8, st_atime=[Apr 02 23:08:14], st_mtime=[Mar 22 18:43:28], st_ctime=[Apr 02 23:13:32]}
[2010-04-04 10:35:27] N [trace.c:590:trace_lookup_cbk] trace-after: 6: (op_ret=0, ino=0, *buf {st_ino=13011334, st_mode=40755, st_nlink=2, st_uid=0, st_gid=0, st_size=4096, st_blocks=8, st_atime=[Apr 02 23:08:14], st_mtime=[Mar 22 18:43:28], st_ctime=[Apr 02 23:13:32]}, *postparent {st_ino=13011334, st_mode=40755, st_nlink=2, st_uid=0, st_gid=0, st_size=4096, st_blocks=8, st_atime=[Apr 02 23:08:14], st_mtime=[Mar 22 18:43:28], st_ctime=[Apr 02 23:13:32]}
[2010-04-04 10:35:27] N [trace.c:1289:trace_lookup] trace-after: 7: (loc {path=/s/t/nunki-0-test/cgi-bin/php5-fcgi, ino=0})
[2010-04-04 10:35:27] N [trace.c:1289:trace_lookup] trace-before: 7: (loc {path=/s/t/nunki-0-test/cgi-bin/php5-fcgi, ino=0})
[2010-04-04 10:35:27] N [trace.c:590:trace_lookup_cbk] trace-before: 7: (op_ret=0, ino=0, *buf {st_ino=13013446, st_mode=100755, st_nlink=1, st_uid=0, st_gid=0, st_size=671, st_blocks=8, st_atime=[Apr 02 23:08:11], st_mtime=[Mar 22 18:43:28], st_ctime=[Apr 02 23:13:31]}, *postparent {st_ino=13013446, st_mode=100755, st_nlink=1, st_uid=0, st_gid=0, st_size=671, st_blocks=8, st_atime=[Apr 02 23:08:11], st_mtime=[Mar 22 18:43:28], st_ctime=[Apr 02 23:13:31]}
[2010-04-04 10:35:27] N [trace.c:590:trace_lookup_cbk] trace-after: 7: (op_ret=0, ino=0, *buf {st_ino=13013446, st_mode=100755, st_nlink=1, st_uid=0, st_gid=0, st_size=671, st_blocks=8, st_atime=[Apr 02 23:08:11], st_mtime=[Mar 22 18:43:28], st_ctime=[Apr 02 23:13:31]}, *postparent {st_ino=13013446, st_mode=100755, st_nlink=1, st_uid=0, st_gid=0, st_size=671, st_blocks=8, st_atime=[Apr 02 23:08:11], st_mtime=[Mar 22 18:43:28], st_ctime=[Apr 02 23:13:31]}
[2010-04-04 10:35:27] N [trace.c:1587:trace_open] trace-after: 8: (loc {path=/s/t/nunki-0-test/cgi-bin/php5-fcgi, ino=13013446}, flags=32768, fd=0x7fa708000990, wbflags=0)
[2010-04-04 10:35:27] N [trace.c:1587:trace_open] trace-before: 8: (loc {path=/s/t/nunki-0-test/cgi-bin/php5-fcgi, ino=13013446}, flags=32768, fd=0x7fa708000990, wbflags=0)
[2010-04-04 10:35:27] N [trace.c:142:trace_open_cbk] trace-before: 8: (op_ret=0, op_errno=117, *fd=0x7fa708000990)
[2010-04-04 10:35:27] N [trace.c:142:trace_open_cbk] trace-after: 8: (op_ret=0, op_errno=117, *fd=0x7fa708000990)
[2010-04-04 10:35:27] N [trace.c:1623:trace_readv] trace-after: 9: (*fd=0x7fa708000990, size=4096, offset=0)
[2010-04-04 10:35:27] N [trace.c:1623:trace_readv] trace-before: 9: (*fd=0x7fa708000990, size=131072, offset=0)
[2010-04-04 10:35:27] N [trace.c:211:trace_readv_cbk] trace-before: 9: (op_ret=671, *buf {st_dev=5455183987250385959, st_ino=13013446, st_mode=100755, st_nlink=1, st_uid=0, st_gid=0, st_rdev=0, st_size=671, st_blksize=4096, st_blocks=8, st_atime=[Apr 02 23:08:11], st_mtime=[Mar 22 18:43:28], st_ctime=[Apr 02 23:13:31]})
[2010-04-04 10:35:27] N [trace.c:211:trace_readv_cbk] trace-after: 9: (op_ret=671, *buf {st_dev=0, st_ino=0, st_mode=0, st_nlink=0, st_uid=0, st_gid=0, st_rdev=0, st_size=0, st_blksize=0, st_blocks=0, st_atime=[Jan 01 01:00:00], st_mtime=[Jan 01 01:00:00], st_ctime=[Jan 01 01:00:00]})
[2010-04-04 10:35:30] N [trace.c:1289:trace_lookup] trace-after: 13: (loc {path=/, ino=1})
[2010-04-04 10:35:30] N [trace.c:1289:trace_lookup] trace-before: 13: (loc {path=/, ino=1})
[2010-04-04 10:35:30] N [trace.c:590:trace_lookup_cbk] trace-before: 13: (op_ret=0, ino=1, *buf {st_ino=1, st_mode=40755, st_nlink=30, st_uid=0, st_gid=0, st_size=4096, st_blocks=16, st_atime=[Apr 01 17:00:11], st_mtime=[Apr 01 17:17:42], st_ctime=[Apr 01 17:17:42]}, *postparent {st_ino=1, st_mode=40755, st_nlink=30, st_uid=0, st_gid=0, st_size=4096, st_blocks=16, st_atime=[Apr 01 17:00:11], st_mtime=[Apr 01 17:17:42], st_ctime=[Apr 01 17:17:42]}
[2010-04-04 10:35:30] N [trace.c:590:trace_lookup_cbk] trace-after: 13: (op_ret=0, ino=1, *buf {st_ino=1, st_mode=40755, st_nlink=30, st_uid=0, st_gid=0, st_size=4096, st_blocks=16, st_atime=[Apr 01 17:00:11], st_mtime=[Apr 01 17:17:42], st_ctime=[Apr 01 17:17:42]}, *postparent {st_ino=1, st_mode=40755, st_nlink=30, st_uid=0, st_gid=0, st_size=4096, st_blocks=16, st_atime=[Apr 01 17:00:11], st_mtime=[Apr 01 17:17:42], st_ctime=[Apr 01 17:17:42]}
[2010-04-04 10:35:30] N [trace.c:1289:trace_lookup] trace-after: 14: (loc {path=/s, ino=85983234})
[2010-04-04 10:35:30] N [trace.c:1289:trace_lookup] trace-before: 14: (loc {path=/s, ino=85983234})
[2010-04-04 10:35:30] N [trace.c:590:trace_lookup_cbk] trace-before: 14: (op_ret=0, ino=85983234, *buf {st_ino=85983234, st_mode=40755, st_nlink=16, st_uid=0, st_gid=0, st_size=4096, st_blocks=8, st_atime=[Apr 02 22:02:17], st_mtime=[Mar 09 09:31:01], st_ctime=[Apr 02 22:07:37]}, *postparent {st_ino=85983234, st_mode=40755, st_nlink=16, st_uid=0, st_gid=0, st_size=4096, st_blocks=8, st_atime=[Apr 02 22:02:17], st_mtime=[Mar 09 09:31:01], st_ctime=[Apr 02 22:07:37]}
[2010-04-04 10:35:30] N [trace.c:590:trace_lookup_cbk] trace-after: 14: (op_ret=0, ino=85983234, *buf {st_ino=85983234, st_mode=40755, st_nlink=16, st_uid=0, st_gid=0, st_size=4096, st_blocks=8, st_atime=[Apr 02 22:02:17], st_mtime=[Mar 09 09:31:01], st_ctime=[Apr 02 22:07:37]}, *postparent {st_ino=85983234, st_mode=40755, st_nlink=16, st_uid=0, st_gid=0, st_size=4096, st_blocks=8, st_atime=[Apr 02 22:02:17], st_mtime=[Mar 09 09:31:01], st_ctime=[Apr 02 22:07:37]}
[2010-04-04 10:35:30] N [trace.c:1289:trace_lookup] trace-after: 15: (loc {path=/s/t, ino=11078108})
[2010-04-04 10:35:30] N [trace.c:1289:trace_lookup] trace-before: 15: (loc {path=/s/t, ino=11078108})
[2010-04-04 10:35:30] N [trace.c:590:trace_lookup_cbk] trace-before: 15: (op_ret=0, ino=11078108, *buf {st_ino=11078108, st_mode=40755, st_nlink=10, st_uid=0, st_gid=0, st_size=4096, st_blocks=8, st_atime=[Apr 02 23:02:55], st_mtime=[Jan 27 08:30:02], st_ctime=[Apr 02 23:08:13]}, *postparent {st_ino=11078108, st_mode=40755, st_nlink=10, st_uid=0, st_gid=0, st_size=4096, st_blocks=8, st_atime=[Apr 02 23:02:55], st_mtime=[Jan 27 08:30:02], st_ctime=[Apr 02 23:08:13]}
[2010-04-04 10:35:30] N [trace.c:590:trace_lookup_cbk] trace-after: 15: (op_ret=0, ino=11078108, *buf {st_ino=11078108, st_mode=40755, st_nlink=10, st_uid=0, st_gid=0, st_size=4096, st_blocks=8, st_atime=[Apr 02 23:02:55], st_mtime=[Jan 27 08:30:02], st_ctime=[Apr 02 23:08:13]}, *postparent {st_ino=11078108, st_mode=40755, st_nlink=10, st_uid=0, st_gid=0, st_size=4096, st_blocks=8, st_atime=[Apr 02 23:02:55], st_mtime=[Jan 27 08:30:02], st_ctime=[Apr 02 23:08:13]}
[2010-04-04 10:35:30] N [trace.c:1289:trace_lookup] trace-after: 16: (loc {path=/s/t/nunki-0-test, ino=11196338})
[2010-04-04 10:35:30] N [trace.c:1289:trace_lookup] trace-before: 16: (loc {path=/s/t/nunki-0-test, ino=11196338})
[2010-04-04 10:35:30] N [trace.c:590:trace_lookup_cbk] trace-before: 16: (op_ret=0, ino=11196338, *buf {st_ino=11196338, st_mode=40755, st_nlink=9, st_uid=0, st_gid=0, st_size=4096, st_blocks=8, st_atime=[Apr 02 23:08:14], st_mtime=[Feb 18 09:51:02], st_ctime=[Apr 02 23:13:34]}, *postparent {st_ino=11196338, st_mode=40755, st_nlink=9, st_uid=0, st_gid=0, st_size=4096, st_blocks=8, st_atime=[Apr 02 23:08:14], st_mtime=[Feb 18 09:51:02], st_ctime=[Apr 02 23:13:34]}
[2010-04-04 10:35:30] N [trace.c:590:trace_lookup_cbk] trace-after: 16: (op_ret=0, ino=11196338, *buf {st_ino=11196338, st_mode=40755, st_nlink=9, st_uid=0, st_gid=0, st_size=4096, st_blocks=8, st_atime=[Apr 02 23:08:14], st_mtime=[Feb 18 09:51:02], st_ctime=[Apr 02 23:13:34]}, *postparent {st_ino=11196338, st_mode=40755, st_nlink=9, st_uid=0, st_gid=0, st_size=4096, st_blocks=8, st_atime=[Apr 02 23:08:14], st_mtime=[Feb 18 09:51:02], st_ctime=[Apr 02 23:13:34]}
[2010-04-04 10:35:30] N [trace.c:1289:trace_lookup] trace-after: 17: (loc {path=/s/t/nunki-0-test/cgi-bin, ino=13011334})
[2010-04-04 10:35:30] N [trace.c:1289:trace_lookup] trace-before: 17: (loc {path=/s/t/nunki-0-test/cgi-bin, ino=13011334})
[2010-04-04 10:35:30] N [trace.c:590:trace_lookup_cbk] trace-before: 17: (op_ret=0, ino=13011334, *buf {st_ino=13011334, st_mode=40755, st_nlink=2, st_uid=0, st_gid=0, st_size=4096, st_blocks=8, st_atime=[Apr 02 23:08:14], st_mtime=[Mar 22 18:43:28], st_ctime=[Apr 02 23:13:32]}, *postparent {st_ino=13011334, st_mode=40755, st_nlink=2, st_uid=0, st_gid=0, st_size=4096, st_blocks=8, st_atime=[Apr 02 23:08:14], st_mtime=[Mar 22 18:43:28], st_ctime=[Apr 02 23:13:32]}
[2010-04-04 10:35:30] N [trace.c:590:trace_lookup_cbk] trace-after: 17: (op_ret=0, ino=13011334, *buf {st_ino=13011334, st_mode=40755, st_nlink=2, st_uid=0, st_gid=0, st_size=4096, st_blocks=8, st_atime=[Apr 02 23:08:14], st_mtime=[Mar 22 18:43:28], st_ctime=[Apr 02 23:13:32]}, *postparent {st_ino=13011334, st_mode=40755, st_nlink=2, st_uid=0, st_gid=0, st_size=4096, st_blocks=8, st_atime=[Apr 02 23:08:14], st_mtime=[Mar 22 18:43:28], st_ctime=[Apr 02 23:13:32]}
[2010-04-04 10:35:30] N [trace.c:1289:trace_lookup] trace-after: 18: (loc {path=/s/t/nunki-0-test/cgi-bin/php5-fcgi, ino=13013446})
[2010-04-04 10:35:30] N [trace.c:1289:trace_lookup] trace-before: 18: (loc {path=/s/t/nunki-0-test/cgi-bin/php5-fcgi, ino=13013446})
[2010-04-04 10:35:30] N [trace.c:590:trace_lookup_cbk] trace-before: 18: (op_ret=0, ino=13013446, *buf {st_ino=13013446, st_mode=100755, st_nlink=1, st_uid=0, st_gid=0, st_size=671, st_blocks=8, st_atime=[Apr 02 23:08:11], st_mtime=[Mar 22 18:43:28], st_ctime=[Apr 02 23:13:31]}, *postparent {st_ino=13013446, st_mode=100755, st_nlink=1, st_uid=0, st_gid=0, st_size=671, st_blocks=8, st_atime=[Apr 02 23:08:11], st_mtime=[Mar 22 18:43:28], st_ctime=[Apr 02 23:13:31]}
[2010-04-04 10:35:30] N [trace.c:590:trace_lookup_cbk] trace-after: 18: (op_ret=0, ino=13013446, *buf {st_ino=13013446, st_mode=100755, st_nlink=1, st_uid=0, st_gid=0, st_size=671, st_blocks=8, st_atime=[Apr 02 23:08:11], st_mtime=[Mar 22 18:43:28], st_ctime=[Apr 02 23:13:31]}, *postparent {st_ino=13013446, st_mode=100755, st_nlink=1, st_uid=0, st_gid=0, st_size=671, st_blocks=8, st_atime=[Apr 02 23:08:11], st_mtime=[Mar 22 18:43:28], st_ctime=[Apr 02 23:13:31]}
[2010-04-04 10:35:30] N [trace.c:1587:trace_open] trace-after: 19: (loc {path=/s/t/nunki-0-test/cgi-bin/php5-fcgi, ino=13013446}, flags=32768, fd=0x7fa708003700, wbflags=0)
[2010-04-04 10:35:30] N [trace.c:1587:trace_open] trace-before: 19: (loc {path=/s/t/nunki-0-test/cgi-bin/php5-fcgi, ino=13013446}, flags=32768, fd=0x7fa708003700, wbflags=0)
[2010-04-04 10:35:30] N [trace.c:142:trace_open_cbk] trace-before: 19: (op_ret=0, op_errno=117, *fd=0x7fa708003700)
[2010-04-04 10:35:30] N [trace.c:142:trace_open_cbk] trace-after: 19: (op_ret=0, op_errno=117, *fd=0x7fa708003700)
[2010-04-04 10:35:30] N [trace.c:1623:trace_readv] trace-after: 20: (*fd=0x7fa708003700, size=4096, offset=0)
[2010-04-04 10:35:30] N [trace.c:211:trace_readv_cbk] trace-after: 20: (op_ret=671, *buf {st_dev=0, st_ino=0, st_mode=0, st_nlink=0, st_uid=0, st_gid=0, st_rdev=0, st_size=0, st_blksize=0, st_blocks=0, st_atime=[Jan 01 01:00:00], st_mtime=[Jan 01 01:00:00], st_ctime=[Jan 01 01:00:00]})
[2010-04-04 10:35:32] N [trace.c:1289:trace_lookup] trace-after: 24: (loc {path=/, ino=1})
[2010-04-04 10:35:32] N [trace.c:1289:trace_lookup] trace-before: 24: (loc {path=/, ino=1})
[2010-04-04 10:35:32] N [trace.c:590:trace_lookup_cbk] trace-before: 24: (op_ret=0, ino=1, *buf {st_ino=1, st_mode=40755, st_nlink=30, st_uid=0, st_gid=0, st_size=4096, st_blocks=16, st_atime=[Apr 01 17:00:11], st_mtime=[Apr 01 17:17:42], st_ctime=[Apr 01 17:17:42]}, *postparent {st_ino=1, st_mode=40755, st_nlink=30, st_uid=0, st_gid=0, st_size=4096, st_blocks=16, st_atime=[Apr 01 17:00:11], st_mtime=[Apr 01 17:17:42], st_ctime=[Apr 01 17:17:42]}
[2010-04-04 10:35:32] N [trace.c:590:trace_lookup_cbk] trace-after: 24: (op_ret=0, ino=1, *buf {st_ino=1, st_mode=40755, st_nlink=30, st_uid=0, st_gid=0, st_size=4096, st_blocks=16, st_atime=[Apr 01 17:00:11], st_mtime=[Apr 01 17:17:42], st_ctime=[Apr 01 17:17:42]}, *postparent {st_ino=1, st_mode=40755, st_nlink=30, st_uid=0, st_gid=0, st_size=4096, st_blocks=16, st_atime=[Apr 01 17:00:11], st_mtime=[Apr 01 17:17:42], st_ctime=[Apr 01 17:17:42]}
[2010-04-04 10:35:32] N [trace.c:1289:trace_lookup] trace-after: 25: (loc {path=/s, ino=85983234})
[2010-04-04 10:35:32] N [trace.c:1289:trace_lookup] trace-before: 25: (loc {path=/s, ino=85983234})
[2010-04-04 10:35:32] N [trace.c:590:trace_lookup_cbk] trace-before: 25: (op_ret=0, ino=85983234, *buf {st_ino=85983234, st_mode=40755, st_nlink=16, st_uid=0, st_gid=0, st_size=4096, st_blocks=8, st_atime=[Apr 02 22:02:17], st_mtime=[Mar 09 09:31:01], st_ctime=[Apr 02 22:07:37]}, *postparent {st_ino=85983234, st_mode=40755, st_nlink=16, st_uid=0, st_gid=0, st_size=4096, st_blocks=8, st_atime=[Apr 02 22:02:17], st_mtime=[Mar 09 09:31:01], st_ctime=[Apr 02 22:07:37]}
[2010-04-04 10:35:32] N [trace.c:590:trace_lookup_cbk] trace-after: 25: (op_ret=0, ino=85983234, *buf {st_ino=85983234, st_mode=40755, st_nlink=16, st_uid=0, st_gid=0, st_size=4096, st_blocks=8, st_atime=[Apr 02 22:02:17], st_mtime=[Mar 09 09:31:01], st_ctime=[Apr 02 22:07:37]}, *postparent {st_ino=85983234, st_mode=40755, st_nlink=16, st_uid=0, st_gid=0, st_size=4096, st_blocks=8, st_atime=[Apr 02 22:02:17], st_mtime=[Mar 09 09:31:01], st_ctime=[Apr 02 22:07:37]}
[2010-04-04 10:35:32] N [trace.c:1289:trace_lookup] trace-after: 26: (loc {path=/s/t, ino=11078108})
[2010-04-04 10:35:32] N [trace.c:1289:trace_lookup] trace-before: 26: (loc {path=/s/t, ino=11078108})
[2010-04-04 10:35:32] N [trace.c:590:trace_lookup_cbk] trace-before: 26: (op_ret=0, ino=11078108, *buf {st_ino=11078108, st_mode=40755, st_nlink=10, st_uid=0, st_gid=0, st_size=4096, st_blocks=8, st_atime=[Apr 02 23:02:55], st_mtime=[Jan 27 08:30:02], st_ctime=[Apr 02 23:08:13]}, *postparent {st_ino=11078108, st_mode=40755, st_nlink=10, st_uid=0, st_gid=0, st_size=4096, st_blocks=8, st_atime=[Apr 02 23:02:55], st_mtime=[Jan 27 08:30:02], st_ctime=[Apr 02 23:08:13]}
[2010-04-04 10:35:32] N [trace.c:590:trace_lookup_cbk] trace-after: 26: (op_ret=0, ino=11078108, *buf {st_ino=11078108, st_mode=40755, st_nlink=10, st_uid=0, st_gid=0, st_size=4096, st_blocks=8, st_atime=[Apr 02 23:02:55], st_mtime=[Jan 27 08:30:02], st_ctime=[Apr 02 23:08:13]}, *postparent {st_ino=11078108, st_mode=40755, st_nlink=10, st_uid=0, st_gid=0, st_size=4096, st_blocks=8, st_atime=[Apr 02 23:02:55], st_mtime=[Jan 27 08:30:02], st_ctime=[Apr 02 23:08:13]}
[2010-04-04 10:35:32] N [trace.c:1289:trace_lookup] trace-after: 27: (loc {path=/s/t/nunki-0-test, ino=11196338})
[2010-04-04 10:35:32] N [trace.c:1289:trace_lookup] trace-before: 27: (loc {path=/s/t/nunki-0-test, ino=11196338})
[2010-04-04 10:35:32] N [trace.c:590:trace_lookup_cbk] trace-before: 27: (op_ret=0, ino=11196338, *buf {st_ino=11196338, st_mode=40755, st_nlink=9, st_uid=0, st_gid=0, st_size=4096, st_blocks=8, st_atime=[Apr 02 23:08:14], st_mtime=[Feb 18 09:51:02], st_ctime=[Apr 02 23:13:34]}, *postparent {st_ino=11196338, st_mode=40755, st_nlink=9, st_uid=0, st_gid=0, st_size=4096, st_blocks=8, st_atime=[Apr 02 23:08:14], st_mtime=[Feb 18 09:51:02], st_ctime=[Apr 02 23:13:34]}
[2010-04-04 10:35:32] N [trace.c:590:trace_lookup_cbk] trace-after: 27: (op_ret=0, ino=11196338, *buf {st_ino=11196338, st_mode=40755, st_nlink=9, st_uid=0, st_gid=0, st_size=4096, st_blocks=8, st_atime=[Apr 02 23:08:14], st_mtime=[Feb 18 09:51:02], st_ctime=[Apr 02 23:13:34]}, *postparent {st_ino=11196338, st_mode=40755, st_nlink=9, st_uid=0, st_gid=0, st_size=4096, st_blocks=8, st_atime=[Apr 02 23:08:14], st_mtime=[Feb 18 09:51:02], st_ctime=[Apr 02 23:13:34]}
[2010-04-04 10:35:32] N [trace.c:1289:trace_lookup] trace-after: 28: (loc {path=/s/t/nunki-0-test/cgi-bin, ino=13011334})
[2010-04-04 10:35:32] N [trace.c:1289:trace_lookup] trace-before: 28: (loc {path=/s/t/nunki-0-test/cgi-bin, ino=13011334})
[2010-04-04 10:35:32] N [trace.c:590:trace_lookup_cbk] trace-before: 28: (op_ret=0, ino=13011334, *buf {st_ino=13011334, st_mode=40755, st_nlink=2, st_uid=0, st_gid=0, st_size=4096, st_blocks=8, st_atime=[Apr 02 23:08:14], st_mtime=[Mar 22 18:43:28], st_ctime=[Apr 02 23:13:32]}, *postparent {st_ino=13011334, st_mode=40755, st_nlink=2, st_uid=0, st_gid=0, st_size=4096, st_blocks=8, st_atime=[Apr 02 23:08:14], st_mtime=[Mar 22 18:43:28], st_ctime=[Apr 02 23:13:32]}
[2010-04-04 10:35:32] N [trace.c:590:trace_lookup_cbk] trace-after: 28: (op_ret=0, ino=13011334, *buf {st_ino=13011334, st_mode=40755, st_nlink=2, st_uid=0, st_gid=0, st_size=4096, st_blocks=8, st_atime=[Apr 02 23:08:14], st_mtime=[Mar 22 18:43:28], st_ctime=[Apr 02 23:13:32]}, *postparent {st_ino=13011334, st_mode=40755, st_nlink=2, st_uid=0, st_gid=0, st_size=4096, st_blocks=8, st_atime=[Apr 02 23:08:14], st_mtime=[Mar 22 18:43:28], st_ctime=[Apr 02 23:13:32]}
[2010-04-04 10:35:32] N [trace.c:1289:trace_lookup] trace-after: 29: (loc {path=/s/t/nunki-0-test/cgi-bin/php5-fcgi, ino=13013446})
[2010-04-04 10:35:32] N [trace.c:1289:trace_lookup] trace-before: 29: (loc {path=/s/t/nunki-0-test/cgi-bin/php5-fcgi, ino=13013446})
[2010-04-04 10:35:32] N [trace.c:590:trace_lookup_cbk] trace-before: 29: (op_ret=0, ino=13013446, *buf {st_ino=13013446, st_mode=100755, st_nlink=1, st_uid=0, st_gid=0, st_size=671, st_blocks=8, st_atime=[Apr 02 23:08:11], st_mtime=[Mar 22 18:43:28], st_ctime=[Apr 02 23:13:31]}, *postparent {st_ino=13013446, st_mode=100755, st_nlink=1, st_uid=0, st_gid=0, st_size=671, st_blocks=8, st_atime=[Apr 02 23:08:11], st_mtime=[Mar 22 18:43:28], st_ctime=[Apr 02 23:13:31]}
[2010-04-04 10:35:32] N [trace.c:590:trace_lookup_cbk] trace-after: 29: (op_ret=0, ino=13013446, *buf {st_ino=13013446, st_mode=100755, st_nlink=1, st_uid=0, st_gid=0, st_size=671, st_blocks=8, st_atime=[Apr 02 23:08:11], st_mtime=[Mar 22 18:43:28], st_ctime=[Apr 02 23:13:31]}, *postparent {st_ino=13013446, st_mode=100755, st_nlink=1, st_uid=0, st_gid=0, st_size=671, st_blocks=8, st_atime=[Apr 02 23:08:11], st_mtime=[Mar 22 18:43:28], st_ctime=[Apr 02 23:13:31]}
[2010-04-04 10:35:32] N [trace.c:1587:trace_open] trace-after: 30: (loc {path=/s/t/nunki-0-test/cgi-bin/php5-fcgi, ino=13013446}, flags=32768, fd=0x7fa708000990, wbflags=0)
[2010-04-04 10:35:32] N [trace.c:1587:trace_open] trace-before: 30: (loc {path=/s/t/nunki-0-test/cgi-bin/php5-fcgi, ino=13013446}, flags=32768, fd=0x7fa708000990, wbflags=0)
[2010-04-04 10:35:32] N [trace.c:142:trace_open_cbk] trace-before: 30: (op_ret=0, op_errno=117, *fd=0x7fa708000990)
[2010-04-04 10:35:32] N [trace.c:142:trace_open_cbk] trace-after: 30: (op_ret=0, op_errno=117, *fd=0x7fa708000990)
[2010-04-04 10:35:32] N [trace.c:1623:trace_readv] trace-after: 31: (*fd=0x7fa708000990, size=4096, offset=0)
[2010-04-04 10:35:32] N [trace.c:211:trace_readv_cbk] trace-after: 31: (op_ret=671, *buf {st_dev=0, st_ino=0, st_mode=0, st_nlink=0, st_uid=0, st_gid=0, st_rdev=0, st_size=0, st_blksize=0, st_blocks=0, st_atime=[Jan 01 01:00:00], st_mtime=[Jan 01 01:00:00], st_ctime=[Jan 01 01:00:00]})
[2010-04-04 10:39:31] N [trace.c:1289:trace_lookup] trace-after: 35: (loc {path=/, ino=1})
[2010-04-04 10:39:31] N [trace.c:1289:trace_lookup] trace-before: 35: (loc {path=/, ino=1})
[2010-04-04 10:39:31] N [trace.c:590:trace_lookup_cbk] trace-before: 35: (op_ret=0, ino=1, *buf {st_ino=1, st_mode=40755, st_nlink=30, st_uid=0, st_gid=0, st_size=4096, st_blocks=16, st_atime=[Apr 01 17:00:11], st_mtime=[Apr 01 17:17:42], st_ctime=[Apr 01 17:17:42]}, *postparent {st_ino=1, st_mode=40755, st_nlink=30, st_uid=0, st_gid=0, st_size=4096, st_blocks=16, st_atime=[Apr 01 17:00:11], st_mtime=[Apr 01 17:17:42], st_ctime=[Apr 01 17:17:42]}
[2010-04-04 10:39:31] N [trace.c:590:trace_lookup_cbk] trace-after: 35: (op_ret=0, ino=1, *buf {st_ino=1, st_mode=40755, st_nlink=30, st_uid=0, st_gid=0, st_size=4096, st_blocks=16, st_atime=[Apr 01 17:00:11], st_mtime=[Apr 01 17:17:42], st_ctime=[Apr 01 17:17:42]}, *postparent {st_ino=1, st_mode=40755, st_nlink=30, st_uid=0, st_gid=0, st_size=4096, st_blocks=16, st_atime=[Apr 01 17:00:11], st_mtime=[Apr 01 17:17:42], st_ctime=[Apr 01 17:17:42]}
[2010-04-04 10:39:31] N [trace.c:1289:trace_lookup] trace-after: 36: (loc {path=/s, ino=85983234})
[2010-04-04 10:39:31] N [trace.c:1289:trace_lookup] trace-before: 36: (loc {path=/s, ino=85983234})
[2010-04-04 10:39:31] N [trace.c:590:trace_lookup_cbk] trace-before: 36: (op_ret=0, ino=85983234, *buf {st_ino=85983234, st_mode=40755, st_nlink=16, st_uid=0, st_gid=0, st_size=4096, st_blocks=8, st_atime=[Apr 02 22:02:17], st_mtime=[Mar 09 09:31:01], st_ctime=[Apr 02 22:07:37]}, *postparent {st_ino=85983234, st_mode=40755, st_nlink=16, st_uid=0, st_gid=0, st_size=4096, st_blocks=8, st_atime=[Apr 02 22:02:17], st_mtime=[Mar 09 09:31:01], st_ctime=[Apr 02 22:07:37]}
[2010-04-04 10:39:31] N [trace.c:590:trace_lookup_cbk] trace-after: 36: (op_ret=0, ino=85983234, *buf {st_ino=85983234, st_mode=40755, st_nlink=16, st_uid=0, st_gid=0, st_size=4096, st_blocks=8, st_atime=[Apr 02 22:02:17], st_mtime=[Mar 09 09:31:01], st_ctime=[Apr 02 22:07:37]}, *postparent {st_ino=85983234, st_mode=40755, st_nlink=16, st_uid=0, st_gid=0, st_size=4096, st_blocks=8, st_atime=[Apr 02 22:02:17], st_mtime=[Mar 09 09:31:01], st_ctime=[Apr 02 22:07:37]}
[2010-04-04 10:39:31] N [trace.c:1289:trace_lookup] trace-after: 37: (loc {path=/s/t, ino=11078108})
[2010-04-04 10:39:31] N [trace.c:1289:trace_lookup] trace-before: 37: (loc {path=/s/t, ino=11078108})
[2010-04-04 10:39:31] N [trace.c:590:trace_lookup_cbk] trace-before: 37: (op_ret=0, ino=11078108, *buf {st_ino=11078108, st_mode=40755, st_nlink=10, st_uid=0, st_gid=0, st_size=4096, st_blocks=8, st_atime=[Apr 02 23:02:55], st_mtime=[Jan 27 08:30:02], st_ctime=[Apr 02 23:08:13]}, *postparent {st_ino=11078108, st_mode=40755, st_nlink=10, st_uid=0, st_gid=0, st_size=4096, st_blocks=8, st_atime=[Apr 02 23:02:55], st_mtime=[Jan 27 08:30:02], st_ctime=[Apr 02 23:08:13]}
[2010-04-04 10:39:31] N [trace.c:590:trace_lookup_cbk] trace-after: 37: (op_ret=0, ino=11078108, *buf {st_ino=11078108, st_mode=40755, st_nlink=10, st_uid=0, st_gid=0, st_size=4096, st_blocks=8, st_atime=[Apr 02 23:02:55], st_mtime=[Jan 27 08:30:02], st_ctime=[Apr 02 23:08:13]}, *postparent {st_ino=11078108, st_mode=40755, st_nlink=10, st_uid=0, st_gid=0, st_size=4096, st_blocks=8, st_atime=[Apr 02 23:02:55], st_mtime=[Jan 27 08:30:02], st_ctime=[Apr 02 23:08:13]}
[2010-04-04 10:39:31] N [trace.c:1289:trace_lookup] trace-after: 38: (loc {path=/s/t/nunki-0-test, ino=11196338})
[2010-04-04 10:39:31] N [trace.c:1289:trace_lookup] trace-before: 38: (loc {path=/s/t/nunki-0-test, ino=11196338})
[2010-04-04 10:39:31] N [trace.c:590:trace_lookup_cbk] trace-before: 38: (op_ret=0, ino=11196338, *buf {st_ino=11196338, st_mode=40755, st_nlink=9, st_uid=0, st_gid=0, st_size=4096, st_blocks=8, st_atime=[Apr 02 23:08:14], st_mtime=[Feb 18 09:51:02], st_ctime=[Apr 02 23:13:34]}, *postparent {st_ino=11196338, st_mode=40755, st_nlink=9, st_uid=0, st_gid=0, st_size=4096, st_blocks=8, st_atime=[Apr 02 23:08:14], st_mtime=[Feb 18 09:51:02], st_ctime=[Apr 02 23:13:34]}
[2010-04-04 10:39:31] N [trace.c:590:trace_lookup_cbk] trace-after: 38: (op_ret=0, ino=11196338, *buf {st_ino=11196338, st_mode=40755, st_nlink=9, st_uid=0, st_gid=0, st_size=4096, st_blocks=8, st_atime=[Apr 02 23:08:14], st_mtime=[Feb 18 09:51:02], st_ctime=[Apr 02 23:13:34]}, *postparent {st_ino=11196338, st_mode=40755, st_nlink=9, st_uid=0, st_gid=0, st_size=4096, st_blocks=8, st_atime=[Apr 02 23:08:14], st_mtime=[Feb 18 09:51:02], st_ctime=[Apr 02 23:13:34]}
[2010-04-04 10:39:31] N [trace.c:1289:trace_lookup] trace-after: 39: (loc {path=/s/t/nunki-0-test/cgi-bin, ino=13011334})
[2010-04-04 10:39:31] N [trace.c:1289:trace_lookup] trace-before: 39: (loc {path=/s/t/nunki-0-test/cgi-bin, ino=13011334})
[2010-04-04 10:39:31] N [trace.c:590:trace_lookup_cbk] trace-before: 39: (op_ret=0, ino=13011334, *buf {st_ino=13011334, st_mode=40755, st_nlink=2, st_uid=0, st_gid=0, st_size=4096, st_blocks=8, st_atime=[Apr 02 23:08:14], st_mtime=[Mar 22 18:43:28], st_ctime=[Apr 02 23:13:32]}, *postparent {st_ino=13011334, st_mode=40755, st_nlink=2, st_uid=0, st_gid=0, st_size=4096, st_blocks=8, st_atime=[Apr 02 23:08:14], st_mtime=[Mar 22 18:43:28], st_ctime=[Apr 02 23:13:32]}
[2010-04-04 10:39:31] N [trace.c:590:trace_lookup_cbk] trace-after: 39: (op_ret=0, ino=13011334, *buf {st_ino=13011334, st_mode=40755, st_nlink=2, st_uid=0, st_gid=0, st_size=4096, st_blocks=8, st_atime=[Apr 02 23:08:14], st_mtime=[Mar 22 18:43:28], st_ctime=[Apr 02 23:13:32]}, *postparent {st_ino=13011334, st_mode=40755, st_nlink=2, st_uid=0, st_gid=0, st_size=4096, st_blocks=8, st_atime=[Apr 02 23:08:14], st_mtime=[Mar 22 18:43:28], st_ctime=[Apr 02 23:13:32]}
[2010-04-04 10:39:31] N [trace.c:1289:trace_lookup] trace-after: 40: (loc {path=/s/t/nunki-0-test/cgi-bin/php5-fcgi, ino=13013446})
[2010-04-04 10:39:31] N [trace.c:1289:trace_lookup] trace-before: 40: (loc {path=/s/t/nunki-0-test/cgi-bin/php5-fcgi, ino=13013446})
[2010-04-04 10:39:31] N [trace.c:590:trace_lookup_cbk] trace-before: 40: (op_ret=0, ino=13013446, *buf {st_ino=13013446, st_mode=100755, st_nlink=1, st_uid=0, st_gid=0, st_size=671, st_blocks=8, st_atime=[Apr 02 23:08:11], st_mtime=[Mar 22 18:43:28], st_ctime=[Apr 02 23:13:31]}, *postparent {st_ino=13013446, st_mode=100755, st_nlink=1, st_uid=0, st_gid=0, st_size=671, st_blocks=8, st_atime=[Apr 02 23:08:11], st_mtime=[Mar 22 18:43:28], st_ctime=[Apr 02 23:13:31]}
[2010-04-04 10:39:31] N [trace.c:590:trace_lookup_cbk] trace-after: 40: (op_ret=0, ino=13013446, *buf {st_ino=13013446, st_mode=100755, st_nlink=1, st_uid=0, st_gid=0, st_size=671, st_blocks=8, st_atime=[Apr 02 23:08:11], st_mtime=[Mar 22 18:43:28], st_ctime=[Apr 02 23:13:31]}, *postparent {st_ino=13013446, st_mode=100755, st_nlink=1, st_uid=0, st_gid=0, st_size=671, st_blocks=8, st_atime=[Apr 02 23:08:11], st_mtime=[Mar 22 18:43:28], st_ctime=[Apr 02 23:13:31]}
[2010-04-04 10:39:31] N [trace.c:1587:trace_open] trace-after: 41: (loc {path=/s/t/nunki-0-test/cgi-bin/php5-fcgi, ino=13013446}, flags=32768, fd=0x7fa708002d30, wbflags=0)
[2010-04-04 10:39:31] N [trace.c:1587:trace_open] trace-before: 41: (loc {path=/s/t/nunki-0-test/cgi-bin/php5-fcgi, ino=13013446}, flags=32768, fd=0x7fa708002d30, wbflags=0)
[2010-04-04 10:39:31] N [trace.c:142:trace_open_cbk] trace-before: 41: (op_ret=0, op_errno=117, *fd=0x7fa708002d30)
[2010-04-04 10:39:31] N [trace.c:142:trace_open_cbk] trace-after: 41: (op_ret=0, op_errno=117, *fd=0x7fa708002d30)
[2010-04-04 10:39:31] N [trace.c:1623:trace_readv] trace-after: 42: (*fd=0x7fa708002d30, size=4096, offset=0)
[2010-04-04 10:39:31] N [trace.c:211:trace_readv_cbk] trace-after: 42: (op_ret=671, *buf {st_dev=0, st_ino=0, st_mode=0, st_nlink=0, st_uid=0, st_gid=0, st_rdev=0, st_size=0, st_blksize=0, st_blocks=0, st_atime=[Jan 01 01:00:00], st_mtime=[Jan 01 01:00:00], st_ctime=[Jan 01 01:00:00]})
[2010-04-04 10:39:38] N [trace.c:1289:trace_lookup] trace-after: 46: (loc {path=/, ino=1})
[2010-04-04 10:39:38] N [trace.c:1289:trace_lookup] trace-before: 46: (loc {path=/, ino=1})
[2010-04-04 10:39:38] N [trace.c:590:trace_lookup_cbk] trace-before: 46: (op_ret=0, ino=1, *buf {st_ino=1, st_mode=40755, st_nlink=30, st_uid=0, st_gid=0, st_size=4096, st_blocks=16, st_atime=[Apr 01 17:00:11], st_mtime=[Apr 01 17:17:42], st_ctime=[Apr 01 17:17:42]}, *postparent {st_ino=1, st_mode=40755, st_nlink=30, st_uid=0, st_gid=0, st_size=4096, st_blocks=16, st_atime=[Apr 01 17:00:11], st_mtime=[Apr 01 17:17:42], st_ctime=[Apr 01 17:17:42]}
[2010-04-04 10:39:38] N [trace.c:590:trace_lookup_cbk] trace-after: 46: (op_ret=0, ino=1, *buf {st_ino=1, st_mode=40755, st_nlink=30, st_uid=0, st_gid=0, st_size=4096, st_blocks=16, st_atime=[Apr 01 17:00:11], st_mtime=[Apr 01 17:17:42], st_ctime=[Apr 01 17:17:42]}, *postparent {st_ino=1, st_mode=40755, st_nlink=30, st_uid=0, st_gid=0, st_size=4096, st_blocks=16, st_atime=[Apr 01 17:00:11], st_mtime=[Apr 01 17:17:42], st_ctime=[Apr 01 17:17:42]}
[2010-04-04 10:39:38] N [trace.c:1289:trace_lookup] trace-after: 47: (loc {path=/s, ino=85983234})
[2010-04-04 10:39:38] N [trace.c:1289:trace_lookup] trace-before: 47: (loc {path=/s, ino=85983234})
[2010-04-04 10:39:38] N [trace.c:590:trace_lookup_cbk] trace-before: 47: (op_ret=0, ino=85983234, *buf {st_ino=85983234, st_mode=40755, st_nlink=16, st_uid=0, st_gid=0, st_size=4096, st_blocks=8, st_atime=[Apr 02 22:02:17], st_mtime=[Mar 09 09:31:01], st_ctime=[Apr 02 22:07:37]}, *postparent {st_ino=85983234, st_mode=40755, st_nlink=16, st_uid=0, st_gid=0, st_size=4096, st_blocks=8, st_atime=[Apr 02 22:02:17], st_mtime=[Mar 09 09:31:01], st_ctime=[Apr 02 22:07:37]}
[2010-04-04 10:39:38] N [trace.c:590:trace_lookup_cbk] trace-after: 47: (op_ret=0, ino=85983234, *buf {st_ino=85983234, st_mode=40755, st_nlink=16, st_uid=0, st_gid=0, st_size=4096, st_blocks=8, st_atime=[Apr 02 22:02:17], st_mtime=[Mar 09 09:31:01], st_ctime=[Apr 02 22:07:37]}, *postparent {st_ino=85983234, st_mode=40755, st_nlink=16, st_uid=0, st_gid=0, st_size=4096, st_blocks=8, st_atime=[Apr 02 22:02:17], st_mtime=[Mar 09 09:31:01], st_ctime=[Apr 02 22:07:37]}
[2010-04-04 10:39:38] N [trace.c:1289:trace_lookup] trace-after: 48: (loc {path=/s/t, ino=11078108})
[2010-04-04 10:39:38] N [trace.c:1289:trace_lookup] trace-before: 48: (loc {path=/s/t, ino=11078108})
[2010-04-04 10:39:38] N [trace.c:590:trace_lookup_cbk] trace-before: 48: (op_ret=0, ino=11078108, *buf {st_ino=11078108, st_mode=40755, st_nlink=10, st_uid=0, st_gid=0, st_size=4096, st_blocks=8, st_atime=[Apr 02 23:02:55], st_mtime=[Jan 27 08:30:02], st_ctime=[Apr 02 23:08:13]}, *postparent {st_ino=11078108, st_mode=40755, st_nlink=10, st_uid=0, st_gid=0, st_size=4096, st_blocks=8, st_atime=[Apr 02 23:02:55], st_mtime=[Jan 27 08:30:02], st_ctime=[Apr 02 23:08:13]}
[2010-04-04 10:39:38] N [trace.c:590:trace_lookup_cbk] trace-after: 48: (op_ret=0, ino=11078108, *buf {st_ino=11078108, st_mode=40755, st_nlink=10, st_uid=0, st_gid=0, st_size=4096, st_blocks=8, st_atime=[Apr 02 23:02:55], st_mtime=[Jan 27 08:30:02], st_ctime=[Apr 02 23:08:13]}, *postparent {st_ino=11078108, st_mode=40755, st_nlink=10, st_uid=0, st_gid=0, st_size=4096, st_blocks=8, st_atime=[Apr 02 23:02:55], st_mtime=[Jan 27 08:30:02], st_ctime=[Apr 02 23:08:13]}
[2010-04-04 10:39:38] N [trace.c:1289:trace_lookup] trace-after: 49: (loc {path=/s/t/nunki-0-test, ino=11196338})
[2010-04-04 10:39:38] N [trace.c:1289:trace_lookup] trace-before: 49: (loc {path=/s/t/nunki-0-test, ino=11196338})
[2010-04-04 10:39:38] N [trace.c:590:trace_lookup_cbk] trace-before: 49: (op_ret=0, ino=11196338, *buf {st_ino=11196338, st_mode=40755, st_nlink=9, st_uid=0, st_gid=0, st_size=4096, st_blocks=8, st_atime=[Apr 02 23:08:14], st_mtime=[Feb 18 09:51:02], st_ctime=[Apr 02 23:13:34]}, *postparent {st_ino=11196338, st_mode=40755, st_nlink=9, st_uid=0, st_gid=0, st_size=4096, st_blocks=8, st_atime=[Apr 02 23:08:14], st_mtime=[Feb 18 09:51:02], st_ctime=[Apr 02 23:13:34]}
[2010-04-04 10:39:38] N [trace.c:590:trace_lookup_cbk] trace-after: 49: (op_ret=0, ino=11196338, *buf {st_ino=11196338, st_mode=40755, st_nlink=9, st_uid=0, st_gid=0, st_size=4096, st_blocks=8, st_atime=[Apr 02 23:08:14], st_mtime=[Feb 18 09:51:02], st_ctime=[Apr 02 23:13:34]}, *postparent {st_ino=11196338, st_mode=40755, st_nlink=9, st_uid=0, st_gid=0, st_size=4096, st_blocks=8, st_atime=[Apr 02 23:08:14], st_mtime=[Feb 18 09:51:02], st_ctime=[Apr 02 23:13:34]}
[2010-04-04 10:39:38] N [trace.c:1289:trace_lookup] trace-after: 50: (loc {path=/s/t/nunki-0-test/cgi-bin, ino=13011334})
[2010-04-04 10:39:38] N [trace.c:1289:trace_lookup] trace-before: 50: (loc {path=/s/t/nunki-0-test/cgi-bin, ino=13011334})
[2010-04-04 10:39:38] N [trace.c:590:trace_lookup_cbk] trace-before: 50: (op_ret=0, ino=13011334, *buf {st_ino=13011334, st_mode=40755, st_nlink=2, st_uid=0, st_gid=0, st_size=4096, st_blocks=8, st_atime=[Apr 02 23:08:14], st_mtime=[Mar 22 18:43:28], st_ctime=[Apr 02 23:13:32]}, *postparent {st_ino=13011334, st_mode=40755, st_nlink=2, st_uid=0, st_gid=0, st_size=4096, st_blocks=8, st_atime=[Apr 02 23:08:14], st_mtime=[Mar 22 18:43:28], st_ctime=[Apr 02 23:13:32]}
[2010-04-04 10:39:38] N [trace.c:590:trace_lookup_cbk] trace-after: 50: (op_ret=0, ino=13011334, *buf {st_ino=13011334, st_mode=40755, st_nlink=2, st_uid=0, st_gid=0, st_size=4096, st_blocks=8, st_atime=[Apr 02 23:08:14], st_mtime=[Mar 22 18:43:28], st_ctime=[Apr 02 23:13:32]}, *postparent {st_ino=13011334, st_mode=40755, st_nlink=2, st_uid=0, st_gid=0, st_size=4096, st_blocks=8, st_atime=[Apr 02 23:08:14], st_mtime=[Mar 22 18:43:28], st_ctime=[Apr 02 23:13:32]}
[2010-04-04 10:39:38] N [trace.c:1289:trace_lookup] trace-after: 51: (loc {path=/s/t/nunki-0-test/cgi-bin/php5-fcgi, ino=13013446})
[2010-04-04 10:39:38] N [trace.c:1289:trace_lookup] trace-before: 51: (loc {path=/s/t/nunki-0-test/cgi-bin/php5-fcgi, ino=13013446})
[2010-04-04 10:39:38] N [trace.c:590:trace_lookup_cbk] trace-before: 51: (op_ret=0, ino=13013446, *buf {st_ino=13013446, st_mode=100755, st_nlink=1, st_uid=0, st_gid=0, st_size=671, st_blocks=8, st_atime=[Apr 02 23:08:11], st_mtime=[Mar 22 18:43:28], st_ctime=[Apr 02 23:13:31]}, *postparent {st_ino=13013446, st_mode=100755, st_nlink=1, st_uid=0, st_gid=0, st_size=671, st_blocks=8, st_atime=[Apr 02 23:08:11], st_mtime=[Mar 22 18:43:28], st_ctime=[Apr 02 23:13:31]}
[2010-04-04 10:39:38] N [trace.c:590:trace_lookup_cbk] trace-after: 51: (op_ret=0, ino=13013446, *buf {st_ino=13013446, st_mode=100755, st_nlink=1, st_uid=0, st_gid=0, st_size=671, st_blocks=8, st_atime=[Apr 02 23:08:11], st_mtime=[Mar 22 18:43:28], st_ctime=[Apr 02 23:13:31]}, *postparent {st_ino=13013446, st_mode=100755, st_nlink=1, st_uid=0, st_gid=0, st_size=671, st_blocks=8, st_atime=[Apr 02 23:08:11], st_mtime=[Mar 22 18:43:28], st_ctime=[Apr 02 23:13:31]}
[2010-04-04 10:39:38] N [trace.c:1587:trace_open] trace-after: 52: (loc {path=/s/t/nunki-0-test/cgi-bin/php5-fcgi, ino=13013446}, flags=32768, fd=0x7fa708003700, wbflags=0)
[2010-04-04 10:39:38] N [trace.c:1587:trace_open] trace-before: 52: (loc {path=/s/t/nunki-0-test/cgi-bin/php5-fcgi, ino=13013446}, flags=32768, fd=0x7fa708003700, wbflags=0)
[2010-04-04 10:39:38] N [trace.c:142:trace_open_cbk] trace-before: 52: (op_ret=0, op_errno=117, *fd=0x7fa708003700)
[2010-04-04 10:39:38] N [trace.c:142:trace_open_cbk] trace-after: 52: (op_ret=0, op_errno=117, *fd=0x7fa708003700)
[2010-04-04 10:39:38] N [trace.c:1623:trace_readv] trace-after: 53: (*fd=0x7fa708003700, size=4096, offset=0)
[2010-04-04 10:39:38] N [trace.c:211:trace_readv_cbk] trace-after: 53: (op_ret=671, *buf {st_dev=0, st_ino=0, st_mode=0, st_nlink=0, st_uid=0, st_gid=0, st_rdev=0, st_size=0, st_blksize=0, st_blocks=0, st_atime=[Jan 01 01:00:00], st_mtime=[Jan 01 01:00:00], st_ctime=[Jan 01 01:00:00]})
