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 2.6.31.5-127.fc12.x86_64 #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())
        next

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

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

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.