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