Commit | Line | Data |
---|---|---|
15ba0538 CD |
1 | ================ |
2 | NMI Trace Events | |
3 | ================ | |
4 | ||
5 | These events normally show up here: | |
6 | ||
2abfcd29 | 7 | /sys/kernel/tracing/events/nmi |
15ba0538 CD |
8 | |
9 | ||
10 | nmi_handler | |
11 | ----------- | |
12 | ||
13 | You might want to use this tracepoint if you suspect that your | |
14 | NMI handlers are hogging large amounts of CPU time. The kernel | |
15 | will warn if it sees long-running handlers:: | |
16 | ||
17 | INFO: NMI handler took too long to run: 9.207 msecs | |
18 | ||
19 | and this tracepoint will allow you to drill down and get some | |
20 | more details. | |
21 | ||
22 | Let's say you suspect that perf_event_nmi_handler() is causing | |
23 | you some problems and you only want to trace that handler | |
24 | specifically. You need to find its address:: | |
25 | ||
26 | $ grep perf_event_nmi_handler /proc/kallsyms | |
27 | ffffffff81625600 t perf_event_nmi_handler | |
28 | ||
29 | Let's also say you are only interested in when that function is | |
30 | really hogging a lot of CPU time, like a millisecond at a time. | |
31 | Note that the kernel's output is in milliseconds, but the input | |
32 | to the filter is in nanoseconds! You can filter on 'delta_ns':: | |
33 | ||
2abfcd29 | 34 | cd /sys/kernel/tracing/events/nmi/nmi_handler |
15ba0538 CD |
35 | echo 'handler==0xffffffff81625600 && delta_ns>1000000' > filter |
36 | echo 1 > enable | |
37 | ||
38 | Your output would then look like:: | |
39 | ||
2abfcd29 | 40 | $ cat /sys/kernel/tracing/trace_pipe |
15ba0538 CD |
41 | <idle>-0 [000] d.h3 505.397558: nmi_handler: perf_event_nmi_handler() delta_ns: 3236765 handled: 1 |
42 | <idle>-0 [000] d.h3 505.805893: nmi_handler: perf_event_nmi_handler() delta_ns: 3174234 handled: 1 | |
43 | <idle>-0 [000] d.h3 506.158206: nmi_handler: perf_event_nmi_handler() delta_ns: 3084642 handled: 1 | |
44 | <idle>-0 [000] d.h3 506.334346: nmi_handler: perf_event_nmi_handler() delta_ns: 3080351 handled: 1 | |
45 |