From mboxrd@z Thu Jan 1 00:00:00 1970 Return-Path: Received: (qmail 89533 invoked by alias); 28 Nov 2016 19:19:28 -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 87944 invoked by uid 89); 28 Nov 2016 19:19:27 -0000 Authentication-Results: sourceware.org; auth=none X-Virus-Found: No X-Spam-SWARE-Status: No, score=-4.8 required=5.0 tests=BAYES_00,RP_MATCHES_RCVD,SPF_HELO_PASS autolearn=ham version=3.3.2 spammy=Having, ordinary, Hx-languages-length:2542, sk:local_t X-HELO: mx1.redhat.com Received: from mx1.redhat.com (HELO mx1.redhat.com) (209.132.183.28) by sourceware.org (qpsmtpd/0.93/v0.84-503-g423c35a) with ESMTP; Mon, 28 Nov 2016 19:19:17 +0000 Received: from int-mx10.intmail.prod.int.phx2.redhat.com (int-mx10.intmail.prod.int.phx2.redhat.com [10.5.11.23]) (using TLSv1.2 with cipher ECDHE-RSA-AES256-GCM-SHA384 (256/256 bits)) (No client certificate requested) by mx1.redhat.com (Postfix) with ESMTPS id 8E0BF64C4; Mon, 28 Nov 2016 19:19:16 +0000 (UTC) Received: from fche.csb (vpn-53-177.rdu2.redhat.com [10.10.53.177]) by int-mx10.intmail.prod.int.phx2.redhat.com (8.14.4/8.14.4) with ESMTP id uASJJGLx014362; Mon, 28 Nov 2016 14:19:16 -0500 Received: by fche.csb (Postfix, from userid 2569) id 68EE458985; Mon, 28 Nov 2016 14:19:10 -0500 (EST) From: fche@redhat.com (Frank Ch. Eigler) To: Aubrey Li Cc: systemtap@sourceware.org Subject: Re: kernel function probe overhead References: Date: Mon, 28 Nov 2016 19:19:00 -0000 In-Reply-To: (Aubrey Li's message of "Sat, 26 Nov 2016 14:18:37 +0800") Message-ID: User-Agent: Gnus/5.13 (Gnus v5.13) Emacs/23.4 (gnu/linux) MIME-Version: 1.0 Content-Type: text/plain; charset=us-ascii X-SW-Source: 2016-q4/txt/msg00093.txt.bz2 aubreylee wrote: >> 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() > [...] > Timestamp function: get_cycles() > [...] > Timestamp function: local_clock_ns() > [...] Thanks for testing! The distribution of those three seem remarkably similar - a nice central peak, and a second small peak at 4-8x the first. It suggests we can probably rule out clock problems. >> 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? Not directly; the kernel does not give us such control. The probe could include a if (cpu() != 0) next; at the top of the probe handler body. That way locks still are taken, but released quickly on the other CPUs. Another solution would be to have per-thread global variables. Since the kernel doesn't help us out with this, we'd have to emulate it somehow, and for this to be wortwhile, it'd have to work faster than ordinary locked/shared array[tid()] accesses. >> 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. 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 > [...] > 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("local_touch_nmi@arch/x86/kernel/nmi.c:561").call, > (test2.stp:18:1), hits: 2801, cycles: 396min/5118avg/160096max, from: > [...] 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). - FChE