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