| lists.openwall.net | lists / announce owl-users owl-dev john-users john-dev passwdqc-users yescrypt popa3d-users / oss-security kernel-hardening musl sabotage tlsify passwords / crypt-dev xvendor / Bugtraq Full-Disclosure linux-kernel linux-netdev linux-ext4 linux-hardening linux-cve-announce PHC | |
|
Open Source and information security mailing list archives
| ||
|
Message-ID: <20161214111716.312273c8@gandalf.local.home>
Date: Wed, 14 Dec 2016 11:17:16 -0500
From: Steven Rostedt <rostedt@...dmis.org>
To: Namhyung Kim <namhyung@...nel.org>
Cc: Ingo Molnar <mingo@...nel.org>, LKML <linux-kernel@...r.kernel.org>
Subject: Re: [RFC/PATCH] tracing: show total NMI time in hwlat tracer
[ added the forgotten LKML ;-) ]
On Wed, 14 Dec 2016 09:53:01 -0500
Steven Rostedt <rostedt@...dmis.org> wrote:
> On Wed, 14 Dec 2016 16:13:51 +0900
> Namhyung Kim <namhyung@...nel.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.
>
> -- Steve
>
> > Signed-off-by: Namhyung Kim <namhyung@...nel.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);
}
Powered by blists - more mailing lists