1TRACE-CMD-REPORT(1)                                        TRACE-CMD-REPORT(1)
2
3
4

NAME

6       trace-cmd-report - show in ASCII a trace created by trace-cmd record
7

SYNOPSIS

9       trace-cmd report [OPTIONS] [input-file]
10

DESCRIPTION

12       The trace-cmd(1) report command will output a human readable report of
13       a trace created by trace-cmd record.
14

OPTIONS

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
21       -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
26       -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
32       -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
37       -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
41       --events
42           This will list the event formats that are stored in the trace.dat
43           file.
44
45       --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
51               trace-cmd report --event sys:read
52
53               The above will only match events where the system name contains "sys"
54               and the event name contains "read".
55
56               trace-cmd report --event read
57
58               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
61       --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
66       -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
72       -F filter
73           Add a filter to limit what events are displayed. The format of the
74           filter is:
75
76               <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
84           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
89           Whitespace is ignored, such that "sched:next_pid==123" is equivalent to
90           "sched : next_pid == 123".
91
92           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
96           The representation of a SYSTEM or EVENT may also be a regular expression
97           as defined by 'regcomp(3)'.
98
99           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
103               -F 'sched : bogus == 1 || common_pid == 2'
104
105           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
110           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
119               -F 'sched/sched_switch : prev_state==0'
120
121           Although the output displays 'R', having 'prev_stat=="R"' will not work.
122
123           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
127               -F '.*:COMM != "trace-cmd"'
128
129       -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
136       -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
140       -v
141           This causes the following filters of -F to filter out the matching
142           events.
143
144               -v -F 'sched/sched_switch : prev_state == 0'
145
146           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
149       -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
157       -V
158           Show the plugins that are loaded.
159
160       -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
164       -N
165           This will not load any plugins.
166
167       -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
173       --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
179               See trace-cmd-profile(1) for more details and examples.
180
181       -G
182           Set interrupt (soft and hard) events as global (associated to CPU
183           instead of tasks). Only works for --profile.
184
185       -H event-hooks
186           Add custom event matching to connect any two events together.
187
188               See trace-cmd-profile(1) for format.
189
190       -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
195       -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
200       -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
209                 <idle>-0       0d.h1. 106467.859747: function:             ktime_get <-- tick_check_idle
210
211           The 0d.h1. denotes this information. The first character is never a '.'
212           and represents what CPU the trace was recorded on (CPU 0). The 'd' denotes
213           that interrupts were disabled. The 'h' means that this was called inside
214           an interrupt handler. The '1' is the preemption disabled (preempt_count)
215           was set to one.  The two '.'s are "need_resched" flag and kernel lock
216           counter.  If the "need_resched" flag is set, then that character would be a
217           'N'.
218
219       -w
220           If both the sched_switch and sched_wakeup events are enabled, then
221           this option will report the latency between the time the task was
222           first woken, and the time it was scheduled in.
223
224       -q
225           Quiet non critical warnings.
226
227       -O
228           Pass options to the trace-cmd plugins that are loaded.
229
230               -O plugin:var=value
231
232               The 'plugin:' and '=value' are optional. Value may be left off for options
233               that are boolean. If the 'plugin:' is left off, then any variable that matches
234               in all plugins will be set.
235
236               Example:  -O fgraph:tailprint
237
238       --cpu <cpu list>
239           List of CPUs, separated by "," or ":", used for filtering the
240           events. A range of CPUs can be specified using "cpuX-cpuY"
241           notation, where all CPUs in the range between cpuX and cpuY will be
242           included in the list. The order of CPUs in the list must be from
243           lower to greater.
244
245               Example:  "--cpu 0,3" - show events from CPUs 0 and 3
246                         "--cpu 2-4" - show events from CPUs 2, 3 and 4
247
248       --stat
249           If the trace.dat file recorded the final stats (outputed at the end
250           of record) the --stat option can be used to retrieve them.
251
252       --uname
253           If the trace.dat file recorded uname during the run, this will
254           retrieve that information.
255
256       --version
257           If the trace.dat file recorded the version of the executable used
258           to create it, report that version.
259
260       --ts-offset offset
261           Add (or subtract if negative) an offset for all timestamps of the
262           previous data file specified with -i. This is useful to merge sort
263           multiple trace.dat files where the difference in the timestamp is
264           known. For example if a trace is done on a virtual guest, and
265           another trace is done on the host. If the host timestamp is 1000
266           units ahead of the guest, the following can be done:
267
268               trace-cmd report -i host.dat --ts-offset -1000 -i guest.dat
269
270               This will subtract 1000 timestamp units from all the host events as it merges
271               with the guest.dat events. Note, the units is for the raw units recorded in
272               the trace. If the units are nanoseconds, the addition (or subtraction) from
273               the offset will be nanoseconds even if the displayed units are microseconds.
274
275       --ts2secs HZ
276           Convert the current clock source into a second (nanosecond
277           resolution) output. When using clocks like x86-tsc, if the
278           frequency is known, by passing in the clock frequency, this will
279           convert the time to seconds.
280
281               This option affects any trace.dat file given with *-i* proceeding it.
282               If this option comes before any *-i* option, then that value becomes
283               the default conversion for all other trace.dat files. If another
284               --ts2secs option appears after a *-i* trace.dat file, than that option
285               will override the default value.
286
287               Example: On a 3.4 GHz machine
288
289               trace-cmd record -p function -C x86-tsc
290
291               trace-cmd report --ts2ns 3400000000
292
293               The report will convert the cycles timestamps into a readable second
294               display. The default display resolution is microseconds, unless *-t*
295               is used.
296
297               The value of --ts-offset must still be in the raw timestamp units, even
298               with this option. The offset will be converted as well.
299
300       --ts-diff
301           Show the time differences between events. The difference will
302           appear in parenthesis just after the timestamp.
303
304       --ts-check
305           Make sure no timestamp goes backwards, and if it does, print out a
306           warning message of the fact.
307

