Using DTrace to understand GNOME

I read with some interest about
the GNOME startup bounty.
As
Stephen O’Grady
pointed out, this problem is indeed perfect for
DTrace.
To get a feel for the problem, I wrote a very simple D script:

#!/usr/sbin/dtrace -s
#pragma D option quiet
proc:::exec-success
/execname == "gnome-session"/
{
start = timestamp;
go = 1;
}
io:::start
/go/
{
printf("%10d { -> I/O %d %s %s %s }\n",
(timestamp - start) / 1000000, pid, execname,
args[0]->b_flags & B_READ ? "reads" : "writes",
args[2]->fi_pathname);
}
io:::done
/go/
{
printf("%10d { fi_pathname);
}
io:::start
/go && ((struct buf *)arg0)->b_file != NULL &&
((struct buf *)arg0)->b_file->v_path == NULL/
{
printf("%10s   (vp %p)\n", "", ((struct buf *)arg0)->b_file);
}
io:::start
/go/
{
@apps[execname] = count();
@files[args[2]->fi_pathname] = count();
@appsfiles[execname, args[2]->fi_pathname] = count();
}
proc:::exec
/go/
{
self->parent = execname;
}
proc:::exec-success
/self->parent != NULL/
{
printf("%10d -> %d %s (from %d %s)\n",
(timestamp - start) / 1000000, pid, execname,
curpsinfo->pr_ppid, self->parent);
self->parent = NULL;
}
proc:::exit
/go/
{
printf("%10d pr_flag & PR_IDLE)/
{
printf("%10d [ idle ]\n",
(timestamp - start) / 1000000);
}
END
{
printf("\n  %-72s %s\n", "APPLICATION", "I/Os");
printa("  %-72s %@d\n", @apps);
printf("\n  %-72s %s\n", "FILE", "I/Os");
printa("  %-72s %@d\n", @files);
printf("\n  %-16s %-55s %s\n", "APPLICATION", "FILE", "I/Os");
printa("  %-16s %-55s %@d\n", @appsfiles);
}

This script uses a combination of CPU sampling and I/O tracing to determine
roughly what’s going on over the course of logging in. I ran the above
script on on my
Acer Ferrari 3400
laptop running
OpenSolaris by dropping to the
command-line login
after a reboot and running:

# nohup ./login.d > /var/tmp/login.out &

I then logged in, and made sure that the first thing I did was launch a
gnome-terminal to pkill dtrace.
(This could obviously be made quite a bit more precise, but it works as
a crude way of indicating the completion of login.)
Here is
the output from performing this experiment.
The first column is the millisecond offset from the start of gnome-session.
CPU samples are contained within square brackets, launched programs
are contained withing curly braces, and I/O is explicitly noted.
An I/O summary is provided at the end.
A couple of observations:

• Nearly one third of all I/O is to shared object text and read-only data.
  This is classic death-of-a-thousand-cuts, and it’s hard to see that there’s
  an easy way to fix this. But perhaps text could be reordered to save some
  I/O? More investigation is probably merited here.

• Over a quarter of all I/O is from
  GConf
  — and many of these are from
  wandering around an expansive directory hierarchy looking for configuration
  information. It is well-known that the XML backend is a big performance
  problem, and a better backend is apparently being worked on. At any rate,
  solving this problem is clearly in
  GConf’s future.

• Of the remaining I/O, a bunch
  is to icon files.
  Glynn Foster
  pointed out that this looks to be addressed by the
  GTK+ gtk-update-icon-cache, new in
  GTK+ 2.6 and contained within
  GNOME 2.10, so this experiment will obviously need to
  be repeated on
  GNOME 2.10.

• CPU utilization doesn’t look like a big issue — or it’s one that is at
  least dwarfed by the cost of performing I/O. That said, gconfd-2 looks to
  be a bit piggy in this department as well. We’re only using CPU sampling —
  and we’re using a pretty coarse grained sample — and gconfd-2 still
  showed up. More precise investigation into CPU utilization can be
  performed with the sched provider and its on-cpu and
  off-cpu probes.

And an end-note: you might note many files named “<unknown>” in the
output.
This is due to I/Os being induced by lookups that are going through
directories and/or symlinks that haven’t been explicitly opened. For these
I/Os, my script also gives you the pointer to the vnode structure in
the kernel; you can get the path to these by using ::vnode2path
in MDB:

# mdb -k
Loading modules: [ unix krtld genunix specfs dtrace ufs ip
sctp usba uhci s1394 random nca lofs nfs audiosup sppp ptm ipc ]
> ffffffff8f6851c0::vnode2path
/usr/sfw/lib/libXrender.so.1
>

Yes, having to do this sucks a bit, and

it’s
a known issue.
And rumor has
it that
Eric even has a workspace
with the fix, so stay tuned…

Update: Eric pointed me to a prototype with the fix, and I reran the script on
a GNOME cold start;
here is the output
from that run. Interestingly, because the symlinks now show up, a little postprocessing
reveals that we chased nearly eighty symlinks on startup! From the output, reading many
of these took 10 to 20 milliseconds; we might be spending as much as one second of GNOME
startup blocked on I/O just to chase symlinks! Ouch! Again, it’s not clear how one
would fix this; having an app link to libpango-1.0.so.0 and not libpango-1.0.so.400.1 is clearly a Good Thing, and having this be a symlink
instead of a hardlink is clearly a Good Thing — but all of that goodness leaves you
with a read dependency that’s hard to work around. Anyway, be looking for Eric’s fix
in OpenSolaris and then in an upcoming Solaris Express release;
it makes this kind of analysis much easier — and thanks Eric for the quick prototype!

Technorati tags:
OpenSolaris
Solaris
DTrace
GNOME