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