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 samplesn", @2, @count(stats)) printf("max/avg/min: %d/%d/%dn", @max(stats), @avg(stats), @min(stats)) print(@hist_log(stats)) } } global begin, stats
Advertisement
Answer
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()) }