| Changbin Du | 15ba053 | 2018-02-17 13:39:45 +0800 | [diff] [blame] | 1 | ================ |
| 2 | NMI Trace Events |
| 3 | ================ |
| 4 | |
| 5 | These events normally show up here: |
| 6 | |
| 7 | /sys/kernel/debug/tracing/events/nmi |
| 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 | |
| 34 | cd /sys/kernel/debug/tracing/events/nmi/nmi_handler |
| 35 | echo 'handler==0xffffffff81625600 && delta_ns>1000000' > filter |
| 36 | echo 1 > enable |
| 37 | |
| 38 | Your output would then look like:: |
| 39 | |
| 40 | $ cat /sys/kernel/debug/tracing/trace_pipe |
| 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 | |