0c4df02d73
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>
43 lines
1.5 KiB
Text
43 lines
1.5 KiB
Text
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
|
|
|