Home | History | Annotate | Download | only in tools 
      1 Demonstrations of profile, the Linux eBPF/bcc version.
      2 
      3 
      4 This is a CPU profiler. It works by taking samples of stack traces at timed
      5 intervals, and frequency counting them in kernel context for efficiency.
      6 
      7 Example output:
      8 
      9 # ./profile
     10 Sampling 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 
     67 The output was long; I truncated some lines ("[...]").
     68 
     69 This default output prints stack traces, followed by a line to describe the
     70 process (a dash, the process name, and a PID in parenthesis), and then an
     71 integer count of how many times this stack trace was sampled.
     72 
     73 The output above shows the most frequent stack was from the "swapper/1"
     74 process (PID 0), running the native_safe_halt() function, which was called
     75 by default_idle(), which was called by arch_cpu_idle(), and so on. This is
     76 the idle thread. Stacks can be read top-down, to follow ancestry: child,
     77 parent, grandparent, etc.
     78 
     79 The func_ab process is running the func_a() function, called by main(),
     80 called by __libc_start_main(), and called by "[unknown]" with what looks
     81 like a bogus address (1st column). That's evidence of a broken stack trace.
     82 It's common for user-level software that hasn't been compiled with frame
     83 pointers (in this case, libc).
     84 
     85 The dd process has called read(), and then enters the kernel via
     86 entry_SYSCALL_64_fastpath(), calling sys_read(), and so on. Yes, I'm now
     87 reading it bottom up. That way follows the code flow.
     88 
     89 
     90 The dd process is actually "dd if=/dev/zero of=/dev/null": it's a simple
     91 workload to analyze that just moves bytes from /dev/zero to /dev/null.
     92 Profiling just that process:
     93 
     94 # ./profile -p 25036
     95 Sampling 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 
    151 Again, I've truncated some lines. Now we're just analyzing the dd process.
    152 The filtering is performed in kernel context, for efficiency.
    153 
    154 This output has some "[unknown]" frames that probably have valid addresses,
    155 but we're lacking the symbol translation. This is a common for all profilers
    156 on Linux, and is usually fixable. See the DEBUGGING section of the profile(8)
    157 man page.
    158 
    159 
    160 Lets 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 
    202 In this mode, the delimiters are "--".
    203 
    204 
    205 
    206 Here's another example, a func_ab program that runs two functions, func_a() and
    207 func_b(). Profiling it for 5 seconds:
    208 
    209 # ./profile -p `pgrep -n func_ab` 5
    210 Sampling 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 
    268 Note that the same stack (2nd column) seems to be repeated. Weren't we doing
    269 frequency counting and only printing unique stacks? We are, but in terms of
    270 the raw addresses, not the symbols. See the 1st column: those stacks are
    271 all unique.
    272 
    273 
    274 We can output in "folded format", which puts the stack trace on one line,
    275 separating frames with semi-colons. Eg:
    276 
    277 # ./profile -f -p `pgrep -n func_ab` 5
    278 func_ab;[unknown];__libc_start_main;main;func_a 2
    279 func_ab;[unknown];__libc_start_main;main;func_b 2
    280 func_ab;[unknown];__libc_start_main;main;func_a 11
    281 func_ab;[unknown];__libc_start_main;main;func_b 12
    282 func_ab;[unknown];__libc_start_main;main;func_a 23
    283 func_ab;[unknown];__libc_start_main;main;func_b 28
    284 func_ab;[unknown];__libc_start_main;main;func_b 57
    285 func_ab;[unknown];__libc_start_main;main;func_a 64
    286 
    287 I find this pretty useful for writing to files and later grepping.
    288 
    289 
    290 Folded format can also be used by flame graph stack visualizers, including
    291 the original implementation:
    292 
    293 	https://github.com/brendangregg/FlameGraph
    294 
    295 I'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
    302 keep the raw folded profiles around: can be useful for regenerating flamegraphs
    303 with different options, and, for differential flame graphs.)
    304 
    305 
    306 Some flamegraph.pl palettes recognize kernel annotations, which can be added
    307 with -a. It simply adds a "_[k]" at the end of kernel function names.
    308 For example:
    309 
    310 # ./profile -adf -p `pgrep -n dd` 10
    311 dd;[unknown] 1
    312 dd;[unknown];[unknown] 1
    313 dd;[unknown];[unknown] 1
    314 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
    315 dd;[unknown];__write;-;entry_SYSCALL_64_fastpath_[k];sys_write_[k];vfs_write_[k];__fsnotify_parent_[k] 1
    316 dd;[unknown];read;-;entry_SYSCALL_64_fastpath_[k];SyS_read_[k];__fdget_pos_[k] 1
    317 dd;read;-;entry_SYSCALL_64_fastpath_[k];SyS_read_[k];vfs_read_[k];rw_verify_area_[k];apparmor_file_permission_[k] 1
    318 dd;[unknown] 1
    319 dd;[unknown];[unknown] 1
    320 dd;__write;-;entry_SYSCALL_64_fastpath_[k];sys_write_[k];vfs_write_[k] 1
    321 dd;[unknown] 1
    322 dd;read;-;entry_SYSCALL_64_fastpath_[k];SyS_read_[k];__fget_light_[k] 1
    323 dd;read;-;entry_SYSCALL_64_fastpath_[k];SyS_read_[k];vfs_read_[k];rw_verify_area_[k];__fsnotify_parent_[k] 1
    324 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
    325 dd;[unknown];__write;-;entry_SYSCALL_64_fastpath_[k];sys_write_[k];__fget_light_[k] 1
    326 dd;[unknown];[unknown] 1
    327 dd;read;-;entry_SYSCALL_64_fastpath_[k];SyS_read_[k] 1
    328 dd;[unknown];[unknown] 1
    329 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
    330 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
    331 dd;read;-;entry_SYSCALL_64_fastpath_[k];SyS_read_[k];vfs_read_[k];read_iter_zero_[k] 1
    332 dd;[unknown];read;-;entry_SYSCALL_64_fastpath_[k];SyS_read_[k];vfs_read_[k];__fsnotify_parent_[k] 1
    333 dd;[unknown];[unknown] 1
    334 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
    335 dd;read;-;entry_SYSCALL_64_fastpath_[k];SyS_read_[k];__fsnotify_parent_[k] 1
    336 dd;__write;-;entry_SYSCALL_64_fastpath_[k];sys_write_[k];vfs_write_[k];fsnotify_[k] 1
    337 dd;__write;-;entry_SYSCALL_64_fastpath_[k];sys_write_[k];vfs_write_[k];rw_verify_area_[k];security_file_permission_[k] 1
    338 dd;[unknown];__write;-;entry_SYSCALL_64_fastpath_[k];sys_write_[k];__fdget_pos_[k] 1
    339 dd;[unknown];__write;-;entry_SYSCALL_64_fastpath_[k] 1
    340 dd;[unknown];[unknown] 1
    341 dd;read;-;entry_SYSCALL_64_fastpath_[k];SyS_read_[k];vfs_read_[k];rw_verify_area_[k];security_file_permission_[k] 1
    342 dd;__write;-;entry_SYSCALL_64_fastpath_[k];sys_write_[k];vfs_write_[k] 1
    343 dd;[unknown];read;-;entry_SYSCALL_64_fastpath_[k];SyS_read_[k];__fget_light_[k] 1
    344 dd;[unknown] 1
    345 dd;[unknown];__write;-;entry_SYSCALL_64_fastpath_[k];sys_write_[k];vfs_write_[k] 1
    346 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
    347 dd;[unknown];[unknown] 1
    348 dd;read;-;entry_SYSCALL_64_fastpath_[k];SyS_read_[k];vfs_read_[k];rw_verify_area_[k];security_file_permission_[k] 1
    349 dd;[unknown];read;-;entry_SYSCALL_64_fastpath_[k];SyS_read_[k];vfs_read_[k];rw_verify_area_[k];__fsnotify_parent_[k] 1
    350 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
    351 dd;__write;-;entry_SYSCALL_64_fastpath_[k];sys_write_[k];vfs_write_[k];rw_verify_area_[k];security_file_permission_[k] 1
    352 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
    353 dd;[unknown];[unknown] 1
    354 dd;__write;-;entry_SYSCALL_64_fastpath_[k];sys_write_[k];vfs_write_[k] 1
    355 dd;[unknown];[unknown] 1
    356 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
    357 dd;read 1
    358 dd;__write;-;entry_SYSCALL_64_fastpath_[k];sys_write_[k];vfs_write_[k];security_file_permission_[k] 1
    359 dd;read;-;entry_SYSCALL_64_fastpath_[k];SyS_read_[k];vfs_read_[k];fsnotify_[k] 1
    360 dd;read;-;entry_SYSCALL_64_fastpath_[k];SyS_read_[k];vfs_read_[k];fsnotify_[k] 1
    361 dd;__write;-;entry_SYSCALL_64_fastpath_[k];sys_write_[k];vfs_write_[k];rw_verify_area_[k];apparmor_file_permission_[k] 1
    362 dd;[unknown];__write;-;entry_SYSCALL_64_fastpath_[k];sys_write_[k];vfs_write_[k];__fsnotify_parent_[k] 1
    363 dd;[unknown];__write;-;entry_SYSCALL_64_fastpath_[k];sys_write_[k];vfs_write_[k];rw_verify_area_[k];apparmor_file_permission_[k] 1
    364 dd;[unknown];read;-;entry_SYSCALL_64_fastpath_[k];SyS_read_[k];vfs_read_[k] 1
    365 dd;read;-;entry_SYSCALL_64_fastpath_[k];SyS_read_[k];vfs_read_[k];__vfs_read_[k];iov_iter_init_[k] 1
    366 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
    367 dd;[unknown];__write;-;entry_SYSCALL_64_fastpath_[k];sys_write_[k];vfs_write_[k];__vfs_write_[k];write_null_[k] 1
    368 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
    369 dd;[unknown];read;-;entry_SYSCALL_64_fastpath_[k];SyS_read_[k];vfs_read_[k];security_file_permission_[k] 1
    370 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
    371 dd;read;-;entry_SYSCALL_64_fastpath_[k];SyS_read_[k];vfs_read_[k];__vfs_read_[k];read_iter_zero_[k] 1
    372 dd;[unknown];__write;-;entry_SYSCALL_64_fastpath_[k];sys_write_[k];vfs_write_[k] 1
    373 dd;__write;-;entry_SYSCALL_64_fastpath_[k];sys_write_[k];vfs_write_[k] 1
    374 dd;[unknown];read;-;entry_SYSCALL_64_fastpath_[k];SyS_read_[k];vfs_read_[k];rw_verify_area_[k] 1
    375 dd;read;-;entry_SYSCALL_64_fastpath_[k];SyS_read_[k];__fget_light_[k] 1
    376 dd;[unknown];__write;-;entry_SYSCALL_64_fastpath_[k];sys_write_[k];vfs_write_[k];rw_verify_area_[k] 1
    377 dd;read;-;entry_SYSCALL_64_fastpath_[k];SyS_read_[k];vfs_read_[k];__vfs_read_[k] 1
    378 dd;[unknown];read;-;entry_SYSCALL_64_fastpath_[k];SyS_read_[k];__vfs_read_[k] 1
    379 dd;[unknown];__write;-;entry_SYSCALL_64_fastpath_[k];sys_write_[k];vfs_write_[k];__vfs_write_[k] 1
    380 dd;[unknown] 1
    381 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
    382 dd;[unknown] 1
    383 dd;read;-;entry_SYSCALL_64_fastpath_[k];SyS_read_[k];vfs_read_[k];__vfs_read_[k] 1
    384 dd;__write;-;entry_SYSCALL_64_fastpath_[k];sys_write_[k];__fsnotify_parent_[k] 1
    385 dd;__write;-;entry_SYSCALL_64_fastpath_[k];sys_write_[k];vfs_write_[k] 1
    386 dd;[unknown];[unknown] 1
    387 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
    388 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
    389 dd;[unknown];__write;-;sys_write_[k] 1
    390 dd;read;-;entry_SYSCALL_64_fastpath_[k];SyS_read_[k];__fsnotify_parent_[k] 1
    391 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
    392 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
    393 dd;[unknown];[unknown] 1
    394 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
    395 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
    396 dd;__write;-;entry_SYSCALL_64_fastpath_[k];sys_write_[k];__fget_light_[k] 1
    397 dd;read;-;entry_SYSCALL_64_fastpath_[k];SyS_read_[k];vfs_read_[k] 1
    398 dd;read;-;entry_SYSCALL_64_fastpath_[k];vfs_read_[k] 1
    399 dd;__write 1
    400 dd;read;-;entry_SYSCALL_64_fastpath_[k];vfs_read_[k] 1
    401 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
    402 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
    403 dd;[unknown];__write;-;entry_SYSCALL_64_fastpath_[k];sys_write_[k];__fget_light_[k] 1
    404 dd;[unknown];[unknown] 1
    405 dd;[unknown] 1
    406 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
    407 dd;[unknown] 1
    408 dd;[unknown] 1
    409 dd;[unknown];[unknown] 1
    410 dd;__write;-;entry_SYSCALL_64_fastpath_[k];sys_write_[k];vfs_write_[k] 1
    411 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
    412 dd;read;-;entry_SYSCALL_64_fastpath_[k];SyS_read_[k] 1
    413 dd;[unknown];read;-;entry_SYSCALL_64_fastpath_[k];SyS_read_[k];vfs_read_[k];__vfs_read_[k];read_iter_zero_[k] 1
    414 dd;read;-;entry_SYSCALL_64_fastpath_[k];SyS_read_[k];vfs_read_[k] 1
    415 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
    416 dd;__write 1
    417 dd;[unknown];read;-;entry_SYSCALL_64_fastpath_[k];SyS_read_[k];__fget_light_[k] 1
    418 dd;read;-;entry_SYSCALL_64_fastpath_[k];SyS_read_[k];vfs_read_[k];rw_verify_area_[k];security_file_permission_[k] 1
    419 dd;__write;-;entry_SYSCALL_64_fastpath_[k];sys_write_[k] 1
    420 dd;[unknown] 1
    421 dd;[unknown];read;-;entry_SYSCALL_64_fastpath_[k];SyS_read_[k];__fget_light_[k] 1
    422 dd;read;-;entry_SYSCALL_64_fastpath_[k];SyS_read_[k];vfs_read_[k];__vfs_read_[k];read_iter_zero_[k] 1
    423 dd;[unknown];[unknown] 1
    424 dd;__write;-;entry_SYSCALL_64_fastpath_[k];sys_write_[k];__fdget_pos_[k] 1
    425 dd;read;-;entry_SYSCALL_64_fastpath_[k];SyS_read_[k];vfs_read_[k];__vfs_read_[k];read_iter_zero_[k] 1
    426 dd;[unknown];read;-;entry_SYSCALL_64_fastpath_[k];SyS_read_[k];vfs_read_[k];__vfs_read_[k];read_iter_zero_[k] 1
    427 dd;read;-;entry_SYSCALL_64_fastpath_[k];SyS_read_[k];vfs_read_[k];__vfs_read_[k];_cond_resched_[k] 1
    428 dd;[unknown];read;-;entry_SYSCALL_64_fastpath_[k];SyS_read_[k];vfs_read_[k];iov_iter_init_[k] 1
    429 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
    430 dd;[unknown];read;-;entry_SYSCALL_64_fastpath_[k];SyS_read_[k];vfs_read_[k];__vfs_read_[k] 1
    431 dd;__write;-;entry_SYSCALL_64_fastpath_[k];sys_write_[k];rw_verify_area_[k] 1
    432 dd;[unknown];read;-;entry_SYSCALL_64_fastpath_[k];SyS_read_[k];vfs_read_[k];rw_verify_area_[k];apparmor_file_permission_[k] 1
    433 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
    434 dd;read;-;entry_SYSCALL_64_fastpath_[k];SyS_read_[k];vfs_read_[k] 1
    435 dd;[unknown] 1
    436 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
    437 dd;read;-;entry_SYSCALL_64_fastpath_[k];SyS_read_[k];vfs_read_[k];__vfs_read_[k] 1
    438 dd;__write;-;entry_SYSCALL_64_fastpath_[k];sys_write_[k];__fdget_pos_[k] 1
    439 dd;[unknown];read;-;entry_SYSCALL_64_fastpath_[k];SyS_read_[k];vfs_read_[k];rw_verify_area_[k];security_file_permission_[k] 1
    440 dd;__write;-;entry_SYSCALL_64_fastpath_[k];sys_write_[k];vfs_write_[k] 1
    441 dd;[unknown];__write;-;entry_SYSCALL_64_fastpath_[k];sys_write_[k];vfs_write_[k];__vfs_write_[k] 1
    442 dd;__write;-;entry_SYSCALL_64_fastpath_[k];sys_write_[k];vfs_write_[k];rw_verify_area_[k];apparmor_file_permission_[k] 1
    443 dd;read;-;entry_SYSCALL_64_fastpath_[k];SyS_read_[k];vfs_read_[k];rw_verify_area_[k];security_file_permission_[k] 1
    444 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
    445 dd;__write;-;entry_SYSCALL_64_fastpath_[k];sys_write_[k];vfs_write_[k] 1
    446 dd;__write;-;entry_SYSCALL_64_fastpath_[k];sys_write_[k];vfs_write_[k] 1
    447 dd;read;-;entry_SYSCALL_64_fastpath_[k];SyS_read_[k];__fget_light_[k] 1
    448 dd;[unknown] 1
    449 dd;[unknown];__write;-;entry_SYSCALL_64_fastpath_[k];sys_write_[k];vfs_write_[k];fsnotify_[k] 1
    450 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
    451 dd;__write;-;entry_SYSCALL_64_fastpath_[k];sys_write_[k];vfs_write_[k];rw_verify_area_[k] 1
    452 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
    453 dd;read;-;entry_SYSCALL_64_fastpath_[k];SyS_read_[k];fsnotify_[k] 1
    454 dd;[unknown];__write;-;entry_SYSCALL_64_fastpath_[k];sys_write_[k];vfs_write_[k] 1
    455 dd;__write;-;entry_SYSCALL_64_fastpath_[k];vfs_write_[k] 1
    456 dd;[unknown];read;-;entry_SYSCALL_64_fastpath_[k];SyS_read_[k];vfs_read_[k];rw_verify_area_[k] 1
    457 dd;read;-;entry_SYSCALL_64_fastpath_[k];SyS_read_[k];vfs_read_[k];__vfs_read_[k] 1
    458 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
    459 dd;[unknown];read;-;entry_SYSCALL_64_fastpath_[k];SyS_read_[k];vfs_read_[k];__vfs_read_[k];read_iter_zero_[k] 1
    460 dd;[unknown];read;-;entry_SYSCALL_64_fastpath_[k];SyS_read_[k];vfs_read_[k];rw_verify_area_[k];fsnotify_[k] 1
    461 dd;[unknown];__write;-;entry_SYSCALL_64_fastpath_[k];sys_write_[k];vfs_write_[k];rw_verify_area_[k];apparmor_file_permission_[k] 2
    462 dd;read;-;entry_SYSCALL_64_fastpath_[k];__fdget_pos_[k] 2
    463 dd;[unknown];[unknown] 2
    464 dd;read;-;entry_SYSCALL_64_fastpath_[k];SyS_read_[k];__fdget_pos_[k] 2
    465 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
    466 dd;[unknown];[unknown] 2
    467 dd;[unknown];[unknown] 2
    468 dd;[unknown];[unknown] 2
    469 dd;[unknown];read;-;entry_SYSCALL_64_fastpath_[k];SyS_read_[k];vfs_read_[k] 2
    470 dd;[unknown];[unknown] 2
    471 dd;read;-;entry_SYSCALL_64_fastpath_[k];SyS_read_[k];vfs_read_[k];__vfs_read_[k];read_iter_zero_[k];__clear_user_[k] 2
    472 dd;__write;-;entry_SYSCALL_64_fastpath_[k];__fdget_pos_[k] 2
    473 dd;[unknown];read;-;entry_SYSCALL_64_fastpath_[k];SyS_read_[k];vfs_read_[k];__vfs_read_[k] 2
    474 dd;[unknown];read;-;entry_SYSCALL_64_fastpath_[k];SyS_read_[k];vfs_read_[k];__vfs_read_[k] 2
    475 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
    476 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
    477 dd;[unknown];[unknown] 2
    478 dd;__write;-;entry_SYSCALL_64_fastpath_[k];sys_write_[k];__fget_light_[k] 2
    479 dd;read;-;entry_SYSCALL_64_fastpath_[k];SyS_read_[k];vfs_read_[k];rw_verify_area_[k];security_file_permission_[k];fsnotify_[k] 2
    480 dd;__write;-;sys_write_[k] 2
    481 dd;[unknown];read;-;entry_SYSCALL_64_fastpath_[k];SyS_read_[k];vfs_read_[k];fsnotify_[k] 2
    482 dd;[unknown];[unknown] 2
    483 dd;[unknown];read;-;entry_SYSCALL_64_fastpath_[k];SyS_read_[k];vfs_read_[k];__vfs_read_[k] 2
    484 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
    485 dd;read;-;SyS_read_[k] 2
    486 dd;[unknown] 2
    487 dd;__write;-;entry_SYSCALL_64_fastpath_[k];sys_write_[k];vfs_write_[k];rw_verify_area_[k] 2
    488 dd;[unknown];__write;-;entry_SYSCALL_64_fastpath_[k];sys_write_[k];__fget_light_[k] 2
    489 dd;read;-;entry_SYSCALL_64_fastpath_[k];SyS_read_[k];vfs_read_[k];__vfs_read_[k] 2
    490 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
    491 dd;read;-;entry_SYSCALL_64_fastpath_[k];SyS_read_[k];vfs_read_[k];__vfs_read_[k];read_iter_zero_[k];__clear_user_[k] 2
    492 dd;[unknown];__write;-;entry_SYSCALL_64_fastpath_[k];sys_write_[k];rw_verify_area_[k] 2
    493 dd;[unknown];[unknown] 3
    494 dd;[unknown];read;-;entry_SYSCALL_64_fastpath_[k];SyS_read_[k];rw_verify_area_[k] 3
    495 dd;[unknown];[unknown] 3
    496 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
    497 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
    498 dd;[unknown];[unknown] 3
    499 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
    500 dd;[unknown];[unknown] 3
    501 dd;[unknown];[unknown] 3
    502 dd;__write;-;entry_SYSCALL_64_fastpath_[k];sys_write_[k];vfs_write_[k] 3
    503 dd;[unknown];read;-;entry_SYSCALL_64_fastpath_[k];SyS_read_[k];vfs_read_[k] 3
    504 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
    505 dd;[unknown] 4
    506 dd;[unknown];read;-;entry_SYSCALL_64_fastpath_[k];SyS_read_[k];vfs_read_[k] 4
    507 dd;[unknown];[unknown] 4
    508 dd;read;-;entry_SYSCALL_64_fastpath_[k];SyS_read_[k];vfs_read_[k] 4
    509 dd;[unknown] 4
    510 dd;[unknown];[unknown] 4
    511 dd;[unknown];read;-;entry_SYSCALL_64_fastpath_[k];SyS_read_[k] 4
    512 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
    513 dd;[unknown];__write;-;entry_SYSCALL_64_fastpath_[k];sys_write_[k];vfs_write_[k] 5
    514 dd;[unknown];[unknown] 5
    515 dd;[unknown];[unknown] 5
    516 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
    517 dd;read 15
    518 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
    519 dd;[unknown];__write;-;entry_SYSCALL_64_fastpath_[k] 20
    520 dd;read;-;entry_SYSCALL_64_fastpath_[k] 23
    521 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
    522 dd;__write;-;entry_SYSCALL_64_fastpath_[k] 25
    523 dd;__write 29
    524 dd;[unknown];read;-;entry_SYSCALL_64_fastpath_[k] 31
    525 
    526 This 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 
    532 It will highlight the kernel frames in orange, and user-level in red (and Java
    533 in green, and C++ in yellow). If you copy-n-paste the above output into a
    534 out.profile file, you can try it out.
    535 
    536 
    537 You can increase or decrease the sample frequency. Eg, sampling at 9 Hertz:
    538 
    539 # ./profile -F 9
    540 Sampling 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 
    573 You can also restrict profiling to just kernel stacks (-K) or user stacks (-U).
    574 For example, just user stacks:
    575 
    576 # ./profile -C 7 2
    577 Sampling 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 
    608 in this example python application was busylooping on a single core/cpu (#7)
    609 we were collecting stack traces only from it
    610 
    611 # ./profile -U
    612 Sampling 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 
    729 If there are too many unique stack traces for the kernel to save, a warning
    730 will be printed. Eg:
    731 
    732 # ./profile
    733 [...]
    734 WARNING: 8 stack traces could not be displayed. Consider increasing --stack-storage-size.
    735 
    736 Run ./profile -h to see the default.
    737 
    738 
    739 USAGE message:
    740 
    741 # ./profile -h
    742 usage: profile [-h] [-p PID] [-U | -K] [-F FREQUENCY | -c COUNT] [-d] [-a]
    743                   [-f] [--stack-storage-size STACK_STORAGE_SIZE]
    744                   [duration]
    745 
    746 Profile CPU stack traces at a timed interval
    747 
    748 positional arguments:
    749   duration              duration of trace, in seconds
    750 
    751 optional 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 
    773 examples:
    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