1TRACE-CMD-PROFILE(1) libtracefs Manual 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 --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 Example: enable all critical, error and warning logs
101 trace-cmd profile --verbose=warning
103
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 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 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 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 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 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 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 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 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 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 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 Stack traces are attached to events that are related to them.
448 Taking a look at the above output:
450 Event: sched_switch:R (2) Total: 234559 Avg: 117279 Max: 129886 Min:104673
452 This shows that task was preempted (it’s in the running R state). It
454 was preempted twice [4m(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 The tree shows where it was preempted:
459 |
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 Event: sched_switch:S (1) Total: 1000513242 Avg: 1000513242 Max: 1000513242 Min:10005132
492 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 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 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 Count of times the event was hit is always in parenthesis [4m(5).
519 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 -l 'sys_*' -l 'SyS_*'
525 To disable function graph tracing totally, use:
527 -p nop
529 To use function tracing instead (note, this will not record timings,
531 but just the count of times a function is hit):
532 -p function
534 Following the functions are the events that are recorded.
536 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 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 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 It attempted to execve the "sleep" command for each path in $PATH until
566 it found one.
567 The page_fault_user events show what userspace address took a page
569 fault.
570 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 The timings for the softirq_raise events measure the time it took from
591 the raised softirq to the time it executed.
592 The timings for the softirq_entry events measure the time the softirq
594 took to execute.
595 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 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 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 ---
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 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 # trace-cmd profile --stderr cyclictest -p 80 -n -t1 2> profile.out
647 Or simple use -o
649 # trace-cmd profile -o profile.out cyclictest -p 80 -n -t1
651
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
658 Written by Steven Rostedt, <rostedt@goodmis.org[1]>
659
661 https://git.kernel.org/pub/scm/utils/trace-cmd/trace-cmd.git/
662
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
668 1. rostedt@goodmis.org
669 mailto:rostedt@goodmis.org
670libtracefs 10/11/2022 TRACE-CMD-PROFILE(1)