diff options
| author | Steven Rostedt (Red Hat) <rostedt@goodmis.org> | 2016-08-04 12:49:53 -0400 |
|---|---|---|
| committer | Steven Rostedt <rostedt@goodmis.org> | 2016-09-02 12:47:55 -0400 |
| commit | 7b2c86250122de316cbab8754050622ead04af39 (patch) | |
| tree | d6605100cf4fc03d8654c9757de0e70a813151ca /kernel/trace/trace_output.c | |
| parent | 0330f7aa8ee63d0c435c0cb4e47ea06235ee4b7f (diff) | |
| download | linux-7b2c86250122de316cbab8754050622ead04af39.tar.gz linux-7b2c86250122de316cbab8754050622ead04af39.tar.bz2 linux-7b2c86250122de316cbab8754050622ead04af39.zip | |
tracing: Add NMI tracing in hwlat detector
As NMIs can also cause latency when interrupts are disabled, the hwlat
detectory has no way to know if the latency it detects is from an NMI or an
SMI or some other hardware glitch.
As ftrace_nmi_enter/exit() funtions are no longer used (except for sh, which
isn't supported anymore), I converted those to "arch_ftrace_nmi_enter/exit"
and use ftrace_nmi_enter/exit() to check if hwlat detector is tracing or
not, and if so, it calls into the hwlat utility.
Since the hwlat detector only has a single kthread that is spinning with
interrupts disabled, it marks what CPU it is on, and if the NMI callback
happens on that CPU, it records the time spent in that NMI. This is added to
the output that is generated by the hwlat detector as:
#3 inner/outer(us): 9/9 ts:1470836488.206734548
#4 inner/outer(us): 0/8 ts:1470836497.140808588
#5 inner/outer(us): 0/6 ts:1470836499.140825168 nmi-total:5 nmi-count:1
#6 inner/outer(us): 9/9 ts:1470836501.140841748
All time is still tracked in microseconds.
The NMI information is only shown when an NMI occurred during the sample.
Signed-off-by: Steven Rostedt <rostedt@goodmis.org>
Diffstat (limited to 'kernel/trace/trace_output.c')
| -rw-r--r-- | kernel/trace/trace_output.c | 16 |
1 files changed, 15 insertions, 1 deletions
diff --git a/kernel/trace/trace_output.c b/kernel/trace/trace_output.c index d67a562df259..3fc20422c166 100644 --- a/kernel/trace/trace_output.c +++ b/kernel/trace/trace_output.c @@ -1109,13 +1109,27 @@ trace_hwlat_print(struct trace_iterator *iter, int flags, trace_assign_type(field, entry); - trace_seq_printf(s, "#%-5u inner/outer(us): %4llu/%-5llu ts:%ld.%09ld\n", + trace_seq_printf(s, "#%-5u inner/outer(us): %4llu/%-5llu ts:%ld.%09ld", field->seqnum, field->duration, field->outer_duration, field->timestamp.tv_sec, field->timestamp.tv_nsec); + if (field->nmi_count) { + /* + * 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)) + trace_seq_printf(s, " nmi-total:%llu", + field->nmi_total_ts); + trace_seq_printf(s, " nmi-count:%u", + field->nmi_count); + } + + trace_seq_putc(s, '\n'); + return trace_handle_return(s); } |