Fwd: kernel function probe overhead

[Cody Santing <csanting at redhat dot com>]

---------- Forwarded message ----------
From: Aubrey Li <aubreylee@gmail.com>
Date: Thu, Dec 8, 2016 at 8:44 AM
Subject: Re: kernel function probe overhead
To: Cody Santing <csanting@redhat.com>


On Fri, Dec 2, 2016 at 2:47 AM, Cody Santing <csanting@redhat.com> wrote:
>
> Hello  Aubrey,
>
> >> Ah, I note that we don't track occurrences of lock contention,
> >> even though we could.  Opened https://sourceware.org/bugzilla/show_bug.cgi?id=20879
> >
> > okay, thanks, I'll keep an eye on this ticket.
> >
>
> I have yet to update the ticket but I have added tracking of lock
> contention.  The number of lock contention occurrences on global
> variables will be printed following the probe hit report from the '-t'
> option.
>
> >> That inconsistency dramatic contention or caching or some other source
> >> of jitter.  Having the variance figure in there would be useful though.
> >> Would anyone like to give that a try?  (translate.cxx line 2283ish and
> >> runtime/linux/common_session_state.h _stp_stat_init area).
> >>
>
> I have also added variance to the '-t' option.  It is immediately
> following min/avg/max of each probe.
>
> >
> > If there is a patch delivered against git head, I can apply it and
> > paste the output here.
> >
>
> You should find the patch there.  Give it a shot, if you have any
> feedback I would like to hear it.
>
Thanks Cody.
Here is what I got:

============================================================
$ sudo stap -t test.stp
-----------------------------------------
Timestamp function: gettimeofday_ns()
Total time: 10092 miliseconds
t_end @count=2962 @min=268 @max=81878 @sum=10843684 @avg=3660

----- probe hit report:
begin, (./test.stp:8:1), hits: 1, cycles: 3752min/3752avg/3752max,
variance: 0, from: begin, index: 0
kernel.function("arch_cpu_idle_enter@arch/x86/kernel/process.c:277").call,
(./test.stp:14:1), hits: 2962, cycles:

>400min/30951avg/233043max, variance: 824817112, from: kernel.function("arch_cpu_idle_enter@arch/x86/kernel/process.c:277").call

May I know what does variance value mean here?

from: kernel.function("arch_cpu_idle_enter").call, index: 2
kernel.function("local_touch_nmi@arch/x86/kernel/nmi.c:561").call,
(./test.stp:19:1), hits: 2962, cycles: 288min/4483avg/177541max,
variance: 36900201, from:
kernel.function("local_touch_nmi@arch/x86/kernel/nmi.c:561").call
from: kernel.function("local_touch_nmi").call, index: 3
timer.s(10), (./test.stp:27:1), hits: 1, cycles:
6974min/6974avg/6974max, variance: 0, from: timer.s(10), index: 4
end, (./test.stp:32:1), hits: 1, cycles: 6928min/6928avg/6928max,
variance: 0, from: end, index: 5
end, (./test.stp:1:1), hits: 1, cycles: 9956min/9956avg/9956max,
variance: 0, from: end, index: 6

----- refresh report:
>'__global_t_start' lock contention occurred 2853 times

Would it be nice to report time cost of lock contention?

Anyway, instead of reporting lock contention, it would be nice if we
can reduce it, :)

Thanks,
-Aubrey