1TRACE-CMD-PROFILE(1)                                      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

EXAMPLES

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

SEE ALSO

642       trace-cmd(1), trace-cmd-record(1), trace-cmd-report(1),
643       trace-cmd-start(1), trace-cmd-stop(1), trace-cmd-reset(1),
644       trace-cmd-split(1), trace-cmd-list(1), trace-cmd-listen(1)
645

AUTHOR

647       Written by Steven Rostedt, <rostedt@goodmis.org[1]>
648

RESOURCES

650       git://git.kernel.org/pub/scm/linux/kernel/git/rostedt/trace-cmd.git
651

COPYING

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

NOTES

657        1. rostedt@goodmis.org
658           mailto:rostedt@goodmis.org
659
660
661
662                                  04/11/2018              TRACE-CMD-PROFILE(1)
Impressum