Re: [Gluster-devel] lookup caching

[Olivier Le Cam]

Raghavendra G wrote:
> On Fri, Apr 2, 2010 at 3:32 PM, Olivier Le Cam 
> <address@hidden 
> <mailto:address@hidden>> 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]})