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 32576285Well, 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, colorspaceAnd 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-directoryWith 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!'
Like this post?
|
|
|
|
|
|
|
|
