From mboxrd@z Thu Jan 1 00:00:00 1970 Return-Path: Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S1753123AbdBISoA (ORCPT ); Thu, 9 Feb 2017 13:44:00 -0500 Received: from mga14.intel.com ([192.55.52.115]:39370 "EHLO mga14.intel.com" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S1752300AbdBISn6 (ORCPT ); Thu, 9 Feb 2017 13:43:58 -0500 X-ExtLoop1: 1 X-IronPort-AV: E=Sophos;i="5.35,137,1484035200"; d="scan'208";a="818991869" Message-ID: <1486665817.2871.150.camel@tzanussi-mobl.amr.corp.intel.com> Subject: Re: [RFC][PATCH 00/21] tracing: Inter-event (e.g. latency) support From: Tom Zanussi To: "Frank Ch. Eigler" Cc: Masami Hiramatsu , rostedt@goodmis.org, tglx@linutronix.de, namhyung@kernel.org, linux-kernel@vger.kernel.org, linux-rt-users@vger.kernel.org Date: Thu, 09 Feb 2017 12:43:37 -0600 In-Reply-To: References: <20170209081327.0f0f4db4e5cb8f1b9be25338@kernel.org> <1486602862.2871.62.camel@tzanussi-mobl.amr.corp.intel.com> Content-Type: text/plain; charset="UTF-8" X-Mailer: Evolution 3.10.4 (3.10.4-4.fc20) Mime-Version: 1.0 Content-Transfer-Encoding: 7bit Sender: linux-kernel-owner@vger.kernel.org List-ID: X-Mailing-List: linux-kernel@vger.kernel.org Hi Frank, On Thu, 2017-02-09 at 09:46 -0500, Frank Ch. Eigler wrote: > Hi, Tom - > > > tom.zanussi wrote: > > > [...] > >> Hmm, this looks a bit hard to understand, I guess that onmatch() means > >> "if there is an event which has ts0 variable and the event's key matches > >> this key, take some action". > > > > Yes, that's pretty much it. It's essentially shorthand for this kind of > > common idiom, where timestamp[] is an associative array, which in our > > case is the tracing_map of the histogram: > > > > event sched_wakeup() > > { > > ts0[wakeup_pid] = now() > > } > > event sched_switch() > > { > > if (ts0[next_pid]) > > latency = now() - ts0[next_pid] /* next_pid == wakeup_pid */ > > } > > By the way, here is a working systemtap version of this demo: > > # cat foo.stp > global ts0%, latency% > function now() { return gettimeofday_us() } > > probe kernel.trace("sched_wakeup") { ts0[$p->pid] = now() } > > probe kernel.trace("sched_switch") { > if (ts0[$next->pid]) > latency[$next->pid,$next->prio] <<< now() - ts0[$next->pid]; > } > > probe timer.s(5) { > foreach ([pid+,x] in latency) { > println("pid:", pid, " prio:", x) > print(@hist_log(latency[pid,x])) > } > delete latency > } > > > # stap foo.stp > [...] > pid:20183 prio:109 > value |-------------------------------------------------- count > 2 | 0 > 4 | 0 > 8 |@ 1 > 16 | 0 > 32 | 0 > > pid:29095 prio:120 > value |-------------------------------------------------- count > 0 | 1 > 1 |@@@@ 8 > 2 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 76 > 4 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 60 > 8 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 68 > 16 |@@@@@@@@ 16 > 32 | 0 > 64 | 0 > [...] > > Nice! > > > > ts0 is basically a per-table-entry variable - there's one for each > > entry in the table, and it can only be accessed by events with > > matching keys. [...] So, that's a long-winded way of saying that the > > name ts0 is global across all tables (histograms) but an instance of > > ts0 is local to each entry in the table that owns the name. > > In systemtap, one of the things we take care of is automatic concurrency > control over such shared variables. Even if many CPUs run these same > functions and try to access the same ts0/latency hash tables at the same > time, things will work correctly. I'm curious how your code deals with > this. > The hash tables used by the hist triggers this is based on are themselves based on tracing_maps, which are lock-free hash tables, and the variables themselves are atomic, so there shouldn't be any problems with concurrent access, unless I'm missing something... Tom > > - FChE