diff options
author | Carlos R. Mafra <crmafra2@gmail.com> | 2009-08-05 14:53:34 -0400 |
---|---|---|
committer | Ingo Molnar <mingo@elte.hu> | 2009-08-09 06:54:46 -0400 |
commit | c24b513337f06712b8c81eb4f1413d44591dfee7 (patch) | |
tree | 803dc18c10e93c02cbd0f6b26a072fdc2194935d | |
parent | 3a80b4a3539696f4b0574876326860323035a302 (diff) |
perf: "Longum est iter per praecepta, breve et efficax per exempla"
A few examples of how 'perf' can be used, from an e-mail by
Ingo Molnar http://lkml.org/lkml/2009/8/4/346.
Signed-off-by: Carlos R. Mafra <crmafra2@gmail.com>
Cc: Peter Zijlstra <a.p.zijlstra@chello.nl>
Cc: Valdis.Kletnieks@vt.edu
LKML-Reference: <20090805185334.GA4535@Pilar.aei.mpg.de>
Signed-off-by: Ingo Molnar <mingo@elte.hu>
-rw-r--r-- | tools/perf/Documentation/perf-examples.txt | 225 |
1 files changed, 225 insertions, 0 deletions
diff --git a/tools/perf/Documentation/perf-examples.txt b/tools/perf/Documentation/perf-examples.txt new file mode 100644 index 000000000000..8eb6c489fb15 --- /dev/null +++ b/tools/perf/Documentation/perf-examples.txt | |||
@@ -0,0 +1,225 @@ | |||
1 | |||
2 | ------------------------------ | ||
3 | ****** perf by examples ****** | ||
4 | ------------------------------ | ||
5 | |||
6 | [ From an e-mail by Ingo Molnar, http://lkml.org/lkml/2009/8/4/346 ] | ||
7 | |||
8 | |||
9 | First, discovery/enumeration of available counters can be done via | ||
10 | 'perf list': | ||
11 | |||
12 | titan:~> perf list | ||
13 | [...] | ||
14 | kmem:kmalloc [Tracepoint event] | ||
15 | kmem:kmem_cache_alloc [Tracepoint event] | ||
16 | kmem:kmalloc_node [Tracepoint event] | ||
17 | kmem:kmem_cache_alloc_node [Tracepoint event] | ||
18 | kmem:kfree [Tracepoint event] | ||
19 | kmem:kmem_cache_free [Tracepoint event] | ||
20 | kmem:mm_page_free_direct [Tracepoint event] | ||
21 | kmem:mm_pagevec_free [Tracepoint event] | ||
22 | kmem:mm_page_alloc [Tracepoint event] | ||
23 | kmem:mm_page_alloc_zone_locked [Tracepoint event] | ||
24 | kmem:mm_page_pcpu_drain [Tracepoint event] | ||
25 | kmem:mm_page_alloc_extfrag [Tracepoint event] | ||
26 | |||
27 | Then any (or all) of the above event sources can be activated and | ||
28 | measured. For example the page alloc/free properties of a 'hackbench | ||
29 | run' are: | ||
30 | |||
31 | titan:~> perf stat -e kmem:mm_page_pcpu_drain -e kmem:mm_page_alloc | ||
32 | -e kmem:mm_pagevec_free -e kmem:mm_page_free_direct ./hackbench 10 | ||
33 | Time: 0.575 | ||
34 | |||
35 | Performance counter stats for './hackbench 10': | ||
36 | |||
37 | 13857 kmem:mm_page_pcpu_drain | ||
38 | 27576 kmem:mm_page_alloc | ||
39 | 6025 kmem:mm_pagevec_free | ||
40 | 20934 kmem:mm_page_free_direct | ||
41 | |||
42 | 0.613972165 seconds time elapsed | ||
43 | |||
44 | You can observe the statistical properties as well, by using the | ||
45 | 'repeat the workload N times' feature of perf stat: | ||
46 | |||
47 | titan:~> perf stat --repeat 5 -e kmem:mm_page_pcpu_drain -e | ||
48 | kmem:mm_page_alloc -e kmem:mm_pagevec_free -e | ||
49 | kmem:mm_page_free_direct ./hackbench 10 | ||
50 | Time: 0.627 | ||
51 | Time: 0.644 | ||
52 | Time: 0.564 | ||
53 | Time: 0.559 | ||
54 | Time: 0.626 | ||
55 | |||
56 | Performance counter stats for './hackbench 10' (5 runs): | ||
57 | |||
58 | 12920 kmem:mm_page_pcpu_drain ( +- 3.359% ) | ||
59 | 25035 kmem:mm_page_alloc ( +- 3.783% ) | ||
60 | 6104 kmem:mm_pagevec_free ( +- 0.934% ) | ||
61 | 18376 kmem:mm_page_free_direct ( +- 4.941% ) | ||
62 | |||
63 | 0.643954516 seconds time elapsed ( +- 2.363% ) | ||
64 | |||
65 | Furthermore, these tracepoints can be used to sample the workload as | ||
66 | well. For example the page allocations done by a 'git gc' can be | ||
67 | captured the following way: | ||
68 | |||
69 | titan:~/git> perf record -f -e kmem:mm_page_alloc -c 1 ./git gc | ||
70 | Counting objects: 1148, done. | ||
71 | Delta compression using up to 2 threads. | ||
72 | Compressing objects: 100% (450/450), done. | ||
73 | Writing objects: 100% (1148/1148), done. | ||
74 | Total 1148 (delta 690), reused 1148 (delta 690) | ||
75 | [ perf record: Captured and wrote 0.267 MB perf.data (~11679 samples) ] | ||
76 | |||
77 | To check which functions generated page allocations: | ||
78 | |||
79 | titan:~/git> perf report | ||
80 | # Samples: 10646 | ||
81 | # | ||
82 | # Overhead Command Shared Object | ||
83 | # ........ ............... .......................... | ||
84 | # | ||
85 | 23.57% git-repack /lib64/libc-2.5.so | ||
86 | 21.81% git /lib64/libc-2.5.so | ||
87 | 14.59% git ./git | ||
88 | 11.79% git-repack ./git | ||
89 | 7.12% git /lib64/ld-2.5.so | ||
90 | 3.16% git-repack /lib64/libpthread-2.5.so | ||
91 | 2.09% git-repack /bin/bash | ||
92 | 1.97% rm /lib64/libc-2.5.so | ||
93 | 1.39% mv /lib64/ld-2.5.so | ||
94 | 1.37% mv /lib64/libc-2.5.so | ||
95 | 1.12% git-repack /lib64/ld-2.5.so | ||
96 | 0.95% rm /lib64/ld-2.5.so | ||
97 | 0.90% git-update-serv /lib64/libc-2.5.so | ||
98 | 0.73% git-update-serv /lib64/ld-2.5.so | ||
99 | 0.68% perf /lib64/libpthread-2.5.so | ||
100 | 0.64% git-repack /usr/lib64/libz.so.1.2.3 | ||
101 | |||
102 | Or to see it on a more finegrained level: | ||
103 | |||
104 | titan:~/git> perf report --sort comm,dso,symbol | ||
105 | # Samples: 10646 | ||
106 | # | ||
107 | # Overhead Command Shared Object Symbol | ||
108 | # ........ ............... .......................... ...... | ||
109 | # | ||
110 | 9.35% git-repack ./git [.] insert_obj_hash | ||
111 | 9.12% git ./git [.] insert_obj_hash | ||
112 | 7.31% git /lib64/libc-2.5.so [.] memcpy | ||
113 | 6.34% git-repack /lib64/libc-2.5.so [.] _int_malloc | ||
114 | 6.24% git-repack /lib64/libc-2.5.so [.] memcpy | ||
115 | 5.82% git-repack /lib64/libc-2.5.so [.] __GI___fork | ||
116 | 5.47% git /lib64/libc-2.5.so [.] _int_malloc | ||
117 | 2.99% git /lib64/libc-2.5.so [.] memset | ||
118 | |||
119 | Furthermore, call-graph sampling can be done too, of page | ||
120 | allocations - to see precisely what kind of page allocations there | ||
121 | are: | ||
122 | |||
123 | titan:~/git> perf record -f -g -e kmem:mm_page_alloc -c 1 ./git gc | ||
124 | Counting objects: 1148, done. | ||
125 | Delta compression using up to 2 threads. | ||
126 | Compressing objects: 100% (450/450), done. | ||
127 | Writing objects: 100% (1148/1148), done. | ||
128 | Total 1148 (delta 690), reused 1148 (delta 690) | ||
129 | [ perf record: Captured and wrote 0.963 MB perf.data (~42069 samples) ] | ||
130 | |||
131 | titan:~/git> perf report -g | ||
132 | # Samples: 10686 | ||
133 | # | ||
134 | # Overhead Command Shared Object | ||
135 | # ........ ............... .......................... | ||
136 | # | ||
137 | 23.25% git-repack /lib64/libc-2.5.so | ||
138 | | | ||
139 | |--50.00%-- _int_free | ||
140 | | | ||
141 | |--37.50%-- __GI___fork | ||
142 | | make_child | ||
143 | | | ||
144 | |--12.50%-- ptmalloc_unlock_all2 | ||
145 | | make_child | ||
146 | | | ||
147 | --6.25%-- __GI_strcpy | ||
148 | 21.61% git /lib64/libc-2.5.so | ||
149 | | | ||
150 | |--30.00%-- __GI_read | ||
151 | | | | ||
152 | | --83.33%-- git_config_from_file | ||
153 | | git_config | ||
154 | | | | ||
155 | [...] | ||
156 | |||
157 | Or you can observe the whole system's page allocations for 10 | ||
158 | seconds: | ||
159 | |||
160 | titan:~/git> perf stat -a -e kmem:mm_page_pcpu_drain -e | ||
161 | kmem:mm_page_alloc -e kmem:mm_pagevec_free -e | ||
162 | kmem:mm_page_free_direct sleep 10 | ||
163 | |||
164 | Performance counter stats for 'sleep 10': | ||
165 | |||
166 | 171585 kmem:mm_page_pcpu_drain | ||
167 | 322114 kmem:mm_page_alloc | ||
168 | 73623 kmem:mm_pagevec_free | ||
169 | 254115 kmem:mm_page_free_direct | ||
170 | |||
171 | 10.000591410 seconds time elapsed | ||
172 | |||
173 | Or observe how fluctuating the page allocations are, via statistical | ||
174 | analysis done over ten 1-second intervals: | ||
175 | |||
176 | titan:~/git> perf stat --repeat 10 -a -e kmem:mm_page_pcpu_drain -e | ||
177 | kmem:mm_page_alloc -e kmem:mm_pagevec_free -e | ||
178 | kmem:mm_page_free_direct sleep 1 | ||
179 | |||
180 | Performance counter stats for 'sleep 1' (10 runs): | ||
181 | |||
182 | 17254 kmem:mm_page_pcpu_drain ( +- 3.709% ) | ||
183 | 34394 kmem:mm_page_alloc ( +- 4.617% ) | ||
184 | 7509 kmem:mm_pagevec_free ( +- 4.820% ) | ||
185 | 25653 kmem:mm_page_free_direct ( +- 3.672% ) | ||
186 | |||
187 | 1.058135029 seconds time elapsed ( +- 3.089% ) | ||
188 | |||
189 | Or you can annotate the recorded 'git gc' run on a per symbol basis | ||
190 | and check which instructions/source-code generated page allocations: | ||
191 | |||
192 | titan:~/git> perf annotate __GI___fork | ||
193 | ------------------------------------------------ | ||
194 | Percent | Source code & Disassembly of libc-2.5.so | ||
195 | ------------------------------------------------ | ||
196 | : | ||
197 | : | ||
198 | : Disassembly of section .plt: | ||
199 | : Disassembly of section .text: | ||
200 | : | ||
201 | : 00000031a2e95560 <__fork>: | ||
202 | [...] | ||
203 | 0.00 : 31a2e95602: b8 38 00 00 00 mov $0x38,%eax | ||
204 | 0.00 : 31a2e95607: 0f 05 syscall | ||
205 | 83.42 : 31a2e95609: 48 3d 00 f0 ff ff cmp $0xfffffffffffff000,%rax | ||
206 | 0.00 : 31a2e9560f: 0f 87 4d 01 00 00 ja 31a2e95762 <__fork+0x202> | ||
207 | 0.00 : 31a2e95615: 85 c0 test %eax,%eax | ||
208 | |||
209 | ( this shows that 83.42% of __GI___fork's page allocations come from | ||
210 | the 0x38 system call it performs. ) | ||
211 | |||
212 | etc. etc. - a lot more is possible. I could list a dozen of | ||
213 | other different usecases straight away - neither of which is | ||
214 | possible via /proc/vmstat. | ||
215 | |||
216 | /proc/vmstat is not in the same league really, in terms of | ||
217 | expressive power of system analysis and performance | ||
218 | analysis. | ||
219 | |||
220 | All that the above results needed were those new tracepoints | ||
221 | in include/tracing/events/kmem.h. | ||
222 | |||
223 | Ingo | ||
224 | |||
225 | |||