1TRACE-CMD-PROFILE(1) TRACE-CMD-PROFILE(1)
2
6 trace-cmd-profile - profile tasks running live
7
9 trace-cmd profile [OPTIONS] [command]
10
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 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 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 To disable calling function graph, use the -p option to enable another
30 tracer. To not enable any tracer, use -p nop.
31 All timings are currently in nanoseconds.
33
35 These are the same as trace-cmd-record(1) with the --profile option.
36 -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 -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 -G
49 Set interrupt (soft and hard) events as global (associated to CPU
50 instead of tasks).
51 -o file
53 Write the output of the profile to file. This supersedes --stderr
54 -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 The start_system:start_event (start_system is optional), is the event that
62 starts the timing.
63 start_match is the field in the start event that is to match with the
65 end_match in the end event.
66 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 end_system:end_event is the event that ends the timing (end_system is
72 optional).
73 end_match is the field in end_match that wil match the start event field
75 start_match.
76 flags are optional and can be the following (case insensitive):
78 p : The two events are pinned to the same CPU (start and end happen
80 on the same CPU always).
81 s : The event should have a stack traced with it (enable stack tracing
83 for the start event).
84 g : The event is global (not associated to a task). start_pid is
86 not applicable with this flag.
87 --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
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 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 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 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 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 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 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 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 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 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 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 Stack traces are attached to events that are related to them.
437 Taking a look at the above output:
439 Event: sched_switch:R (2) Total: 234559 Avg: 117279 Max: 129886 Min:104673
441 This shows that task was preempted (it’s in the running R state). It
443 was preempted twice [4m(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 The tree shows where it was preempted:
448 |
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 Event: sched_switch:S (1) Total: 1000513242 Avg: 1000513242 Max: 1000513242 Min:10005132
481 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 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 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 Count of times the event was hit is always in parenthesis [4m(5).
508 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 -l 'sys_*' -l 'SyS_*'
514 To disable function graph tracing totally, use:
516 -p nop
518 To use function tracing instead (note, this will not record timings,
520 but just the count of times a function is hit):
521 -p function
523 Following the functions are the events that are recorded.
525 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 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 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 It attempted to execve the "sleep" command for each path in $PATH until
555 it found one.
556 The page_fault_user events show what userspace address took a page
558 fault.
559 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 The timings for the softirq_raise events measure the time it took from
580 the raised softirq to the time it executed.
581 The timings for the softirq_entry events measure the time the softirq
583 took to execute.
584 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 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 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 ---
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 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 # trace-cmd profile --stderr cyclictest -p 80 -n -t1 2> profile.out
636 Or simple use -o
638 # trace-cmd profile -o profile.out cyclictest -p 80 -n -t1
640
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
647 Written by Steven Rostedt, <rostedt@goodmis.org[1]>
648
650 git://git.kernel.org/pub/scm/linux/kernel/git/rostedt/trace-cmd.git
651
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
657 1. rostedt@goodmis.org
658 mailto:rostedt@goodmis.org
659 08/07/2019 TRACE-CMD-PROFILE(1)