Re: kernel function probe overhead

[Aubrey Li <aubreylee at gmail dot com>]

On Sat, Nov 26, 2016 at 1:22 AM, Frank Ch. Eigler <fche@redhat.com> wrote:
>

Thanks for your reply, Frank.

> 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

Timestamp function: gettimeofday_ns()
 value |-------------------------------------------------- count
    32 |                                                      0
    64 |                                                      0
   128 |                                                      6
   256 |@                                                    62
   512 |@@@@@@@@@@                                          434
  1024 |@@@@@@@@@@@                                         487
  2048 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@  2014
  4096 |                                                     35
  8192 |@                                                    44
 16384 |                                                     28
 32768 |                                                     20
 65536 |                                                      0
131072 |                                                      0

Total time: 10096 miliseconds

> Consider using get_cycles()

Timestamp function: get_cycles()
 value |-------------------------------------------------- count
    64 |                                                      0
   128 |                                                      0
   256 |                                                      9
   512 |@@@                                                  91
  1024 |@@@@@@@@@@                                          313
  2048 |@@@@@@@@@@@@@@                                      420
  4096 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@  1495
  8192 |@@@@@@@@@@@                                         350
 16384 |@@                                                   83
 32768 |                                                     29
 65536 |@                                                    31
131072 |                                                      1
262144 |                                                      0
524288 |                                                      0


> or the
> functions in the [man tapset::timestamp_monotonic] tapset.
>

Timestamp function: local_clock_ns()
 value |-------------------------------------------------- count
    32 |                                                      0
    64 |                                                      0
   128 |                                                      6
   256 |@                                                    57
   512 |@@@@@@@@@@                                          377
  1024 |@@@@@@@@@@@                                         426
  2048 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@  1792
  4096 |                                                     29
  8192 |@                                                    50
 16384 |                                                     23
 32768 |                                                     23
 65536 |                                                      0
131072 |                                                      0

> Another possibility is jitter like caching effects within the kernel due
> to activity elsewhere.

I doubt caching effects cause so big variance.

>  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.

Do we have an approach to probe the function on CPU0 only?

>
> 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.

"-t" option output.
----- probe hit report:
begin, (test2.stp:8:1), hits: 1, cycles: 3280min/3280avg/3280max,
from: begin, index: 0
kernel.function("arch_cpu_idle_enter@arch/x86/kernel/process.c:277").call,
(test2.stp:13:1), hits: 2801, cycles: 560min/34290avg/230611max, from:
kernel.function("arch_cpu_idle_enter@arch/x86/kernel/process.c:277").call
from: kernel.function("arch_cpu_idle_enter").call, index: 2
kernel.function("local_touch_nmi@arch/x86/kernel/nmi.c:561").call,
(test2.stp:18:1), hits: 2801, cycles: 396min/5118avg/160096max, 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), (test2.stp:26:1), hits: 1, cycles:
126258min/126258avg/126258max, from: timer.s(10), index: 4
end, (test2.stp:32:1), hits: 1, cycles: 6240min/6240avg/6240max, from:
end, index: 5
----- refresh report:

Thanks,
-Aubrey