Profiling GNOME glib with Dtrace
Thursday May 05, 2005
I noticed that dtrace -l | grep glib shows probes available for glib. So here is a variation on a script on my friend Gleb's blog. His script looks at time in system calls. This one just looks at entries into glib functions:
#!/usr/sbin/dtrace -s
:libglib-2.0.so.0.400.1::entry
{
@usage[probefunc]=count();
}
There are a couple of interesting things here. First of all, I'm not just measuring the number of function calls from one process (though I could), I'm also including anything gnome-vfs-daemon, bonobo-activation, nautilus and even nautilus-throbber are doing. It also includes other users on my system. So, I'll run it, switch workspaces and open up a nautilus documents folder.
{Stuff deleted, here's the top 20...}
g_static_rw_lock_reader_lock 7697
g_static_rw_lock_reader_unlock 7697
g_datalist_id_set_data_full 7733
g_data_set_internal 8183
g_utf8_get_char 10441
g_quark_from_string 10999
g_strdup 12326
g_datalist_id_get_data 14068
g_pattern_match 21518
g_str_hash 22092
g_direct_hash 23809
g_string_append_len 24494
g_string_insert_len 26298
g_string_maybe_expand 28720
standard_free 30569
standard_malloc 30751
g_malloc 33444
g_free 43051
g_str_equal 43970
g_hash_table_lookup 64280
I wonder why there are so many calls to g_string_maybe_expand? I haven't found docs for the function, but the code seems to take a GString as arg0 and realloc memory if necessary. So why are we doing this so much?
#!/usr/sbin/dtrace -s
:libglib-2.0.so.0.400.1:g_string_maybe_expand:entry
{
ustack(6);
printf("Maybe expanding:'%s'\n\n", copyinstr(arg0));
}
This document explains how copyinstr and ustack are used. Now look at this, we're just creating a bunch of new strings for converting the uri:
CPU ID FUNCTION:NAME
0 36667 g_string_maybe_expand:entry
libglib-2.0.so.0.400.1`g_string_maybe_expand
libglib-2.0.so.0.400.1`g_string_sized_new+0x128
libglib-2.0.so.0.400.1`g_string_new+0x2c
libgnomevfs-2.so.0.600.0`gnome_vfs_uri_to_string+0x1c
libgnomevfs-2.so.0.600.0`gnome_vfs_make_uri_canonical_old+0x2c
libgnomevfs-2.so.0.600.0`gnome_vfs_make_uri_canonical+0x15c
maybe_expanding:''
0 36667 g_string_maybe_expand:entry
libglib-2.0.so.0.400.1`g_string_maybe_expand
libglib-2.0.so.0.400.1`g_string_insert_len+0x1b0
libglib-2.0.so.0.400.1`g_string_new+0x3c
libgnomevfs-2.so.0.600.0`gnome_vfs_uri_to_string+0x1c
libgnomevfs-2.so.0.600.0`gnome_vfs_make_uri_canonical_old+0x2c
libgnomevfs-2.so.0.600.0`gnome_vfs_make_uri_canonical+0x15c
maybe_expanding:''
0 36667 g_string_maybe_expand:entry
libglib-2.0.so.0.400.1`g_string_maybe_expand
libglib-2.0.so.0.400.1`g_string_insert_c+0x44
libgnomevfs-2.so.0.600.0`g_string_append_c_inline+0x10
libgnomevfs-2.so.0.600.0`gnome_vfs_uri_to_string+0x28
libgnomevfs-2.so.0.600.0`gnome_vfs_make_uri_canonical_old+0x2c
libgnomevfs-2.so.0.600.0`gnome_vfs_make_uri_canonical+0x15c
maybe_expanding:''
0 36667 g_string_maybe_expand:entry
libglib-2.0.so.0.400.1`g_string_maybe_expand
libglib-2.0.so.0.400.1`g_string_insert_len+0x1b0
libgnomevfs-2.so.0.600.0`gnome_vfs_uri_to_string+0x8c
libgnomevfs-2.so.0.600.0`gnome_vfs_make_uri_canonical_old+0x2c
libgnomevfs-2.so.0.600.0`gnome_vfs_make_uri_canonical+0x15c
libeel-2.so.2.6.1`eel_make_uri_canonical+0x184
maybe_expanding:''
0 36667 g_string_maybe_expand:entry
libglib-2.0.so.0.400.1`g_string_maybe_expand
libglib-2.0.so.0.400.1`g_string_insert_len+0x1b0
libgnomevfs-2.so.0.600.0`gnome_vfs_uri_to_string+0x1dc
libgnomevfs-2.so.0.600.0`gnome_vfs_make_uri_canonical_old+0x2c
libgnomevfs-2.so.0.600.0`gnome_vfs_make_uri_canonical+0x15c
libeel-2.so.2.6.1`eel_make_uri_canonical+0x184
maybe_expanding:''
0 36667 g_string_maybe_expand:entry
libglib-2.0.so.0.400.1`g_string_maybe_expand
libglib-2.0.so.0.400.1`g_string_sized_new+0x128
libglib-2.0.so.0.400.1`g_string_new+0x2c
libgnomevfs-2.so.0.600.0`gnome_vfs_uri_to_string+0x1c
libgnomevfs-2.so.0.600.0`gnome_vfs_make_uri_canonical_old+0x2c
libgnomevfs-2.so.0.600.0`gnome_vfs_make_uri_canonical+0x15c
maybe_expanding:''
0 36667 g_string_maybe_expand:entry
libglib-2.0.so.0.400.1`g_string_maybe_expand
libglib-2.0.so.0.400.1`g_string_insert_len+0x1b0
libglib-2.0.so.0.400.1`g_string_new+0x3c
libgnomevfs-2.so.0.600.0`gnome_vfs_uri_to_string+0x1c
libgnomevfs-2.so.0.600.0`gnome_vfs_make_uri_canonical_old+0x2c
libgnomevfs-2.so.0.600.0`gnome_vfs_make_uri_canonical+0x15c
maybe_expanding:''
0 36667 g_string_maybe_expand:entry
libglib-2.0.so.0.400.1`g_string_maybe_expand
libglib-2.0.so.0.400.1`g_string_insert_c+0x44
libgnomevfs-2.so.0.600.0`g_string_append_c_inline+0x10
libgnomevfs-2.so.0.600.0`gnome_vfs_uri_to_string+0x28
libgnomevfs-2.so.0.600.0`gnome_vfs_make_uri_canonical_old+0x2c
libgnomevfs-2.so.0.600.0`gnome_vfs_make_uri_canonical+0x15c
maybe_expanding:''
0 36667 g_string_maybe_expand:entry
libglib-2.0.so.0.400.1`g_string_maybe_expand
libglib-2.0.so.0.400.1`g_string_insert_len+0x1b0
libgnomevfs-2.so.0.600.0`gnome_vfs_uri_to_string+0x8c
libgnomevfs-2.so.0.600.0`gnome_vfs_make_uri_canonical_old+0x2c
libgnomevfs-2.so.0.600.0`gnome_vfs_make_uri_canonical+0x15c
libeel-2.so.2.6.1`eel_make_uri_canonical+0x184
maybe_expanding:''
0 36667 g_string_maybe_expand:entry
libglib-2.0.so.0.400.1`g_string_maybe_expand
libglib-2.0.so.0.400.1`g_string_insert_len+0x1b0
libgnomevfs-2.so.0.600.0`gnome_vfs_uri_to_string+0x1dc
libgnomevfs-2.so.0.600.0`gnome_vfs_make_uri_canonical_old+0x2c
libgnomevfs-2.so.0.600.0`gnome_vfs_make_uri_canonical+0x15c
libeel-2.so.2.6.1`eel_make_uri_canonical+0x184
maybe_expanding:''
Once I learn a bit more about dtrace I'd like to improve the script to ignore library calls which take less than say, 10000 nanoseconds. It's great that GString automatically grows when necessary, I sure hope GString isn't leaky! Maybe a glib, nautilus or GNOME expert could tell me whether this is meaningfull at all, or if not, where should I be looking? I just noticed that probes are available for libgtk also. Stay tuned!
Note:The first script above does not measure time as Gleb's script does.
Like this post?
|
|
|
|
|
|
|
|
