46 lines · plain
1================2NMI Trace Events3================4 5These events normally show up here:6 7 /sys/kernel/tracing/events/nmi8 9 10nmi_handler11-----------12 13You might want to use this tracepoint if you suspect that your14NMI handlers are hogging large amounts of CPU time. The kernel15will warn if it sees long-running handlers::16 17 INFO: NMI handler took too long to run: 9.207 msecs18 19and this tracepoint will allow you to drill down and get some20more details.21 22Let's say you suspect that perf_event_nmi_handler() is causing23you some problems and you only want to trace that handler24specifically. You need to find its address::25 26 $ grep perf_event_nmi_handler /proc/kallsyms27 ffffffff81625600 t perf_event_nmi_handler28 29Let's also say you are only interested in when that function is30really hogging a lot of CPU time, like a millisecond at a time.31Note that the kernel's output is in milliseconds, but the input32to the filter is in nanoseconds! You can filter on 'delta_ns'::33 34 cd /sys/kernel/tracing/events/nmi/nmi_handler35 echo 'handler==0xffffffff81625600 && delta_ns>1000000' > filter36 echo 1 > enable37 38Your output would then look like::39 40 $ cat /sys/kernel/tracing/trace_pipe41 <idle>-0 [000] d.h3 505.397558: nmi_handler: perf_event_nmi_handler() delta_ns: 3236765 handled: 142 <idle>-0 [000] d.h3 505.805893: nmi_handler: perf_event_nmi_handler() delta_ns: 3174234 handled: 143 <idle>-0 [000] d.h3 506.158206: nmi_handler: perf_event_nmi_handler() delta_ns: 3084642 handled: 144 <idle>-0 [000] d.h3 506.334346: nmi_handler: perf_event_nmi_handler() delta_ns: 3080351 handled: 145 46