EXAMPLES

309       Using a trace.dat file that was created with:
310
311               # trace-cmd record -p function -e all sleep 5
312
313       The default report shows:
314
315            # trace-cmd report
316                  trace-cmd-16129 [002] 158126.498411: function: __mutex_unlock_slowpath <-- mutex_unlock
317                  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
318                  trace-cmd-16130 [003] 158126.498411: function:             do_splice_to <-- sys_splice
319                      sleep-16133 [001] 158126.498412: function: inotify_inode_queue_event <-- vfs_write
320                  trace-cmd-16129 [002] 158126.498420: lock_release: 0xffff88003f1fa4f8 &sb->s_type->i_mutex_key
321                  trace-cmd-16131 [000] 158126.498421: function: security_file_alloc <-- get_empty_filp
322                      sleep-16133 [001] 158126.498422: function: __fsnotify_parent <-- vfs_write
323                  trace-cmd-16130 [003] 158126.498422: function: rw_verify_area <-- do_splice_to
324                  trace-cmd-16131 [000] 158126.498424: function: cap_file_alloc_security <-- security_file_alloc
325                  trace-cmd-16129 [002] 158126.498425: function: syscall_trace_leave <-- int_check_syscall_exit_work
326                      sleep-16133 [001] 158126.498426: function: inotify_dentry_parent_queue_event <-- vfs_write
327                  trace-cmd-16130 [003] 158126.498426: function: security_file_permission <-- rw_verify_area
328                  trace-cmd-16129 [002] 158126.498428: function: audit_syscall_exit <-- syscall_trace_leave
329           [...]
330
331       To see everything but the function traces:
332
333            # trace-cmd report -v -F 'function'
334                  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
335                  trace-cmd-16129 [002] 158126.498420: lock_release: 0xffff88003f1fa4f8 &sb->s_type->i_mutex_key
336                  trace-cmd-16130 [003] 158126.498436: lock_acquire: 0xffffffff8166bf78 read all_cpu_access_lock
337                  trace-cmd-16131 [000] 158126.498438: lock_acquire: 0xffff88003df5b520 read &fs->lock
338                  trace-cmd-16129 [002] 158126.498446: kfree: call_site=810a7abb ptr=0x0
339                  trace-cmd-16130 [003] 158126.498448: lock_acquire: 0xffff880002250a80 &per_cpu(cpu_access_lock, cpu)
340                  trace-cmd-16129 [002] 158126.498450: sys_exit_splice:      0xfffffff5
341                  trace-cmd-16131 [000] 158126.498454: lock_release: 0xffff88003df5b520 &fs->lock
342                      sleep-16133 [001] 158126.498456: kfree: call_site=810a7abb ptr=0x0
343                      sleep-16133 [001] 158126.498460: sys_exit_write:       0x1
344                  trace-cmd-16130 [003] 158126.498462: kmalloc: call_site=810bf95b ptr=0xffff88003dedc040 bytes_req=24 bytes_alloc=32 gfp_flags=GFP_KERNEL|GFP_ZERO
345
346       To see only the kmalloc calls that were greater than 1000 bytes:
347
348            #trace-cmd report -F 'kmalloc: bytes_req > 1000'
349                     <idle>-0     [000] 158128.126641: kmalloc: call_site=81330635 ptr=0xffff88003c2fd000 bytes_req=2096 bytes_alloc=4096 gfp_flags=GFP_ATOMIC
350
351       To see wakeups and sched switches that left the previous task in the
352       running state:
353
354            # trace-cmd report -F 'sched: prev_state == 0 || (success == 1)'
355                  trace-cmd-16132 [002] 158126.499951: sched_wakeup: comm=trace-cmd pid=16129 prio=120 success=1 target_cpu=002
356                  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
357                     <idle>-0     [003] 158126.500585: sched_wakeup: comm=trace-cmd pid=16130 prio=120 success=1 target_cpu=003
358                     <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
359                  trace-cmd-16132 [000] 158126.502475: sched_wakeup: comm=trace-cmd pid=16131 prio=120 success=1 target_cpu=000
360                  trace-cmd-16131 [002] 158126.506516: sched_wakeup: comm=trace-cmd pid=16129 prio=120 success=1 target_cpu=002
361                     <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
362                  trace-cmd-16131 [003] 158126.570243: sched_wakeup: comm=trace-cmd pid=16129 prio=120 success=1 target_cpu=003
363                  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
364                  trace-cmd-16129 [003] 158126.622379: sched_wakeup: comm=trace-cmd pid=16131 prio=120 success=1 target_cpu=003
365                  trace-cmd-16129 [000] 158126.649287: sched_wakeup: comm=trace-cmd pid=16131 prio=120 success=1 target_cpu=000
366
367       The above needs a little explanation. The filter specifies the "sched"
368       subsystem, which includes both sched_switch and sched_wakeup events.
369       Any event that does not have the format field "prev_state" or
370       "success", will evaluate those expressions as FALSE, and will not
371       produce a match. Using "||" will have the "prev_state" test happen for
372       the "sched_switch" event and the "success" test happen for the
373       "sched_wakeup" event.
374
375             # trace-cmd report -w -F 'sched_switch, sched_wakeup.*'
376           [...]
377                  trace-cmd-16130 [003] 158131.580616: sched_wakeup: comm=trace-cmd pid=16131 prio=120 success=1 target_cpu=003
378                  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
379                  trace-cmd-16131 [000] 158131.582414: sched_wakeup: comm=trace-cmd pid=16129 prio=120 success=1 target_cpu=000
380                  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
381                      sleep-16133 [002] 158131.584121: sched_wakeup: comm=trace-cmd pid=16120 prio=120 success=1 target_cpu=002
382                  trace-cmd-16129 [001] 158131.584128: sched_wakeup: comm=trace-cmd pid=16132 prio=120 success=1 target_cpu=001
383                      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
384                  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
385
386           Average wakeup latency: 26626.656 usecs
387
388       The above trace produces the wakeup latencies of the tasks. The
389       "sched_switch" event reports each individual latency after writing the
390       event information. At the end of the report, the average wakeup latency
391       is reported.
392
393             # trace-cmd report -w -F 'sched_switch, sched_wakeup.*: prio < 100 || next_prio < 100'
394                     <idle>-0     [003] 158131.516753: sched_wakeup: comm=ksoftirqd/3 pid=13 prio=49 success=1 target_cpu=003
395                     <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
396                     <idle>-0     [003] 158131.533781: sched_wakeup: comm=ksoftirqd/3 pid=13 prio=49 success=1 target_cpu=003
397                     <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
398                     <idle>-0     [003] 158131.569730: sched_wakeup: comm=ksoftirqd/3 pid=13 prio=49 success=1 target_cpu=003
399                     <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
400
401           Average wakeup latency: 110.021 usecs
402
403       The above version will only show the wakeups and context switches of
404       Real Time tasks. The prio used inside the kernel starts at 0 for
405       highest priority. That is prio 0 is equivalent to user space real time
406       priority 99, and priority 98 is equivalent to user space real time
407       priority 1. Prios less than 100 represent Real Time tasks.
408
409       An example of the profile:
410
411            # trace-cmd record --profile sleep 1
412            # trace-cmd report --profile --comm sleep
413           task: sleep-21611
414             Event: sched_switch:R (1) Total: 99442 Avg: 99442 Max: 99442 Min:99442
415                <stack> 1 total:99442 min:99442 max:99442 avg=99442
416                  => ftrace_raw_event_sched_switch (0xffffffff8105f812)
417                  => __schedule (0xffffffff8150810a)
418                  => preempt_schedule (0xffffffff8150842e)
419                  => ___preempt_schedule (0xffffffff81273354)
420                  => cpu_stop_queue_work (0xffffffff810b03c5)
421                  => stop_one_cpu (0xffffffff810b063b)
422                  => sched_exec (0xffffffff8106136d)
423                  => do_execve_common.isra.27 (0xffffffff81148c89)
424                  => do_execve (0xffffffff811490b0)
425                  => SyS_execve (0xffffffff811492c4)
426                  => return_to_handler (0xffffffff8150e3c8)
427                  => stub_execve (0xffffffff8150c699)
428             Event: sched_switch:S (1) Total: 1000506680 Avg: 1000506680 Max: 1000506680 Min:1000506680
429                <stack> 1 total:1000506680 min:1000506680 max:1000506680 avg=1000506680
430                  => ftrace_raw_event_sched_switch (0xffffffff8105f812)
431                  => __schedule (0xffffffff8150810a)
432                  => schedule (0xffffffff815084b8)
433                  => do_nanosleep (0xffffffff8150b22c)
434                  => hrtimer_nanosleep (0xffffffff8108d647)
435                  => SyS_nanosleep (0xffffffff8108d72c)
436                  => return_to_handler (0xffffffff8150e3c8)
437                  => tracesys_phase2 (0xffffffff8150c304)
438             Event: sched_wakeup:21611 (1) Total: 30326 Avg: 30326 Max: 30326 Min:30326
439                <stack> 1 total:30326 min:30326 max:30326 avg=30326
440                  => ftrace_raw_event_sched_wakeup_template (0xffffffff8105f653)
441                  => ttwu_do_wakeup (0xffffffff810606eb)
442                  => ttwu_do_activate.constprop.124 (0xffffffff810607c8)
443                  => try_to_wake_up (0xffffffff8106340a)
444

SEE ALSO

446       trace-cmd(1), trace-cmd-record(1), trace-cmd-start(1),
447       trace-cmd-stop(1), trace-cmd-extract(1), trace-cmd-reset(1),
448       trace-cmd-split(1), trace-cmd-list(1), trace-cmd-listen(1),
449       trace-cmd-profile(1)
450

AUTHOR

452       Written by Steven Rostedt, <rostedt@goodmis.org[1]>
453

RESOURCES

455       https://git.kernel.org/pub/scm/utils/trace-cmd/trace-cmd.git/
456

COPYING

458       Copyright (C) 2010 Red Hat, Inc. Free use of this software is granted
459       under the terms of the GNU Public License (GPL).
460

NOTES

462        1. rostedt@goodmis.org
463           mailto:rostedt@goodmis.org
464
465
466
467                                  07/23/2021               TRACE-CMD-REPORT(1)
Impressum