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