* Re: [RFC/PATCH] tracing: show total NMI time in hwlat tracer
2016-12-14 16:17 ` [RFC/PATCH] tracing: show total NMI time in hwlat tracer Steven Rostedt
@ 2016-12-15 15:32 ` Namhyung Kim
2016-12-15 15:41 ` Namhyung Kim
2016-12-16 0:20 ` Namhyung Kim
1 sibling, 1 reply; 4+ messages in thread
From: Namhyung Kim @ 2016-12-15 15:32 UTC (permalink / raw)
To: Steven Rostedt; +Cc: Ingo Molnar, LKML
On Wed, Dec 14, 2016 at 11:17:16AM -0500, Steven Rostedt wrote:
>
> [ added the forgotten LKML ;-) ]
Thanks! :)
>
> On Wed, 14 Dec 2016 09:53:01 -0500
> Steven Rostedt <rostedt@goodmis.org> wrote:
>
> > On Wed, 14 Dec 2016 16:13:51 +0900
> > Namhyung Kim <namhyung@kernel.org> 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.
Looks good to me, I just have a couple of nitpicks though..
>
> >
> > -- Steve
> >
> > > Signed-off-by: Namhyung Kim <namhyung@kernel.org>
> > > ---
> > > 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 )
Wouldn't it be better adding it to F_printk() also?
> 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;
The nmi_total_ts is u64 type, while nmi_t1 and _t2 are time_type.
> + 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;
It these are time_type, it should use time_to_us() instead.
Thanks,
Namhyung
> + 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);
> }
>
>
^ permalink raw reply [flat|nested] 4+ messages in thread* Re: [RFC/PATCH] tracing: show total NMI time in hwlat tracer
2016-12-14 16:17 ` [RFC/PATCH] tracing: show total NMI time in hwlat tracer Steven Rostedt
2016-12-15 15:32 ` Namhyung Kim
@ 2016-12-16 0:20 ` Namhyung Kim
1 sibling, 0 replies; 4+ messages in thread
From: Namhyung Kim @ 2016-12-16 0:20 UTC (permalink / raw)
To: Steven Rostedt; +Cc: Ingo Molnar, LKML
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 <rostedt@goodmis.org> wrote:
>
> > On Wed, 14 Dec 2016 16:13:51 +0900
> > Namhyung Kim <namhyung@kernel.org> 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 <namhyung@kernel.org>
> > > ---
> > > 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);
^ permalink raw reply related [flat|nested] 4+ messages in thread