diff options
Diffstat (limited to 'Documentation/trace/tracepoint-analysis.txt')
-rw-r--r-- | Documentation/trace/tracepoint-analysis.txt | 60 |
1 files changed, 30 insertions, 30 deletions
diff --git a/Documentation/trace/tracepoint-analysis.txt b/Documentation/trace/tracepoint-analysis.txt index 5eb4e487e667..87bee3c129ba 100644 --- a/Documentation/trace/tracepoint-analysis.txt +++ b/Documentation/trace/tracepoint-analysis.txt | |||
@@ -10,8 +10,8 @@ Tracepoints (see Documentation/trace/tracepoints.txt) can be used without | |||
10 | creating custom kernel modules to register probe functions using the event | 10 | creating custom kernel modules to register probe functions using the event |
11 | tracing infrastructure. | 11 | tracing infrastructure. |
12 | 12 | ||
13 | Simplistically, tracepoints will represent an important event that when can | 13 | Simplistically, tracepoints represent important events that can be |
14 | be taken in conjunction with other tracepoints to build a "Big Picture" of | 14 | taken in conjunction with other tracepoints to build a "Big Picture" of |
15 | what is going on within the system. There are a large number of methods for | 15 | what is going on within the system. There are a large number of methods for |
16 | gathering and interpreting these events. Lacking any current Best Practises, | 16 | gathering and interpreting these events. Lacking any current Best Practises, |
17 | this document describes some of the methods that can be used. | 17 | this document describes some of the methods that can be used. |
@@ -33,12 +33,12 @@ calling | |||
33 | 33 | ||
34 | will give a fair indication of the number of events available. | 34 | will give a fair indication of the number of events available. |
35 | 35 | ||
36 | 2.2 PCL | 36 | 2.2 PCL (Performance Counters for Linux) |
37 | ------- | 37 | ------- |
38 | 38 | ||
39 | Discovery and enumeration of all counters and events, including tracepoints | 39 | Discovery and enumeration of all counters and events, including tracepoints, |
40 | are available with the perf tool. Getting a list of available events is a | 40 | are available with the perf tool. Getting a list of available events is a |
41 | simple case of | 41 | simple case of: |
42 | 42 | ||
43 | $ perf list 2>&1 | grep Tracepoint | 43 | $ perf list 2>&1 | grep Tracepoint |
44 | ext4:ext4_free_inode [Tracepoint event] | 44 | ext4:ext4_free_inode [Tracepoint event] |
@@ -49,19 +49,19 @@ simple case of | |||
49 | [ .... remaining output snipped .... ] | 49 | [ .... remaining output snipped .... ] |
50 | 50 | ||
51 | 51 | ||
52 | 2. Enabling Events | 52 | 3. Enabling Events |
53 | ================== | 53 | ================== |
54 | 54 | ||
55 | 2.1 System-Wide Event Enabling | 55 | 3.1 System-Wide Event Enabling |
56 | ------------------------------ | 56 | ------------------------------ |
57 | 57 | ||
58 | See Documentation/trace/events.txt for a proper description on how events | 58 | See Documentation/trace/events.txt for a proper description on how events |
59 | can be enabled system-wide. A short example of enabling all events related | 59 | can be enabled system-wide. A short example of enabling all events related |
60 | to page allocation would look something like | 60 | to page allocation would look something like: |
61 | 61 | ||
62 | $ for i in `find /sys/kernel/debug/tracing/events -name "enable" | grep mm_`; do echo 1 > $i; done | 62 | $ for i in `find /sys/kernel/debug/tracing/events -name "enable" | grep mm_`; do echo 1 > $i; done |
63 | 63 | ||
64 | 2.2 System-Wide Event Enabling with SystemTap | 64 | 3.2 System-Wide Event Enabling with SystemTap |
65 | --------------------------------------------- | 65 | --------------------------------------------- |
66 | 66 | ||
67 | In SystemTap, tracepoints are accessible using the kernel.trace() function | 67 | In SystemTap, tracepoints are accessible using the kernel.trace() function |
@@ -86,7 +86,7 @@ were allocating the pages. | |||
86 | print_count() | 86 | print_count() |
87 | } | 87 | } |
88 | 88 | ||
89 | 2.3 System-Wide Event Enabling with PCL | 89 | 3.3 System-Wide Event Enabling with PCL |
90 | --------------------------------------- | 90 | --------------------------------------- |
91 | 91 | ||
92 | By specifying the -a switch and analysing sleep, the system-wide events | 92 | By specifying the -a switch and analysing sleep, the system-wide events |
@@ -107,16 +107,16 @@ for a duration of time can be examined. | |||
107 | Similarly, one could execute a shell and exit it as desired to get a report | 107 | Similarly, one could execute a shell and exit it as desired to get a report |
108 | at that point. | 108 | at that point. |
109 | 109 | ||
110 | 2.4 Local Event Enabling | 110 | 3.4 Local Event Enabling |
111 | ------------------------ | 111 | ------------------------ |
112 | 112 | ||
113 | Documentation/trace/ftrace.txt describes how to enable events on a per-thread | 113 | Documentation/trace/ftrace.txt describes how to enable events on a per-thread |
114 | basis using set_ftrace_pid. | 114 | basis using set_ftrace_pid. |
115 | 115 | ||
116 | 2.5 Local Event Enablement with PCL | 116 | 3.5 Local Event Enablement with PCL |
117 | ----------------------------------- | 117 | ----------------------------------- |
118 | 118 | ||
119 | Events can be activate and tracked for the duration of a process on a local | 119 | Events can be activated and tracked for the duration of a process on a local |
120 | basis using PCL such as follows. | 120 | basis using PCL such as follows. |
121 | 121 | ||
122 | $ perf stat -e kmem:mm_page_alloc -e kmem:mm_page_free_direct \ | 122 | $ perf stat -e kmem:mm_page_alloc -e kmem:mm_page_free_direct \ |
@@ -131,18 +131,18 @@ basis using PCL such as follows. | |||
131 | 131 | ||
132 | 0.973913387 seconds time elapsed | 132 | 0.973913387 seconds time elapsed |
133 | 133 | ||
134 | 3. Event Filtering | 134 | 4. Event Filtering |
135 | ================== | 135 | ================== |
136 | 136 | ||
137 | Documentation/trace/ftrace.txt covers in-depth how to filter events in | 137 | Documentation/trace/ftrace.txt covers in-depth how to filter events in |
138 | ftrace. Obviously using grep and awk of trace_pipe is an option as well | 138 | ftrace. Obviously using grep and awk of trace_pipe is an option as well |
139 | as any script reading trace_pipe. | 139 | as any script reading trace_pipe. |
140 | 140 | ||
141 | 4. Analysing Event Variances with PCL | 141 | 5. Analysing Event Variances with PCL |
142 | ===================================== | 142 | ===================================== |
143 | 143 | ||
144 | Any workload can exhibit variances between runs and it can be important | 144 | Any workload can exhibit variances between runs and it can be important |
145 | to know what the standard deviation in. By and large, this is left to the | 145 | to know what the standard deviation is. By and large, this is left to the |
146 | performance analyst to do it by hand. In the event that the discrete event | 146 | performance analyst to do it by hand. In the event that the discrete event |
147 | occurrences are useful to the performance analyst, then perf can be used. | 147 | occurrences are useful to the performance analyst, then perf can be used. |
148 | 148 | ||
@@ -166,7 +166,7 @@ In the event that some higher-level event is required that depends on some | |||
166 | aggregation of discrete events, then a script would need to be developed. | 166 | aggregation of discrete events, then a script would need to be developed. |
167 | 167 | ||
168 | Using --repeat, it is also possible to view how events are fluctuating over | 168 | Using --repeat, it is also possible to view how events are fluctuating over |
169 | time on a system wide basis using -a and sleep. | 169 | time on a system-wide basis using -a and sleep. |
170 | 170 | ||
171 | $ perf stat -e kmem:mm_page_alloc -e kmem:mm_page_free_direct \ | 171 | $ perf stat -e kmem:mm_page_alloc -e kmem:mm_page_free_direct \ |
172 | -e kmem:mm_pagevec_free \ | 172 | -e kmem:mm_pagevec_free \ |
@@ -180,7 +180,7 @@ time on a system wide basis using -a and sleep. | |||
180 | 180 | ||
181 | 1.002251757 seconds time elapsed ( +- 0.005% ) | 181 | 1.002251757 seconds time elapsed ( +- 0.005% ) |
182 | 182 | ||
183 | 5. Higher-Level Analysis with Helper Scripts | 183 | 6. Higher-Level Analysis with Helper Scripts |
184 | ============================================ | 184 | ============================================ |
185 | 185 | ||
186 | When events are enabled the events that are triggering can be read from | 186 | When events are enabled the events that are triggering can be read from |
@@ -190,11 +190,11 @@ be gathered on-line as appropriate. Examples of post-processing might include | |||
190 | 190 | ||
191 | o Reading information from /proc for the PID that triggered the event | 191 | o Reading information from /proc for the PID that triggered the event |
192 | o Deriving a higher-level event from a series of lower-level events. | 192 | o Deriving a higher-level event from a series of lower-level events. |
193 | o Calculate latencies between two events | 193 | o Calculating latencies between two events |
194 | 194 | ||
195 | Documentation/trace/postprocess/trace-pagealloc-postprocess.pl is an example | 195 | Documentation/trace/postprocess/trace-pagealloc-postprocess.pl is an example |
196 | script that can read trace_pipe from STDIN or a copy of a trace. When used | 196 | script that can read trace_pipe from STDIN or a copy of a trace. When used |
197 | on-line, it can be interrupted once to generate a report without existing | 197 | on-line, it can be interrupted once to generate a report without exiting |
198 | and twice to exit. | 198 | and twice to exit. |
199 | 199 | ||
200 | Simplistically, the script just reads STDIN and counts up events but it | 200 | Simplistically, the script just reads STDIN and counts up events but it |
@@ -212,12 +212,12 @@ also can do more such as | |||
212 | processes, the parent process responsible for creating all the helpers | 212 | processes, the parent process responsible for creating all the helpers |
213 | can be identified | 213 | can be identified |
214 | 214 | ||
215 | 6. Lower-Level Analysis with PCL | 215 | 7. Lower-Level Analysis with PCL |
216 | ================================ | 216 | ================================ |
217 | 217 | ||
218 | There may also be a requirement to identify what functions with a program | 218 | There may also be a requirement to identify what functions within a program |
219 | were generating events within the kernel. To begin this sort of analysis, the | 219 | were generating events within the kernel. To begin this sort of analysis, the |
220 | data must be recorded. At the time of writing, this required root | 220 | data must be recorded. At the time of writing, this required root: |
221 | 221 | ||
222 | $ perf record -c 1 \ | 222 | $ perf record -c 1 \ |
223 | -e kmem:mm_page_alloc -e kmem:mm_page_free_direct \ | 223 | -e kmem:mm_page_alloc -e kmem:mm_page_free_direct \ |
@@ -253,11 +253,11 @@ perf report. | |||
253 | # (For more details, try: perf report --sort comm,dso,symbol) | 253 | # (For more details, try: perf report --sort comm,dso,symbol) |
254 | # | 254 | # |
255 | 255 | ||
256 | According to this, the vast majority of events occured triggered on events | 256 | According to this, the vast majority of events triggered on events |
257 | within the VDSO. With simple binaries, this will often be the case so lets | 257 | within the VDSO. With simple binaries, this will often be the case so let's |
258 | take a slightly different example. In the course of writing this, it was | 258 | take a slightly different example. In the course of writing this, it was |
259 | noticed that X was generating an insane amount of page allocations so lets look | 259 | noticed that X was generating an insane amount of page allocations so let's look |
260 | at it | 260 | at it: |
261 | 261 | ||
262 | $ perf record -c 1 -f \ | 262 | $ perf record -c 1 -f \ |
263 | -e kmem:mm_page_alloc -e kmem:mm_page_free_direct \ | 263 | -e kmem:mm_page_alloc -e kmem:mm_page_free_direct \ |
@@ -280,8 +280,8 @@ This was interrupted after a few seconds and | |||
280 | # (For more details, try: perf report --sort comm,dso,symbol) | 280 | # (For more details, try: perf report --sort comm,dso,symbol) |
281 | # | 281 | # |
282 | 282 | ||
283 | So, almost half of the events are occuring in a library. To get an idea which | 283 | So, almost half of the events are occurring in a library. To get an idea which |
284 | symbol. | 284 | symbol: |
285 | 285 | ||
286 | $ perf report --sort comm,dso,symbol | 286 | $ perf report --sort comm,dso,symbol |
287 | # Samples: 27666 | 287 | # Samples: 27666 |
@@ -297,7 +297,7 @@ symbol. | |||
297 | 0.01% Xorg /opt/gfx-test/lib/libpixman-1.so.0.13.1 [.] get_fast_path | 297 | 0.01% Xorg /opt/gfx-test/lib/libpixman-1.so.0.13.1 [.] get_fast_path |
298 | 0.00% Xorg [kernel] [k] ftrace_trace_userstack | 298 | 0.00% Xorg [kernel] [k] ftrace_trace_userstack |
299 | 299 | ||
300 | To see where within the function pixmanFillsse2 things are going wrong | 300 | To see where within the function pixmanFillsse2 things are going wrong: |
301 | 301 | ||
302 | $ perf annotate pixmanFillsse2 | 302 | $ perf annotate pixmanFillsse2 |
303 | [ ... ] | 303 | [ ... ] |