1TRACE-CMD-REPORT(1) libtracefs Manual TRACE-CMD-REPORT(1)
2
6 trace-cmd-report - show in ASCII a trace created by trace-cmd record
7
9 trace-cmd report [OPTIONS] [input-file]
10
12 The trace-cmd(1) report command will output a human readable report of
13 a trace created by trace-cmd record.
14
16 -i input-file
17 By default, trace-cmd report will read the file trace.dat. But the
18 -i option open up the given input-file instead. Note, the input
19 file may also be specified as the last item on the command line.
20 -e
22 This outputs the endianess of the file. trace-cmd report is smart
23 enough to be able to read big endian files on little endian
24 machines, and vise versa.
25 -f
27 This outputs the list of all functions that have been mapped in the
28 trace.dat file. Note, this list may contain functions that may not
29 appear in the trace, as it is the list of mappings to translate
30 function addresses into function names.
31 -P
33 This outputs the list of "trace_printk()" data. The raw trace data
34 points to static pointers in the kernel. This must be stored in the
35 trace.dat file.
36 -E
38 This lists the possible events in the file (but this list is not
39 necessarily the list of events in the file).
40 --events
42 This will list the event formats that are stored in the trace.dat
43 file.
44 --event regex
46 This will print events that match the given regex. If a colon is
47 specified, then the characters before the colon will be used to
48 match the system and the characters after the colon will match the
49 event.
50 trace-cmd report --event sys:read
52 The above will only match events where the system name contains "sys"
54 and the event name contains "read".
55 trace-cmd report --event read
57 The above will match all events that contain "read" in its name. Also it
59 may list all events of a system that contains "read" as well.
60 --check-events
62 This will parse the event format strings that are stored in the
63 trace.dat file and return whether the formats can be parsed
64 correctly. It will load plugins unless -N is specified.
65 -t
67 Print the full timestamp. The timestamps in the data file are
68 usually recorded to the nanosecond. But the default display of the
69 timestamp is only to the microsecond. To see the full timestamp,
70 add the -t option.
71 -F filter
73 Add a filter to limit what events are displayed. The format of the
74 filter is:
75 <events> ':' <filter>
77 <events> = SYSTEM'/'EVENT | SYSTEM | EVENT | <events> ',' <events>
78 <filter> = EVENT_FIELD <op> <value> | <filter> '&&' <filter> |
79 <filter> '||' <filter> | '(' <filter> ')' | '!' <filter>
80 <op> = '==' | '!=' | '>=' | '<=' | '>' | '<' | '&' | '|' | '^' |
81 '+' | '-' | '*' | '/' | '%'
82 <value> = NUM | STRING | EVENT_FIELD
83 SYSTEM is the name of the system to filter on. If the EVENT is left out,
85 then it applies to all events under the SYSTEM. If only one string is used
86 without the '/' to deliminate between SYSTEM and EVENT, then the filter
87 will be applied to all systems and events that match the given string.
88 Whitespace is ignored, such that "sched:next_pid==123" is equivalent to
90 "sched : next_pid == 123".
91 STRING is defined with single or double quotes (single quote must end with
93 single quote, and double with double). Whitespace within quotes are not
94 ignored.
95 The representation of a SYSTEM or EVENT may also be a regular expression
97 as defined by 'regcomp(3)'.
98 The EVENT_FIELD is the name of the field of an event that is being
100 filtered. If the event does not contain the EVENT_FIELD, that part of the
101 equation will be considered false.
102 -F 'sched : bogus == 1 || common_pid == 2'
104 The "bogus == 1" will always evaluate to FALSE because no event has a
106 field called "bogus", but the "common_pid == 2" will still be evaluated
107 since all events have the field "common_pid". Any "sched" event that was
108 traced by the process with the PID of 2 will be shown.
109 Note, the EVENT_FIELD is the field name as shown by an events format
111 (as displayed with *--events*), and not what is found in the output.
112 If the output shows "ID:foo" but the field that "foo" belongs to was
113 called "name" in the event format, then "name" must be used in the filter.
114 The same is true about values. If the value that is displayed is converted
115 by to a string symbol, the filter checks the original value and not the
116 value displayed. For example, to filter on all tasks that were in the
117 running state at a context switch:
118 -F 'sched/sched_switch : prev_state==0'
120 Although the output displays 'R', having 'prev_stat=="R"' will not work.
122 Note: You can also specify 'COMM' as an EVENT_FIELD. This will use the
124 task name (or comm) of the record to compare. For example, to filter out
125 all of the "trace-cmd" tasks:
126 -F '.*:COMM != "trace-cmd"'
128 -I
130 Do not print events where the HARDIRQ latency flag is set. This
131 will filter out most events that are from interrupt context. Note,
132 it may not filter out function traced functions that are in
133 interrupt context but were called before the kernel "in interrupt"
134 flag was set.
135 -S
137 Do not print events where the SOFTIRQ latency flag is set. This
138 will filter out most events that are from soft interrupt context.
139 -v
141 This causes the following filters of -F to filter out the matching
142 events.
143 -v -F 'sched/sched_switch : prev_state == 0'
145 Will not display any sched_switch events that have a prev_state of 0.
147 Removing the *-v* will only print out those events.
148 -T
150 Test the filters of -F. After processing a filter string, the
151 resulting filter will be displayed for each event. This is useful
152 for using a filter for more than one event where a field may not
153 exist in all events. Also it can be used to make sure there are no
154 misspelled event field names, as they will simply be ignored. -T
155 is ignored if -F is not specified.
156 -V
158 Show verbose messages (see --verbose but only for the numbers)
159 -L
161 This will not load system wide plugins. It loads "local only". That
162 is what it finds in the ~/.trace-cmd/plugins directory.
163 -N
165 This will not load any plugins.
166 -n event-re
168 This will cause all events that match the option to ignore any
169 registered handler (by the plugins) to print the event. The normal
170 event will be printed instead. The event-re is a regular expression
171 as defined by regcomp(3).
172 --profile
174 With the --profile option, "trace-cmd report" will process all the
175 events first, and then output a format showing where tasks have
176 spent their time in the kernel, as well as where they are blocked
177 the most, and where wake up latencies are.
178 See trace-cmd-profile(1) for more details and examples.
180 -G
182 Set interrupt (soft and hard) events as global (associated to CPU
183 instead of tasks). Only works for --profile.
184 -H event-hooks
186 Add custom event matching to connect any two events together.
187 See trace-cmd-profile(1) for format.
189 -R
191 This will show the events in "raw" format. That is, it will ignore
192 the event’s print formatting and just print the contents of each
193 field.
194 -r event-re
196 This will cause all events that match the option to print its raw
197 fields. The event-re is a regular expression as defined by
198 regcomp(3).
199 -l
201 This adds a "latency output" format. Information about interrupts
202 being disabled, soft irq being disabled, the "need_resched" flag
203 being set, preempt count, and big kernel lock are all being
204 recorded with every event. But the default display does not show
205 this information. This option will set display this information
206 with 6 characters. When one of the fields is zero or N/A a '.\' is
207 shown.
208 <idle>-0 0d.h1. 106467.859747: function: ktime_get <-- tick_check_idle
210 The 0d.h1. denotes this information.
212 It starts with a number. This represents the CPU number that the event occurred
214 on.
215 The second character is one of the following:
217 'd' - Interrupts are disabled
219 '.' - Interrupts are enabled
220 'X' - Has flags that are not yet known by trace-cmd
221 The third character is the "need rescheduling" flag.
223 'N' - A schedule is set to take place
225 '.' - No scheduling is set
226 The fourth character represents the context the event was in when it triggered
228 'h' - Hard interrupt context
230 's' - Soft interrupt context
231 'H' - Hard interrupt context that interrupted a soft interrupt
232 '.' - Normal context
233 The next is a number (should be less than 10), that represents the preemption
235 depth (the number of times preempt_disable() is called without preempt_enable()).
236 '.' means preemption is enabled.
237 On some systems, "migrate disable" may exist, in which case a number will be
239 shown for that, or '.' meaning migration is enabled.
240 If lockdep in enabled on the system, then the number represents the depth of
242 locks that are held when the event triggered. '.' means no locks are held.
243 -w
245 If both the sched_switch and sched_wakeup events are enabled, then
246 this option will report the latency between the time the task was
247 first woken, and the time it was scheduled in.
248 -q
250 Quiet non critical warnings.
251 -O
253 Pass options to the trace-cmd plugins that are loaded.
254 -O plugin:var=value
256 The 'plugin:' and '=value' are optional. Value may be left off for options
258 that are boolean. If the 'plugin:' is left off, then any variable that matches
259 in all plugins will be set.
260 Example: -O fgraph:tailprint
262 --cpu <cpu list>
264 List of CPUs, separated by "," or ":", used for filtering the
265 events. A range of CPUs can be specified using "cpuX-cpuY"
266 notation, where all CPUs in the range between cpuX and cpuY will be
267 included in the list. The order of CPUs in the list must be from
268 lower to greater.
269 Example: "--cpu 0,3" - show events from CPUs 0 and 3
271 "--cpu 2-4" - show events from CPUs 2, 3 and 4
272 --cpus
274 List the CPUs that have data in the trace file then exit.
275 --first-event
277 Show the timestamp of the first event of all CPUs that have data.
278 --last-event
280 Show the timestamp of the last event of all CPUs that have data.
281 --stat
283 If the trace.dat file recorded the final stats (outputed at the end
284 of record) the --stat option can be used to retrieve them.
285 --uname
287 If the trace.dat file recorded uname during the run, this will
288 retrieve that information.
289 --version
291 If the trace.dat file recorded the version of the executable used
292 to create it, report that version.
293 --ts-offset offset
295 Add (or subtract if negative) an offset for all timestamps of the
296 previous data file specified with -i. This is useful to merge sort
297 multiple trace.dat files where the difference in the timestamp is
298 known. For example if a trace is done on a virtual guest, and
299 another trace is done on the host. If the host timestamp is 1000
300 units ahead of the guest, the following can be done:
301 trace-cmd report -i host.dat --ts-offset -1000 -i guest.dat
303 This will subtract 1000 timestamp units from all the host events as it merges
305 with the guest.dat events. Note, the units is for the raw units recorded in
306 the trace. If the units are nanoseconds, the addition (or subtraction) from
307 the offset will be nanoseconds even if the displayed units are microseconds.
308 --ts2secs HZ
310 Convert the current clock source into a second (nanosecond
311 resolution) output. When using clocks like x86-tsc, if the
312 frequency is known, by passing in the clock frequency, this will
313 convert the time to seconds.
314 This option affects any trace.dat file given with *-i* proceeding it.
316 If this option comes before any *-i* option, then that value becomes
317 the default conversion for all other trace.dat files. If another
318 --ts2secs option appears after a *-i* trace.dat file, than that option
319 will override the default value.
320 Example: On a 3.4 GHz machine
322 trace-cmd record -p function -C x86-tsc
324 trace-cmd report --ts2ns 3400000000
326 The report will convert the cycles timestamps into a readable second
328 display. The default display resolution is microseconds, unless *-t*
329 is used.
330 The value of --ts-offset must still be in the raw timestamp units, even
332 with this option. The offset will be converted as well.
333 --ts-diff
335 Show the time differences between events. The difference will
336 appear in parenthesis just after the timestamp.
337 --ts-check
339 Make sure no timestamp goes backwards, and if it does, print out a
340 warning message of the fact.
341 --nodate
343 Ignore converting the timestamps to the date set by trace-cmd
344 record(3) --date option.
345 --raw-ts
347 Display raw timestamps, without any corrections.
348 --align-ts
350 Display timestamps aligned to the first event.
351 --verbose[=level]
353 Set the log level. Supported log levels are "none", "crit", "err",
354 "warn", "info", "debug", "all" or their identifiers "0", "1", "2",
355 "3", "4", "5", "6". Setting the log level to specific value enables
356 all logs from that and all previous levels. The level will default
357 to "info" if one is not specified.
358 Example: enable all critical, error and warning logs
360 trace-cmd report --verbose=warning
362
364 Using a trace.dat file that was created with:
365 # trace-cmd record -p function -e all sleep 5
367 The default report shows:
369 # trace-cmd report
371 trace-cmd-16129 [002] 158126.498411: function: __mutex_unlock_slowpath <-- mutex_unlock
372 trace-cmd-16131 [000] 158126.498411: kmem_cache_alloc: call_site=811223c5 ptr=0xffff88003ecf2b40 bytes_req=272 bytes_alloc=320 gfp_flags=GFP_KERNEL|GFP_ZERO
373 trace-cmd-16130 [003] 158126.498411: function: do_splice_to <-- sys_splice
374 sleep-16133 [001] 158126.498412: function: inotify_inode_queue_event <-- vfs_write
375 trace-cmd-16129 [002] 158126.498420: lock_release: 0xffff88003f1fa4f8 &sb->s_type->i_mutex_key
376 trace-cmd-16131 [000] 158126.498421: function: security_file_alloc <-- get_empty_filp
377 sleep-16133 [001] 158126.498422: function: __fsnotify_parent <-- vfs_write
378 trace-cmd-16130 [003] 158126.498422: function: rw_verify_area <-- do_splice_to
379 trace-cmd-16131 [000] 158126.498424: function: cap_file_alloc_security <-- security_file_alloc
380 trace-cmd-16129 [002] 158126.498425: function: syscall_trace_leave <-- int_check_syscall_exit_work
381 sleep-16133 [001] 158126.498426: function: inotify_dentry_parent_queue_event <-- vfs_write
382 trace-cmd-16130 [003] 158126.498426: function: security_file_permission <-- rw_verify_area
383 trace-cmd-16129 [002] 158126.498428: function: audit_syscall_exit <-- syscall_trace_leave
384 [...]
385 To see everything but the function traces:
387 # trace-cmd report -v -F 'function'
389 trace-cmd-16131 [000] 158126.498411: kmem_cache_alloc: call_site=811223c5 ptr=0xffff88003ecf2b40 bytes_req=272 bytes_alloc=320 gfp_flags=GFP_KERNEL|GFP_ZERO
390 trace-cmd-16129 [002] 158126.498420: lock_release: 0xffff88003f1fa4f8 &sb->s_type->i_mutex_key
391 trace-cmd-16130 [003] 158126.498436: lock_acquire: 0xffffffff8166bf78 read all_cpu_access_lock
392 trace-cmd-16131 [000] 158126.498438: lock_acquire: 0xffff88003df5b520 read &fs->lock
393 trace-cmd-16129 [002] 158126.498446: kfree: call_site=810a7abb ptr=0x0
394 trace-cmd-16130 [003] 158126.498448: lock_acquire: 0xffff880002250a80 &per_cpu(cpu_access_lock, cpu)
395 trace-cmd-16129 [002] 158126.498450: sys_exit_splice: 0xfffffff5
396 trace-cmd-16131 [000] 158126.498454: lock_release: 0xffff88003df5b520 &fs->lock
397 sleep-16133 [001] 158126.498456: kfree: call_site=810a7abb ptr=0x0
398 sleep-16133 [001] 158126.498460: sys_exit_write: 0x1
399 trace-cmd-16130 [003] 158126.498462: kmalloc: call_site=810bf95b ptr=0xffff88003dedc040 bytes_req=24 bytes_alloc=32 gfp_flags=GFP_KERNEL|GFP_ZERO
400 To see only the kmalloc calls that were greater than 1000 bytes:
402 #trace-cmd report -F 'kmalloc: bytes_req > 1000'
404 <idle>-0 [000] 158128.126641: kmalloc: call_site=81330635 ptr=0xffff88003c2fd000 bytes_req=2096 bytes_alloc=4096 gfp_flags=GFP_ATOMIC
405 To see wakeups and sched switches that left the previous task in the
407 running state:
408 # trace-cmd report -F 'sched: prev_state == 0 || (success == 1)'
410 trace-cmd-16132 [002] 158126.499951: sched_wakeup: comm=trace-cmd pid=16129 prio=120 success=1 target_cpu=002
411 trace-cmd-16132 [002] 158126.500401: sched_switch: prev_comm=trace-cmd prev_pid=16132 prev_prio=120 prev_state=R ==> next_comm=trace-cmd next_pid=16129 next_prio=120
412 <idle>-0 [003] 158126.500585: sched_wakeup: comm=trace-cmd pid=16130 prio=120 success=1 target_cpu=003
413 <idle>-0 [003] 158126.501241: sched_switch: prev_comm=swapper prev_pid=0 prev_prio=120 prev_state=R ==> next_comm=trace-cmd next_pid=16130 next_prio=120
414 trace-cmd-16132 [000] 158126.502475: sched_wakeup: comm=trace-cmd pid=16131 prio=120 success=1 target_cpu=000
415 trace-cmd-16131 [002] 158126.506516: sched_wakeup: comm=trace-cmd pid=16129 prio=120 success=1 target_cpu=002
416 <idle>-0 [003] 158126.550110: sched_switch: prev_comm=swapper prev_pid=0 prev_prio=120 prev_state=R ==> next_comm=trace-cmd next_pid=16130 next_prio=120
417 trace-cmd-16131 [003] 158126.570243: sched_wakeup: comm=trace-cmd pid=16129 prio=120 success=1 target_cpu=003
418 trace-cmd-16130 [002] 158126.618202: sched_switch: prev_comm=trace-cmd prev_pid=16130 prev_prio=120 prev_state=R ==> next_comm=yum-updatesd next_pid=3088 next_prio=1 20
419 trace-cmd-16129 [003] 158126.622379: sched_wakeup: comm=trace-cmd pid=16131 prio=120 success=1 target_cpu=003
420 trace-cmd-16129 [000] 158126.649287: sched_wakeup: comm=trace-cmd pid=16131 prio=120 success=1 target_cpu=000
421 The above needs a little explanation. The filter specifies the "sched"
423 subsystem, which includes both sched_switch and sched_wakeup events.
424 Any event that does not have the format field "prev_state" or
425 "success", will evaluate those expressions as FALSE, and will not
426 produce a match. Using "||" will have the "prev_state" test happen for
427 the "sched_switch" event and the "success" test happen for the
428 "sched_wakeup" event.
429 # trace-cmd report -w -F 'sched_switch, sched_wakeup.*'
431 [...]
432 trace-cmd-16130 [003] 158131.580616: sched_wakeup: comm=trace-cmd pid=16131 prio=120 success=1 target_cpu=003
433 trace-cmd-16129 [000] 158131.581502: sched_switch: prev_comm=trace-cmd prev_pid=16129 prev_prio=120 prev_state=S ==> next_comm=trace-cmd next_pid=16131 next_prio=120 Latency: 885.901 usecs
434 trace-cmd-16131 [000] 158131.582414: sched_wakeup: comm=trace-cmd pid=16129 prio=120 success=1 target_cpu=000
435 trace-cmd-16132 [001] 158131.583219: sched_switch: prev_comm=trace-cmd prev_pid=16132 prev_prio=120 prev_state=S ==> next_comm=trace-cmd next_pid=16129 next_prio=120 Latency: 804.809 usecs
436 sleep-16133 [002] 158131.584121: sched_wakeup: comm=trace-cmd pid=16120 prio=120 success=1 target_cpu=002
437 trace-cmd-16129 [001] 158131.584128: sched_wakeup: comm=trace-cmd pid=16132 prio=120 success=1 target_cpu=001
438 sleep-16133 [002] 158131.584275: sched_switch: prev_comm=sleep prev_pid=16133 prev_prio=120 prev_state=R ==> next_comm=trace-cmd next_pid=16120 next_prio=120 Latency: 153.915 usecs
439 trace-cmd-16130 [003] 158131.585284: sched_switch: prev_comm=trace-cmd prev_pid=16130 prev_prio=120 prev_state=S ==> next_comm=trace-cmd next_pid=16132 next_prio=120 Latency: 1155.677 usecs
440 Average wakeup latency: 26626.656 usecs
442 The above trace produces the wakeup latencies of the tasks. The
444 "sched_switch" event reports each individual latency after writing the
445 event information. At the end of the report, the average wakeup latency
446 is reported.
447 # trace-cmd report -w -F 'sched_switch, sched_wakeup.*: prio < 100 || next_prio < 100'
449 <idle>-0 [003] 158131.516753: sched_wakeup: comm=ksoftirqd/3 pid=13 prio=49 success=1 target_cpu=003
450 <idle>-0 [003] 158131.516855: sched_switch: prev_comm=swapper prev_pid=0 prev_prio=120 prev_state=R ==> next_comm=ksoftirqd/3 next_pid=13 next_prio=49 Latency: 101.244 usecs
451 <idle>-0 [003] 158131.533781: sched_wakeup: comm=ksoftirqd/3 pid=13 prio=49 success=1 target_cpu=003
452 <idle>-0 [003] 158131.533897: sched_switch: prev_comm=swapper prev_pid=0 prev_prio=120 prev_state=R ==> next_comm=ksoftirqd/3 next_pid=13 next_prio=49 Latency: 115.608 usecs
453 <idle>-0 [003] 158131.569730: sched_wakeup: comm=ksoftirqd/3 pid=13 prio=49 success=1 target_cpu=003
454 <idle>-0 [003] 158131.569851: sched_switch: prev_comm=swapper prev_pid=0 prev_prio=120 prev_state=R ==> next_comm=ksoftirqd/3 next_pid=13 next_prio=49 Latency: 121.024 usecs
455 Average wakeup latency: 110.021 usecs
457 The above version will only show the wakeups and context switches of
459 Real Time tasks. The prio used inside the kernel starts at 0 for
460 highest priority. That is prio 0 is equivalent to user space real time
461 priority 99, and priority 98 is equivalent to user space real time
462 priority 1. Prios less than 100 represent Real Time tasks.
463 An example of the profile:
465 # trace-cmd record --profile sleep 1
467 # trace-cmd report --profile --comm sleep
468 task: sleep-21611
469 Event: sched_switch:R (1) Total: 99442 Avg: 99442 Max: 99442 Min:99442
470 <stack> 1 total:99442 min:99442 max:99442 avg=99442
471 => ftrace_raw_event_sched_switch (0xffffffff8105f812)
472 => __schedule (0xffffffff8150810a)
473 => preempt_schedule (0xffffffff8150842e)
474 => ___preempt_schedule (0xffffffff81273354)
475 => cpu_stop_queue_work (0xffffffff810b03c5)
476 => stop_one_cpu (0xffffffff810b063b)
477 => sched_exec (0xffffffff8106136d)
478 => do_execve_common.isra.27 (0xffffffff81148c89)
479 => do_execve (0xffffffff811490b0)
480 => SyS_execve (0xffffffff811492c4)
481 => return_to_handler (0xffffffff8150e3c8)
482 => stub_execve (0xffffffff8150c699)
483 Event: sched_switch:S (1) Total: 1000506680 Avg: 1000506680 Max: 1000506680 Min:1000506680
484 <stack> 1 total:1000506680 min:1000506680 max:1000506680 avg=1000506680
485 => ftrace_raw_event_sched_switch (0xffffffff8105f812)
486 => __schedule (0xffffffff8150810a)
487 => schedule (0xffffffff815084b8)
488 => do_nanosleep (0xffffffff8150b22c)
489 => hrtimer_nanosleep (0xffffffff8108d647)
490 => SyS_nanosleep (0xffffffff8108d72c)
491 => return_to_handler (0xffffffff8150e3c8)
492 => tracesys_phase2 (0xffffffff8150c304)
493 Event: sched_wakeup:21611 (1) Total: 30326 Avg: 30326 Max: 30326 Min:30326
494 <stack> 1 total:30326 min:30326 max:30326 avg=30326
495 => ftrace_raw_event_sched_wakeup_template (0xffffffff8105f653)
496 => ttwu_do_wakeup (0xffffffff810606eb)
497 => ttwu_do_activate.constprop.124 (0xffffffff810607c8)
498 => try_to_wake_up (0xffffffff8106340a)
499
501 trace-cmd(1), trace-cmd-record(1), trace-cmd-start(1),
502 trace-cmd-stop(1), trace-cmd-extract(1), trace-cmd-reset(1),
503 trace-cmd-split(1), trace-cmd-list(1), trace-cmd-listen(1),
504 trace-cmd-profile(1)
505
507 Written by Steven Rostedt, <rostedt@goodmis.org[1]>
508
510 https://git.kernel.org/pub/scm/utils/trace-cmd/trace-cmd.git/
511
513 Copyright (C) 2010 Red Hat, Inc. Free use of this software is granted
514 under the terms of the GNU Public License (GPL).
515
517 1. rostedt@goodmis.org
518 mailto:rostedt@goodmis.org
519libtracefs 10/11/2022 TRACE-CMD-REPORT(1)