Thursday, 3 December 2009

Profiling function calls with Systemtap on Fedora 12

Linux now has Systemtap, a system-wide tool to observe and investigate the inner workings of software stacks. Being similar to DTrace, Systemtap can dynamically instrument the Linux kernel and applications.

Having read an excellent introduction Linux introspection and SystemTap, I tried using it to dynamically instrument an application to profile function call times on Fedora 12. Dynamic instrumentation requires debuginfo to be available for the application being instrumented.

The application that was dynamically instrumented is /bin/ls. It was invoked as `ls -Rl ~/src > /dev/null`.

Here is the output of the profile script:

[max@truth ~]$ uname -a
Linux truth #1 SMP Sat Nov 7 21:11:14 EST 2009 x86_64 x86_64 x86_64 GNU/Linux

[max@truth ~]$ stap -V
SystemTap translator/driver (version 1.0/0.143 non-git sources)
Copyright (C) 2005-2009 Red Hat, Inc. and others
This is free software; see the source for copying conditions.

[max@truth ~]$ sudo stap --vp 01 ~/src/systemtap-scripts/profile.stp /bin/ls
Pass 2: analyzed script: 421 probe(s), 4 function(s), 3 embed(s), 3 global(s) in 20usr/0sys/19real ms.
Collecting data for /bin/ls
process 10505 started
process 10505 terminated
978009 calls 11411514046nsec gnu_mbswidth
978009 calls 5095937872nsec mbsnwidth
553455 calls 6516854084nsec xstrcoll_name
553455 calls 2973420055nsec xstrcoll
432234 calls 2443338583nsec human_readable
279432 calls 5578451810nsec format_user_or_group_width
279431 calls 1454525884nsec getuser
279431 calls 1476571224nsec umaxtostr
279431 calls 1462740182nsec getgroup
279430 calls 5592908987nsec format_user_or_group
205189 calls 1096534601nsec xmalloc
165892 calls 2214172043nsec xmemdup
165890 calls 3276158518nsec xstrdup
152831 calls 3470895161nsec quote_name
152831 calls 2164873563nsec quotearg_buffer
152831 calls 857089762nsec quotearg_buffer_restyled
139744 calls 4347714683nsec print_name_with_quoting
139716 calls 25976606795nsec gobble_file
139716 calls 4942869834nsec format_user_width
139716 calls 2251024688nsec file_has_acl
139715 calls 727046826nsec strmode
139715 calls 3132965701nsec align_nstrftime
139715 calls 27707055961nsec print_long_format
139715 calls 1972675668nsec nstrftime
139715 calls 4871097460nsec format_group
139715 calls 4933490513nsec format_user
139715 calls 1627706138nsec filemodestring
139715 calls 818129922nsec strftime_case_
131267 calls 10444585148nsec mpsort_with_tmp
26174 calls 144849501nsec free_pending_ent
26174 calls 500319229nsec hash_find_entry
26174 calls 939925939nsec queue_directory
26174 calls 139966373nsec dev_ino_hash
26172 calls 140919473nsec last_component
16519 calls 87194194nsec dev_ino_compare
13088 calls 9420945286nsec sort_files
13088 calls 1642026249nsec extract_dirs_from_files
13088 calls 9303928062nsec mpsort
13088 calls 82016194nsec clear_files
13087 calls 67338468933nsec print_dir
13087 calls 411821913nsec hash_delete
13087 calls 308501198nsec hash_insert
13087 calls 68924698nsec dev_ino_free
13086 calls 287384316nsec mfile_name_concat
13086 calls 68382189nsec base_len
13086 calls 396034744nsec file_name_concat
13056 calls 28224393588nsec print_current_files
29 calls 323169nsec areadlink_with_size
4 calls 156509nsec xrealloc
2 calls 27356nsec close_stream
2 calls 50274nsec clone_quoting_options
1 calls 41537nsec close_stdout
1 calls 12722nsec xstrtoul
1 calls 6598nsec set_char_quoting
1 calls 12513nsec set_program_name
1 calls 7107nsec check_tuning
1 calls 7215nsec hard_locale
1 calls 7616nsec hash_free
1 calls 9458nsec hash_get_n_entries
1 calls 32489nsec hash_initialize
1 calls 6820nsec get_quoting_style
1 calls 7110nsec gettime
1 calls 9946nsec argmatch
1 calls 6972nsec compute_bucket_size
1 calls 10856nsec human_options
1 calls 20279nsec __xargmatch_internal
It shows the number of calls and the total time spent in a function. The total time function is inclusive, that is, it includes the time a function spent calling other functions.

Here is the script:

[max@truth ~]$ cat ~/src/systemtap-scripts/profile.stp
global gpid = -1
global times, entry

probe begin {
printf("Collecting data for %s\n", @1)

probe process(@1).begin {
gpid = pid()
printf("process %u started\n", gpid)

probe process(@1).end {
if(gpid != pid())

printf("process %u terminated\n", gpid)

foreach(fn in times-)
printf("%6u calls %12unsec %s\n", @count(times[fn]), @sum(times[fn]), fn)

probe process(@1).function("*").call {
now = gettimeofday_ns()
entry[probefunc()] = now

probe process(@1).function("*").return {
now = gettimeofday_ns()
time = now - entry[probefunc()]
times[probefunc()] <<< time

It looks quite simple.

Systemtap appears to be quite a useful tool, will try to use it more.


  1. Thank you Ivan, this blog entry is all your fault ;)

  2. So it seems system tap can do profiling based on wall clock time. So if a function is CPU bound or IO bound it will show the elapsed time.

    I wonder what is the effect for a function waiting on some event. If you have a function that calls receive and waits for data, it will surely have a very long time before the function begins and ends.

  3. This script is too naive to handle this case :(. It accounts for total function time including the time of the child function calls (so called inclusive time). There may be a way to find out function exclusive time. Haven't used systemtap enough yet to figure out how to do so though.