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