• WSCallGraph

Call graph tracing

Problem

An early step in understanding a piece of software is to trace function calls coming and going.

Scripts

Elaborated from the systemtap tutorial, here is a dynamic call graph trace. It uses the thread_indent tapset function for per-thread nesting, and

para-callgraph.stp

function trace(entry_p) {
   if(tid() in trace)
       printf("%s%s%s\n",thread_indent(entry_p),
                         (entry_p>0?"->":"<-"),
                         probefunc())
}

global trace
probe kernel.function(@1).call {
   if (execname() == "stapio") next # skip our own helper process
   trace[tid()] = 1
   trace(1)
}
probe kernel.function(@1).return {
   trace(-1)
   delete trace[tid()]
}

probe kernel.function(@2).call { trace(1) }
probe kernel.function(@2).return { trace(-1) }

Output

This script is parametrized with two strings. The first is the name of the trigger function: its lifetime on the call stack enables or disables tracing on a per-thread basis. The second is a pattern of probe functions whose entry/exit we want to trace. This script needs to be interrupted by hand when your curiosity is satisfied.

# stap para-callgraph.stp sys_read '*@fs/*.c'
[...]
     0 klogd(1391):->sys_read
    14 klogd(1391): ->fget_light
    22 klogd(1391): <-fget_light
    27 klogd(1391): ->vfs_read
    35 klogd(1391):  ->rw_verify_area
    43 klogd(1391):  <-rw_verify_area
    49 klogd(1391):  ->kmsg_read
     0 sendmail(1696):->sys_read
    17 sendmail(1696): ->fget_light
    26 sendmail(1696): <-fget_light
    34 sendmail(1696): ->vfs_read
    44 sendmail(1696):  ->rw_verify_area
    52 sendmail(1696):  <-rw_verify_area
    58 sendmail(1696):  ->proc_file_read
    70 sendmail(1696):   ->loadavg_read_proc
    84 sendmail(1696):    ->proc_calc_metrics
    92 sendmail(1696):    <-proc_calc_metrics
    95 sendmail(1696):   <-loadavg_read_proc
   101 sendmail(1696):  <-proc_file_read
   106 sendmail(1696):  ->dnotify_parent
   115 sendmail(1696):  <-dnotify_parent
   119 sendmail(1696):  ->inotify_dentry_parent_queue_event
   127 sendmail(1696):  <-inotify_dentry_parent_queue_event
   133 sendmail(1696):  ->inotify_inode_queue_event
   141 sendmail(1696):  <-inotify_inode_queue_event
   146 sendmail(1696): <-vfs_read
   151 sendmail(1696):<-sys_read
[...]
^C

Lessons

Convenient functionality like per-thread nesting and timekeeping is easily stored in the tapset library (the thread_indent function). It would be easy to add filtering predicates on process name, user name, or whatnot. One may also use much broader wildcards for selecting target modules to trace, but the data can quickly become overwhelming (both to you, the user, and to the system).

See also http://sourceware.org/systemtap/examples/keyword-index.html#CALLGRAPH.

WarStories