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