Hinterher - Tracing vala (c-) code with systemtap.

As many others I've read Richard's post on tracing shared library calls using SystemTap (stap). This reminded me about a problem with vala a while back, which was about how to profile vala code.
Taking the following snippet, we will trace the calls to of methods of the Foo class, for some profiling.

$ cat <<EOF > foo.vala
using Gee;

class Foo : Object
{
  public void do ()
  {
    print ("done");
    }
}


void main()
{
  var map = new HashMap ();
  map["one"] = 1;
  map["two"] = 2;
  map["forty"] = 40;
  print ("%d\n", map["forty"] + map["two"]);

  var f = new Foo ();
  f.do ();
  f.do ();
}
EOF
$ vala --pkg libgee-1.0 --debug --save-temps foo.vala

Have a look at the C-code derived from the vala snippet above and look at the function names, to build a regular expression for the to-be-watched function calls. It is important to compile the snippet using the --debug switch, this enables stap to look out for the functions in question.
Additionally we need the following stap snippet (normally found in .stp files), to add the appropriate hooks to the kernel. The following stap script get's compiled into a kernel module and watches the mathod calls on instances of the Foo class.

$ cat <<EOF > foo.stp
#!/usr/bin/stap

global last;

function display_time () {
  now = gettimeofday_us ();
  delta = 0;
  if (last > 0)
    delta = now - last;
  last = now;

  printf ("%d (+%d):", now, delta);
}

probe begin {
  last = 0;
  printf ("ready\n");
}

# Modify to match the C signatures of teh methods in question
probe process("/home/fabiand/tmp/sl")
            .function("foo_[a-z]*") ? {
  display_time();
  printf ("\t%s %s\n", probefunc(), $$parms);
}
EOF

Now we've got the binary to trace and the script to watch the appropriate function calls, next is to compile/launch the script before we finally launch our binary.

$ sudo stap -tv foo.stp
ready

And on a different terminal run the binary:

$ ./sl
42

This should get the above stap call, to spit out the following (or comparable) lines:

1318412226924288 (+0): foo_new 
1318412226924298 (+10): foo_get_type 
1318412226924309 (+11): foo_construct object_type=0x11afe30
1318412226924317 (+8): foo_class_init klass=0x11aff30
1318412226924324 (+7): foo_instance_init self=0x11a7180
1318412226924330 (+6): foo_do self=0x11a7180
1318412226924348 (+18): foo_do self=0x11a7180

First there is an absolute timestamp, followed by the delta between two (matched) function calls in brackets. The delta does not mean that the function call took so long, it is more the time between two function calls matching the regexp in the .stp file, so there can be an arbitary number of function calls between two listed ones.