This is the mail archive of the
systemtap@sourceware.org
mailing list for the systemtap project.
Re: kernel function probe overhead
- From: fche at redhat dot com (Frank Ch. Eigler)
- To: Aubrey Li <aubreylee at gmail dot com>
- Cc: systemtap at sourceware dot org
- Date: Fri, 25 Nov 2016 12:22:01 -0500
- Subject: Re: kernel function probe overhead
- Authentication-results: sourceware.org; auth=none
- References: <CAGPKeUKWAvBv=SL_ebVkR3ZwCeGZoCQ1MEJ5xQi-VXuF=kt3Wg@mail.gmail.com>
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