Alan Hargreaves' Blog

The ramblings of an Australian SaND TSC* Principal Field Technologist

dtracing on the train – gnome-vfs-daemon

There was some discussion internally recently about using gnome-vfs-daemon as a process to start demonstrating dtrace with. As a result I thought it would be interesting to have a look at it on my notebook while coming to work on the train (about a 90 minute trip).

OK, first off, let’s have a look at the system calls. We could do this with

$ /usr/sbin/dtrace -n 'syscall:::entry/execname=="gnome-vfs-daemon"'

But that really generates a lot of output. One of the things that I do notice though is the following sequence repeating itself every three seconds.

0    397                     open64:entry
0    397                     open64:entry
0    103                      ioctl:entry
0    103                      ioctl:entry
0    103                      ioctl:entry
0    103                      ioctl:entry
0    103                      ioctl:entry
0    103                      ioctl:entry
0    103                      ioctl:entry
0    103                      ioctl:entry
0    103                      ioctl:entry
0    103                      ioctl:entry
0    103                      ioctl:entry
0    103                      ioctl:entry
0    103                      ioctl:entry
0    103                      ioctl:entry
0    103                      ioctl:entry
0    103                      ioctl:entry
0    103                      ioctl:entry
0    103                      ioctl:entry
0    309                     llseek:entry
0     17                      close:entry
0    317                    pollsys:entry

This peaked my interest. How about an aggregation over a minute?

$ /usr/sbin/dtrace -q -n '
syscall:::entry/execname=="gnome-vfs-daemon"/{
@p[probefunc] = count();
}
tick-1m {
printf("\nCount Syscall\n----- -------\n");
printa(" %@3d  %s\n",@p); exit(0);
}'
Count Syscall
----- -------
20  pollsys
20  close
20  llseek
40  open64
360  ioctl

So, for each pollsys() and close(), it looks like I am seeing two open64()s and 18 ioctl()s, and from earlier we know that we see two open64()s followed by the ioctl()s. Let’s have a closer look at these system calls. Also, while we are at it, let’s try and find out what the ioctl is. We now move to scripting files.

#!/usr/sbin/dtrace -s
syscall::ioctl:entry
/execname == "gnome-vfs-daemon"/
{
self->interest = timestamp;
self->fd = arg0;
self->cmd1 = (char)(arg1>>8);
self->cmd2 = arg1&0xff
}
syscall::ioctl:return
/self->interest/
{
printf("ioctl(%d, '%c'<fd,
self->cmd1,
self->cmd2,
(timestamp - self->interest)/1000
);
ustack();
self->interest = 0;
}
syscall::open64:entry
/execname == "gnome-vfs-daemon"/
{
self->file = copyinstr(arg0);
self->interest = 1;
}
syscall::open64:return
/self->interest/
{
printf("%s returns fd %d\n", self->file, (int)arg1);
ustack();
self->interest = 0;
}

An excerpt of the output shows

CPU     ID                    FUNCTION:NAME
0    398                    open64:return /etc/fstab returns fd -1
libc.so.1`__open64+0x15
libc.so.1`_endopen+0xa8
libc.so.1`fopen64+0x26
libgnomevfs-2.so.0.600.0`_gnome_vfs_get_unix_mount_table+0x3e
libglib-2.0.so.0.400.1`g_source_callback_funcs
libgnomevfs-2.so.0.600.0`poll_fstab
0    398                    open64:return /etc/mnttab returns fd 44
libc.so.1`__open64+0x15
libc.so.1`_endopen+0xa8
libc.so.1`fopen64+0x26
libgnomevfs-2.so.0.600.0`_gnome_vfs_get_current_unix_mounts+0x37
libglib-2.0.so.0.400.1`g_source_callback_funcs
libgnomevfs-2.so.0.600.0`poll_mtab
0    104                     ioctl:return ioctl(44, 'm'<<8|7, buf) took 232 us
libc.so.1`ioctl+0x15
libgnomevfs-2.so.0.600.0`_gnome_vfs_get_current_unix_mounts+0x55
0    104                     ioctl:return ioctl(44, 'm'<<8|7, buf) took 4 us
libc.so.1`ioctl+0x15
libgnomevfs-2.so.0.600.0`_gnome_vfs_get_current_unix_mounts+0xfe

OK, so we first attempt to open /etc/fstab, which obviously does not exist in solaris, then we open /etc/mnttab, which does. We then go and do lots of ioctl()s on it.

The 'm'<<8|7 (as well as being MTIOCGUARANTEEDORDER in sys/mtio.h) is apparantly MNTIOC_GETMNTENT (common/sys/mntio.h).

This has only gone back into Solaris 10 in the last few months. It’s generally called by getmntent(3C).

So basically, it looks like gnome-vfs-daemon is reading the mount table of the system every three seconds. This certainly seems like a lot of overkill. Indeed on the notebook I ran it on, if we try the following script

#!/usr/sbin/dtrace -s
syscall::ioctl:entry
/execname == "gnome-vfs-daemon"/
{
self->interest = timestamp;
}
syscall::ioctl:return
/self->interest/
{
@ioctl[probefunc] = quantize((timestamp - self->interest)/1000);
self->timestamp = 0;
}
syscall::open64:entry
{
self->interest = timestamp;
self->file = copyinstr(arg0);
}
syscall::open64:return {
@open64[self->file] = quantize((timestamp - self->interest)/1000);
self->timestamp = 0;
}
tick-1min {
printa (@ioctl);
printa (@open64);
exit(0)
}

We can look at just how much time is being spent (we could always actually sum the numbers, but I like looking at graphs).

ioctl
value  ------------- Distribution ------------- count
1 |                                         0
2 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@   340
4 |                                         0
8 |                                         0
16 |                                         0
32 |                                         0
64 |                                         0
128 |                                         0
256 |@@                                       20
512 |                                         0
/etc/fstab
value  ------------- Distribution ------------- count
8 |                                         0
16 |@@@@@@@@@@@@@@@@@@@@                     10
32 |@@@@@@@@@@@@@@@@@@@@                     10
64 |                                         0
/etc/mnttab
value  ------------- Distribution ------------- count
32 |                                         0
64 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 20
128 |                                         0

So, worst case on this system is 340*2 + 10*16 + 10*32 + 20*64 = 2440 microseconds every minute, or 122 microseconds every iteration. This might not initially sound like an awful lot to worry about. However, in this iteration, I am only seeing 81 mount points on my system and I only have one gnome-vfs-daemon running. The truly scary concept is when we start looking at this issue in the light of large sunray servers, say with 250-300 entries on the mount table and around 80 users (instances of gnome-vfs-daemon).

Fortunately there is an answer. If we lookat the man page on mnttab(4) we see

NOTES
The snapshot of the mnttab information is taken any  time  a
read(2)  is  performed  at  offset  0 (the beginning) of the
mnttab file. The file modification time returned by  stat(2)
for  the  mnttab  file  is  the  time  of the last change to
mounted file  system  information.  A  poll(2)  system  call
requesting  a POLLRDBAND event can be used to block and wait
for the system's mounted file system information to be  dif-
ferent  from  the most recent snapshot since the mnttab file
was opened.

So we actually only need to stat the file to see if the mount table has changed. This is a much more efficient way of doing things.

After logging a bug on this, the engineer who took it determined that the code to do the stat() was actually in there, but due to some faulty logic, it would never get executed. This is now logged into the gnome bugzilla as
152114 and
152115 and with luck should be fixed shortly.

Advertisements

Written by Alan

September 10, 2004 at 1:15 am

Posted in Solaris Express

%d bloggers like this: