From mboxrd@z Thu Jan 1 00:00:00 1970 Return-Path: Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S964823AbcLPAVR (ORCPT ); Thu, 15 Dec 2016 19:21:17 -0500 Received: from LGEAMRELO12.lge.com ([156.147.23.52]:34033 "EHLO lgeamrelo12.lge.com" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S938393AbcLPAVG (ORCPT ); Thu, 15 Dec 2016 19:21:06 -0500 X-Original-SENDERIP: 156.147.1.127 X-Original-MAILFROM: namhyung@kernel.org X-Original-SENDERIP: 165.244.249.26 X-Original-MAILFROM: namhyung@kernel.org X-Original-SENDERIP: 10.177.227.17 X-Original-MAILFROM: namhyung@kernel.org Date: Fri, 16 Dec 2016 09:20:59 +0900 From: Namhyung Kim To: Steven Rostedt CC: Ingo Molnar , LKML Subject: Re: [RFC/PATCH] tracing: show total NMI time in hwlat tracer Message-ID: <20161216002059.GA4569@sejong> References: <20161214071351.8775-1-namhyung@kernel.org> <20161214095301.09ccf17b@gandalf.local.home> <20161214111716.312273c8@gandalf.local.home> MIME-Version: 1.0 In-Reply-To: <20161214111716.312273c8@gandalf.local.home> User-Agent: Mutt/1.7.1 (2016-10-04) X-MIMETrack: Itemize by SMTP Server on LGEKRMHUB06/LGE/LG Group(Release 8.5.3FP6|November 21, 2013) at 2016/12/16 09:21:01, Serialize by Router on LGEKRMHUB06/LGE/LG Group(Release 8.5.3FP6|November 21, 2013) at 2016/12/16 09:21:01, Serialize complete at 2016/12/16 09:21:01 Content-Type: text/plain; charset="utf-8" Content-Disposition: inline Sender: linux-kernel-owner@vger.kernel.org List-ID: X-Mailing-List: linux-kernel@vger.kernel.org On Wed, Dec 14, 2016 at 11:17:16AM -0500, Steven Rostedt wrote: > > [ added the forgotten LKML ;-) ] > > On Wed, 14 Dec 2016 09:53:01 -0500 > Steven Rostedt wrote: > > > On Wed, 14 Dec 2016 16:13:51 +0900 > > Namhyung Kim wrote: > > > > > Hi Steve, > > > > > > While looking at the code I found the below. I'm not sure the current > > > code is correct but it seems that nmi_total_ts would have *total* time > > > of NMI handler execution IMHO. Or maybe keeping longest time is enough. > > > > > > Currently nmi_total_ts has the duration of the last occurrence of NMI. > > > But I think it should keep all of NMI handling time. > > > > > > > Yeah, that looks like it should be accumulative. > > Actually, I take that back. We don't care what the accumulative NMI > time of the entire sample width is. But we do care what the > accumulative NMI was of each individual loop, as that's what we are > timing. Thinking about it again, maybe we want NMI time at the max sample not the max NMI time in each loop.. > > I'm wondering if we keep a total accumulative count and then take a > snapshot of it in the loop, and record the difference in each iteration. > > I added a patch below on top of your patch. I added a patch below on top of that. :) I didn't change the FTRACE_ENTRY yet. If it looks good to you I may add the nmi_duration and nmi_outer_duration (or just nmi_{outer_,}ts instead of nmi_max_ts. Thanks, Namhyung > > > > > -- Steve > > > > > Signed-off-by: Namhyung Kim > > > --- > > > kernel/trace/trace_hwlat.c | 2 +- > > > 1 file changed, 1 insertion(+), 1 deletion(-) > > > > > > diff --git a/kernel/trace/trace_hwlat.c b/kernel/trace/trace_hwlat.c > > > index 775569ec50d0..0b1ead11658e 100644 > > > --- a/kernel/trace/trace_hwlat.c > > > +++ b/kernel/trace/trace_hwlat.c > > > @@ -151,7 +151,7 @@ void trace_hwlat_callback(bool enter) > > > if (enter) > > > nmi_ts_start = time_get(); > > > else > > > - nmi_total_ts = time_get() - nmi_ts_start; > > > + nmi_total_ts += time_get() - nmi_ts_start; > > > } > > > > > > if (enter) > > > > > --- > kernel/trace/trace_entries.h | 1 + > kernel/trace/trace_hwlat.c | 25 +++++++++++++++++++++++-- > kernel/trace/trace_output.c | 5 ++++- > 3 files changed, 28 insertions(+), 3 deletions(-) > > Index: linux-trace.git/kernel/trace/trace_entries.h > =================================================================== > --- linux-trace.git.orig/kernel/trace/trace_entries.h 2016-11-30 13:08:00.701199978 -0500 > +++ linux-trace.git/kernel/trace/trace_entries.h 2016-12-14 10:11:55.461704990 -0500 > @@ -346,6 +346,7 @@ FTRACE_ENTRY(hwlat, hwlat_entry, > __field( u64, duration ) > __field( u64, outer_duration ) > __field( u64, nmi_total_ts ) > + __field( u64, nmi_max_ts ) > __field_struct( struct timespec, timestamp ) > __field_desc( long, timestamp, tv_sec ) > __field_desc( long, timestamp, tv_nsec ) > Index: linux-trace.git/kernel/trace/trace_hwlat.c > =================================================================== > --- linux-trace.git.orig/kernel/trace/trace_hwlat.c 2016-12-14 10:09:49.937878304 -0500 > +++ linux-trace.git/kernel/trace/trace_hwlat.c 2016-12-14 11:11:52.940771118 -0500 > @@ -82,6 +82,7 @@ struct hwlat_sample { > u64 duration; /* delta */ > u64 outer_duration; /* delta (outer loop) */ > u64 nmi_total_ts; /* Total time spent in NMIs */ > + u64 nmi_max_ts; /* Max time spent in NMIs */ > struct timespec timestamp; /* wall time */ > int nmi_count; /* # NMIs during this sample */ > }; > @@ -124,6 +125,7 @@ static void trace_hwlat_sample(struct hw > entry->outer_duration = sample->outer_duration; > entry->timestamp = sample->timestamp; > entry->nmi_total_ts = sample->nmi_total_ts; > + entry->nmi_max_ts = sample->nmi_max_ts; > entry->nmi_count = sample->nmi_count; > > if (!call_filter_check_discard(call, entry, buffer, event)) > @@ -168,11 +170,12 @@ void trace_hwlat_callback(bool enter) > static int get_sample(void) > { > struct trace_array *tr = hwlat_trace; > - time_type start, t1, t2, last_t2; > - s64 diff, total, last_total = 0; > + time_type start, t1, t2, last_t2, nmi_t1, nmi_t2; > + s64 diff, total, last_total = 0, last_nmi = 0; > u64 sample = 0; > u64 thresh = tracing_thresh; > u64 outer_sample = 0; > + u64 nmi_sample = 0; > int ret = -1; > > do_div(thresh, NSEC_PER_USEC); /* modifies interval value */ > @@ -190,9 +193,15 @@ static int get_sample(void) > > do { > > + nmi_t1 = READ_ONCE(nmi_total_ts); > + barrier(); > + > t1 = time_get(); /* we'll look for a discontinuity */ > t2 = time_get(); > > + barrier(); > + nmi_t2 = READ_ONCE(nmi_total_ts); > + > if (time_u64(last_t2)) { > /* Check the delta from outer loop (t2 to next t1) */ > diff = time_to_us(time_sub(t1, last_t2)); > @@ -203,8 +212,13 @@ static int get_sample(void) > } > if (diff > outer_sample) > outer_sample = diff; > + > + diff = nmi_t1 - last_nmi; > + if (diff > nmi_sample) > + nmi_sample = diff; > } > last_t2 = t2; > + last_nmi = nmi_t2; > > total = time_to_us(time_sub(t2, start)); /* sample width */ > > @@ -227,6 +241,10 @@ static int get_sample(void) > if (diff > sample) > sample = diff; /* only want highest value */ > > + diff = nmi_t2 - nmi_t1; > + if (diff > nmi_sample) > + nmi_sample = diff; > + > } while (total <= hwlat_data.sample_width); > > barrier(); /* finish the above in the view for NMIs */ > @@ -244,6 +262,8 @@ static int get_sample(void) > /* We read in microseconds */ > if (nmi_total_ts) > do_div(nmi_total_ts, NSEC_PER_USEC); > + if (nmi_sample) > + do_div(nmi_sample, NSEC_PER_USEC); > > hwlat_data.count++; > s.seqnum = hwlat_data.count; > @@ -251,6 +271,7 @@ static int get_sample(void) > s.outer_duration = outer_sample; > s.timestamp = CURRENT_TIME; > s.nmi_total_ts = nmi_total_ts; > + s.nmi_max_ts = nmi_sample; > s.nmi_count = nmi_count; > trace_hwlat_sample(&s); > > Index: linux-trace.git/kernel/trace/trace_output.c > =================================================================== > --- linux-trace.git.orig/kernel/trace/trace_output.c 2016-11-30 13:08:00.726199562 -0500 > +++ linux-trace.git/kernel/trace/trace_output.c 2016-12-14 10:33:28.581929129 -0500 > @@ -1121,9 +1121,12 @@ trace_hwlat_print(struct trace_iterator > * The generic sched_clock() is not NMI safe, thus > * we only record the count and not the time. > */ > - if (!IS_ENABLED(CONFIG_GENERIC_SCHED_CLOCK)) > + if (!IS_ENABLED(CONFIG_GENERIC_SCHED_CLOCK)) { > trace_seq_printf(s, " nmi-total:%llu", > field->nmi_total_ts); > + trace_seq_printf(s, " nmi-max:%llu", > + field->nmi_max_ts); > + } > trace_seq_printf(s, " nmi-count:%u", > field->nmi_count); > } > > diff --git a/kernel/trace/trace_hwlat.c b/kernel/trace/trace_hwlat.c index 7b757928b02a..14e4205cce24 100644 --- a/kernel/trace/trace_hwlat.c +++ b/kernel/trace/trace_hwlat.c @@ -170,12 +170,14 @@ void trace_hwlat_callback(bool enter) static int get_sample(void) { struct trace_array *tr = hwlat_trace; - time_type start, t1, t2, last_t2, nmi_t1, nmi_t2; + time_type start, t1, t2, last_t2; + u64 nmi_t1, nmi_t2; s64 diff, total, last_total = 0, last_nmi = 0; u64 sample = 0; u64 thresh = tracing_thresh; u64 outer_sample = 0; u64 nmi_sample = 0; + u64 nmi_outer_sample = 0; int ret = -1; do_div(thresh, NSEC_PER_USEC); /* modifies interval value */ @@ -210,12 +212,10 @@ static int get_sample(void) pr_err(BANNER "time running backwards\n"); goto out; } - if (diff > outer_sample) + if (diff > outer_sample) { outer_sample = diff; - - diff = nmi_t1 - last_nmi; - if (diff > nmi_sample) - nmi_sample = diff; + nmi_outer_sample = nmi_t1 - last_nmi; + } } last_t2 = t2; last_nmi = nmi_t2; @@ -238,12 +238,10 @@ static int get_sample(void) goto out; } - if (diff > sample) + if (diff > sample) { sample = diff; /* only want highest value */ - - diff = nmi_t2 - nmi_t1; - if (diff > nmi_sample) - nmi_sample = diff; + nmi_sample = nmi_t2 - nmi_t1; + } } while (total <= hwlat_data.sample_width);