Permalink
Fetching contributors…
Cannot retrieve contributors at this time
744 lines (635 sloc) 31.9 KB
Demonstrations of profile, the Linux eBPF/bcc version.
This is a CPU profiler. It works by taking samples of stack traces at timed
intervals, and frequency counting them in kernel context for efficiency.
Example output:
# ./profile
Sampling at 49 Hertz of all threads by user + kernel stack... Hit Ctrl-C to end.
^C
ffffffff81189249 filemap_map_pages
ffffffff811bd3f5 handle_mm_fault
ffffffff81065990 __do_page_fault
ffffffff81065caf do_page_fault
ffffffff817ce228 page_fault
00007fed989afcc0 [unknown]
- cp (9036)
1
00007f31d76c3251 [unknown]
47a2c1e752bf47f7 [unknown]
- sign-file (8877)
1
ffffffff813d0af8 __clear_user
ffffffff813d5277 iov_iter_zero
ffffffff814ec5f2 read_iter_zero
ffffffff8120be9d __vfs_read
ffffffff8120c385 vfs_read
ffffffff8120d786 sys_read
ffffffff817cc076 entry_SYSCALL_64_fastpath
00007fc5652ad9b0 read
- dd (25036)
4
0000000000400542 func_a
0000000000400598 main
00007f12a133e830 __libc_start_main
083e258d4c544155 [unknown]
- func_ab (13549)
5
[...]
ffffffff8105eb66 native_safe_halt
ffffffff8103659e default_idle
ffffffff81036d1f arch_cpu_idle
ffffffff810bba5a default_idle_call
ffffffff810bbd07 cpu_startup_entry
ffffffff817bf4a7 rest_init
ffffffff81d65f58 start_kernel
ffffffff81d652db x86_64_start_reservations
ffffffff81d65418 x86_64_start_kernel
- swapper/0 (0)
72
ffffffff8105eb66 native_safe_halt
ffffffff8103659e default_idle
ffffffff81036d1f arch_cpu_idle
ffffffff810bba5a default_idle_call
ffffffff810bbd07 cpu_startup_entry
ffffffff8104df55 start_secondary
- swapper/1 (0)
75
The output was long; I truncated some lines ("[...]").
This default output prints stack traces as two columns (raw addresses, and
then translated symbol names), followed by a line to describe the process (a
dash, the process name, and a PID in parenthesis), and then an integer count
of how many times this stack trace was sampled.
The output above shows the most frequent stack was from the "swapper/1"
process (PID 0), running the native_safe_halt() function, which was called
by default_idle(), which was called by arch_cpu_idle(), and so on. This is
the idle thread. Stacks can be read top-down, to follow ancestry: child,
parent, grandparent, etc.
The func_ab process is running the func_a() function, called by main(),
called by __libc_start_main(), and called by "[unknown]" with what looks
like a bogus address (1st column). That's evidence of a broken stack trace.
It's common for user-level software that hasn't been compiled with frame
pointers (in this case, libc).
The dd process has called read(), and then enters the kernel via
entry_SYSCALL_64_fastpath(), calling sys_read(), and so on. Yes, I'm now
reading it bottom up. That way follows the code flow.
The dd process is actually "dd if=/dev/zero of=/dev/null": it's a simple
workload to analyze that just moves bytes from /dev/zero to /dev/null.
Profiling just that process:
# ./profile -p 25036
Sampling at 49 Hertz of PID 25036 by user + kernel stack... Hit Ctrl-C to end.
^C
0000000000402748 [unknown]
00007fc56561422c [unknown]
- dd (25036)
1
00007fc5652ada0e __write
- dd (25036)
1
00007fc5652ad9b0 read
- dd (25036)
1
[...]
00000000004047b2 [unknown]
00007fc56561422c [unknown]
- dd (25036)
2
ffffffff817cc060 entry_SYSCALL_64_fastpath
00007fc5652ada10 __write
00007fc56561422c [unknown]
- dd (25036)
3
ffffffff817cc060 entry_SYSCALL_64_fastpath
00007fc5652ad9b0 read
- dd (25036)
3
ffffffff813d0af8 __clear_user
ffffffff813d5277 iov_iter_zero
ffffffff814ec5f2 read_iter_zero
ffffffff8120be9d __vfs_read
ffffffff8120c385 vfs_read
ffffffff8120d786 sys_read
ffffffff817cc076 entry_SYSCALL_64_fastpath
00007fc5652ad9b0 read
00007fc56561422c [unknown]
- dd (25036)
3
ffffffff813d0af8 __clear_user
ffffffff813d5277 iov_iter_zero
ffffffff814ec5f2 read_iter_zero
ffffffff8120be9d __vfs_read
ffffffff8120c385 vfs_read
ffffffff8120d786 sys_read
ffffffff817cc076 entry_SYSCALL_64_fastpath
00007fc5652ad9b0 read
- dd (25036)
7
Again, I've truncated some lines. Now we're just analyzing the dd process.
The filtering is performed in kernel context, for efficiency.
This output has some "[unknown]" frames that probably have valid addresses,
but we're lacking the symbol translation. This is a common for all profilers
on Linux, and is usually fixable. See the DEBUGGING section of the profile(8)
man page.
Lets add delimiters between the user and kernel stacks, using -d:
# ./profile -p 25036 -d
^C
ffffffff8120b385 __vfs_write
ffffffff8120d826 sys_write
ffffffff817cc076 entry_SYSCALL_64_fastpath
--
00007fc5652ada10 __write
- dd (25036)
1
--
00007fc565255ef3 [unknown]
00007fc56561422c [unknown]
- dd (25036)
1
ffffffff813d4569 iov_iter_init
ffffffff8120be8e __vfs_read
ffffffff8120c385 vfs_read
ffffffff8120d786 sys_read
ffffffff817cc076 entry_SYSCALL_64_fastpath
--
00007fc5652ad9b0 read
- dd (25036)
1
[...]
ffffffff813d0af8 __clear_user
ffffffff813d5277 iov_iter_zero
ffffffff814ec5f2 read_iter_zero
ffffffff8120be9d __vfs_read
ffffffff8120c385 vfs_read
ffffffff8120d786 sys_read
ffffffff817cc076 entry_SYSCALL_64_fastpath
--
00007fc5652ad9b0 read
- dd (25036)
9
In this mode, the delimiters are "--".
Here's another example, a func_ab program that runs two functions, func_a() and
func_b(). Profiling it for 5 seconds:
# ./profile -p `pgrep -n func_ab` 5
Sampling at 49 Hertz of PID 2930 by user + kernel stack for 5 secs.
000000000040053e func_a
0000000000400598 main
00007f0458819830 __libc_start_main
083e258d4c544155 [unknown]
- func_ab (2930)
2
0000000000400566 func_b
00000000004005ac main
00007f0458819830 __libc_start_main
083e258d4c544155 [unknown]
- func_ab (2930)
3
000000000040053a func_a
0000000000400598 main
00007f0458819830 __libc_start_main
083e258d4c544155 [unknown]
- func_ab (2930)
5
0000000000400562 func_b
00000000004005ac main
00007f0458819830 __libc_start_main
083e258d4c544155 [unknown]
- func_ab (2930)
12
000000000040056a func_b
00000000004005ac main
00007f0458819830 __libc_start_main
083e258d4c544155 [unknown]
- func_ab (2930)
19
0000000000400542 func_a
0000000000400598 main
00007f0458819830 __libc_start_main
083e258d4c544155 [unknown]
- func_ab (2930)
22
0000000000400571 func_b
00000000004005ac main
00007f0458819830 __libc_start_main
083e258d4c544155 [unknown]
- func_ab (2930)
64
0000000000400549 func_a
0000000000400598 main
00007f0458819830 __libc_start_main
083e258d4c544155 [unknown]
- func_ab (2930)
72
Note that the same stack (2nd column) seems to be repeated. Weren't we doing
frequency counting and only printing unique stacks? We are, but in terms of
the raw addresses, not the symbols. See the 1st column: those stacks are
all unique.
We can output in "folded format", which puts the stack trace on one line,
separating frames with semi-colons. Eg:
# ./profile -f -p `pgrep -n func_ab` 5
func_ab;[unknown];__libc_start_main;main;func_a 2
func_ab;[unknown];__libc_start_main;main;func_b 2
func_ab;[unknown];__libc_start_main;main;func_a 11
func_ab;[unknown];__libc_start_main;main;func_b 12
func_ab;[unknown];__libc_start_main;main;func_a 23
func_ab;[unknown];__libc_start_main;main;func_b 28
func_ab;[unknown];__libc_start_main;main;func_b 57
func_ab;[unknown];__libc_start_main;main;func_a 64
I find this pretty useful for writing to files and later grepping.
Folded format can also be used by flame graph stack visualizers, including
the original implementation:
https://github.com/brendangregg/FlameGraph
I'd include delimiters, -d. For example:
# ./profile -df -p `pgrep -n func_ab` 5 > out.profile
# git clone https://github.com/brendangregg/FlameGraph
# ./FlameGraph/flamegraph.pl < out.profile > out.svg
(Yes, I could pipe profile directly into flamegraph.pl, however, I like to
keep the raw folded profiles around: can be useful for regenerating flamegraphs
with different options, and, for differential flame graphs.)
Some flamegraph.pl palettes recognize kernel annotations, which can be added
with -a. It simply adds a "_[k]" at the end of kernel function names.
For example:
# ./profile -adf -p `pgrep -n dd` 10
dd;[unknown] 1
dd;[unknown];[unknown] 1
dd;[unknown];[unknown] 1
dd;[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
dd;[unknown];__write;-;entry_SYSCALL_64_fastpath_[k];sys_write_[k];vfs_write_[k];__fsnotify_parent_[k] 1
dd;[unknown];read;-;entry_SYSCALL_64_fastpath_[k];SyS_read_[k];__fdget_pos_[k] 1
dd;read;-;entry_SYSCALL_64_fastpath_[k];SyS_read_[k];vfs_read_[k];rw_verify_area_[k];apparmor_file_permission_[k] 1
dd;[unknown] 1
dd;[unknown];[unknown] 1
dd;__write;-;entry_SYSCALL_64_fastpath_[k];sys_write_[k];vfs_write_[k] 1
dd;[unknown] 1
dd;read;-;entry_SYSCALL_64_fastpath_[k];SyS_read_[k];__fget_light_[k] 1
dd;read;-;entry_SYSCALL_64_fastpath_[k];SyS_read_[k];vfs_read_[k];rw_verify_area_[k];__fsnotify_parent_[k] 1
dd;read;-;entry_SYSCALL_64_fastpath_[k];SyS_read_[k];vfs_read_[k];__vfs_read_[k];read_iter_zero_[k];iov_iter_zero_[k] 1
dd;[unknown];__write;-;entry_SYSCALL_64_fastpath_[k];sys_write_[k];__fget_light_[k] 1
dd;[unknown];[unknown] 1
dd;read;-;entry_SYSCALL_64_fastpath_[k];SyS_read_[k] 1
dd;[unknown];[unknown] 1
dd;read;-;entry_SYSCALL_64_fastpath_[k];SyS_read_[k];vfs_read_[k];__vfs_read_[k];read_iter_zero_[k];iov_iter_zero_[k] 1
dd;[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
dd;read;-;entry_SYSCALL_64_fastpath_[k];SyS_read_[k];vfs_read_[k];read_iter_zero_[k] 1
dd;[unknown];read;-;entry_SYSCALL_64_fastpath_[k];SyS_read_[k];vfs_read_[k];__fsnotify_parent_[k] 1
dd;[unknown];[unknown] 1
dd;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
dd;read;-;entry_SYSCALL_64_fastpath_[k];SyS_read_[k];__fsnotify_parent_[k] 1
dd;__write;-;entry_SYSCALL_64_fastpath_[k];sys_write_[k];vfs_write_[k];fsnotify_[k] 1
dd;__write;-;entry_SYSCALL_64_fastpath_[k];sys_write_[k];vfs_write_[k];rw_verify_area_[k];security_file_permission_[k] 1
dd;[unknown];__write;-;entry_SYSCALL_64_fastpath_[k];sys_write_[k];__fdget_pos_[k] 1
dd;[unknown];__write;-;entry_SYSCALL_64_fastpath_[k] 1
dd;[unknown];[unknown] 1
dd;read;-;entry_SYSCALL_64_fastpath_[k];SyS_read_[k];vfs_read_[k];rw_verify_area_[k];security_file_permission_[k] 1
dd;__write;-;entry_SYSCALL_64_fastpath_[k];sys_write_[k];vfs_write_[k] 1
dd;[unknown];read;-;entry_SYSCALL_64_fastpath_[k];SyS_read_[k];__fget_light_[k] 1
dd;[unknown] 1
dd;[unknown];__write;-;entry_SYSCALL_64_fastpath_[k];sys_write_[k];vfs_write_[k] 1
dd;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
dd;[unknown];[unknown] 1
dd;read;-;entry_SYSCALL_64_fastpath_[k];SyS_read_[k];vfs_read_[k];rw_verify_area_[k];security_file_permission_[k] 1
dd;[unknown];read;-;entry_SYSCALL_64_fastpath_[k];SyS_read_[k];vfs_read_[k];rw_verify_area_[k];__fsnotify_parent_[k] 1
dd;read;-;entry_SYSCALL_64_fastpath_[k];SyS_read_[k];vfs_read_[k];__vfs_read_[k];read_iter_zero_[k];iov_iter_zero_[k] 1
dd;__write;-;entry_SYSCALL_64_fastpath_[k];sys_write_[k];vfs_write_[k];rw_verify_area_[k];security_file_permission_[k] 1
dd;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
dd;[unknown];[unknown] 1
dd;__write;-;entry_SYSCALL_64_fastpath_[k];sys_write_[k];vfs_write_[k] 1
dd;[unknown];[unknown] 1
dd;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
dd;read 1
dd;__write;-;entry_SYSCALL_64_fastpath_[k];sys_write_[k];vfs_write_[k];security_file_permission_[k] 1
dd;read;-;entry_SYSCALL_64_fastpath_[k];SyS_read_[k];vfs_read_[k];fsnotify_[k] 1
dd;read;-;entry_SYSCALL_64_fastpath_[k];SyS_read_[k];vfs_read_[k];fsnotify_[k] 1
dd;__write;-;entry_SYSCALL_64_fastpath_[k];sys_write_[k];vfs_write_[k];rw_verify_area_[k];apparmor_file_permission_[k] 1
dd;[unknown];__write;-;entry_SYSCALL_64_fastpath_[k];sys_write_[k];vfs_write_[k];__fsnotify_parent_[k] 1
dd;[unknown];__write;-;entry_SYSCALL_64_fastpath_[k];sys_write_[k];vfs_write_[k];rw_verify_area_[k];apparmor_file_permission_[k] 1
dd;[unknown];read;-;entry_SYSCALL_64_fastpath_[k];SyS_read_[k];vfs_read_[k] 1
dd;read;-;entry_SYSCALL_64_fastpath_[k];SyS_read_[k];vfs_read_[k];__vfs_read_[k];iov_iter_init_[k] 1
dd;[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
dd;[unknown];__write;-;entry_SYSCALL_64_fastpath_[k];sys_write_[k];vfs_write_[k];__vfs_write_[k];write_null_[k] 1
dd;[unknown];read;-;entry_SYSCALL_64_fastpath_[k];SyS_read_[k];vfs_read_[k];__vfs_read_[k];read_iter_zero_[k];__clear_user_[k] 1
dd;[unknown];read;-;entry_SYSCALL_64_fastpath_[k];SyS_read_[k];vfs_read_[k];security_file_permission_[k] 1
dd;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
dd;read;-;entry_SYSCALL_64_fastpath_[k];SyS_read_[k];vfs_read_[k];__vfs_read_[k];read_iter_zero_[k] 1
dd;[unknown];__write;-;entry_SYSCALL_64_fastpath_[k];sys_write_[k];vfs_write_[k] 1
dd;__write;-;entry_SYSCALL_64_fastpath_[k];sys_write_[k];vfs_write_[k] 1
dd;[unknown];read;-;entry_SYSCALL_64_fastpath_[k];SyS_read_[k];vfs_read_[k];rw_verify_area_[k] 1
dd;read;-;entry_SYSCALL_64_fastpath_[k];SyS_read_[k];__fget_light_[k] 1
dd;[unknown];__write;-;entry_SYSCALL_64_fastpath_[k];sys_write_[k];vfs_write_[k];rw_verify_area_[k] 1
dd;read;-;entry_SYSCALL_64_fastpath_[k];SyS_read_[k];vfs_read_[k];__vfs_read_[k] 1
dd;[unknown];read;-;entry_SYSCALL_64_fastpath_[k];SyS_read_[k];__vfs_read_[k] 1
dd;[unknown];__write;-;entry_SYSCALL_64_fastpath_[k];sys_write_[k];vfs_write_[k];__vfs_write_[k] 1
dd;[unknown] 1
dd;[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
dd;[unknown] 1
dd;read;-;entry_SYSCALL_64_fastpath_[k];SyS_read_[k];vfs_read_[k];__vfs_read_[k] 1
dd;__write;-;entry_SYSCALL_64_fastpath_[k];sys_write_[k];__fsnotify_parent_[k] 1
dd;__write;-;entry_SYSCALL_64_fastpath_[k];sys_write_[k];vfs_write_[k] 1
dd;[unknown];[unknown] 1
dd;read;-;entry_SYSCALL_64_fastpath_[k];SyS_read_[k];vfs_read_[k];__vfs_read_[k];read_iter_zero_[k];iov_iter_zero_[k] 1
dd;read;-;entry_SYSCALL_64_fastpath_[k];SyS_read_[k];vfs_read_[k];__vfs_read_[k];read_iter_zero_[k];iov_iter_zero_[k] 1
dd;[unknown];__write;-;sys_write_[k] 1
dd;read;-;entry_SYSCALL_64_fastpath_[k];SyS_read_[k];__fsnotify_parent_[k] 1
dd;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
dd;[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
dd;[unknown];[unknown] 1
dd;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
dd;__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
dd;__write;-;entry_SYSCALL_64_fastpath_[k];sys_write_[k];__fget_light_[k] 1
dd;read;-;entry_SYSCALL_64_fastpath_[k];SyS_read_[k];vfs_read_[k] 1
dd;read;-;entry_SYSCALL_64_fastpath_[k];vfs_read_[k] 1
dd;__write 1
dd;read;-;entry_SYSCALL_64_fastpath_[k];vfs_read_[k] 1
dd;__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
dd;read;-;entry_SYSCALL_64_fastpath_[k];SyS_read_[k];vfs_read_[k];__vfs_read_[k];read_iter_zero_[k];iov_iter_zero_[k] 1
dd;[unknown];__write;-;entry_SYSCALL_64_fastpath_[k];sys_write_[k];__fget_light_[k] 1
dd;[unknown];[unknown] 1
dd;[unknown] 1
dd;[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
dd;[unknown] 1
dd;[unknown] 1
dd;[unknown];[unknown] 1
dd;__write;-;entry_SYSCALL_64_fastpath_[k];sys_write_[k];vfs_write_[k] 1
dd;[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
dd;read;-;entry_SYSCALL_64_fastpath_[k];SyS_read_[k] 1
dd;[unknown];read;-;entry_SYSCALL_64_fastpath_[k];SyS_read_[k];vfs_read_[k];__vfs_read_[k];read_iter_zero_[k] 1
dd;read;-;entry_SYSCALL_64_fastpath_[k];SyS_read_[k];vfs_read_[k] 1
dd;__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
dd;__write 1
dd;[unknown];read;-;entry_SYSCALL_64_fastpath_[k];SyS_read_[k];__fget_light_[k] 1
dd;read;-;entry_SYSCALL_64_fastpath_[k];SyS_read_[k];vfs_read_[k];rw_verify_area_[k];security_file_permission_[k] 1
dd;__write;-;entry_SYSCALL_64_fastpath_[k];sys_write_[k] 1
dd;[unknown] 1
dd;[unknown];read;-;entry_SYSCALL_64_fastpath_[k];SyS_read_[k];__fget_light_[k] 1
dd;read;-;entry_SYSCALL_64_fastpath_[k];SyS_read_[k];vfs_read_[k];__vfs_read_[k];read_iter_zero_[k] 1
dd;[unknown];[unknown] 1
dd;__write;-;entry_SYSCALL_64_fastpath_[k];sys_write_[k];__fdget_pos_[k] 1
dd;read;-;entry_SYSCALL_64_fastpath_[k];SyS_read_[k];vfs_read_[k];__vfs_read_[k];read_iter_zero_[k] 1
dd;[unknown];read;-;entry_SYSCALL_64_fastpath_[k];SyS_read_[k];vfs_read_[k];__vfs_read_[k];read_iter_zero_[k] 1
dd;read;-;entry_SYSCALL_64_fastpath_[k];SyS_read_[k];vfs_read_[k];__vfs_read_[k];_cond_resched_[k] 1
dd;[unknown];read;-;entry_SYSCALL_64_fastpath_[k];SyS_read_[k];vfs_read_[k];iov_iter_init_[k] 1
dd;read;-;entry_SYSCALL_64_fastpath_[k];SyS_read_[k];vfs_read_[k];rw_verify_area_[k];security_file_permission_[k];__fsnotify_parent_[k] 1
dd;[unknown];read;-;entry_SYSCALL_64_fastpath_[k];SyS_read_[k];vfs_read_[k];__vfs_read_[k] 1
dd;__write;-;entry_SYSCALL_64_fastpath_[k];sys_write_[k];rw_verify_area_[k] 1
dd;[unknown];read;-;entry_SYSCALL_64_fastpath_[k];SyS_read_[k];vfs_read_[k];rw_verify_area_[k];apparmor_file_permission_[k] 1
dd;[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
dd;read;-;entry_SYSCALL_64_fastpath_[k];SyS_read_[k];vfs_read_[k] 1
dd;[unknown] 1
dd;[unknown];read;-;entry_SYSCALL_64_fastpath_[k];SyS_read_[k];vfs_read_[k];rw_verify_area_[k];security_file_permission_[k];fsnotify_[k] 1
dd;read;-;entry_SYSCALL_64_fastpath_[k];SyS_read_[k];vfs_read_[k];__vfs_read_[k] 1
dd;__write;-;entry_SYSCALL_64_fastpath_[k];sys_write_[k];__fdget_pos_[k] 1
dd;[unknown];read;-;entry_SYSCALL_64_fastpath_[k];SyS_read_[k];vfs_read_[k];rw_verify_area_[k];security_file_permission_[k] 1
dd;__write;-;entry_SYSCALL_64_fastpath_[k];sys_write_[k];vfs_write_[k] 1
dd;[unknown];__write;-;entry_SYSCALL_64_fastpath_[k];sys_write_[k];vfs_write_[k];__vfs_write_[k] 1
dd;__write;-;entry_SYSCALL_64_fastpath_[k];sys_write_[k];vfs_write_[k];rw_verify_area_[k];apparmor_file_permission_[k] 1
dd;read;-;entry_SYSCALL_64_fastpath_[k];SyS_read_[k];vfs_read_[k];rw_verify_area_[k];security_file_permission_[k] 1
dd;__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
dd;__write;-;entry_SYSCALL_64_fastpath_[k];sys_write_[k];vfs_write_[k] 1
dd;__write;-;entry_SYSCALL_64_fastpath_[k];sys_write_[k];vfs_write_[k] 1
dd;read;-;entry_SYSCALL_64_fastpath_[k];SyS_read_[k];__fget_light_[k] 1
dd;[unknown] 1
dd;[unknown];__write;-;entry_SYSCALL_64_fastpath_[k];sys_write_[k];vfs_write_[k];fsnotify_[k] 1
dd;[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
dd;__write;-;entry_SYSCALL_64_fastpath_[k];sys_write_[k];vfs_write_[k];rw_verify_area_[k] 1
dd;[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
dd;read;-;entry_SYSCALL_64_fastpath_[k];SyS_read_[k];fsnotify_[k] 1
dd;[unknown];__write;-;entry_SYSCALL_64_fastpath_[k];sys_write_[k];vfs_write_[k] 1
dd;__write;-;entry_SYSCALL_64_fastpath_[k];vfs_write_[k] 1
dd;[unknown];read;-;entry_SYSCALL_64_fastpath_[k];SyS_read_[k];vfs_read_[k];rw_verify_area_[k] 1
dd;read;-;entry_SYSCALL_64_fastpath_[k];SyS_read_[k];vfs_read_[k];__vfs_read_[k] 1
dd;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
dd;[unknown];read;-;entry_SYSCALL_64_fastpath_[k];SyS_read_[k];vfs_read_[k];__vfs_read_[k];read_iter_zero_[k] 1
dd;[unknown];read;-;entry_SYSCALL_64_fastpath_[k];SyS_read_[k];vfs_read_[k];rw_verify_area_[k];fsnotify_[k] 1
dd;[unknown];__write;-;entry_SYSCALL_64_fastpath_[k];sys_write_[k];vfs_write_[k];rw_verify_area_[k];apparmor_file_permission_[k] 2
dd;read;-;entry_SYSCALL_64_fastpath_[k];__fdget_pos_[k] 2
dd;[unknown];[unknown] 2
dd;read;-;entry_SYSCALL_64_fastpath_[k];SyS_read_[k];__fdget_pos_[k] 2
dd;[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
dd;[unknown];[unknown] 2
dd;[unknown];[unknown] 2
dd;[unknown];[unknown] 2
dd;[unknown];read;-;entry_SYSCALL_64_fastpath_[k];SyS_read_[k];vfs_read_[k] 2
dd;[unknown];[unknown] 2
dd;read;-;entry_SYSCALL_64_fastpath_[k];SyS_read_[k];vfs_read_[k];__vfs_read_[k];read_iter_zero_[k];__clear_user_[k] 2
dd;__write;-;entry_SYSCALL_64_fastpath_[k];__fdget_pos_[k] 2
dd;[unknown];read;-;entry_SYSCALL_64_fastpath_[k];SyS_read_[k];vfs_read_[k];__vfs_read_[k] 2
dd;[unknown];read;-;entry_SYSCALL_64_fastpath_[k];SyS_read_[k];vfs_read_[k];__vfs_read_[k] 2
dd;[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
dd;[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
dd;[unknown];[unknown] 2
dd;__write;-;entry_SYSCALL_64_fastpath_[k];sys_write_[k];__fget_light_[k] 2
dd;read;-;entry_SYSCALL_64_fastpath_[k];SyS_read_[k];vfs_read_[k];rw_verify_area_[k];security_file_permission_[k];fsnotify_[k] 2
dd;__write;-;sys_write_[k] 2
dd;[unknown];read;-;entry_SYSCALL_64_fastpath_[k];SyS_read_[k];vfs_read_[k];fsnotify_[k] 2
dd;[unknown];[unknown] 2
dd;[unknown];read;-;entry_SYSCALL_64_fastpath_[k];SyS_read_[k];vfs_read_[k];__vfs_read_[k] 2
dd;read;-;entry_SYSCALL_64_fastpath_[k];SyS_read_[k];vfs_read_[k];__vfs_read_[k];read_iter_zero_[k];iov_iter_zero_[k] 2
dd;read;-;SyS_read_[k] 2
dd;[unknown] 2
dd;__write;-;entry_SYSCALL_64_fastpath_[k];sys_write_[k];vfs_write_[k];rw_verify_area_[k] 2
dd;[unknown];__write;-;entry_SYSCALL_64_fastpath_[k];sys_write_[k];__fget_light_[k] 2
dd;read;-;entry_SYSCALL_64_fastpath_[k];SyS_read_[k];vfs_read_[k];__vfs_read_[k] 2
dd;__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
dd;read;-;entry_SYSCALL_64_fastpath_[k];SyS_read_[k];vfs_read_[k];__vfs_read_[k];read_iter_zero_[k];__clear_user_[k] 2
dd;[unknown];__write;-;entry_SYSCALL_64_fastpath_[k];sys_write_[k];rw_verify_area_[k] 2
dd;[unknown];[unknown] 3
dd;[unknown];read;-;entry_SYSCALL_64_fastpath_[k];SyS_read_[k];rw_verify_area_[k] 3
dd;[unknown];[unknown] 3
dd;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
dd;read;-;entry_SYSCALL_64_fastpath_[k];SyS_read_[k];vfs_read_[k];__vfs_read_[k];read_iter_zero_[k];iov_iter_zero_[k] 3
dd;[unknown];[unknown] 3
dd;read;-;entry_SYSCALL_64_fastpath_[k];SyS_read_[k];vfs_read_[k];__vfs_read_[k];read_iter_zero_[k];iov_iter_zero_[k] 3
dd;[unknown];[unknown] 3
dd;[unknown];[unknown] 3
dd;__write;-;entry_SYSCALL_64_fastpath_[k];sys_write_[k];vfs_write_[k] 3
dd;[unknown];read;-;entry_SYSCALL_64_fastpath_[k];SyS_read_[k];vfs_read_[k] 3
dd;[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
dd;[unknown] 4
dd;[unknown];read;-;entry_SYSCALL_64_fastpath_[k];SyS_read_[k];vfs_read_[k] 4
dd;[unknown];[unknown] 4
dd;read;-;entry_SYSCALL_64_fastpath_[k];SyS_read_[k];vfs_read_[k] 4
dd;[unknown] 4
dd;[unknown];[unknown] 4
dd;[unknown];read;-;entry_SYSCALL_64_fastpath_[k];SyS_read_[k] 4
dd;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
dd;[unknown];__write;-;entry_SYSCALL_64_fastpath_[k];sys_write_[k];vfs_write_[k] 5
dd;[unknown];[unknown] 5
dd;[unknown];[unknown] 5
dd;[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
dd;read 15
dd;[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
dd;[unknown];__write;-;entry_SYSCALL_64_fastpath_[k] 20
dd;read;-;entry_SYSCALL_64_fastpath_[k] 23
dd;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
dd;__write;-;entry_SYSCALL_64_fastpath_[k] 25
dd;__write 29
dd;[unknown];read;-;entry_SYSCALL_64_fastpath_[k] 31
This can be made into a flamegraph. Eg:
# ./profile -adf -p `pgrep -n func_ab` 10 > out.profile
# git clone https://github.com/brendangregg/FlameGraph
# ./FlameGraph/flamegraph.pl --color=java < out.profile > out.svg
It will highlight the kernel frames in orange, and user-level in red (and Java
in green, and C++ in yellow). If you copy-n-paste the above output into a
out.profile file, you can try it out.
You can increase or decrease the sample frequency. Eg, sampling at 9 Hertz:
# ./profile -F 9
Sampling at 9 Hertz of all threads by user + kernel stack... Hit Ctrl-C to end.
^C
000000000040056a func_b
00000000004005ac main
00007f0458819830 __libc_start_main
083e258d4c544155 [unknown]
- func_ab (2930)
1
[...]
ffffffff8105eb66 native_safe_halt
ffffffff8103659e default_idle
ffffffff81036d1f arch_cpu_idle
ffffffff810bba5a default_idle_call
ffffffff810bbd07 cpu_startup_entry
ffffffff8104df55 start_secondary
- swapper/3 (0)
8
ffffffff8105eb66 native_safe_halt
ffffffff8103659e default_idle
ffffffff81036d1f arch_cpu_idle
ffffffff810bba5a default_idle_call
ffffffff810bbd07 cpu_startup_entry
ffffffff817bf497 rest_init
ffffffff81d65f58 start_kernel
ffffffff81d652db x86_64_start_reservations
ffffffff81d65418 x86_64_start_kernel
- swapper/0 (0)
8
You can also restrict profiling to just kernel stacks (-K) or user stacks (-U).
For example, just user stacks:
# ./profile -U
Sampling at 49 Hertz of all threads by user stack... Hit Ctrl-C to end.
^C
0000000000402ccc [unknown]
00007f45a624422c [unknown]
- dd (2931)
1
0000000000404b80 [unknown]
00007f45a624422c [unknown]
- dd (2931)
1
0000000000404d77 [unknown]
00007f45a624422c [unknown]
- dd (2931)
1
00007f45a5e85e5e [unknown]
00007f45a624422c [unknown]
- dd (2931)
1
0000000000402d12 [unknown]
00007f45a624422c [unknown]
- dd (2931)
1
0000000000400562 func_b
00000000004005ac main
00007f0458819830 __libc_start_main
083e258d4c544155 [unknown]
- func_ab (2930)
1
0000000000404805 [unknown]
- dd (2931)
1
00000000004047de [unknown]
- dd (2931)
1
0000000000400542 func_a
0000000000400598 main
00007f0458819830 __libc_start_main
083e258d4c544155 [unknown]
- func_ab (2930)
3
00007f45a5edda10 __write
00007f45a624422c [unknown]
- dd (2931)
3
000000000040053a func_a
0000000000400598 main
00007f0458819830 __libc_start_main
083e258d4c544155 [unknown]
- func_ab (2930)
4
000000000040056a func_b
00000000004005ac main
00007f0458819830 __libc_start_main
083e258d4c544155 [unknown]
- func_ab (2930)
7
- swapper/6 (0)
10
0000000000400571 func_b
00000000004005ac main
00007f0458819830 __libc_start_main
083e258d4c544155 [unknown]
- func_ab (2930)
10
00007f45a5edda10 __write
- dd (2931)
10
0000000000400549 func_a
0000000000400598 main
00007f0458819830 __libc_start_main
083e258d4c544155 [unknown]
- func_ab (2930)
11
00007f45a5edd9b0 read
- dd (2931)
12
00007f45a5edd9b0 read
00007f45a624422c [unknown]
- dd (2931)
14
- swapper/7 (0)
46
- swapper/0 (0)
46
- swapper/2 (0)
46
- swapper/1 (0)
46
- swapper/3 (0)
46
- swapper/4 (0)
46
If there are too many unique stack traces for the kernel to save, a warning
will be printed. Eg:
# ./profile
[...]
WARNING: 8 stack traces could not be displayed. Consider increasing --stack-storage-size.
Run ./profile -h to see the default.
USAGE message:
# ./profile -h
usage: profile [-h] [-p PID] [-U | -K] [-F FREQUENCY] [-d] [-a] [-f]
[--stack-storage-size STACK_STORAGE_SIZE]
[duration]
Profile CPU stack traces at a timed interval
positional arguments:
duration duration of trace, in seconds
optional arguments:
-h, --help show this help message and exit
-p PID, --pid PID profile this PID only
-U, --user-stacks-only
show stacks from user space only (no kernel space
stacks)
-K, --kernel-stacks-only
show stacks from kernel space only (no user space
stacks)
-F FREQUENCY, --frequency FREQUENCY
sample frequency, Hertz (default 49)
-d, --delimited insert delimiter between kernel/user stacks
-a, --annotations add _[k] annotations to kernel frames
-f, --folded output folded format, one line per stack (for flame
graphs)
--stack-storage-size STACK_STORAGE_SIZE
the number of unique stack traces that can be stored
and displayed (default 2048)
examples:
./profile # profile stack traces at 49 Hertz until Ctrl-C
./profile -F 99 # profile stack traces at 99 Hertz
./profile 5 # profile at 49 Hertz for 5 seconds only
./profile -f 5 # output in folded format for flame graphs
./profile -p 185 # only profile threads for PID 185
./profile -U # only show user space stacks (no kernel)
./profile -K # only show kernel space stacks (no user)