SystemTap script to profile latency of functions

Question

My goal is to profile the execution time of each function in a kernel module. Using the sample scripts I saw online, I came up with the following script to fulfill my need. But occasionally I get negative values for calculated latencies. Although, they happen rarely but I guess that indicates something is wrong with my script. Can anyone help me with that please?

probe module(@1).function(@2).call { 
     begin = gettimeofday_ns()
}

probe module(@1).function(@2).return {
  if (begin>0)
     stats <<< gettimeofday_ns() - begin
}

probe end {
    if (begin == 0) {
        printf("No samples observed so far.\n");

    } else {
        printf("Distribution of %s latencies (in nanoseconds) for %d samples\n", @2, @count(stats))
        printf("max/avg/min: %d/%d/%d\n", @max(stats), @avg(stats), @min(stats))
        print(@hist_log(stats))
    }
}


global begin, stats

Answer 1

The gettimeofday_*() functions can only approximate wallclock time. It is possible that across CPUs, or across a time adjustment moment, the values won't move monotonically the way you expect. get_cycles() is more monotonic on a given CPU, and a few other clock-related functions are available.

Also, your begin variable is a simple scalar. What if the same function is being called from multiple threads/cpus, or if recursion occurs? It'll get overwritten. This should be enough (and work correctly, from a nesting/concurrency point of view):

// no probe FOO.call
probe module(@1).function(@2).return {
  stats <<< gettimeofday_ns() - @entry(gettimeofday_ns())
}