From mboxrd@z Thu Jan 1 00:00:00 1970 Return-Path: Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S933748AbcLNQR0 (ORCPT ); Wed, 14 Dec 2016 11:17:26 -0500 Received: from smtprelay0223.hostedemail.com ([216.40.44.223]:58455 "EHLO smtprelay.hostedemail.com" rhost-flags-OK-OK-OK-FAIL) by vger.kernel.org with ESMTP id S933630AbcLNQRW (ORCPT ); Wed, 14 Dec 2016 11:17:22 -0500 X-Session-Marker: 726F737465647440676F6F646D69732E6F7267 X-Spam-Summary: 2,0,0,,d41d8cd98f00b204,rostedt@goodmis.org,:::::,RULES_HIT:2:41:355:379:541:599:800:960:973:988:989:1260:1277:1311:1313:1314:1345:1359:1437:1515:1516:1518:1535:1593:1594:1605:1730:1747:1777:1792:1981:2194:2198:2199:2200:2393:2553:2559:2562:3138:3139:3140:3141:3142:3865:3866:3867:3868:3870:3871:3872:3874:4049:4118:4250:4321:4384:5007:6117:6261:7875:8660:10004:10848:10967:11026:11232:11473:11658:11914:12043:12291:12295:12296:12438:12555:12663:12679:12683:12740:12760:12895:12986:13138:13148:13230:13231:13439:14096:14097:14659:21060:21080:21324:21325:21451:30012:30054:30070:30090:30091,0,RBL:none,CacheIP:none,Bayesian:0.5,0.5,0.5,Netcheck:none,DomainCache:0,MSF:not bulk,SPF:fn,MSBL:0,DNSBL:none,Custom_rules:0:0:0,LFtime:2,LUA_SUMMARY:none X-HE-Tag: birth24_22ed46acdb727 X-Filterd-Recvd-Size: 7237 Date: Wed, 14 Dec 2016 11:17:16 -0500 From: Steven Rostedt To: Namhyung Kim Cc: Ingo Molnar , LKML Subject: Re: [RFC/PATCH] tracing: show total NMI time in hwlat tracer Message-ID: <20161214111716.312273c8@gandalf.local.home> In-Reply-To: <20161214095301.09ccf17b@gandalf.local.home> References: <20161214071351.8775-1-namhyung@kernel.org> <20161214095301.09ccf17b@gandalf.local.home> X-Mailer: Claws Mail 3.14.0 (GTK+ 2.24.31; x86_64-pc-linux-gnu) MIME-Version: 1.0 Content-Type: text/plain; charset=US-ASCII Content-Transfer-Encoding: 7bit Sender: linux-kernel-owner@vger.kernel.org List-ID: X-Mailing-List: linux-kernel@vger.kernel.org [ 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. 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. > > -- 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); }