1Demonstrations of profile, the Linux eBPF/bcc version.
2
3
4This is a CPU profiler. It works by taking samples of stack traces at timed
5intervals, and frequency counting them in kernel context for efficiency.
6
7Example output:
8
9# ./profile
10Sampling at 49 Hertz of all threads by user + kernel stack... Hit Ctrl-C to end.
11^C
12    ffffffff81189249 filemap_map_pages
13    ffffffff811bd3f5 handle_mm_fault
14    ffffffff81065990 __do_page_fault
15    ffffffff81065caf do_page_fault
16    ffffffff817ce228 page_fault
17    00007fed989afcc0 [unknown]
18    -                cp (9036)
19        1
20
21    00007f31d76c3251 [unknown]
22    47a2c1e752bf47f7 [unknown]
23    -                sign-file (8877)
24        1
25
26    ffffffff813d0af8 __clear_user
27    ffffffff813d5277 iov_iter_zero
28    ffffffff814ec5f2 read_iter_zero
29    ffffffff8120be9d __vfs_read
30    ffffffff8120c385 vfs_read
31    ffffffff8120d786 sys_read
32    ffffffff817cc076 entry_SYSCALL_64_fastpath
33    00007fc5652ad9b0 read
34    -                dd (25036)
35        4
36
37    0000000000400542 func_a
38    0000000000400598 main
39    00007f12a133e830 __libc_start_main
40    083e258d4c544155 [unknown]
41    -                func_ab (13549)
42        5
43
44[...]
45
46    ffffffff8105eb66 native_safe_halt
47    ffffffff8103659e default_idle
48    ffffffff81036d1f arch_cpu_idle
49    ffffffff810bba5a default_idle_call
50    ffffffff810bbd07 cpu_startup_entry
51    ffffffff817bf4a7 rest_init
52    ffffffff81d65f58 start_kernel
53    ffffffff81d652db x86_64_start_reservations
54    ffffffff81d65418 x86_64_start_kernel
55    -                swapper/0 (0)
56        72
57
58    ffffffff8105eb66 native_safe_halt
59    ffffffff8103659e default_idle
60    ffffffff81036d1f arch_cpu_idle
61    ffffffff810bba5a default_idle_call
62    ffffffff810bbd07 cpu_startup_entry
63    ffffffff8104df55 start_secondary
64    -                swapper/1 (0)
65        75
66
67The output was long; I truncated some lines ("[...]").
68
69This default output prints stack traces as two columns (raw addresses, and
70then translated symbol names), followed by a line to describe the process (a
71dash, the process name, and a PID in parenthesis), and then an integer count
72of how many times this stack trace was sampled.
73
74The output above shows the most frequent stack was from the "swapper/1"
75process (PID 0), running the native_safe_halt() function, which was called
76by default_idle(), which was called by arch_cpu_idle(), and so on. This is
77the idle thread. Stacks can be read top-down, to follow ancestry: child,
78parent, grandparent, etc.
79
80The func_ab process is running the func_a() function, called by main(),
81called by __libc_start_main(), and called by "[unknown]" with what looks
82like a bogus address (1st column). That's evidence of a broken stack trace.
83It's common for user-level software that hasn't been compiled with frame
84pointers (in this case, libc).
85
86The dd process has called read(), and then enters the kernel via
87entry_SYSCALL_64_fastpath(), calling sys_read(), and so on. Yes, I'm now
88reading it bottom up. That way follows the code flow.
89
90
91The dd process is actually "dd if=/dev/zero of=/dev/null": it's a simple
92workload to analyze that just moves bytes from /dev/zero to /dev/null.
93Profiling just that process:
94
95# ./profile -p 25036
96Sampling at 49 Hertz of PID 25036 by user + kernel stack... Hit Ctrl-C to end.
97^C
98    0000000000402748 [unknown]
99    00007fc56561422c [unknown]
100    -                dd (25036)
101        1
102
103    00007fc5652ada0e __write
104    -                dd (25036)
105        1
106
107    00007fc5652ad9b0 read
108    -                dd (25036)
109        1
110
111[...]
112
113    00000000004047b2 [unknown]
114    00007fc56561422c [unknown]
115    -                dd (25036)
116        2
117
118    ffffffff817cc060 entry_SYSCALL_64_fastpath
119    00007fc5652ada10 __write
120    00007fc56561422c [unknown]
121    -                dd (25036)
122        3
123
124    ffffffff817cc060 entry_SYSCALL_64_fastpath
125    00007fc5652ad9b0 read
126    -                dd (25036)
127        3
128
129    ffffffff813d0af8 __clear_user
130    ffffffff813d5277 iov_iter_zero
131    ffffffff814ec5f2 read_iter_zero
132    ffffffff8120be9d __vfs_read
133    ffffffff8120c385 vfs_read
134    ffffffff8120d786 sys_read
135    ffffffff817cc076 entry_SYSCALL_64_fastpath
136    00007fc5652ad9b0 read
137    00007fc56561422c [unknown]
138    -                dd (25036)
139        3
140
141    ffffffff813d0af8 __clear_user
142    ffffffff813d5277 iov_iter_zero
143    ffffffff814ec5f2 read_iter_zero
144    ffffffff8120be9d __vfs_read
145    ffffffff8120c385 vfs_read
146    ffffffff8120d786 sys_read
147    ffffffff817cc076 entry_SYSCALL_64_fastpath
148    00007fc5652ad9b0 read
149    -                dd (25036)
150        7
151
152Again, I've truncated some lines. Now we're just analyzing the dd process.
153The filtering is performed in kernel context, for efficiency.
154
155This output has some "[unknown]" frames that probably have valid addresses,
156but we're lacking the symbol translation. This is a common for all profilers
157on Linux, and is usually fixable. See the DEBUGGING section of the profile(8)
158man page.
159
160
161Lets add delimiters between the user and kernel stacks, using -d:
162
163# ./profile -p 25036 -d
164^C
165    ffffffff8120b385 __vfs_write
166    ffffffff8120d826 sys_write
167    ffffffff817cc076 entry_SYSCALL_64_fastpath
168    --
169    00007fc5652ada10 __write
170    -                dd (25036)
171        1
172
173    --
174    00007fc565255ef3 [unknown]
175    00007fc56561422c [unknown]
176    -                dd (25036)
177        1
178
179    ffffffff813d4569 iov_iter_init
180    ffffffff8120be8e __vfs_read
181    ffffffff8120c385 vfs_read
182    ffffffff8120d786 sys_read
183    ffffffff817cc076 entry_SYSCALL_64_fastpath
184    --
185    00007fc5652ad9b0 read
186    -                dd (25036)
187        1
188
189[...]
190
191    ffffffff813d0af8 __clear_user
192    ffffffff813d5277 iov_iter_zero
193    ffffffff814ec5f2 read_iter_zero
194    ffffffff8120be9d __vfs_read
195    ffffffff8120c385 vfs_read
196    ffffffff8120d786 sys_read
197    ffffffff817cc076 entry_SYSCALL_64_fastpath
198    --
199    00007fc5652ad9b0 read
200    -                dd (25036)
201        9
202
203In this mode, the delimiters are "--".
204
205
206
207Here's another example, a func_ab program that runs two functions, func_a() and
208func_b(). Profiling it for 5 seconds:
209
210# ./profile -p `pgrep -n func_ab` 5
211Sampling at 49 Hertz of PID 2930 by user + kernel stack for 5 secs.
212
213    000000000040053e func_a
214    0000000000400598 main
215    00007f0458819830 __libc_start_main
216    083e258d4c544155 [unknown]
217    -                func_ab (2930)
218        2
219
220    0000000000400566 func_b
221    00000000004005ac main
222    00007f0458819830 __libc_start_main
223    083e258d4c544155 [unknown]
224    -                func_ab (2930)
225        3
226
227    000000000040053a func_a
228    0000000000400598 main
229    00007f0458819830 __libc_start_main
230    083e258d4c544155 [unknown]
231    -                func_ab (2930)
232        5
233
234    0000000000400562 func_b
235    00000000004005ac main
236    00007f0458819830 __libc_start_main
237    083e258d4c544155 [unknown]
238    -                func_ab (2930)
239        12
240
241    000000000040056a func_b
242    00000000004005ac main
243    00007f0458819830 __libc_start_main
244    083e258d4c544155 [unknown]
245    -                func_ab (2930)
246        19
247
248    0000000000400542 func_a
249    0000000000400598 main
250    00007f0458819830 __libc_start_main
251    083e258d4c544155 [unknown]
252    -                func_ab (2930)
253        22
254
255    0000000000400571 func_b
256    00000000004005ac main
257    00007f0458819830 __libc_start_main
258    083e258d4c544155 [unknown]
259    -                func_ab (2930)
260        64
261
262    0000000000400549 func_a
263    0000000000400598 main
264    00007f0458819830 __libc_start_main
265    083e258d4c544155 [unknown]
266    -                func_ab (2930)
267        72
268
269Note that the same stack (2nd column) seems to be repeated. Weren't we doing
270frequency counting and only printing unique stacks? We are, but in terms of
271the raw addresses, not the symbols. See the 1st column: those stacks are
272all unique.
273
274
275We can output in "folded format", which puts the stack trace on one line,
276separating frames with semi-colons. Eg:
277
278# ./profile -f -p `pgrep -n func_ab` 5
279func_ab;[unknown];__libc_start_main;main;func_a 2
280func_ab;[unknown];__libc_start_main;main;func_b 2
281func_ab;[unknown];__libc_start_main;main;func_a 11
282func_ab;[unknown];__libc_start_main;main;func_b 12
283func_ab;[unknown];__libc_start_main;main;func_a 23
284func_ab;[unknown];__libc_start_main;main;func_b 28
285func_ab;[unknown];__libc_start_main;main;func_b 57
286func_ab;[unknown];__libc_start_main;main;func_a 64
287
288I find this pretty useful for writing to files and later grepping.
289
290
291Folded format can also be used by flame graph stack visualizers, including
292the original implementation:
293
294	https://github.com/brendangregg/FlameGraph
295
296I'd include delimiters, -d. For example:
297
298# ./profile -df -p `pgrep -n func_ab` 5 > out.profile
299# git clone https://github.com/brendangregg/FlameGraph
300# ./FlameGraph/flamegraph.pl < out.profile > out.svg
301
302(Yes, I could pipe profile directly into flamegraph.pl, however, I like to
303keep the raw folded profiles around: can be useful for regenerating flamegraphs
304with different options, and, for differential flame graphs.)
305
306
307Some flamegraph.pl palettes recognize kernel annotations, which can be added
308with -a. It simply adds a "_[k]" at the end of kernel function names.
309For example:
310
311# ./profile -adf -p `pgrep -n dd` 10
312dd;[unknown] 1
313dd;[unknown];[unknown] 1
314dd;[unknown];[unknown] 1
315dd;[unknown];read;-;entry_SYSCALL_64_fastpath_[k];SyS_read_[k];vfs_read_[k];rw_verify_area_[k];security_file_permission_[k];__fsnotify_parent_[k] 1
316dd;[unknown];__write;-;entry_SYSCALL_64_fastpath_[k];sys_write_[k];vfs_write_[k];__fsnotify_parent_[k] 1
317dd;[unknown];read;-;entry_SYSCALL_64_fastpath_[k];SyS_read_[k];__fdget_pos_[k] 1
318dd;read;-;entry_SYSCALL_64_fastpath_[k];SyS_read_[k];vfs_read_[k];rw_verify_area_[k];apparmor_file_permission_[k] 1
319dd;[unknown] 1
320dd;[unknown];[unknown] 1
321dd;__write;-;entry_SYSCALL_64_fastpath_[k];sys_write_[k];vfs_write_[k] 1
322dd;[unknown] 1
323dd;read;-;entry_SYSCALL_64_fastpath_[k];SyS_read_[k];__fget_light_[k] 1
324dd;read;-;entry_SYSCALL_64_fastpath_[k];SyS_read_[k];vfs_read_[k];rw_verify_area_[k];__fsnotify_parent_[k] 1
325dd;read;-;entry_SYSCALL_64_fastpath_[k];SyS_read_[k];vfs_read_[k];__vfs_read_[k];read_iter_zero_[k];iov_iter_zero_[k] 1
326dd;[unknown];__write;-;entry_SYSCALL_64_fastpath_[k];sys_write_[k];__fget_light_[k] 1
327dd;[unknown];[unknown] 1
328dd;read;-;entry_SYSCALL_64_fastpath_[k];SyS_read_[k] 1
329dd;[unknown];[unknown] 1
330dd;read;-;entry_SYSCALL_64_fastpath_[k];SyS_read_[k];vfs_read_[k];__vfs_read_[k];read_iter_zero_[k];iov_iter_zero_[k] 1
331dd;[unknown];read;-;entry_SYSCALL_64_fastpath_[k];SyS_read_[k];vfs_read_[k];__vfs_read_[k];read_iter_zero_[k];iov_iter_zero_[k] 1
332dd;read;-;entry_SYSCALL_64_fastpath_[k];SyS_read_[k];vfs_read_[k];read_iter_zero_[k] 1
333dd;[unknown];read;-;entry_SYSCALL_64_fastpath_[k];SyS_read_[k];vfs_read_[k];__fsnotify_parent_[k] 1
334dd;[unknown];[unknown] 1
335dd;read;-;entry_SYSCALL_64_fastpath_[k];SyS_read_[k];vfs_read_[k];rw_verify_area_[k];security_file_permission_[k];apparmor_file_permission_[k];common_file_perm_[k] 1
336dd;read;-;entry_SYSCALL_64_fastpath_[k];SyS_read_[k];__fsnotify_parent_[k] 1
337dd;__write;-;entry_SYSCALL_64_fastpath_[k];sys_write_[k];vfs_write_[k];fsnotify_[k] 1
338dd;__write;-;entry_SYSCALL_64_fastpath_[k];sys_write_[k];vfs_write_[k];rw_verify_area_[k];security_file_permission_[k] 1
339dd;[unknown];__write;-;entry_SYSCALL_64_fastpath_[k];sys_write_[k];__fdget_pos_[k] 1
340dd;[unknown];__write;-;entry_SYSCALL_64_fastpath_[k] 1
341dd;[unknown];[unknown] 1
342dd;read;-;entry_SYSCALL_64_fastpath_[k];SyS_read_[k];vfs_read_[k];rw_verify_area_[k];security_file_permission_[k] 1
343dd;__write;-;entry_SYSCALL_64_fastpath_[k];sys_write_[k];vfs_write_[k] 1
344dd;[unknown];read;-;entry_SYSCALL_64_fastpath_[k];SyS_read_[k];__fget_light_[k] 1
345dd;[unknown] 1
346dd;[unknown];__write;-;entry_SYSCALL_64_fastpath_[k];sys_write_[k];vfs_write_[k] 1
347dd;read;-;entry_SYSCALL_64_fastpath_[k];SyS_read_[k];vfs_read_[k];rw_verify_area_[k];security_file_permission_[k];apparmor_file_permission_[k] 1
348dd;[unknown];[unknown] 1
349dd;read;-;entry_SYSCALL_64_fastpath_[k];SyS_read_[k];vfs_read_[k];rw_verify_area_[k];security_file_permission_[k] 1
350dd;[unknown];read;-;entry_SYSCALL_64_fastpath_[k];SyS_read_[k];vfs_read_[k];rw_verify_area_[k];__fsnotify_parent_[k] 1
351dd;read;-;entry_SYSCALL_64_fastpath_[k];SyS_read_[k];vfs_read_[k];__vfs_read_[k];read_iter_zero_[k];iov_iter_zero_[k] 1
352dd;__write;-;entry_SYSCALL_64_fastpath_[k];sys_write_[k];vfs_write_[k];rw_verify_area_[k];security_file_permission_[k] 1
353dd;read;-;entry_SYSCALL_64_fastpath_[k];SyS_read_[k];vfs_read_[k];__vfs_read_[k];read_iter_zero_[k];iov_iter_zero_[k];__clear_user_[k] 1
354dd;[unknown];[unknown] 1
355dd;__write;-;entry_SYSCALL_64_fastpath_[k];sys_write_[k];vfs_write_[k] 1
356dd;[unknown];[unknown] 1
357dd;read;-;entry_SYSCALL_64_fastpath_[k];SyS_read_[k];vfs_read_[k];rw_verify_area_[k];security_file_permission_[k];apparmor_file_permission_[k];common_file_perm_[k] 1
358dd;read 1
359dd;__write;-;entry_SYSCALL_64_fastpath_[k];sys_write_[k];vfs_write_[k];security_file_permission_[k] 1
360dd;read;-;entry_SYSCALL_64_fastpath_[k];SyS_read_[k];vfs_read_[k];fsnotify_[k] 1
361dd;read;-;entry_SYSCALL_64_fastpath_[k];SyS_read_[k];vfs_read_[k];fsnotify_[k] 1
362dd;__write;-;entry_SYSCALL_64_fastpath_[k];sys_write_[k];vfs_write_[k];rw_verify_area_[k];apparmor_file_permission_[k] 1
363dd;[unknown];__write;-;entry_SYSCALL_64_fastpath_[k];sys_write_[k];vfs_write_[k];__fsnotify_parent_[k] 1
364dd;[unknown];__write;-;entry_SYSCALL_64_fastpath_[k];sys_write_[k];vfs_write_[k];rw_verify_area_[k];apparmor_file_permission_[k] 1
365dd;[unknown];read;-;entry_SYSCALL_64_fastpath_[k];SyS_read_[k];vfs_read_[k] 1
366dd;read;-;entry_SYSCALL_64_fastpath_[k];SyS_read_[k];vfs_read_[k];__vfs_read_[k];iov_iter_init_[k] 1
367dd;[unknown];read;-;entry_SYSCALL_64_fastpath_[k];SyS_read_[k];vfs_read_[k];rw_verify_area_[k];security_file_permission_[k];__fsnotify_parent_[k] 1
368dd;[unknown];__write;-;entry_SYSCALL_64_fastpath_[k];sys_write_[k];vfs_write_[k];__vfs_write_[k];write_null_[k] 1
369dd;[unknown];read;-;entry_SYSCALL_64_fastpath_[k];SyS_read_[k];vfs_read_[k];__vfs_read_[k];read_iter_zero_[k];__clear_user_[k] 1
370dd;[unknown];read;-;entry_SYSCALL_64_fastpath_[k];SyS_read_[k];vfs_read_[k];security_file_permission_[k] 1
371dd;read;-;entry_SYSCALL_64_fastpath_[k];SyS_read_[k];vfs_read_[k];rw_verify_area_[k];security_file_permission_[k];apparmor_file_permission_[k];common_file_perm_[k] 1
372dd;read;-;entry_SYSCALL_64_fastpath_[k];SyS_read_[k];vfs_read_[k];__vfs_read_[k];read_iter_zero_[k] 1
373dd;[unknown];__write;-;entry_SYSCALL_64_fastpath_[k];sys_write_[k];vfs_write_[k] 1
374dd;__write;-;entry_SYSCALL_64_fastpath_[k];sys_write_[k];vfs_write_[k] 1
375dd;[unknown];read;-;entry_SYSCALL_64_fastpath_[k];SyS_read_[k];vfs_read_[k];rw_verify_area_[k] 1
376dd;read;-;entry_SYSCALL_64_fastpath_[k];SyS_read_[k];__fget_light_[k] 1
377dd;[unknown];__write;-;entry_SYSCALL_64_fastpath_[k];sys_write_[k];vfs_write_[k];rw_verify_area_[k] 1
378dd;read;-;entry_SYSCALL_64_fastpath_[k];SyS_read_[k];vfs_read_[k];__vfs_read_[k] 1
379dd;[unknown];read;-;entry_SYSCALL_64_fastpath_[k];SyS_read_[k];__vfs_read_[k] 1
380dd;[unknown];__write;-;entry_SYSCALL_64_fastpath_[k];sys_write_[k];vfs_write_[k];__vfs_write_[k] 1
381dd;[unknown] 1
382dd;[unknown];read;-;entry_SYSCALL_64_fastpath_[k];SyS_read_[k];vfs_read_[k];__vfs_read_[k];read_iter_zero_[k];iov_iter_zero_[k] 1
383dd;[unknown] 1
384dd;read;-;entry_SYSCALL_64_fastpath_[k];SyS_read_[k];vfs_read_[k];__vfs_read_[k] 1
385dd;__write;-;entry_SYSCALL_64_fastpath_[k];sys_write_[k];__fsnotify_parent_[k] 1
386dd;__write;-;entry_SYSCALL_64_fastpath_[k];sys_write_[k];vfs_write_[k] 1
387dd;[unknown];[unknown] 1
388dd;read;-;entry_SYSCALL_64_fastpath_[k];SyS_read_[k];vfs_read_[k];__vfs_read_[k];read_iter_zero_[k];iov_iter_zero_[k] 1
389dd;read;-;entry_SYSCALL_64_fastpath_[k];SyS_read_[k];vfs_read_[k];__vfs_read_[k];read_iter_zero_[k];iov_iter_zero_[k] 1
390dd;[unknown];__write;-;sys_write_[k] 1
391dd;read;-;entry_SYSCALL_64_fastpath_[k];SyS_read_[k];__fsnotify_parent_[k] 1
392dd;read;-;entry_SYSCALL_64_fastpath_[k];SyS_read_[k];vfs_read_[k];rw_verify_area_[k];security_file_permission_[k];common_file_perm_[k] 1
393dd;[unknown];read;-;entry_SYSCALL_64_fastpath_[k];SyS_read_[k];vfs_read_[k];__vfs_read_[k];read_iter_zero_[k];iov_iter_zero_[k] 1
394dd;[unknown];[unknown] 1
395dd;read;-;entry_SYSCALL_64_fastpath_[k];SyS_read_[k];vfs_read_[k];__vfs_read_[k];read_iter_zero_[k];iov_iter_zero_[k];__clear_user_[k] 1
396dd;__write;-;entry_SYSCALL_64_fastpath_[k];sys_write_[k];vfs_write_[k];rw_verify_area_[k];security_file_permission_[k];apparmor_file_permission_[k] 1
397dd;__write;-;entry_SYSCALL_64_fastpath_[k];sys_write_[k];__fget_light_[k] 1
398dd;read;-;entry_SYSCALL_64_fastpath_[k];SyS_read_[k];vfs_read_[k] 1
399dd;read;-;entry_SYSCALL_64_fastpath_[k];vfs_read_[k] 1
400dd;__write 1
401dd;read;-;entry_SYSCALL_64_fastpath_[k];vfs_read_[k] 1
402dd;__write;-;entry_SYSCALL_64_fastpath_[k];sys_write_[k];vfs_write_[k];rw_verify_area_[k];security_file_permission_[k];apparmor_file_permission_[k];common_file_perm_[k] 1
403dd;read;-;entry_SYSCALL_64_fastpath_[k];SyS_read_[k];vfs_read_[k];__vfs_read_[k];read_iter_zero_[k];iov_iter_zero_[k] 1
404dd;[unknown];__write;-;entry_SYSCALL_64_fastpath_[k];sys_write_[k];__fget_light_[k] 1
405dd;[unknown];[unknown] 1
406dd;[unknown] 1
407dd;[unknown];read;-;entry_SYSCALL_64_fastpath_[k];SyS_read_[k];vfs_read_[k];__vfs_read_[k];read_iter_zero_[k];iov_iter_zero_[k] 1
408dd;[unknown] 1
409dd;[unknown] 1
410dd;[unknown];[unknown] 1
411dd;__write;-;entry_SYSCALL_64_fastpath_[k];sys_write_[k];vfs_write_[k] 1
412dd;[unknown];read;-;entry_SYSCALL_64_fastpath_[k];SyS_read_[k];vfs_read_[k];__vfs_read_[k];read_iter_zero_[k];iov_iter_zero_[k] 1
413dd;read;-;entry_SYSCALL_64_fastpath_[k];SyS_read_[k] 1
414dd;[unknown];read;-;entry_SYSCALL_64_fastpath_[k];SyS_read_[k];vfs_read_[k];__vfs_read_[k];read_iter_zero_[k] 1
415dd;read;-;entry_SYSCALL_64_fastpath_[k];SyS_read_[k];vfs_read_[k] 1
416dd;__write;-;entry_SYSCALL_64_fastpath_[k];sys_write_[k];vfs_write_[k];rw_verify_area_[k];security_file_permission_[k];apparmor_file_permission_[k];common_file_perm_[k] 1
417dd;__write 1
418dd;[unknown];read;-;entry_SYSCALL_64_fastpath_[k];SyS_read_[k];__fget_light_[k] 1
419dd;read;-;entry_SYSCALL_64_fastpath_[k];SyS_read_[k];vfs_read_[k];rw_verify_area_[k];security_file_permission_[k] 1
420dd;__write;-;entry_SYSCALL_64_fastpath_[k];sys_write_[k] 1
421dd;[unknown] 1
422dd;[unknown];read;-;entry_SYSCALL_64_fastpath_[k];SyS_read_[k];__fget_light_[k] 1
423dd;read;-;entry_SYSCALL_64_fastpath_[k];SyS_read_[k];vfs_read_[k];__vfs_read_[k];read_iter_zero_[k] 1
424dd;[unknown];[unknown] 1
425dd;__write;-;entry_SYSCALL_64_fastpath_[k];sys_write_[k];__fdget_pos_[k] 1
426dd;read;-;entry_SYSCALL_64_fastpath_[k];SyS_read_[k];vfs_read_[k];__vfs_read_[k];read_iter_zero_[k] 1
427dd;[unknown];read;-;entry_SYSCALL_64_fastpath_[k];SyS_read_[k];vfs_read_[k];__vfs_read_[k];read_iter_zero_[k] 1
428dd;read;-;entry_SYSCALL_64_fastpath_[k];SyS_read_[k];vfs_read_[k];__vfs_read_[k];_cond_resched_[k] 1
429dd;[unknown];read;-;entry_SYSCALL_64_fastpath_[k];SyS_read_[k];vfs_read_[k];iov_iter_init_[k] 1
430dd;read;-;entry_SYSCALL_64_fastpath_[k];SyS_read_[k];vfs_read_[k];rw_verify_area_[k];security_file_permission_[k];__fsnotify_parent_[k] 1
431dd;[unknown];read;-;entry_SYSCALL_64_fastpath_[k];SyS_read_[k];vfs_read_[k];__vfs_read_[k] 1
432dd;__write;-;entry_SYSCALL_64_fastpath_[k];sys_write_[k];rw_verify_area_[k] 1
433dd;[unknown];read;-;entry_SYSCALL_64_fastpath_[k];SyS_read_[k];vfs_read_[k];rw_verify_area_[k];apparmor_file_permission_[k] 1
434dd;[unknown];read;-;entry_SYSCALL_64_fastpath_[k];SyS_read_[k];vfs_read_[k];__vfs_read_[k];read_iter_zero_[k];iov_iter_zero_[k] 1
435dd;read;-;entry_SYSCALL_64_fastpath_[k];SyS_read_[k];vfs_read_[k] 1
436dd;[unknown] 1
437dd;[unknown];read;-;entry_SYSCALL_64_fastpath_[k];SyS_read_[k];vfs_read_[k];rw_verify_area_[k];security_file_permission_[k];fsnotify_[k] 1
438dd;read;-;entry_SYSCALL_64_fastpath_[k];SyS_read_[k];vfs_read_[k];__vfs_read_[k] 1
439dd;__write;-;entry_SYSCALL_64_fastpath_[k];sys_write_[k];__fdget_pos_[k] 1
440dd;[unknown];read;-;entry_SYSCALL_64_fastpath_[k];SyS_read_[k];vfs_read_[k];rw_verify_area_[k];security_file_permission_[k] 1
441dd;__write;-;entry_SYSCALL_64_fastpath_[k];sys_write_[k];vfs_write_[k] 1
442dd;[unknown];__write;-;entry_SYSCALL_64_fastpath_[k];sys_write_[k];vfs_write_[k];__vfs_write_[k] 1
443dd;__write;-;entry_SYSCALL_64_fastpath_[k];sys_write_[k];vfs_write_[k];rw_verify_area_[k];apparmor_file_permission_[k] 1
444dd;read;-;entry_SYSCALL_64_fastpath_[k];SyS_read_[k];vfs_read_[k];rw_verify_area_[k];security_file_permission_[k] 1
445dd;__write;-;entry_SYSCALL_64_fastpath_[k];sys_write_[k];vfs_write_[k];rw_verify_area_[k];security_file_permission_[k];apparmor_file_permission_[k];common_file_perm_[k] 1
446dd;__write;-;entry_SYSCALL_64_fastpath_[k];sys_write_[k];vfs_write_[k] 1
447dd;__write;-;entry_SYSCALL_64_fastpath_[k];sys_write_[k];vfs_write_[k] 1
448dd;read;-;entry_SYSCALL_64_fastpath_[k];SyS_read_[k];__fget_light_[k] 1
449dd;[unknown] 1
450dd;[unknown];__write;-;entry_SYSCALL_64_fastpath_[k];sys_write_[k];vfs_write_[k];fsnotify_[k] 1
451dd;[unknown];__write;-;entry_SYSCALL_64_fastpath_[k];sys_write_[k];vfs_write_[k];rw_verify_area_[k];security_file_permission_[k];apparmor_file_permission_[k];common_file_perm_[k] 1
452dd;__write;-;entry_SYSCALL_64_fastpath_[k];sys_write_[k];vfs_write_[k];rw_verify_area_[k] 1
453dd;[unknown];read;-;entry_SYSCALL_64_fastpath_[k];SyS_read_[k];vfs_read_[k];__vfs_read_[k];read_iter_zero_[k];iov_iter_zero_[k] 1
454dd;read;-;entry_SYSCALL_64_fastpath_[k];SyS_read_[k];fsnotify_[k] 1
455dd;[unknown];__write;-;entry_SYSCALL_64_fastpath_[k];sys_write_[k];vfs_write_[k] 1
456dd;__write;-;entry_SYSCALL_64_fastpath_[k];vfs_write_[k] 1
457dd;[unknown];read;-;entry_SYSCALL_64_fastpath_[k];SyS_read_[k];vfs_read_[k];rw_verify_area_[k] 1
458dd;read;-;entry_SYSCALL_64_fastpath_[k];SyS_read_[k];vfs_read_[k];__vfs_read_[k] 1
459dd;read;-;entry_SYSCALL_64_fastpath_[k];SyS_read_[k];vfs_read_[k];rw_verify_area_[k];security_file_permission_[k];apparmor_file_permission_[k];common_file_perm_[k] 1
460dd;[unknown];read;-;entry_SYSCALL_64_fastpath_[k];SyS_read_[k];vfs_read_[k];__vfs_read_[k];read_iter_zero_[k] 1
461dd;[unknown];read;-;entry_SYSCALL_64_fastpath_[k];SyS_read_[k];vfs_read_[k];rw_verify_area_[k];fsnotify_[k] 1
462dd;[unknown];__write;-;entry_SYSCALL_64_fastpath_[k];sys_write_[k];vfs_write_[k];rw_verify_area_[k];apparmor_file_permission_[k] 2
463dd;read;-;entry_SYSCALL_64_fastpath_[k];__fdget_pos_[k] 2
464dd;[unknown];[unknown] 2
465dd;read;-;entry_SYSCALL_64_fastpath_[k];SyS_read_[k];__fdget_pos_[k] 2
466dd;[unknown];read;-;entry_SYSCALL_64_fastpath_[k];SyS_read_[k];vfs_read_[k];rw_verify_area_[k];security_file_permission_[k];apparmor_file_permission_[k];common_file_perm_[k] 2
467dd;[unknown];[unknown] 2
468dd;[unknown];[unknown] 2
469dd;[unknown];[unknown] 2
470dd;[unknown];read;-;entry_SYSCALL_64_fastpath_[k];SyS_read_[k];vfs_read_[k] 2
471dd;[unknown];[unknown] 2
472dd;read;-;entry_SYSCALL_64_fastpath_[k];SyS_read_[k];vfs_read_[k];__vfs_read_[k];read_iter_zero_[k];__clear_user_[k] 2
473dd;__write;-;entry_SYSCALL_64_fastpath_[k];__fdget_pos_[k] 2
474dd;[unknown];read;-;entry_SYSCALL_64_fastpath_[k];SyS_read_[k];vfs_read_[k];__vfs_read_[k] 2
475dd;[unknown];read;-;entry_SYSCALL_64_fastpath_[k];SyS_read_[k];vfs_read_[k];__vfs_read_[k] 2
476dd;[unknown];read;-;entry_SYSCALL_64_fastpath_[k];SyS_read_[k];vfs_read_[k];__vfs_read_[k];read_iter_zero_[k];iov_iter_zero_[k];__clear_user_[k] 2
477dd;[unknown];read;-;entry_SYSCALL_64_fastpath_[k];SyS_read_[k];vfs_read_[k];__vfs_read_[k];read_iter_zero_[k];iov_iter_zero_[k];__clear_user_[k] 2
478dd;[unknown];[unknown] 2
479dd;__write;-;entry_SYSCALL_64_fastpath_[k];sys_write_[k];__fget_light_[k] 2
480dd;read;-;entry_SYSCALL_64_fastpath_[k];SyS_read_[k];vfs_read_[k];rw_verify_area_[k];security_file_permission_[k];fsnotify_[k] 2
481dd;__write;-;sys_write_[k] 2
482dd;[unknown];read;-;entry_SYSCALL_64_fastpath_[k];SyS_read_[k];vfs_read_[k];fsnotify_[k] 2
483dd;[unknown];[unknown] 2
484dd;[unknown];read;-;entry_SYSCALL_64_fastpath_[k];SyS_read_[k];vfs_read_[k];__vfs_read_[k] 2
485dd;read;-;entry_SYSCALL_64_fastpath_[k];SyS_read_[k];vfs_read_[k];__vfs_read_[k];read_iter_zero_[k];iov_iter_zero_[k] 2
486dd;read;-;SyS_read_[k] 2
487dd;[unknown] 2
488dd;__write;-;entry_SYSCALL_64_fastpath_[k];sys_write_[k];vfs_write_[k];rw_verify_area_[k] 2
489dd;[unknown];__write;-;entry_SYSCALL_64_fastpath_[k];sys_write_[k];__fget_light_[k] 2
490dd;read;-;entry_SYSCALL_64_fastpath_[k];SyS_read_[k];vfs_read_[k];__vfs_read_[k] 2
491dd;__write;-;entry_SYSCALL_64_fastpath_[k];sys_write_[k];vfs_write_[k];rw_verify_area_[k];security_file_permission_[k];apparmor_file_permission_[k] 2
492dd;read;-;entry_SYSCALL_64_fastpath_[k];SyS_read_[k];vfs_read_[k];__vfs_read_[k];read_iter_zero_[k];__clear_user_[k] 2
493dd;[unknown];__write;-;entry_SYSCALL_64_fastpath_[k];sys_write_[k];rw_verify_area_[k] 2
494dd;[unknown];[unknown] 3
495dd;[unknown];read;-;entry_SYSCALL_64_fastpath_[k];SyS_read_[k];rw_verify_area_[k] 3
496dd;[unknown];[unknown] 3
497dd;read;-;entry_SYSCALL_64_fastpath_[k];SyS_read_[k];vfs_read_[k];__vfs_read_[k];read_iter_zero_[k];iov_iter_zero_[k];__clear_user_[k] 3
498dd;read;-;entry_SYSCALL_64_fastpath_[k];SyS_read_[k];vfs_read_[k];__vfs_read_[k];read_iter_zero_[k];iov_iter_zero_[k] 3
499dd;[unknown];[unknown] 3
500dd;read;-;entry_SYSCALL_64_fastpath_[k];SyS_read_[k];vfs_read_[k];__vfs_read_[k];read_iter_zero_[k];iov_iter_zero_[k] 3
501dd;[unknown];[unknown] 3
502dd;[unknown];[unknown] 3
503dd;__write;-;entry_SYSCALL_64_fastpath_[k];sys_write_[k];vfs_write_[k] 3
504dd;[unknown];read;-;entry_SYSCALL_64_fastpath_[k];SyS_read_[k];vfs_read_[k] 3
505dd;[unknown];read;-;entry_SYSCALL_64_fastpath_[k];SyS_read_[k];vfs_read_[k];__vfs_read_[k];read_iter_zero_[k];iov_iter_zero_[k];__clear_user_[k] 3
506dd;[unknown] 4
507dd;[unknown];read;-;entry_SYSCALL_64_fastpath_[k];SyS_read_[k];vfs_read_[k] 4
508dd;[unknown];[unknown] 4
509dd;read;-;entry_SYSCALL_64_fastpath_[k];SyS_read_[k];vfs_read_[k] 4
510dd;[unknown] 4
511dd;[unknown];[unknown] 4
512dd;[unknown];read;-;entry_SYSCALL_64_fastpath_[k];SyS_read_[k] 4
513dd;read;-;entry_SYSCALL_64_fastpath_[k];SyS_read_[k];vfs_read_[k];__vfs_read_[k];read_iter_zero_[k];iov_iter_zero_[k];__clear_user_[k] 5
514dd;[unknown];__write;-;entry_SYSCALL_64_fastpath_[k];sys_write_[k];vfs_write_[k] 5
515dd;[unknown];[unknown] 5
516dd;[unknown];[unknown] 5
517dd;[unknown];read;-;entry_SYSCALL_64_fastpath_[k];SyS_read_[k];vfs_read_[k];__vfs_read_[k];read_iter_zero_[k];iov_iter_zero_[k] 6
518dd;read 15
519dd;[unknown];read;-;entry_SYSCALL_64_fastpath_[k];SyS_read_[k];vfs_read_[k];__vfs_read_[k];read_iter_zero_[k];iov_iter_zero_[k];__clear_user_[k] 19
520dd;[unknown];__write;-;entry_SYSCALL_64_fastpath_[k] 20
521dd;read;-;entry_SYSCALL_64_fastpath_[k] 23
522dd;read;-;entry_SYSCALL_64_fastpath_[k];SyS_read_[k];vfs_read_[k];__vfs_read_[k];read_iter_zero_[k];iov_iter_zero_[k];__clear_user_[k] 24
523dd;__write;-;entry_SYSCALL_64_fastpath_[k] 25
524dd;__write 29
525dd;[unknown];read;-;entry_SYSCALL_64_fastpath_[k] 31
526
527This can be made into a flamegraph. Eg:
528
529# ./profile -adf -p `pgrep -n func_ab` 10 > out.profile
530# git clone https://github.com/brendangregg/FlameGraph
531# ./FlameGraph/flamegraph.pl --color=java < out.profile > out.svg
532
533It will highlight the kernel frames in orange, and user-level in red (and Java
534in green, and C++ in yellow). If you copy-n-paste the above output into a
535out.profile file, you can try it out.
536
537
538You can increase or decrease the sample frequency. Eg, sampling at 9 Hertz:
539
540# ./profile -F 9
541Sampling at 9 Hertz of all threads by user + kernel stack... Hit Ctrl-C to end.
542^C
543    000000000040056a func_b
544    00000000004005ac main
545    00007f0458819830 __libc_start_main
546    083e258d4c544155 [unknown]
547    -                func_ab (2930)
548        1
549
550[...]
551
552    ffffffff8105eb66 native_safe_halt
553    ffffffff8103659e default_idle
554    ffffffff81036d1f arch_cpu_idle
555    ffffffff810bba5a default_idle_call
556    ffffffff810bbd07 cpu_startup_entry
557    ffffffff8104df55 start_secondary
558    -                swapper/3 (0)
559        8
560
561    ffffffff8105eb66 native_safe_halt
562    ffffffff8103659e default_idle
563    ffffffff81036d1f arch_cpu_idle
564    ffffffff810bba5a default_idle_call
565    ffffffff810bbd07 cpu_startup_entry
566    ffffffff817bf497 rest_init
567    ffffffff81d65f58 start_kernel
568    ffffffff81d652db x86_64_start_reservations
569    ffffffff81d65418 x86_64_start_kernel
570    -                swapper/0 (0)
571        8
572
573
574You can also restrict profiling to just kernel stacks (-K) or user stacks (-U).
575For example, just user stacks:
576
577# ./profile -U
578Sampling at 49 Hertz of all threads by user stack... Hit Ctrl-C to end.
579^C
580    0000000000402ccc [unknown]
581    00007f45a624422c [unknown]
582    -                dd (2931)
583        1
584
585    0000000000404b80 [unknown]
586    00007f45a624422c [unknown]
587    -                dd (2931)
588        1
589
590    0000000000404d77 [unknown]
591    00007f45a624422c [unknown]
592    -                dd (2931)
593        1
594
595    00007f45a5e85e5e [unknown]
596    00007f45a624422c [unknown]
597    -                dd (2931)
598        1
599
600    0000000000402d12 [unknown]
601    00007f45a624422c [unknown]
602    -                dd (2931)
603        1
604
605    0000000000400562 func_b
606    00000000004005ac main
607    00007f0458819830 __libc_start_main
608    083e258d4c544155 [unknown]
609    -                func_ab (2930)
610        1
611
612    0000000000404805 [unknown]
613    -                dd (2931)
614        1
615
616    00000000004047de [unknown]
617    -                dd (2931)
618        1
619
620    0000000000400542 func_a
621    0000000000400598 main
622    00007f0458819830 __libc_start_main
623    083e258d4c544155 [unknown]
624    -                func_ab (2930)
625        3
626
627    00007f45a5edda10 __write
628    00007f45a624422c [unknown]
629    -                dd (2931)
630        3
631
632    000000000040053a func_a
633    0000000000400598 main
634    00007f0458819830 __libc_start_main
635    083e258d4c544155 [unknown]
636    -                func_ab (2930)
637        4
638
639    000000000040056a func_b
640    00000000004005ac main
641    00007f0458819830 __libc_start_main
642    083e258d4c544155 [unknown]
643    -                func_ab (2930)
644        7
645
646    -                swapper/6 (0)
647        10
648
649    0000000000400571 func_b
650    00000000004005ac main
651    00007f0458819830 __libc_start_main
652    083e258d4c544155 [unknown]
653    -                func_ab (2930)
654        10
655
656    00007f45a5edda10 __write
657    -                dd (2931)
658        10
659
660    0000000000400549 func_a
661    0000000000400598 main
662    00007f0458819830 __libc_start_main
663    083e258d4c544155 [unknown]
664    -                func_ab (2930)
665        11
666
667    00007f45a5edd9b0 read
668    -                dd (2931)
669        12
670
671    00007f45a5edd9b0 read
672    00007f45a624422c [unknown]
673    -                dd (2931)
674        14
675
676    -                swapper/7 (0)
677        46
678
679    -                swapper/0 (0)
680        46
681
682    -                swapper/2 (0)
683        46
684
685    -                swapper/1 (0)
686        46
687
688    -                swapper/3 (0)
689        46
690
691    -                swapper/4 (0)
692        46
693
694
695If there are too many unique stack traces for the kernel to save, a warning
696will be printed. Eg:
697
698# ./profile
699[...]
700WARNING: 8 stack traces could not be displayed. Consider increasing --stack-storage-size.
701
702Run ./profile -h to see the default.
703
704
705There is a -S option to skip kernel frames. You probably don't need to mess
706with this. Here's why it exists: consider the following kernel stack trace,
707and IP:
708
709    ffffffff81174e78 perf_swevent_hrtimer
710    ffffffff810e6984 __hrtimer_run_queues
711    ffffffff810e70f8 hrtimer_interrupt
712    ffffffff81022c69 xen_timer_interrupt
713    ffffffff810d2942 handle_irq_event_percpu
714    ffffffff810d62da handle_percpu_irq
715    ffffffff810d1f52 generic_handle_irq
716    ffffffff814a5137 evtchn_2l_handle_events
717    ffffffff814a2853 __xen_evtchn_do_upcall
718    ffffffff814a4740 xen_evtchn_do_upcall
719    ffffffff817cd50c xen_hvm_callback_vector
720    ffffffff8103663e default_idle
721    ffffffff81036dbf arch_cpu_idle
722    ffffffff810bb8ea default_idle_call
723    ffffffff810bbb97 cpu_startup_entry
724    ffffffff8104df85 start_secondary
725
726IP: ffffffff8105eb66 native_safe_halt
727
728This is the idle thread. The first function is native_safe_halt(), and its
729parent is default_idle(). But what you see there is really what we are
730profiling. All that stuff above default_idle()? Interrupt framework stack.
731
732So we have to exclude those interrupt frames. I do this by fetching the ret IP
733from the kernel stack, and then scanning for it in user-level: in this case
734it would be default_idle(). Ok.
735
736If this doesn't work on your architecture (and your kernel stacks are a
737single line, the IP), then you might consider setting a fixed skip count,
738which avoids this ret IP logic. For the above stack, I'd set "-S 11", and
739it would slice off those 11 interrupt frames nicely. It also does this in
740kernel context for efficiency.
741
742So how do you figure out what number to use? 11? 14? 5? Well.. Try "-S 1",
743and then see how much higher you need to set it. Remember on the real
744profile output that the IP line is printed on top of the sliced stack.
745
746
747USAGE message:
748
749# ./profile -h
750usage: profile [-h] [-p PID] [-U | -K] [-F FREQUENCY] [-d] [-a] [-f]
751                  [--stack-storage-size STACK_STORAGE_SIZE] [-S KERNEL_SKIP]
752                  [duration]
753
754Profile CPU stack traces at a timed interval
755
756positional arguments:
757  duration              duration of trace, in seconds
758
759optional arguments:
760  -h, --help            show this help message and exit
761  -p PID, --pid PID     profile this PID only
762  -U, --user-stacks-only
763                        show stacks from user space only (no kernel space
764                        stacks)
765  -K, --kernel-stacks-only
766                        show stacks from kernel space only (no user space
767                        stacks)
768  -F FREQUENCY, --frequency FREQUENCY
769                        sample frequency, Hertz (default 49)
770  -d, --delimited       insert delimiter between kernel/user stacks
771  -a, --annotations     add _[k] annotations to kernel frames
772  -f, --folded          output folded format, one line per stack (for flame
773                        graphs)
774  --stack-storage-size STACK_STORAGE_SIZE
775                        the number of unique stack traces that can be stored
776                        and displayed (default 2048)
777  -S KERNEL_SKIP, --kernel-skip KERNEL_SKIP
778                        skip this many kernel frames (default 3)
779
780examples:
781    ./profile             # profile stack traces at 49 Hertz until Ctrl-C
782    ./profile -F 99       # profile stack traces at 99 Hertz
783    ./profile 5           # profile at 49 Hertz for 5 seconds only
784    ./profile -f 5        # output in folded format for flame graphs
785    ./profile -p 185      # only profile threads for PID 185
786    ./profile -U          # only show user space stacks (no kernel)
787    ./profile -K          # only show kernel space stacks (no user)
788    ./profile -S 11       # always skip 11 frames of kernel stack
789