Focusing in on nautilus glib calls with dtrace

Sunday May 08, 2005

The script in this previous post just counts the number of glib library calls. While this could be a useful bit of information, I'd really like to know how much time is being spent in each glib library call. For that I will take Gleb's script and change it to only look at calls and returns from libglib:

#!/usr/sbin/dtrace -s
#pragma D option quiet

:libglib-2.0.so.0.400.1::entry
{
   self->ts=timestamp;
}

:libglib-2.0.so.0.400.1::entry
{
   self->elapsed = timestamp - self->ts;
   @time[execname,probefunc,pid,tid]=sum(self->elapsed);
}

END
{
   printf("\n%20s %20s %8s %7s %20s\n","Execname", "Syscall", "Process", "Thread", "Time elapsed");
   printa("%20s %20s %8d %7d %20@u\n", @time);
}

It is interesting to run it on an idle system and see how much nautilus and the mixer applet do, but I've done that in a previous entry. So now I'll run the script and open a Nautilus document folder. This time I'll list the top 21 because you'll see that the function I was previously interested in is number 21 on this list:

Execname              Syscall           Process  Thread         Time elapsed(nanoseconds)
 nautilus g_string_maybe_expand          24620       1              3664329
 nautilus g_slist_prepend                24620       1              3785852
 nautilus g_static_rw_lock_reader_unlock 24620       1              4203187
 nautilus g_datalist_id_set_data_full    24620       1              4208898
 nautilus g_ascii_tolower                24620       1              4235995
 nautilus g_mem_chunk_area_search        24620       1              4317412
 nautilus g_static_rw_lock_reader_lock   24620       1              4381652
 nautilus g_data_set_internal            24620       1              4384423
 nautilus g_utf8_get_char                24620       1              5486703
 nautilus g_quark_from_string            24620       1              6065780
 nautilus g_strdup                       24620       1              6991822
 nautilus g_datalist_id_get_data         24620       1              7843746
 nautilus g_direct_hash                  24620       1              9642739
 nautilus g_pattern_match                24620       1             10652166
 nautilus g_str_hash                     24620       1             12129172
 nautilus standard_malloc                24620       1             16639586
 nautilus standard_free                  24620       1             16929274
 nautilus g_malloc                       24620       1             18480955
 nautilus g_str_equal                    24620       1             23843484
 nautilus g_free                         24620       1             24054223
 nautilus g_hash_table_lookup            24620       1             32576285

Well, now I want to focus on the nautilus process and see what is being passed to g_str_equal. I'll pass the pid of nautilus as a parameter to this script:

#!/usr/sbin/dtrace -s

pid$1:libglib-2.0.so.0.400.1:g_str_equal:entry
{
   printf("%s, %s\n", copyinstr(arg0),copyinstr(arg1));
}

I get some errors here, presumably because I haven't thinned the data enough or memory is on the other CPU or swapped out, or I made some other mistake:

out of scratch space in action #2 at DIF offset 28
dtrace: error on enabled probe ID 1 (ID 37446: pid24620:libglib-2.0.so.0.400.1:g_str_equal:entry): 

But I also get some data. This first part is interesting, seemingly whenever I hover over an icon on nautilus, someone looks up the width, height, color depth, alpha...:

CPU     ID                    FUNCTION:NAME
  0  37446                g_str_equal:entry pixels, pixels
  0  37446                g_str_equal:entry rowstride, rowstride
  0  37446                g_str_equal:entry height, height
  0  37446                g_str_equal:entry width, width
  0  37446                g_str_equal:entry GnomeVFSVolumeMonitor, has-alpha
  0  37446                g_str_equal:entry GnomeDateEditFlags, has-alpha
  0  37446                g_str_equal:entry has-alpha, has-alpha
  0  37446                g_str_equal:entry GConfClient, bits-per-sample
  0  37446                g_str_equal:entry bits-per-sample, bits-per-sample
  0  37446                g_str_equal:entry n-channels, n-channels
  0  37446                g_str_equal:entry colorspace, colorspace
  0  37446                g_str_equal:entry pixels, pixels
  0  37446                g_str_equal:entry rowstride, rowstride
  0  37446                g_str_equal:entry height, height
  0  37446                g_str_equal:entry width, width
  0  37446                g_str_equal:entry GnomeVFSVolumeMonitor, has-alpha
  0  37446                g_str_equal:entry GnomeDateEditFlags, has-alpha
  0  37446                g_str_equal:entry has-alpha, has-alpha
  0  37446                g_str_equal:entry GConfClient, bits-per-sample
  0  37446                g_str_equal:entry bits-per-sample, bits-per-sample
  0  37446                g_str_equal:entry n-channels, n-channels
  0  37446                g_str_equal:entry colorspace, colorspace

And then:

  
 0  37446                g_str_equal:entry image/bmp, x-directory/normal
 0  37446                g_str_equal:entry /home/bn/Documents, /home/bn/Documents
 0  37446                g_str_equal:entry image/x-icb, x-directory/normal
 0  37446                g_str_equal:entry image/x-icb, x-directory/normal
 0  37446                g_str_equal:entry x-directory/normal, x-directory/normal
 0  37446                g_str_equal:entry description, icon_filename
 0  37446                g_str_equal:entry gtk-goto-bottom, gnome-mime-x-directory-normal
 0  37446                g_str_equal:entry gtk-print, gnome-mime-x-directory-normal
 0  37446                g_str_equal:entry gtk-go-forward-ltr, gnome-mime-x-directory-normal
 0  37446                g_str_equal:entry gtk-indent, gnome-mime-x-directory-normal
 0  37446                g_str_equal:entry gtk-print-preview, gnome-mime-x-directory

With open source we are lucky, we can pepper the code with printfs and rebuild the application and get the same information I gathered above. But this takes time. With dtrace I can get valuable debug information from all applications and I can change what I'm looking at as quickly as I can type 'wq!'