1TRACE-CMD-PROFILE(1) 2==================== 3 4NAME 5---- 6trace-cmd-profile - profile tasks running live 7 8SYNOPSIS 9-------- 10*trace-cmd profile ['OPTIONS']* ['command'] 11 12DESCRIPTION 13----------- 14The trace-cmd(1) profile will start tracing just like trace-cmd-record(1), 15with the *--profile* option, except that it does not write to a file, 16but instead, it will read the events as they happen and will update the accounting 17of the events. When the trace is finished, it will report the results just like 18trace-cmd-report(1) would do with its *--profile* option. In other words, 19the profile command does the work of trace-cmd record --profile, and trace-cmd 20report --profile without having to record the data to disk, in between. 21 22The advantage of using the profile command is that the profiling can be done 23over a long period of time where recording all events would take up too much 24disk space. 25 26This will enable several events as well as the function graph tracer 27with a depth of one (if the kernel supports it). This is to show where 28tasks enter and exit the kernel and how long they were in the kernel. 29 30To disable calling function graph, use the *-p* option to enable another 31tracer. To not enable any tracer, use *-p nop*. 32 33All timings are currently in nanoseconds. 34 35OPTIONS 36------- 37These are the same as trace-cmd-record(1) with the *--profile* option. 38 39*-p* 'tracer':: 40 Set a tracer plugin to run instead of function graph tracing set to 41 depth of 1. To not run any tracer, use *-p nop*. 42 43*-S*:: 44 Only enable the tracer or events speficied on the command line. 45 With this option, the function_graph tracer is not enabled, nor are 46 any events (like sched_switch), unless they are specifically specified 47 on the command line (i.e. -p function -e sched_switch -e sched_wakeup) 48 49*-G*:: 50 Set interrupt (soft and hard) events as global (associated to CPU 51 instead of tasks). 52 53*-o* 'file':: 54 Write the output of the profile to 'file'. This supersedes *--stderr* 55 56*-H* 'event-hooks':: 57 Add custom event matching to connect any two events together. Format is: 58 [<start_system>:]<start_event>,<start_match>[,<start_pid>]/ 59 [<end_system>:]<end_event>,<end_match>[,<flags>] 60 61 The start_system:start_event (start_system is optional), is the event that 62 starts the timing. 63 64 start_match is the field in the start event that is to match with the 65 end_match in the end event. 66 67 start_pid is optional, as matches are attached to the tasks that run 68 the events, if another field should be used to find that task, then 69 it is specified with start_pid. 70 71 end_system:end_event is the event that ends the timing (end_system is 72 optional). 73 74 end_match is the field in end_match that wil match the start event field 75 start_match. 76 77 flags are optional and can be the following (case insensitive): 78 79 p : The two events are pinned to the same CPU (start and end happen 80 on the same CPU always). 81 82 s : The event should have a stack traced with it (enable stack tracing 83 for the start event). 84 85 g : The event is global (not associated to a task). start_pid is 86 not applicable with this flag. 87 88*--stderr*:: 89 Redirect the output to stderr. The output of the command being executed 90 is not changed. This allows watching the command execute and saving the 91 output of the profile to another file. 92 93*--verbose*[='level']:: 94 Set the log level. Supported log levels are "none", "critical", "error", "warning", 95 "info", "debug", "all" or their identifiers "0", "1", "2", "3", "4", "5", "6". Setting the log 96 level to specific value enables all logs from that and all previous levels. 97 The level will default to "info" if one is not specified. 98 99 Example: enable all critical, error and warning logs 100 101 trace-cmd profile --verbose=warning 102 103EXAMPLES 104-------- 105 106 --- 107# trace-cmd profile -F sleep 1 108 [..] 109task: sleep-1121 110 Event: sched_switch:R (2) Total: 234559 Avg: 117279 Max: 129886 Min:104673 111 | 112 + ftrace_raw_event_sched_switch (0xffffffff8109f310) 113 100% (2) time:234559 max:129886 min:104673 avg:117279 114 __schedule (0xffffffff816c1e81) 115 preempt_schedule (0xffffffff816c236e) 116 ___preempt_schedule (0xffffffff81351a59) 117 | 118 + unmap_single_vma (0xffffffff81198c05) 119 | 55% (1) time:129886 max:129886 min:0 avg:129886 120 | stop_one_cpu (0xffffffff8110909a) 121 | sched_exec (0xffffffff810a119b) 122 | do_execveat_common.isra.31 (0xffffffff811de528) 123 | do_execve (0xffffffff811dea8c) 124 | SyS_execve (0xffffffff811ded1e) 125 | return_to_handler (0xffffffff816c8458) 126 | stub_execve (0xffffffff816c6929) 127 | 128 + unmap_single_vma (0xffffffff81198c05) 129 45% (1) time:104673 max:104673 min:0 avg:104673 130 unmap_vmas (0xffffffff81199174) 131 exit_mmap (0xffffffff811a1f5b) 132 mmput (0xffffffff8107699a) 133 flush_old_exec (0xffffffff811ddb75) 134 load_elf_binary (0xffffffff812287df) 135 search_binary_handler (0xffffffff811dd3e0) 136 do_execveat_common.isra.31 (0xffffffff811de8bd) 137 do_execve (0xffffffff811dea8c) 138 SyS_execve (0xffffffff811ded1e) 139 return_to_handler (0xffffffff816c8458) 140 stub_execve (0xffffffff816c6929) 141 142 143 144 145 Event: sched_switch:S (1) Total: 1000513242 Avg: 1000513242 Max: 1000513242 Min:1000513242 146 | 147 + ftrace_raw_event_sched_switch (0xffffffff8109f310) 148 100% (1) time:1000513242 max:1000513242 min:0 avg:1000513242 149 __schedule (0xffffffff816c1e81) 150 schedule (0xffffffff816c23b9) 151 do_nanosleep (0xffffffff816c4f1c) 152 hrtimer_nanosleep (0xffffffff810dcd86) 153 SyS_nanosleep (0xffffffff810dcea6) 154 return_to_handler (0xffffffff816c8458) 155 tracesys_phase2 (0xffffffff816c65b0) 156 157 158 159 Event: sched_wakeup:1121 (1) Total: 43405 Avg: 43405 Max: 43405 Min:43405 160 | 161 + ftrace_raw_event_sched_wakeup_template (0xffffffff8109d960) 162 100% (1) time:43405 max:43405 min:0 avg:43405 163 ttwu_do_wakeup (0xffffffff810a01a2) 164 ttwu_do_activate.constprop.122 (0xffffffff810a0236) 165 try_to_wake_up (0xffffffff810a3ec3) 166 wake_up_process (0xffffffff810a4057) 167 hrtimer_wakeup (0xffffffff810db772) 168 __run_hrtimer (0xffffffff810dbd91) 169 hrtimer_interrupt (0xffffffff810dc6b7) 170 local_apic_timer_interrupt (0xffffffff810363e7) 171 smp_trace_apic_timer_interrupt (0xffffffff816c8c6a) 172 trace_apic_timer_interrupt (0xffffffff816c725a) 173 finish_task_switch (0xffffffff8109c3a4) 174 __schedule (0xffffffff816c1e01) 175 schedule (0xffffffff816c23b9) 176 ring_buffer_wait (0xffffffff811323a3) 177 wait_on_pipe (0xffffffff81133d93) 178 tracing_buffers_splice_read (0xffffffff811350b0) 179 do_splice_to (0xffffffff8120476f) 180 SyS_splice (0xffffffff81206c1f) 181 tracesys_phase2 (0xffffffff816c65b0) 182 183 184 Event: func: sys_nanosleep() (1) Total: 1000598016 Avg: 1000598016 Max: 1000598016 Min:1000598016 185 Event: func: sys_munmap() (1) Total: 14300 Avg: 14300 Max: 14300 Min:14300 186 Event: func: sys_arch_prctl() (1) Total: 571 Avg: 571 Max: 571 Min:571 187 Event: func: sys_mprotect() (4) Total: 14382 Avg: 3595 Max: 7196 Min:2190 188 Event: func: SyS_read() (1) Total: 2640 Avg: 2640 Max: 2640 Min:2640 189 Event: func: sys_close() (5) Total: 4001 Avg: 800 Max: 1252 Min:414 190 Event: func: sys_newfstat() (3) Total: 11684 Avg: 3894 Max: 10206 Min:636 191 Event: func: SyS_open() (3) Total: 23615 Avg: 7871 Max: 10535 Min:4743 192 Event: func: sys_access() (1) Total: 5924 Avg: 5924 Max: 5924 Min:5924 193 Event: func: SyS_mmap() (8) Total: 39153 Avg: 4894 Max: 12354 Min:1518 194 Event: func: smp_trace_apic_timer_interrupt() (1) Total: 10298 Avg: 10298 Max: 10298 Min:10298 195 Event: func: SyS_brk() (4) Total: 2407 Avg: 601 Max: 1564 Min:206 196 Event: func: do_notify_resume() (2) Total: 4095 Avg: 2047 Max: 2521 Min:1574 197 Event: func: sys_execve() (5) Total: 1625251 Avg: 325050 Max: 1605698 Min:3570 198 | 199 + ftrace_raw_event_sched_wakeup_template (0xffffffff8109d960) 200 100% (1) time:1605698 max:1605698 min:0 avg:1605698 201 ttwu_do_wakeup (0xffffffff810a01a2) 202 ttwu_do_activate.constprop.122 (0xffffffff810a0236) 203 try_to_wake_up (0xffffffff810a3ec3) 204 wake_up_process (0xffffffff810a4057) 205 cpu_stop_queue_work (0xffffffff81108df8) 206 stop_one_cpu (0xffffffff8110909a) 207 sched_exec (0xffffffff810a119b) 208 do_execveat_common.isra.31 (0xffffffff811de528) 209 do_execve (0xffffffff811dea8c) 210 SyS_execve (0xffffffff811ded1e) 211 return_to_handler (0xffffffff816c8458) 212 stub_execve (0xffffffff816c6929) 213 stub_execve (0xffffffff816c6929) 214 215 216 Event: func: syscall_trace_enter_phase2() (38) Total: 21544 Avg: 566 Max: 1066 Min:329 217 Event: func: syscall_trace_enter_phase1() (38) Total: 9202 Avg: 242 Max: 376 Min:150 218 Event: func: __do_page_fault() (53) Total: 257672 Avg: 4861 Max: 27745 Min:458 219 | 220 + ftrace_raw_event_sched_wakeup_template (0xffffffff8109d960) 221 100% (1) time:27745 max:27745 min:0 avg:27745 222 ttwu_do_wakeup (0xffffffff810a01a2) 223 ttwu_do_activate.constprop.122 (0xffffffff810a0236) 224 try_to_wake_up (0xffffffff810a3ec3) 225 default_wake_function (0xffffffff810a4002) 226 autoremove_wake_function (0xffffffff810b50fd) 227 __wake_up_common (0xffffffff810b4958) 228 __wake_up (0xffffffff810b4cb8) 229 rb_wake_up_waiters (0xffffffff8112f126) 230 irq_work_run_list (0xffffffff81157d0f) 231 irq_work_run (0xffffffff81157d5e) 232 smp_trace_irq_work_interrupt (0xffffffff810082fc) 233 trace_irq_work_interrupt (0xffffffff816c7aaa) 234 return_to_handler (0xffffffff816c8458) 235 trace_do_page_fault (0xffffffff810478b2) 236 trace_page_fault (0xffffffff816c7dd2) 237 238 239 Event: func: syscall_trace_leave() (38) Total: 26145 Avg: 688 Max: 1264 Min:381 240 Event: func: __sb_end_write() (1) Total: 373 Avg: 373 Max: 373 Min:373 241 Event: func: fsnotify() (1) Total: 598 Avg: 598 Max: 598 Min:598 242 Event: func: __fsnotify_parent() (1) Total: 286 Avg: 286 Max: 286 Min:286 243 Event: func: mutex_unlock() (2) Total: 39636 Avg: 19818 Max: 39413 Min:223 244 Event: func: smp_trace_irq_work_interrupt() (6) Total: 236459 Avg: 39409 Max: 100671 Min:634 245 | 246 + ftrace_raw_event_sched_wakeup_template (0xffffffff8109d960) 247 100% (4) time:234348 max:100671 min:38745 avg:58587 248 ttwu_do_wakeup (0xffffffff810a01a2) 249 ttwu_do_activate.constprop.122 (0xffffffff810a0236) 250 try_to_wake_up (0xffffffff810a3ec3) 251 default_wake_function (0xffffffff810a4002) 252 autoremove_wake_function (0xffffffff810b50fd) 253 __wake_up_common (0xffffffff810b4958) 254 __wake_up (0xffffffff810b4cb8) 255 rb_wake_up_waiters (0xffffffff8112f126) 256 irq_work_run_list (0xffffffff81157d0f) 257 irq_work_run (0xffffffff81157d5e) 258 smp_trace_irq_work_interrupt (0xffffffff810082fc) 259 return_to_handler (0xffffffff816c8458) 260 trace_irq_work_interrupt (0xffffffff816c7aaa) 261 | 262 + ftrace_return_to_handler (0xffffffff81140840) 263 | 84% (3) time:197396 max:100671 min:38745 avg:65798 264 | return_to_handler (0xffffffff816c846d) 265 | trace_page_fault (0xffffffff816c7dd2) 266 | 267 + ftrace_return_to_handler (0xffffffff81140840) 268 16% (1) time:36952 max:36952 min:0 avg:36952 269 ftrace_graph_caller (0xffffffff816c8428) 270 mutex_unlock (0xffffffff816c3f75) 271 rb_simple_write (0xffffffff81133142) 272 vfs_write (0xffffffff811d7727) 273 SyS_write (0xffffffff811d7acf) 274 tracesys_phase2 (0xffffffff816c65b0) 275 276 277 278 279 Event: sys_enter:35 (1) Total: 1000599765 Avg: 1000599765 Max: 1000599765 Min:1000599765 280 Event: sys_enter:11 (1) Total: 55025 Avg: 55025 Max: 55025 Min:55025 281 Event: sys_enter:158 (1) Total: 1584 Avg: 1584 Max: 1584 Min:1584 282 Event: sys_enter:10 (4) Total: 18359 Avg: 4589 Max: 8764 Min:2933 283 Event: sys_enter:0 (1) Total: 4223 Avg: 4223 Max: 4223 Min:4223 284 Event: sys_enter:3 (5) Total: 9948 Avg: 1989 Max: 2606 Min:1203 285 Event: sys_enter:5 (3) Total: 15530 Avg: 5176 Max: 11840 Min:1405 286 Event: sys_enter:2 (3) Total: 28002 Avg: 9334 Max: 12035 Min:5656 287 Event: sys_enter:21 (1) Total: 7814 Avg: 7814 Max: 7814 Min:7814 288 Event: sys_enter:9 (8) Total: 49583 Avg: 6197 Max: 14137 Min:2362 289 Event: sys_enter:12 (4) Total: 108493 Avg: 27123 Max: 104079 Min:922 290 Event: sys_enter:59 (5) Total: 1631608 Avg: 326321 Max: 1607529 Min:4563 291 Event: page_fault_user:0x398d86b630 (1) 292 Event: page_fault_user:0x398d844de0 (1) 293 Event: page_fault_user:0x398d8d9020 (1) 294 Event: page_fault_user:0x1d37008 (1) 295 Event: page_fault_user:0x7f0b89e91074 (1) 296 Event: page_fault_user:0x7f0b89d98ed0 (1) 297 Event: page_fault_user:0x7f0b89ec8950 (1) 298 Event: page_fault_user:0x7f0b89d83644 (1) 299 Event: page_fault_user:0x7f0b89d622a8 (1) 300 Event: page_fault_user:0x7f0b89d5a560 (1) 301 Event: page_fault_user:0x7f0b89d34010 (1) 302 Event: page_fault_user:0x1d36008 (1) 303 Event: page_fault_user:0x398d900510 (1) 304 Event: page_fault_user:0x398dbb3ae8 (1) 305 Event: page_fault_user:0x398d87f490 (1) 306 Event: page_fault_user:0x398d8eb660 (1) 307 Event: page_fault_user:0x398d8bd730 (1) 308 Event: page_fault_user:0x398d9625d9 (1) 309 Event: page_fault_user:0x398d931810 (1) 310 Event: page_fault_user:0x398dbb7114 (1) 311 Event: page_fault_user:0x398d837610 (1) 312 Event: page_fault_user:0x398d89e860 (1) 313 Event: page_fault_user:0x398d8f23b0 (1) 314 Event: page_fault_user:0x398dbb4510 (1) 315 Event: page_fault_user:0x398dbad6f0 (1) 316 Event: page_fault_user:0x398dbb1018 (1) 317 Event: page_fault_user:0x398d977b37 (1) 318 Event: page_fault_user:0x398d92eb60 (1) 319 Event: page_fault_user:0x398d8abff0 (1) 320 Event: page_fault_user:0x398dbb0d30 (1) 321 Event: page_fault_user:0x398dbb6c24 (1) 322 Event: page_fault_user:0x398d821c50 (1) 323 Event: page_fault_user:0x398dbb6c20 (1) 324 Event: page_fault_user:0x398d886350 (1) 325 Event: page_fault_user:0x7f0b90125000 (1) 326 Event: page_fault_user:0x7f0b90124740 (1) 327 Event: page_fault_user:0x7f0b90126000 (1) 328 Event: page_fault_user:0x398d816230 (1) 329 Event: page_fault_user:0x398d8002b8 (1) 330 Event: page_fault_user:0x398dbb0b40 (1) 331 Event: page_fault_user:0x398dbb2880 (1) 332 Event: page_fault_user:0x7f0b90141cc6 (1) 333 Event: page_fault_user:0x7f0b9013b85c (1) 334 Event: page_fault_user:0x7f0b90127000 (1) 335 Event: page_fault_user:0x606e70 (1) 336 Event: page_fault_user:0x7f0b90144010 (1) 337 Event: page_fault_user:0x7fffcb31b038 (1) 338 Event: page_fault_user:0x606da8 (1) 339 Event: page_fault_user:0x400040 (1) 340 Event: page_fault_user:0x398d222218 (1) 341 Event: page_fault_user:0x398d015120 (1) 342 Event: page_fault_user:0x398d220ce8 (1) 343 Event: page_fault_user:0x398d220b80 (1) 344 Event: page_fault_user:0x7fffcb2fcff8 (1) 345 Event: page_fault_user:0x398d001590 (1) 346 Event: page_fault_user:0x398d838490 (1) 347 Event: softirq_raise:RCU (3) Total: 252931 Avg: 84310 Max: 243288 Min:4639 348 Event: softirq_raise:SCHED (2) Total: 241249 Avg: 120624 Max: 239076 Min:2173 349 | 350 + ftrace_raw_event_sched_wakeup_template (0xffffffff8109d960) 351 100% (1) time:239076 max:239076 min:0 avg:239076 352 ttwu_do_wakeup (0xffffffff810a01a2) 353 ttwu_do_activate.constprop.122 (0xffffffff810a0236) 354 try_to_wake_up (0xffffffff810a3ec3) 355 default_wake_function (0xffffffff810a4002) 356 autoremove_wake_function (0xffffffff810b50fd) 357 __wake_up_common (0xffffffff810b4958) 358 __wake_up (0xffffffff810b4cb8) 359 rb_wake_up_waiters (0xffffffff8112f126) 360 irq_work_run_list (0xffffffff81157d0f) 361 irq_work_run (0xffffffff81157d5e) 362 smp_trace_irq_work_interrupt (0xffffffff810082fc) 363 trace_irq_work_interrupt (0xffffffff816c7aaa) 364 irq_exit (0xffffffff8107dd66) 365 smp_trace_apic_timer_interrupt (0xffffffff816c8c7a) 366 trace_apic_timer_interrupt (0xffffffff816c725a) 367 prepare_ftrace_return (0xffffffff8103d4fd) 368 ftrace_graph_caller (0xffffffff816c8428) 369 mem_cgroup_begin_page_stat (0xffffffff811cfd25) 370 page_remove_rmap (0xffffffff811a4fc5) 371 stub_execve (0xffffffff816c6929) 372 unmap_single_vma (0xffffffff81198b1c) 373 unmap_vmas (0xffffffff81199174) 374 exit_mmap (0xffffffff811a1f5b) 375 mmput (0xffffffff8107699a) 376 flush_old_exec (0xffffffff811ddb75) 377 load_elf_binary (0xffffffff812287df) 378 search_binary_handler (0xffffffff811dd3e0) 379 do_execveat_common.isra.31 (0xffffffff811de8bd) 380 do_execve (0xffffffff811dea8c) 381 SyS_execve (0xffffffff811ded1e) 382 return_to_handler (0xffffffff816c8458) 383 384 385 Event: softirq_raise:HI (3) Total: 72472 Avg: 24157 Max: 64186 Min:3430 386 Event: softirq_entry:RCU (2) Total: 3191 Avg: 1595 Max: 1788 Min:1403 387 | 388 + ftrace_raw_event_sched_wakeup_template (0xffffffff8109d960) 389 100% (1) time:1788 max:1788 min:0 avg:1788 390 ttwu_do_wakeup (0xffffffff810a01a2) 391 ttwu_do_activate.constprop.122 (0xffffffff810a0236) 392 try_to_wake_up (0xffffffff810a3ec3) 393 default_wake_function (0xffffffff810a4002) 394 autoremove_wake_function (0xffffffff810b50fd) 395 __wake_up_common (0xffffffff810b4958) 396 __wake_up (0xffffffff810b4cb8) 397 rb_wake_up_waiters (0xffffffff8112f126) 398 irq_work_run_list (0xffffffff81157d0f) 399 irq_work_run (0xffffffff81157d5e) 400 smp_trace_irq_work_interrupt (0xffffffff810082fc) 401 trace_irq_work_interrupt (0xffffffff816c7aaa) 402 irq_work_queue (0xffffffff81157e95) 403 ring_buffer_unlock_commit (0xffffffff8113039f) 404 __buffer_unlock_commit (0xffffffff811367d5) 405 trace_buffer_unlock_commit (0xffffffff811376a2) 406 ftrace_event_buffer_commit (0xffffffff81146d5f) 407 ftrace_raw_event_sched_process_exec (0xffffffff8109c511) 408 do_execveat_common.isra.31 (0xffffffff811de9a3) 409 do_execve (0xffffffff811dea8c) 410 SyS_execve (0xffffffff811ded1e) 411 return_to_handler (0xffffffff816c8458) 412 stub_execve (0xffffffff816c6929) 413 414 415 Event: softirq_entry:SCHED (2) Total: 2289 Avg: 1144 Max: 1350 Min:939 416 Event: softirq_entry:HI (3) Total: 180146 Avg: 60048 Max: 178969 Min:499 417 | 418 + ftrace_raw_event_sched_wakeup_template (0xffffffff8109d960) 419 100% (1) time:178969 max:178969 min:0 avg:178969 420 ttwu_do_wakeup (0xffffffff810a01a2) 421 ttwu_do_activate.constprop.122 (0xffffffff810a0236) 422 try_to_wake_up (0xffffffff810a3ec3) 423 wake_up_process (0xffffffff810a4057) 424 wake_up_worker (0xffffffff8108de74) 425 insert_work (0xffffffff8108fca6) 426 __queue_work (0xffffffff8108fe12) 427 delayed_work_timer_fn (0xffffffff81090088) 428 call_timer_fn (0xffffffff810d8f89) 429 run_timer_softirq (0xffffffff810da8a1) 430 __do_softirq (0xffffffff8107d8fa) 431 irq_exit (0xffffffff8107dd66) 432 smp_trace_apic_timer_interrupt (0xffffffff816c8c7a) 433 trace_apic_timer_interrupt (0xffffffff816c725a) 434 prepare_ftrace_return (0xffffffff8103d4fd) 435 ftrace_graph_caller (0xffffffff816c8428) 436 mem_cgroup_begin_page_stat (0xffffffff811cfd25) 437 page_remove_rmap (0xffffffff811a4fc5) 438 stub_execve (0xffffffff816c6929) 439 unmap_single_vma (0xffffffff81198b1c) 440 unmap_vmas (0xffffffff81199174) 441 exit_mmap (0xffffffff811a1f5b) 442 mmput (0xffffffff8107699a) 443 flush_old_exec (0xffffffff811ddb75) 444 load_elf_binary (0xffffffff812287df) 445 search_binary_handler (0xffffffff811dd3e0) 446 do_execveat_common.isra.31 (0xffffffff811de8bd) 447 do_execve (0xffffffff811dea8c) 448 SyS_execve (0xffffffff811ded1e) 449 return_to_handler (0xffffffff816c8458) 450 --- 451 452The above uses *-F* to follow the sleep task. It filters only on events 453that pertain to sleep. Note, in order to follow forks, you need to also 454include the *-c* flag. 455 456Other tasks will appear in the profile as well if events reference more 457than one task (like sched_switch and sched_wakeup do. The "prev_pid" and 458"next_pid" of sched_switch, and the "common_pid" and "pid" of sched_wakeup). 459 460Stack traces are attached to events that are related to them. 461 462Taking a look at the above output: 463 464 Event: sched_switch:R (2) Total: 234559 Avg: 117279 Max: 129886 Min:104673 465 466This shows that task was preempted (it's in the running 'R' state). 467It was preempted twice '(2)' for a total of 234,559 nanoseconds, with a average 468preempt time of 117,279 ns, and maximum of 128,886 ns and minimum of 104,673 ns. 469 470The tree shows where it was preempted: 471 472 473 | 474 + ftrace_raw_event_sched_switch (0xffffffff8109f310) 475 100% (2) time:234559 max:129886 min:104673 avg:117279 476 __schedule (0xffffffff816c1e81) 477 preempt_schedule (0xffffffff816c236e) 478 ___preempt_schedule (0xffffffff81351a59) 479 | 480 + unmap_single_vma (0xffffffff81198c05) 481 | 55% (1) time:129886 max:129886 min:0 avg:129886 482 | stop_one_cpu (0xffffffff8110909a) 483 | sched_exec (0xffffffff810a119b) 484 | do_execveat_common.isra.31 (0xffffffff811de528) 485 | do_execve (0xffffffff811dea8c) 486 | SyS_execve (0xffffffff811ded1e) 487 | return_to_handler (0xffffffff816c8458) 488 | stub_execve (0xffffffff816c6929) 489 | 490 + unmap_single_vma (0xffffffff81198c05) 491 45% (1) time:104673 max:104673 min:0 avg:104673 492 unmap_vmas (0xffffffff81199174) 493 exit_mmap (0xffffffff811a1f5b) 494 mmput (0xffffffff8107699a) 495 flush_old_exec (0xffffffff811ddb75) 496 load_elf_binary (0xffffffff812287df) 497 search_binary_handler (0xffffffff811dd3e0) 498 do_execveat_common.isra.31 (0xffffffff811de8bd) 499 do_execve (0xffffffff811dea8c) 500 SyS_execve (0xffffffff811ded1e) 501 return_to_handler (0xffffffff816c8458) 502 stub_execve (0xffffffff816c6929) 503 504 505 Event: sched_switch:S (1) Total: 1000513242 Avg: 1000513242 Max: 1000513242 Min:10005132 506 507This shows that the task was scheduled out in the INTERRUPTIBLE state once 508for a total of 1,000,513,242 ns (~1s), which makes sense as the task was a 509"sleep 1". 510 511After the schedule events, the function events are shown. By default the 512profiler will use the function graph tracer if the depth setting is supported 513by the kernel. It will set the depth to one which will only trace the first 514function that enters the kernel. It will also record the amount of time 515it was in the kernel. 516 517 Event: func: sys_nanosleep() (1) Total: 1000598016 Avg: 1000598016 Max: 1000598016 Min:1000598016 518 Event: func: sys_munmap() (1) Total: 14300 Avg: 14300 Max: 14300 Min:14300 519 Event: func: sys_arch_prctl() (1) Total: 571 Avg: 571 Max: 571 Min:571 520 Event: func: sys_mprotect() (4) Total: 14382 Avg: 3595 Max: 7196 Min:2190 521 Event: func: SyS_read() (1) Total: 2640 Avg: 2640 Max: 2640 Min:2640 522 Event: func: sys_close() (5) Total: 4001 Avg: 800 Max: 1252 Min:414 523 Event: func: sys_newfstat() (3) Total: 11684 Avg: 3894 Max: 10206 Min:636 524 Event: func: SyS_open() (3) Total: 23615 Avg: 7871 Max: 10535 Min:4743 525 Event: func: sys_access() (1) Total: 5924 Avg: 5924 Max: 5924 Min:5924 526 Event: func: SyS_mmap() (8) Total: 39153 Avg: 4894 Max: 12354 Min:1518 527 Event: func: smp_trace_apic_timer_interrupt() (1) Total: 10298 Avg: 10298 Max: 10298 Min:10298 528 Event: func: SyS_brk() (4) Total: 2407 Avg: 601 Max: 1564 Min:206 529 Event: func: do_notify_resume() (2) Total: 4095 Avg: 2047 Max: 2521 Min:1574 530 Event: func: sys_execve() (5) Total: 1625251 Avg: 325050 Max: 1605698 Min:3570 531 532 533Count of times the event was hit is always in parenthesis '(5)'. 534 535The function graph trace may produce too much overhead as it is still 536triggering (just not tracing) on all functions. To limit functions just to 537system calls (not interrupts), add the following option: 538 539 -l 'sys_*' -l 'SyS_*' 540 541To disable function graph tracing totally, use: 542 543 -p nop 544 545To use function tracing instead (note, this will not record timings, but just 546the count of times a function is hit): 547 548 -p function 549 550 551Following the functions are the events that are recorded. 552 553 554 Event: sys_enter:35 (1) Total: 1000599765 Avg: 1000599765 Max: 1000599765 Min:1000599765 555 Event: sys_enter:11 (1) Total: 55025 Avg: 55025 Max: 55025 Min:55025 556 Event: sys_enter:158 (1) Total: 1584 Avg: 1584 Max: 1584 Min:1584 557 Event: sys_enter:10 (4) Total: 18359 Avg: 4589 Max: 8764 Min:2933 558 Event: sys_enter:0 (1) Total: 4223 Avg: 4223 Max: 4223 Min:4223 559 Event: sys_enter:3 (5) Total: 9948 Avg: 1989 Max: 2606 Min:1203 560 Event: sys_enter:5 (3) Total: 15530 Avg: 5176 Max: 11840 Min:1405 561 Event: sys_enter:2 (3) Total: 28002 Avg: 9334 Max: 12035 Min:5656 562 Event: sys_enter:21 (1) Total: 7814 Avg: 7814 Max: 7814 Min:7814 563 Event: sys_enter:9 (8) Total: 49583 Avg: 6197 Max: 14137 Min:2362 564 Event: sys_enter:12 (4) Total: 108493 Avg: 27123 Max: 104079 Min:922 565 Event: sys_enter:59 (5) Total: 1631608 Avg: 326321 Max: 1607529 Min:4563 566 567These are the raw system call events, with the raw system call ID after 568the "sys_enter:" For example, "59" is execve(2). Why did it execute 5 times? 569Looking at a strace of this run, we can see: 570 571 execve("/usr/lib64/ccache/sleep", ["sleep", "1"], [/* 27 vars */] <unfinished ...> 572 <... execve resumed> ) = -1 ENOENT (No such file or directory) 573 execve("/usr/local/sbin/sleep", ["sleep", "1"], [/* 27 vars */] <unfinished ...> 574 <... execve resumed> ) = -1 ENOENT (No such file or directory) 575 execve("/usr/local/bin/sleep", ["sleep", "1"], [/* 27 vars */] <unfinished ...> 576 <... execve resumed> ) = -1 ENOENT (No such file or directory) 577 execve("/usr/sbin/sleep", ["sleep", "1"], [/* 27 vars */] <unfinished ...> 578 <... execve resumed> ) = -1 ENOENT (No such file or directory) 579 execve("/usr/bin/sleep", ["sleep", "1"], [/* 27 vars */] <unfinished ...> 580 <... execve resumed> ) = 0 581 582It attempted to execve the "sleep" command for each path in $PATH until it found 583one. 584 585The page_fault_user events show what userspace address took a page fault. 586 587 Event: softirq_raise:RCU (3) Total: 252931 Avg: 84310 Max: 243288 Min:4639 588 Event: softirq_raise:SCHED (2) Total: 241249 Avg: 120624 Max: 239076 Min:2173 589 | 590 + ftrace_raw_event_sched_wakeup_template (0xffffffff8109d960) 591 100% (1) time:239076 max:239076 min:0 avg:239076 592 ttwu_do_wakeup (0xffffffff810a01a2) 593 ttwu_do_activate.constprop.122 (0xffffffff810a0236) 594 try_to_wake_up (0xffffffff810a3ec3) 595 default_wake_function (0xffffffff810a4002) 596 autoremove_wake_function (0xffffffff810b50fd) 597 __wake_up_common (0xffffffff810b4958) 598 __wake_up (0xffffffff810b4cb8) 599 rb_wake_up_waiters (0xffffffff8112f126) 600 irq_work_run_list (0xffffffff81157d0f) 601 irq_work_run (0xffffffff81157d5e) 602 smp_trace_irq_work_interrupt (0xffffffff810082fc) 603 trace_irq_work_interrupt (0xffffffff816c7aaa) 604 irq_exit (0xffffffff8107dd66) 605 606The timings for the softirq_raise events measure the time it took from the raised 607softirq to the time it executed. 608 609The timings for the softirq_entry events measure the time the softirq took to 610execute. 611 612The stack traces for the softirqs (and possibly other events) are used when 613an event has a stack attached to it. This can happen if the profile ran 614more stacks than just the sched events, or when events are dropped and 615stacks 616 617 618To have full control of what gets traced, use the *-S* option that will have 619trace-cmd not enable any events or the function_graph tracer. Only the events 620listed on the command line are shown. 621 622If only the time of kmalloc is needed to be seen, and where it was recorded, 623using the *-S* option and enabling function_graph and stack tracing for just 624the function needed will give the profile of only that function. 625 626 --- 627# trace-cmd profile -S -p function_graph -l '*kmalloc*' -l '*kmalloc*:stacktrace' sleep 1 628task: sshd-11786 629 Event: func: __kmalloc_reserve.isra.59() (2) Total: 149684 Avg: 74842 Max: 75598 Min:74086 630 | 631 + __alloc_skb (0xffffffff815a8917) 632 | 67% (2) time:149684 max:75598 min:74086 avg:74842 633 | __kmalloc_node_track_caller (0xffffffff811c6635) 634 | __kmalloc_reserve.isra.59 (0xffffffff815a84ac) 635 | return_to_handler (0xffffffff816c8458) 636 | sk_stream_alloc_skb (0xffffffff81604ea1) 637 | tcp_sendmsg (0xffffffff8160592c) 638 | inet_sendmsg (0xffffffff8162fed1) 639 | sock_aio_write (0xffffffff8159f9fc) 640 | do_sync_write (0xffffffff811d694a) 641 | vfs_write (0xffffffff811d7825) 642 | SyS_write (0xffffffff811d7adf) 643 | system_call_fastpath (0xffffffff816c63d2) 644 | 645 + __alloc_skb (0xffffffff815a8917) 646 33% (1) time:74086 max:74086 min:74086 avg:74086 647 __alloc_skb (0xffffffff815a8917) 648 sk_stream_alloc_skb (0xffffffff81604ea1) 649 tcp_sendmsg (0xffffffff8160592c) 650 inet_sendmsg (0xffffffff8162fed1) 651 sock_aio_write (0xffffffff8159f9fc) 652 do_sync_write (0xffffffff811d694a) 653 vfs_write (0xffffffff811d7825) 654 SyS_write (0xffffffff811d7adf) 655 system_call_fastpath (0xffffffff816c63d2) 656 [..] 657--- 658 659To watch the command run but save the output of the profile to a file 660use --stderr, and redirect stderr to a file 661 662# trace-cmd profile --stderr cyclictest -p 80 -n -t1 2> profile.out 663 664Or simple use *-o* 665 666# trace-cmd profile -o profile.out cyclictest -p 80 -n -t1 667 668SEE ALSO 669-------- 670trace-cmd(1), trace-cmd-record(1), trace-cmd-report(1), trace-cmd-start(1), 671trace-cmd-stop(1), trace-cmd-reset(1), trace-cmd-split(1), 672trace-cmd-list(1), trace-cmd-listen(1) 673 674AUTHOR 675------ 676Written by Steven Rostedt, <[email protected]> 677 678RESOURCES 679--------- 680https://git.kernel.org/pub/scm/utils/trace-cmd/trace-cmd.git/ 681 682COPYING 683------- 684Copyright \(C) 2014 Red Hat, Inc. Free use of this software is granted under 685the terms of the GNU Public License (GPL). 686 687