Re: kernel function probe overhead

[fche@redhat.com (Frank Ch. Eigler)]

aubreylee wrote:

> [...]
> Basically I sampled two kernel function probes,
>
> probe kernel.function(arch_cpu_idle_enter).call
> probe kernel.function(local_touch_nmi).call

... where one directly calls the other.  Good test!


> because local irq is disabled, I suppose the duration of these two
> probes to be ZERO.

Yes, ideally.


> However, I run the attached stp script and here is what I got:
> [...]
> Total time: 10106 miliseconds
> t_end @count=2908 @min=676 @max=88152 @sum=15005802 @avg=5160

> the duration varies from 676 to 88152, I understand all the tracing
> mechanism should have overhead, while 676ns is acceptable, but 88152
> is not.

> probe kernel.function("arch_cpu_idle_enter").call
> 	t_start[cpu()] = gettimeofday_ns()
> probe kernel.function("local_touch_nmi").call
>	t_end <<< gettimeofday_ns() - t_start[cpu()]

A couple of things come to mind.  Use of gettimeofday_ns() function uses
a software-estimated real-time clock, which may not be steady enough for
high-grained measurements like this.  Consider using get_cycles() or the
functions in the [man tapset::timestamp_monotonic] tapset.

Another possibility is jitter like caching effects within the kernel due
to activity elsewhere.  The average is pretty low.  Consider printing a
histogram of t_end, or (if using git systemtap) its @variance.

Another possibility is contention over the t_start[] variable, if
multiple processors are running this region of code, so trigger the
systemtap probes concurrently.  systemtap automatically locks such
global variables, esp. if they contain non-aggregate values like the
scalar timestamps.

Consider using "stap -t FOO.stp" to have the tool print internal
estimates of its own probes' runtimes.  That would include lock
contention, but exclude kernel-side overheads like the code involved in
the its kprobes machinery.

- FChE