1TRACE-CMD-PROFILE(1)           libtracefs Manual          TRACE-CMD-PROFILE(1)
2
3
4

NAME

6       trace-cmd-profile - profile tasks running live
7

SYNOPSIS

9       trace-cmd profile [OPTIONS] [command]
10

DESCRIPTION

12       The trace-cmd(1) profile will start tracing just like
13       trace-cmd-record(1), with the --profile option, except that it does not
14       write to a file, but instead, it will read the events as they happen
15       and will update the accounting of the events. When the trace is
16       finished, it will report the results just like trace-cmd-report(1)
17       would do with its --profile option. In other words, the profile command
18       does the work of trace-cmd record --profile, and trace-cmd report
19       --profile without having to record the data to disk, in between.
20
21       The advantage of using the profile command is that the profiling can be
22       done over a long period of time where recording all events would take
23       up too much disk space.
24
25       This will enable several events as well as the function graph tracer
26       with a depth of one (if the kernel supports it). This is to show where
27       tasks enter and exit the kernel and how long they were in the kernel.
28
29       To disable calling function graph, use the -p option to enable another
30       tracer. To not enable any tracer, use -p nop.
31
32       All timings are currently in nanoseconds.
33

OPTIONS

35       These are the same as trace-cmd-record(1) with the --profile option.
36
37       -p tracer
38           Set a tracer plugin to run instead of function graph tracing set to
39           depth of 1. To not run any tracer, use -p nop.
40
41       -S
42           Only enable the tracer or events speficied on the command line.
43           With this option, the function_graph tracer is not enabled, nor are
44           any events (like sched_switch), unless they are specifically
45           specified on the command line (i.e. -p function -e sched_switch -e
46           sched_wakeup)
47
48       -G
49           Set interrupt (soft and hard) events as global (associated to CPU
50           instead of tasks).
51
52       -o file
53           Write the output of the profile to file. This supersedes --stderr
54
55       -H event-hooks
56           Add custom event matching to connect any two events together.
57           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
90           executed is not changed. This allows watching the command execute
91           and saving the output of the profile to another file.
92
93       --verbose[=level]
94           Set the log level. Supported log levels are "none", "critical",
95           "error", "warning", "info", "debug", "all" or their identifiers
96           "0", "1", "2", "3", "4", "5", "6". Setting the log level to
97           specific value enables all logs from that and all previous levels.
98           The level will default to "info" if one is not specified.
99
100               Example: enable all critical, error and warning logs
101
102               trace-cmd profile --verbose=warning
103

EXAMPLES

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

SEE ALSO

653       trace-cmd(1), trace-cmd-record(1), trace-cmd-report(1),
654       trace-cmd-start(1), trace-cmd-stop(1), trace-cmd-reset(1),
655       trace-cmd-split(1), trace-cmd-list(1), trace-cmd-listen(1)
656

AUTHOR

658       Written by Steven Rostedt, <rostedt@goodmis.org[1]>
659

RESOURCES

661       https://git.kernel.org/pub/scm/utils/trace-cmd/trace-cmd.git/
662

COPYING

664       Copyright (C) 2014 Red Hat, Inc. Free use of this software is granted
665       under the terms of the GNU Public License (GPL).
666

NOTES

668        1. rostedt@goodmis.org
669           mailto:rostedt@goodmis.org
670
671
672
673libtracefs                        07/23/2022              TRACE-CMD-PROFILE(1)
Impressum