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 filtering is performed in kernel context, for efficiency. 158 159This output has some "[unknown]" frames that probably have valid addresses, 160but we're lacking the symbol translation. This is a common for all profilers 161on Linux, and is usually fixable. See the DEBUGGING section of the profile(8) 162man page. 163 164 165Lets add delimiters between the user and kernel stacks, using -d: 166 167# ./profile -p 25036 -d 168^C 169 __vfs_write 170 sys_write 171 entry_SYSCALL_64_fastpath 172 -- 173 __write 174 - dd (25036) 175 1 176 177 -- 178 [unknown] 179 [unknown] 180 - dd (25036) 181 1 182 183 iov_iter_init 184 __vfs_read 185 vfs_read 186 sys_read 187 entry_SYSCALL_64_fastpath 188 -- 189 read 190 - dd (25036) 191 1 192 193[...] 194 195 __clear_user 196 iov_iter_zero 197 read_iter_zero 198 __vfs_read 199 vfs_read 200 sys_read 201 entry_SYSCALL_64_fastpath 202 -- 203 read 204 - dd (25036) 205 9 206 207In this mode, the delimiters are "--". 208 209 210 211Here's another example, a func_ab program that runs two functions, func_a() and 212func_b(). Profiling it for 5 seconds: 213 214# ./profile -p `pgrep -n func_ab` 5 215Sampling at 49 Hertz of PID 2930 by user + kernel stack for 5 secs. 216 217 func_a 218 main 219 __libc_start_main 220 [unknown] 221 - func_ab (2930) 222 2 223 224 func_b 225 main 226 __libc_start_main 227 [unknown] 228 - func_ab (2930) 229 3 230 231 func_a 232 main 233 __libc_start_main 234 [unknown] 235 - func_ab (2930) 236 5 237 238 func_b 239 main 240 __libc_start_main 241 [unknown] 242 - func_ab (2930) 243 12 244 245 func_b 246 main 247 __libc_start_main 248 [unknown] 249 - func_ab (2930) 250 19 251 252 func_a 253 main 254 __libc_start_main 255 [unknown] 256 - func_ab (2930) 257 22 258 259 func_b 260 main 261 __libc_start_main 262 [unknown] 263 - func_ab (2930) 264 64 265 266 func_a 267 main 268 __libc_start_main 269 [unknown] 270 - func_ab (2930) 271 72 272 273Note that the same stack (2nd column) seems to be repeated. Weren't we doing 274frequency counting and only printing unique stacks? We are, but in terms of 275the raw addresses, not the symbols. See the 1st column: those stacks are 276all unique. 277 278 279We can output in "folded format", which puts the stack trace on one line, 280separating frames with semi-colons. Eg: 281 282# ./profile -f -p `pgrep -n func_ab` 5 283func_ab;[unknown];__libc_start_main;main;func_a 2 284func_ab;[unknown];__libc_start_main;main;func_b 2 285func_ab;[unknown];__libc_start_main;main;func_a 11 286func_ab;[unknown];__libc_start_main;main;func_b 12 287func_ab;[unknown];__libc_start_main;main;func_a 23 288func_ab;[unknown];__libc_start_main;main;func_b 28 289func_ab;[unknown];__libc_start_main;main;func_b 57 290func_ab;[unknown];__libc_start_main;main;func_a 64 291 292I find this pretty useful for writing to files and later grepping. 293 294 295Folded format can also be used by flame graph stack visualizers, including 296the original implementation: 297 298 https://github.com/brendangregg/FlameGraph 299 300I'd include delimiters, -d. For example: 301 302# ./profile -df -p `pgrep -n func_ab` 5 > out.profile 303# git clone https://github.com/brendangregg/FlameGraph 304# ./FlameGraph/flamegraph.pl < out.profile > out.svg 305 306(Yes, I could pipe profile directly into flamegraph.pl, however, I like to 307keep the raw folded profiles around: can be useful for regenerating flamegraphs 308with different options, and, for differential flame graphs.) 309 310 311Some flamegraph.pl palettes recognize kernel annotations, which can be added 312with -a. It simply adds a "_[k]" at the end of kernel function names. 313For example: 314 315# ./profile -adf -p `pgrep -n dd` 10 316dd;[unknown] 1 317dd;[unknown];[unknown] 1 318dd;[unknown];[unknown] 1 319dd;[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 320dd;[unknown];__write;-;entry_SYSCALL_64_fastpath_[k];sys_write_[k];vfs_write_[k];__fsnotify_parent_[k] 1 321dd;[unknown];read;-;entry_SYSCALL_64_fastpath_[k];SyS_read_[k];__fdget_pos_[k] 1 322dd;read;-;entry_SYSCALL_64_fastpath_[k];SyS_read_[k];vfs_read_[k];rw_verify_area_[k];apparmor_file_permission_[k] 1 323dd;[unknown] 1 324dd;[unknown];[unknown] 1 325dd;__write;-;entry_SYSCALL_64_fastpath_[k];sys_write_[k];vfs_write_[k] 1 326dd;[unknown] 1 327dd;read;-;entry_SYSCALL_64_fastpath_[k];SyS_read_[k];__fget_light_[k] 1 328dd;read;-;entry_SYSCALL_64_fastpath_[k];SyS_read_[k];vfs_read_[k];rw_verify_area_[k];__fsnotify_parent_[k] 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];__write;-;entry_SYSCALL_64_fastpath_[k];sys_write_[k];__fget_light_[k] 1 331dd;[unknown];[unknown] 1 332dd;read;-;entry_SYSCALL_64_fastpath_[k];SyS_read_[k] 1 333dd;[unknown];[unknown] 1 334dd;read;-;entry_SYSCALL_64_fastpath_[k];SyS_read_[k];vfs_read_[k];__vfs_read_[k];read_iter_zero_[k];iov_iter_zero_[k] 1 335dd;[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 336dd;read;-;entry_SYSCALL_64_fastpath_[k];SyS_read_[k];vfs_read_[k];read_iter_zero_[k] 1 337dd;[unknown];read;-;entry_SYSCALL_64_fastpath_[k];SyS_read_[k];vfs_read_[k];__fsnotify_parent_[k] 1 338dd;[unknown];[unknown] 1 339dd;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 340dd;read;-;entry_SYSCALL_64_fastpath_[k];SyS_read_[k];__fsnotify_parent_[k] 1 341dd;__write;-;entry_SYSCALL_64_fastpath_[k];sys_write_[k];vfs_write_[k];fsnotify_[k] 1 342dd;__write;-;entry_SYSCALL_64_fastpath_[k];sys_write_[k];vfs_write_[k];rw_verify_area_[k];security_file_permission_[k] 1 343dd;[unknown];__write;-;entry_SYSCALL_64_fastpath_[k];sys_write_[k];__fdget_pos_[k] 1 344dd;[unknown];__write;-;entry_SYSCALL_64_fastpath_[k] 1 345dd;[unknown];[unknown] 1 346dd;read;-;entry_SYSCALL_64_fastpath_[k];SyS_read_[k];vfs_read_[k];rw_verify_area_[k];security_file_permission_[k] 1 347dd;__write;-;entry_SYSCALL_64_fastpath_[k];sys_write_[k];vfs_write_[k] 1 348dd;[unknown];read;-;entry_SYSCALL_64_fastpath_[k];SyS_read_[k];__fget_light_[k] 1 349dd;[unknown] 1 350dd;[unknown];__write;-;entry_SYSCALL_64_fastpath_[k];sys_write_[k];vfs_write_[k] 1 351dd;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 352dd;[unknown];[unknown] 1 353dd;read;-;entry_SYSCALL_64_fastpath_[k];SyS_read_[k];vfs_read_[k];rw_verify_area_[k];security_file_permission_[k] 1 354dd;[unknown];read;-;entry_SYSCALL_64_fastpath_[k];SyS_read_[k];vfs_read_[k];rw_verify_area_[k];__fsnotify_parent_[k] 1 355dd;read;-;entry_SYSCALL_64_fastpath_[k];SyS_read_[k];vfs_read_[k];__vfs_read_[k];read_iter_zero_[k];iov_iter_zero_[k] 1 356dd;__write;-;entry_SYSCALL_64_fastpath_[k];sys_write_[k];vfs_write_[k];rw_verify_area_[k];security_file_permission_[k] 1 357dd;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 358dd;[unknown];[unknown] 1 359dd;__write;-;entry_SYSCALL_64_fastpath_[k];sys_write_[k];vfs_write_[k] 1 360dd;[unknown];[unknown] 1 361dd;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 362dd;read 1 363dd;__write;-;entry_SYSCALL_64_fastpath_[k];sys_write_[k];vfs_write_[k];security_file_permission_[k] 1 364dd;read;-;entry_SYSCALL_64_fastpath_[k];SyS_read_[k];vfs_read_[k];fsnotify_[k] 1 365dd;read;-;entry_SYSCALL_64_fastpath_[k];SyS_read_[k];vfs_read_[k];fsnotify_[k] 1 366dd;__write;-;entry_SYSCALL_64_fastpath_[k];sys_write_[k];vfs_write_[k];rw_verify_area_[k];apparmor_file_permission_[k] 1 367dd;[unknown];__write;-;entry_SYSCALL_64_fastpath_[k];sys_write_[k];vfs_write_[k];__fsnotify_parent_[k] 1 368dd;[unknown];__write;-;entry_SYSCALL_64_fastpath_[k];sys_write_[k];vfs_write_[k];rw_verify_area_[k];apparmor_file_permission_[k] 1 369dd;[unknown];read;-;entry_SYSCALL_64_fastpath_[k];SyS_read_[k];vfs_read_[k] 1 370dd;read;-;entry_SYSCALL_64_fastpath_[k];SyS_read_[k];vfs_read_[k];__vfs_read_[k];iov_iter_init_[k] 1 371dd;[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 372dd;[unknown];__write;-;entry_SYSCALL_64_fastpath_[k];sys_write_[k];vfs_write_[k];__vfs_write_[k];write_null_[k] 1 373dd;[unknown];read;-;entry_SYSCALL_64_fastpath_[k];SyS_read_[k];vfs_read_[k];__vfs_read_[k];read_iter_zero_[k];__clear_user_[k] 1 374dd;[unknown];read;-;entry_SYSCALL_64_fastpath_[k];SyS_read_[k];vfs_read_[k];security_file_permission_[k] 1 375dd;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 376dd;read;-;entry_SYSCALL_64_fastpath_[k];SyS_read_[k];vfs_read_[k];__vfs_read_[k];read_iter_zero_[k] 1 377dd;[unknown];__write;-;entry_SYSCALL_64_fastpath_[k];sys_write_[k];vfs_write_[k] 1 378dd;__write;-;entry_SYSCALL_64_fastpath_[k];sys_write_[k];vfs_write_[k] 1 379dd;[unknown];read;-;entry_SYSCALL_64_fastpath_[k];SyS_read_[k];vfs_read_[k];rw_verify_area_[k] 1 380dd;read;-;entry_SYSCALL_64_fastpath_[k];SyS_read_[k];__fget_light_[k] 1 381dd;[unknown];__write;-;entry_SYSCALL_64_fastpath_[k];sys_write_[k];vfs_write_[k];rw_verify_area_[k] 1 382dd;read;-;entry_SYSCALL_64_fastpath_[k];SyS_read_[k];vfs_read_[k];__vfs_read_[k] 1 383dd;[unknown];read;-;entry_SYSCALL_64_fastpath_[k];SyS_read_[k];__vfs_read_[k] 1 384dd;[unknown];__write;-;entry_SYSCALL_64_fastpath_[k];sys_write_[k];vfs_write_[k];__vfs_write_[k] 1 385dd;[unknown] 1 386dd;[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 387dd;[unknown] 1 388dd;read;-;entry_SYSCALL_64_fastpath_[k];SyS_read_[k];vfs_read_[k];__vfs_read_[k] 1 389dd;__write;-;entry_SYSCALL_64_fastpath_[k];sys_write_[k];__fsnotify_parent_[k] 1 390dd;__write;-;entry_SYSCALL_64_fastpath_[k];sys_write_[k];vfs_write_[k] 1 391dd;[unknown];[unknown] 1 392dd;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;read;-;entry_SYSCALL_64_fastpath_[k];SyS_read_[k];vfs_read_[k];__vfs_read_[k];read_iter_zero_[k];iov_iter_zero_[k] 1 394dd;[unknown];__write;-;sys_write_[k] 1 395dd;read;-;entry_SYSCALL_64_fastpath_[k];SyS_read_[k];__fsnotify_parent_[k] 1 396dd;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 397dd;[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 398dd;[unknown];[unknown] 1 399dd;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 400dd;__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 401dd;__write;-;entry_SYSCALL_64_fastpath_[k];sys_write_[k];__fget_light_[k] 1 402dd;read;-;entry_SYSCALL_64_fastpath_[k];SyS_read_[k];vfs_read_[k] 1 403dd;read;-;entry_SYSCALL_64_fastpath_[k];vfs_read_[k] 1 404dd;__write 1 405dd;read;-;entry_SYSCALL_64_fastpath_[k];vfs_read_[k] 1 406dd;__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 407dd;read;-;entry_SYSCALL_64_fastpath_[k];SyS_read_[k];vfs_read_[k];__vfs_read_[k];read_iter_zero_[k];iov_iter_zero_[k] 1 408dd;[unknown];__write;-;entry_SYSCALL_64_fastpath_[k];sys_write_[k];__fget_light_[k] 1 409dd;[unknown];[unknown] 1 410dd;[unknown] 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;[unknown] 1 413dd;[unknown] 1 414dd;[unknown];[unknown] 1 415dd;__write;-;entry_SYSCALL_64_fastpath_[k];sys_write_[k];vfs_write_[k] 1 416dd;[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 417dd;read;-;entry_SYSCALL_64_fastpath_[k];SyS_read_[k] 1 418dd;[unknown];read;-;entry_SYSCALL_64_fastpath_[k];SyS_read_[k];vfs_read_[k];__vfs_read_[k];read_iter_zero_[k] 1 419dd;read;-;entry_SYSCALL_64_fastpath_[k];SyS_read_[k];vfs_read_[k] 1 420dd;__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 421dd;__write 1 422dd;[unknown];read;-;entry_SYSCALL_64_fastpath_[k];SyS_read_[k];__fget_light_[k] 1 423dd;read;-;entry_SYSCALL_64_fastpath_[k];SyS_read_[k];vfs_read_[k];rw_verify_area_[k];security_file_permission_[k] 1 424dd;__write;-;entry_SYSCALL_64_fastpath_[k];sys_write_[k] 1 425dd;[unknown] 1 426dd;[unknown];read;-;entry_SYSCALL_64_fastpath_[k];SyS_read_[k];__fget_light_[k] 1 427dd;read;-;entry_SYSCALL_64_fastpath_[k];SyS_read_[k];vfs_read_[k];__vfs_read_[k];read_iter_zero_[k] 1 428dd;[unknown];[unknown] 1 429dd;__write;-;entry_SYSCALL_64_fastpath_[k];sys_write_[k];__fdget_pos_[k] 1 430dd;read;-;entry_SYSCALL_64_fastpath_[k];SyS_read_[k];vfs_read_[k];__vfs_read_[k];read_iter_zero_[k] 1 431dd;[unknown];read;-;entry_SYSCALL_64_fastpath_[k];SyS_read_[k];vfs_read_[k];__vfs_read_[k];read_iter_zero_[k] 1 432dd;read;-;entry_SYSCALL_64_fastpath_[k];SyS_read_[k];vfs_read_[k];__vfs_read_[k];_cond_resched_[k] 1 433dd;[unknown];read;-;entry_SYSCALL_64_fastpath_[k];SyS_read_[k];vfs_read_[k];iov_iter_init_[k] 1 434dd;read;-;entry_SYSCALL_64_fastpath_[k];SyS_read_[k];vfs_read_[k];rw_verify_area_[k];security_file_permission_[k];__fsnotify_parent_[k] 1 435dd;[unknown];read;-;entry_SYSCALL_64_fastpath_[k];SyS_read_[k];vfs_read_[k];__vfs_read_[k] 1 436dd;__write;-;entry_SYSCALL_64_fastpath_[k];sys_write_[k];rw_verify_area_[k] 1 437dd;[unknown];read;-;entry_SYSCALL_64_fastpath_[k];SyS_read_[k];vfs_read_[k];rw_verify_area_[k];apparmor_file_permission_[k] 1 438dd;[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 439dd;read;-;entry_SYSCALL_64_fastpath_[k];SyS_read_[k];vfs_read_[k] 1 440dd;[unknown] 1 441dd;[unknown];read;-;entry_SYSCALL_64_fastpath_[k];SyS_read_[k];vfs_read_[k];rw_verify_area_[k];security_file_permission_[k];fsnotify_[k] 1 442dd;read;-;entry_SYSCALL_64_fastpath_[k];SyS_read_[k];vfs_read_[k];__vfs_read_[k] 1 443dd;__write;-;entry_SYSCALL_64_fastpath_[k];sys_write_[k];__fdget_pos_[k] 1 444dd;[unknown];read;-;entry_SYSCALL_64_fastpath_[k];SyS_read_[k];vfs_read_[k];rw_verify_area_[k];security_file_permission_[k] 1 445dd;__write;-;entry_SYSCALL_64_fastpath_[k];sys_write_[k];vfs_write_[k] 1 446dd;[unknown];__write;-;entry_SYSCALL_64_fastpath_[k];sys_write_[k];vfs_write_[k];__vfs_write_[k] 1 447dd;__write;-;entry_SYSCALL_64_fastpath_[k];sys_write_[k];vfs_write_[k];rw_verify_area_[k];apparmor_file_permission_[k] 1 448dd;read;-;entry_SYSCALL_64_fastpath_[k];SyS_read_[k];vfs_read_[k];rw_verify_area_[k];security_file_permission_[k] 1 449dd;__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 450dd;__write;-;entry_SYSCALL_64_fastpath_[k];sys_write_[k];vfs_write_[k] 1 451dd;__write;-;entry_SYSCALL_64_fastpath_[k];sys_write_[k];vfs_write_[k] 1 452dd;read;-;entry_SYSCALL_64_fastpath_[k];SyS_read_[k];__fget_light_[k] 1 453dd;[unknown] 1 454dd;[unknown];__write;-;entry_SYSCALL_64_fastpath_[k];sys_write_[k];vfs_write_[k];fsnotify_[k] 1 455dd;[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 456dd;__write;-;entry_SYSCALL_64_fastpath_[k];sys_write_[k];vfs_write_[k];rw_verify_area_[k] 1 457dd;[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 458dd;read;-;entry_SYSCALL_64_fastpath_[k];SyS_read_[k];fsnotify_[k] 1 459dd;[unknown];__write;-;entry_SYSCALL_64_fastpath_[k];sys_write_[k];vfs_write_[k] 1 460dd;__write;-;entry_SYSCALL_64_fastpath_[k];vfs_write_[k] 1 461dd;[unknown];read;-;entry_SYSCALL_64_fastpath_[k];SyS_read_[k];vfs_read_[k];rw_verify_area_[k] 1 462dd;read;-;entry_SYSCALL_64_fastpath_[k];SyS_read_[k];vfs_read_[k];__vfs_read_[k] 1 463dd;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 464dd;[unknown];read;-;entry_SYSCALL_64_fastpath_[k];SyS_read_[k];vfs_read_[k];__vfs_read_[k];read_iter_zero_[k] 1 465dd;[unknown];read;-;entry_SYSCALL_64_fastpath_[k];SyS_read_[k];vfs_read_[k];rw_verify_area_[k];fsnotify_[k] 1 466dd;[unknown];__write;-;entry_SYSCALL_64_fastpath_[k];sys_write_[k];vfs_write_[k];rw_verify_area_[k];apparmor_file_permission_[k] 2 467dd;read;-;entry_SYSCALL_64_fastpath_[k];__fdget_pos_[k] 2 468dd;[unknown];[unknown] 2 469dd;read;-;entry_SYSCALL_64_fastpath_[k];SyS_read_[k];__fdget_pos_[k] 2 470dd;[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 471dd;[unknown];[unknown] 2 472dd;[unknown];[unknown] 2 473dd;[unknown];[unknown] 2 474dd;[unknown];read;-;entry_SYSCALL_64_fastpath_[k];SyS_read_[k];vfs_read_[k] 2 475dd;[unknown];[unknown] 2 476dd;read;-;entry_SYSCALL_64_fastpath_[k];SyS_read_[k];vfs_read_[k];__vfs_read_[k];read_iter_zero_[k];__clear_user_[k] 2 477dd;__write;-;entry_SYSCALL_64_fastpath_[k];__fdget_pos_[k] 2 478dd;[unknown];read;-;entry_SYSCALL_64_fastpath_[k];SyS_read_[k];vfs_read_[k];__vfs_read_[k] 2 479dd;[unknown];read;-;entry_SYSCALL_64_fastpath_[k];SyS_read_[k];vfs_read_[k];__vfs_read_[k] 2 480dd;[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 481dd;[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 482dd;[unknown];[unknown] 2 483dd;__write;-;entry_SYSCALL_64_fastpath_[k];sys_write_[k];__fget_light_[k] 2 484dd;read;-;entry_SYSCALL_64_fastpath_[k];SyS_read_[k];vfs_read_[k];rw_verify_area_[k];security_file_permission_[k];fsnotify_[k] 2 485dd;__write;-;sys_write_[k] 2 486dd;[unknown];read;-;entry_SYSCALL_64_fastpath_[k];SyS_read_[k];vfs_read_[k];fsnotify_[k] 2 487dd;[unknown];[unknown] 2 488dd;[unknown];read;-;entry_SYSCALL_64_fastpath_[k];SyS_read_[k];vfs_read_[k];__vfs_read_[k] 2 489dd;read;-;entry_SYSCALL_64_fastpath_[k];SyS_read_[k];vfs_read_[k];__vfs_read_[k];read_iter_zero_[k];iov_iter_zero_[k] 2 490dd;read;-;SyS_read_[k] 2 491dd;[unknown] 2 492dd;__write;-;entry_SYSCALL_64_fastpath_[k];sys_write_[k];vfs_write_[k];rw_verify_area_[k] 2 493dd;[unknown];__write;-;entry_SYSCALL_64_fastpath_[k];sys_write_[k];__fget_light_[k] 2 494dd;read;-;entry_SYSCALL_64_fastpath_[k];SyS_read_[k];vfs_read_[k];__vfs_read_[k] 2 495dd;__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 496dd;read;-;entry_SYSCALL_64_fastpath_[k];SyS_read_[k];vfs_read_[k];__vfs_read_[k];read_iter_zero_[k];__clear_user_[k] 2 497dd;[unknown];__write;-;entry_SYSCALL_64_fastpath_[k];sys_write_[k];rw_verify_area_[k] 2 498dd;[unknown];[unknown] 3 499dd;[unknown];read;-;entry_SYSCALL_64_fastpath_[k];SyS_read_[k];rw_verify_area_[k] 3 500dd;[unknown];[unknown] 3 501dd;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 502dd;read;-;entry_SYSCALL_64_fastpath_[k];SyS_read_[k];vfs_read_[k];__vfs_read_[k];read_iter_zero_[k];iov_iter_zero_[k] 3 503dd;[unknown];[unknown] 3 504dd;read;-;entry_SYSCALL_64_fastpath_[k];SyS_read_[k];vfs_read_[k];__vfs_read_[k];read_iter_zero_[k];iov_iter_zero_[k] 3 505dd;[unknown];[unknown] 3 506dd;[unknown];[unknown] 3 507dd;__write;-;entry_SYSCALL_64_fastpath_[k];sys_write_[k];vfs_write_[k] 3 508dd;[unknown];read;-;entry_SYSCALL_64_fastpath_[k];SyS_read_[k];vfs_read_[k] 3 509dd;[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 510dd;[unknown] 4 511dd;[unknown];read;-;entry_SYSCALL_64_fastpath_[k];SyS_read_[k];vfs_read_[k] 4 512dd;[unknown];[unknown] 4 513dd;read;-;entry_SYSCALL_64_fastpath_[k];SyS_read_[k];vfs_read_[k] 4 514dd;[unknown] 4 515dd;[unknown];[unknown] 4 516dd;[unknown];read;-;entry_SYSCALL_64_fastpath_[k];SyS_read_[k] 4 517dd;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 518dd;[unknown];__write;-;entry_SYSCALL_64_fastpath_[k];sys_write_[k];vfs_write_[k] 5 519dd;[unknown];[unknown] 5 520dd;[unknown];[unknown] 5 521dd;[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 522dd;read 15 523dd;[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 524dd;[unknown];__write;-;entry_SYSCALL_64_fastpath_[k] 20 525dd;read;-;entry_SYSCALL_64_fastpath_[k] 23 526dd;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 527dd;__write;-;entry_SYSCALL_64_fastpath_[k] 25 528dd;__write 29 529dd;[unknown];read;-;entry_SYSCALL_64_fastpath_[k] 31 530 531This can be made into a flamegraph. Eg: 532 533# ./profile -adf -p `pgrep -n func_ab` 10 > out.profile 534# git clone https://github.com/brendangregg/FlameGraph 535# ./FlameGraph/flamegraph.pl --color=java < out.profile > out.svg 536 537It will highlight the kernel frames in orange, and user-level in red (and Java 538in green, and C++ in yellow). If you copy-n-paste the above output into a 539out.profile file, you can try it out. 540 541 542You can increase or decrease the sample frequency. Eg, sampling at 9 Hertz: 543 544# ./profile -F 9 545Sampling at 9 Hertz of all threads by user + kernel stack... Hit Ctrl-C to end. 546^C 547[...] 548 549 func_b 550 main 551 __libc_start_main 552 [unknown] 553 - func_ab (2930) 554 1 555 556[...] 557 558 559You can also restrict profiling to just kernel stacks (-K) or user stacks (-U). 560For example, just user stacks: 561 562# ./profile -C 7 2 563Sampling at 49 Hertz of all threads by user + kernel stack on CPU#7 for 2 secs. 564 565 PyEval_EvalFrameEx 566 [unknown] 567 [unknown] 568 - python (2827439) 569 1 570 571 PyDict_GetItem 572 [unknown] 573 - python (2827439) 574 1 575 576 [unknown] 577 - python (2827439) 578 1 579 580 PyEval_EvalFrameEx 581 [unknown] 582 [unknown] 583 - python (2827439) 584 1 585 586 PyEval_EvalFrameEx 587 - python (2827439) 588 1 589 590 [unknown] 591 [unknown] 592 - python (2827439) 593 594in this example python application was busylooping on a single core/cpu (#7) 595we were collecting stack traces only from it 596 597# ./profile -U 598Sampling at 49 Hertz of all threads by user stack... Hit Ctrl-C to end. 599^C 600 [unknown] 601 [unknown] 602 - dd (2931) 603 1 604 605 [unknown] 606 [unknown] 607 - dd (2931) 608 1 609 610 [unknown] 611 [unknown] 612 - dd (2931) 613 1 614 615 [unknown] 616 [unknown] 617 - dd (2931) 618 1 619 620 [unknown] 621 [unknown] 622 - dd (2931) 623 1 624 625 func_b 626 main 627 __libc_start_main 628 [unknown] 629 - func_ab (2930) 630 1 631 632 [unknown] 633 - dd (2931) 634 1 635 636 [unknown] 637 - dd (2931) 638 1 639 640 func_a 641 main 642 __libc_start_main 643 [unknown] 644 - func_ab (2930) 645 3 646 647 __write 648 [unknown] 649 - dd (2931) 650 3 651 652 func_a 653 main 654 __libc_start_main 655 [unknown] 656 - func_ab (2930) 657 4 658 659 func_b 660 main 661 __libc_start_main 662 [unknown] 663 - func_ab (2930) 664 7 665 666 - swapper/6 (0) 667 10 668 669 func_b 670 main 671 __libc_start_main 672 [unknown] 673 - func_ab (2930) 674 10 675 676 __write 677 - dd (2931) 678 10 679 680 func_a 681 main 682 __libc_start_main 683 [unknown] 684 - func_ab (2930) 685 11 686 687 read 688 - dd (2931) 689 12 690 691 read 692 [unknown] 693 - dd (2931) 694 14 695 696 697If there are too many unique stack traces for the kernel to save, a warning 698will be printed. Eg: 699 700# ./profile 701[...] 702WARNING: 8 stack traces could not be displayed. Consider increasing --stack-storage-size. 703 704Run ./profile -h to see the default. 705 706The --cgroupmap option filters based on a cgroup set. It is meant to be used 707with an externally created map. 708 709# ./profile --cgroupmap /sys/fs/bpf/test01 710 711For more details, see docs/special_filtering.md 712 713 714USAGE message: 715 716# ./profile -h 717usage: profile.py [-h] [-p PID | -L TID] [-U | -K] [-F FREQUENCY | -c COUNT] 718 [-d] [-a] [-I] [-f] 719 [--stack-storage-size STACK_STORAGE_SIZE] [-C CPU] 720 [--cgroupmap CGROUPMAP] [--mntnsmap MNTNSMAP] 721 [duration] 722 723Profile CPU stack traces at a timed interval 724 725positional arguments: 726 duration duration of trace, in seconds 727 728optional arguments: 729 -h, --help show this help message and exit 730 -p PID, --pid PID profile process with this PID only 731 -L TID, --tid TID profile thread with this TID only 732 -U, --user-stacks-only 733 show stacks from user space only (no kernel space 734 stacks) 735 -K, --kernel-stacks-only 736 show stacks from kernel space only (no user space 737 stacks) 738 -F FREQUENCY, --frequency FREQUENCY 739 sample frequency, Hertz 740 -c COUNT, --count COUNT 741 sample period, number of events 742 -d, --delimited insert delimiter between kernel/user stacks 743 -a, --annotations add _[k] annotations to kernel frames 744 -I, --include-idle include CPU idle stacks 745 -f, --folded output folded format, one line per stack (for flame 746 graphs) 747 --stack-storage-size STACK_STORAGE_SIZE 748 the number of unique stack traces that can be stored 749 and displayed (default 16384) 750 -C CPU, --cpu CPU cpu number to run profile on 751 --cgroupmap CGROUPMAP 752 trace cgroups in this BPF map only 753 --mntnsmap MNTNSMAP trace mount namespaces in this BPF map only 754 755examples: 756 ./profile # profile stack traces at 49 Hertz until Ctrl-C 757 ./profile -F 99 # profile stack traces at 99 Hertz 758 ./profile -c 1000000 # profile stack traces every 1 in a million events 759 ./profile 5 # profile at 49 Hertz for 5 seconds only 760 ./profile -f 5 # output in folded format for flame graphs 761 ./profile -p 185 # only profile process with PID 185 762 ./profile -L 185 # only profile thread with TID 185 763 ./profile -U # only show user space stacks (no kernel) 764 ./profile -K # only show kernel space stacks (no user) 765 ./profile --cgroupmap mappath # only trace cgroups in this BPF map 766 ./profile --mntnsmap mappath # only trace mount namespaces in the map 767
