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