From mboxrd@z Thu Jan 1 00:00:00 1970 Return-Path: Received: (qmail 111320 invoked by alias); 26 Nov 2016 06:18:43 -0000 Mailing-List: contact systemtap-help@sourceware.org; run by ezmlm Precedence: bulk List-Id: List-Subscribe: List-Post: List-Help: , Sender: systemtap-owner@sourceware.org Received: (qmail 111306 invoked by uid 89); 26 Nov 2016 06:18:42 -0000 Authentication-Results: sourceware.org; auth=none X-Virus-Found: No X-Spam-SWARE-Status: No, score=-0.7 required=5.0 tests=AWL,BAYES_00,FREEMAIL_FROM,KAM_ASCII_DIVIDERS,RCVD_IN_DNSWL_NONE,SPF_PASS autolearn=no version=3.3.2 spammy=32768, fcheredhatcom, H*f:sk:y0m1sxz, H*i:sk:y0m1sxz X-HELO: mail-ua0-f194.google.com Received: from mail-ua0-f194.google.com (HELO mail-ua0-f194.google.com) (209.85.217.194) by sourceware.org (qpsmtpd/0.93/v0.84-503-g423c35a) with ESMTP; Sat, 26 Nov 2016 06:18:40 +0000 Received: by mail-ua0-f194.google.com with SMTP id 50so5204198uae.2 for ; Fri, 25 Nov 2016 22:18:39 -0800 (PST) X-Google-DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=1e100.net; s=20130820; h=x-gm-message-state:mime-version:in-reply-to:references:from:date :message-id:subject:to:cc; bh=+RizjeR5GMXXk+s0nHuS83BnNDap/V84dBlyfvQ54Ys=; b=B7R9phYnl3Vnv0hY0zoEDoe5EiDrSaaBT3zAGbK4eImQG5ftwXlJsIVAU6FAXTD8mv eLnrKUNKPHCNy4608+tmo82DGpKAJevKYW1OuOLBYpX3R1BwF2RANYu4FTKJtj1bRCFr gWTaI5EoAy6FAB9XIGlPKSLC+pfAzWcPZUcPa5a+pwimB1TWp2VsfQpUb6Aqo1MqKmoe c28htC+h4Qc2spfeLRn4+op3jhoNQT1mSOvaWKawTTw1uhCCjAIa9A7kC8sw9cdRpOrt p+9OI5iO63zlfDBjqULJwOKqeDz4X6uSFkBSqbnTw+n5Mgt9TXntyXQI87qLRRW3gaPk 4YnA== X-Gm-Message-State: AKaTC02R63iKpwiR3vs0gnAqQpfpHFZZm8bhAtZ0GEtMTSToJvjN61BRMVwQJA2F+SiWpWoE0XH3Iex2dgsnxw== X-Received: by 10.176.2.145 with SMTP id 17mr7026556uah.38.1480141118192; Fri, 25 Nov 2016 22:18:38 -0800 (PST) MIME-Version: 1.0 Received: by 10.103.45.211 with HTTP; Fri, 25 Nov 2016 22:18:37 -0800 (PST) In-Reply-To: References: From: Aubrey Li Date: Sat, 26 Nov 2016 06:18:00 -0000 Message-ID: Subject: Re: kernel function probe overhead To: "Frank Ch. Eigler" Cc: systemtap@sourceware.org Content-Type: text/plain; charset=UTF-8 X-IsSubscribed: yes X-SW-Source: 2016-q4/txt/msg00089.txt.bz2 On Sat, Nov 26, 2016 at 1:22 AM, Frank Ch. Eigler 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