profile_example.txt

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
    filemap_map_pages
    handle_mm_fault
    __do_page_fault
    do_page_fault
    page_fault
    [unknown]
    -                cp (9036)
        1

    [unknown]
    [unknown]
    -                sign-file (8877)
        1

    __clear_user
    iov_iter_zero
    read_iter_zero
    __vfs_read
    vfs_read
    sys_read
    entry_SYSCALL_64_fastpath
    read
    -                dd (25036)
        4

    func_a
    main
    __libc_start_main
    [unknown]
    -                func_ab (13549)
        5

The output was long; I truncated some lines ("[...]").

This default output prints stack traces, 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 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.


By default, CPU idle stacks are excluded. They can be included with -I:

# ./profile -I

[...]

    native_safe_halt
    default_idle
    arch_cpu_idle
    default_idle_call
    cpu_startup_entry
    rest_init
    start_kernel
    x86_64_start_reservations
    x86_64_start_kernel
    -                swapper/0 (0)
        72

    native_safe_halt
    default_idle
    arch_cpu_idle
    default_idle_call
    cpu_startup_entry
    start_secondary
    -                swapper/1 (0)
        75

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 dd process profiled ealrier 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
    [unknown]
    [unknown]
    -                dd (25036)
        1

    __write
    -                dd (25036)
        1

    read
    -                dd (25036)
        1

[...]

    [unknown]
    [unknown]
    -                dd (25036)
        2

    entry_SYSCALL_64_fastpath
    __write
    [unknown]
    -                dd (25036)
        3

    entry_SYSCALL_64_fastpath
    read
    -                dd (25036)
        3

    __clear_user
    iov_iter_zero
    read_iter_zero
    __vfs_read
    vfs_read
    sys_read
    entry_SYSCALL_64_fastpath
    read
    [unknown]
    -                dd (25036)
        3

    __clear_user
    iov_iter_zero
    read_iter_zero
    __vfs_read
    vfs_read
    sys_read
    entry_SYSCALL_64_fastpath
    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
    __vfs_write
    sys_write
    entry_SYSCALL_64_fastpath
    --
    __write
    -                dd (25036)
        1

    --
    [unknown]
    [unknown]
    -                dd (25036)
        1

    iov_iter_init
    __vfs_read
    vfs_read
    sys_read
    entry_SYSCALL_64_fastpath
    --
    read
    -                dd (25036)
        1

[...]

    __clear_user
    iov_iter_zero
    read_iter_zero
    __vfs_read
    vfs_read
    sys_read
    entry_SYSCALL_64_fastpath
    --
    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.

    func_a
    main
    __libc_start_main
    [unknown]
    -                func_ab (2930)
        2

    func_b
    main
    __libc_start_main
    [unknown]
    -                func_ab (2930)
        3

    func_a
    main
    __libc_start_main
    [unknown]
    -                func_ab (2930)
        5

    func_b
    main
    __libc_start_main
    [unknown]
    -                func_ab (2930)
        12

    func_b
    main
    __libc_start_main
    [unknown]
    -                func_ab (2930)
        19

    func_a
    main
    __libc_start_main
    [unknown]
    -                func_ab (2930)
        22

    func_b
    main
    __libc_start_main
    [unknown]
    -                func_ab (2930)
        64

    func_a
    main
    __libc_start_main
    [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
[...]

    func_b
    main
    __libc_start_main
    [unknown]
    -                func_ab (2930)
        1

[...]


You can also restrict profiling to just kernel stacks (-K) or user stacks (-U).
For example, just user stacks:

# ./profile -C 7 2
Sampling at 49 Hertz of all threads by user + kernel stack on CPU#7 for 2 secs.

    PyEval_EvalFrameEx
    [unknown]
    [unknown]
    -                python (2827439)
        1

    PyDict_GetItem
    [unknown]
    -                python (2827439)
        1

    [unknown]
    -                python (2827439)
        1

    PyEval_EvalFrameEx
    [unknown]
    [unknown]
    -                python (2827439)
        1

    PyEval_EvalFrameEx
    -                python (2827439)
        1

    [unknown]
    [unknown]
    -                python (2827439)

in this example python application was busylooping on a single core/cpu (#7)
we were collecting stack traces only from it

# ./profile -U
Sampling at 49 Hertz of all threads by user stack... Hit Ctrl-C to end.
^C
    [unknown]
    [unknown]
    -                dd (2931)
        1

    [unknown]
    [unknown]
    -                dd (2931)
        1

    [unknown]
    [unknown]
    -                dd (2931)
        1

    [unknown]
    [unknown]
    -                dd (2931)
        1

    [unknown]
    [unknown]
    -                dd (2931)
        1

    func_b
    main
    __libc_start_main
    [unknown]
    -                func_ab (2930)
        1

    [unknown]
    -                dd (2931)
        1

    [unknown]
    -                dd (2931)
        1

    func_a
    main
    __libc_start_main
    [unknown]
    -                func_ab (2930)
        3

    __write
    [unknown]
    -                dd (2931)
        3

    func_a
    main
    __libc_start_main
    [unknown]
    -                func_ab (2930)
        4

    func_b
    main
    __libc_start_main
    [unknown]
    -                func_ab (2930)
        7

    -                swapper/6 (0)
        10

    func_b
    main
    __libc_start_main
    [unknown]
    -                func_ab (2930)
        10

    __write
    -                dd (2931)
        10

    func_a
    main
    __libc_start_main
    [unknown]
    -                func_ab (2930)
        11

    read
    -                dd (2931)
        12

    read
    [unknown]
    -                dd (2931)
        14


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.

The --cgroupmap option filters based on a cgroup set. It is meant to be used
with an externally created map.

# ./profile --cgroupmap /sys/fs/bpf/test01

For more details, see docs/special_filtering.md


USAGE message:

# ./profile -h
usage: profile.py [-h] [-p PID | -L TID] [-U | -K] [-F FREQUENCY | -c COUNT]
                  [-d] [-a] [-I] [-f]
                  [--stack-storage-size STACK_STORAGE_SIZE] [-C CPU]
                  [--cgroupmap CGROUPMAP] [--mntnsmap MNTNSMAP]
                  [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 process with this PID only
  -L TID, --tid TID     profile thread with this TID 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
  -c COUNT, --count COUNT
                        sample period, number of events
  -d, --delimited       insert delimiter between kernel/user stacks
  -a, --annotations     add _[k] annotations to kernel frames
  -I, --include-idle    include CPU idle stacks
  -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 16384)
  -C CPU, --cpu CPU     cpu number to run profile on
  --cgroupmap CGROUPMAP
                        trace cgroups in this BPF map only
  --mntnsmap MNTNSMAP   trace mount namespaces in this BPF map only

examples:
    ./profile             # profile stack traces at 49 Hertz until Ctrl-C
    ./profile -F 99       # profile stack traces at 99 Hertz
    ./profile -c 1000000  # profile stack traces every 1 in a million events
    ./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 process with PID 185
    ./profile -L 185      # only profile thread with TID 185
    ./profile -U          # only show user space stacks (no kernel)
    ./profile -K          # only show kernel space stacks (no user)
    ./profile --cgroupmap mappath  # only trace cgroups in this BPF map
    ./profile --mntnsmap mappath   # only trace mount namespaces in the map