OpenSDV
/
original_kernel
1
0
Fork 0
Code Issues Pull Requests Packages Projects Releases Wiki Activity

x86: Add NMI duration tracepoints 

This patch has been invaluable in my adventures finding
issues in the perf NMI handler.  I'm as big a fan of
printk() as anybody is, but using printk() in NMIs is
deadly when they're happening frequently.

Even hacking in trace_printk() ended up eating enough
CPU to throw off some of the measurements I was making.

Signed-off-by: Dave Hansen <dave.hansen@linux.intel.com>
Acked-by: Peter Zijlstra <a.p.zijlstra@chello.nl>
Cc: paulus@samba.org
Cc: acme@ghostprotocols.net
Cc: Dave Hansen <dave@sr71.net>
Signed-off-by: Ingo Molnar <mingo@kernel.org>
This commit is contained in:
Dave Hansen 2013-06-21 08:51:38 -07:00 committed by Ingo Molnar
parent 14c63f17b1
commit 0c4df02d73
3 changed files with 87 additions and 2 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

43
Documentation/trace/events-nmi.txt Normal file
View File

@ -0,0 +1,43 @@
NMI Trace Events
These events normally show up here:
/sys/kernel/debug/tracing/events/nmi
--
nmi_handler:
You might want to use this tracepoint if you suspect that your
NMI handlers are hogging large amounts of CPU time. The kernel
will warn if it sees long-running handlers:
INFO: NMI handler took too long to run: 9.207 msecs
and this tracepoint will allow you to drill down and get some
more details.
Let's say you suspect that perf_event_nmi_handler() is causing
you some problems and you only want to trace that handler
specifically. You need to find its address:
$ grep perf_event_nmi_handler /proc/kallsyms
ffffffff81625600 t perf_event_nmi_handler
Let's also say you are only interested in when that function is
really hogging a lot of CPU time, like a millisecond at a time.
Note that the kernel's output is in milliseconds, but the input
to the filter is in nanoseconds! You can filter on 'delta_ns':
cd /sys/kernel/debug/tracing/events/nmi/nmi_handler
echo 'handler==0xffffffff81625600 && delta_ns>1000000' > filter
echo 1 > enable
Your output would then look like:
$ cat /sys/kernel/debug/tracing/trace_pipe
<idle>-0 [000] d.h3 505.397558: nmi_handler: perf_event_nmi_handler() delta_ns: 3236765 handled: 1
<idle>-0 [000] d.h3 505.805893: nmi_handler: perf_event_nmi_handler() delta_ns: 3174234 handled: 1
<idle>-0 [000] d.h3 506.158206: nmi_handler: perf_event_nmi_handler() delta_ns: 3084642 handled: 1
<idle>-0 [000] d.h3 506.334346: nmi_handler: perf_event_nmi_handler() delta_ns: 3080351 handled: 1

9
arch/x86/kernel/nmi.c
View File

@ -30,6 +30,9 @@
#include <asm/nmi.h>
#include <asm/x86_init.h>
#define CREATE_TRACE_POINTS
#include <trace/events/nmi.h>
struct nmi_desc {
spinlock_t lock;
struct list_head head;
@ -108,11 +111,13 @@ static int __kprobes nmi_handle(unsigned int type, struct pt_regs *regs, bool b2
*/
list_for_each_entry_rcu(a, &desc->head, list) {
u64 before, delta, whole_msecs;
int decimal_msecs;
int decimal_msecs, thishandled;
before = local_clock();
handled += a->handler(type, regs);
thishandled = a->handler(type, regs);
handled += thishandled;
delta = local_clock() - before;
trace_nmi_handler(a->handler, (int)delta, thishandled);
if (delta < nmi_longest_ns)
continue;

37
include/trace/events/nmi.h Normal file
View File

@ -0,0 +1,37 @@
#undef TRACE_SYSTEM
#define TRACE_SYSTEM nmi
#if !defined(_TRACE_NMI_H) || defined(TRACE_HEADER_MULTI_READ)
#define _TRACE_NMI_H
#include <linux/ktime.h>
#include <linux/tracepoint.h>
TRACE_EVENT(nmi_handler,
TP_PROTO(void *handler, s64 delta_ns, int handled),
TP_ARGS(handler, delta_ns, handled),
TP_STRUCT__entry(
__field( void *, handler )
__field( s64, delta_ns)
__field( int, handled )
),
TP_fast_assign(
__entry->handler = handler;
__entry->delta_ns = delta_ns;
__entry->handled = handled;
),
TP_printk("%ps() delta_ns: %lld handled: %d",
__entry->handler,
__entry->delta_ns,
__entry->handled)
);
#endif /* _TRACE_NMI_H */
/* This part ust be outside protection */
#include <trace/define_trace.h>