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 functions that have been recorded in the
28           file.
29
30       -P
31           This outputs the list of "trace_printk()" data. The raw trace data
32           points to static pointers in the kernel. This must be stored in the
33           trace.dat file.
34
35       -E
36           This lists the possible events in the file (but this list is not
37           necessarily the list of events in the file).
38
39       --events
40           This will list the event formats that are stored in the trace.dat
41           file.
42
43       --event regex
44           This will print events that match the given regex. If a colon is
45           specified, then the characters before the colon will be used to
46           match the system and the characters after the colon will match the
47           event.
48
49               trace-cmd report --event sys:read
50
51               The above will only match events where the system name contains "sys"
52               and the event name contains "read".
53
54               trace-cmd report --event read
55
56               The above will match all events that contain "read" in its name. Also it
57               may list all events of a system that contains "read" as well.
58
59       --check-events
60           This will parse the event format strings that are stored in the
61           trace.dat file and return whether the formats can be parsed
62           correctly. It will load plugins unless -N is specified.
63
64       -t
65           Print the full timestamp. The timestamps in the data file are
66           usually recorded to the nanosecond. But the default display of the
67           timestamp is only to the microsecond. To see the full timestamp,
68           add the -t option.
69
70       -F filter
71           Add a filter to limit what events are displayed. The format of the
72           filter is:
73
74               <events> ':' <filter>
75               <events> = SYSTEM'/'EVENT  | SYSTEM | EVENT | <events> ',' <events>
76               <filter> = EVENT_FIELD <op> <value> | <filter> '&&' <filter> |
77                          <filter> '||' <filter> | '(' <filter> ')' | '!' <filter>
78               <op> = '==' | '!=' | '>=' | '<=' | '>' | '<' | '&' | '|' | '^' |
79                      '+' | '-' | '*' | '/' | '%'
80               <value> = NUM | STRING | EVENT_FIELD
81
82           SYSTEM is the name of the system to filter on. If the EVENT is left out,
83           then it applies to all events under the SYSTEM. If only one string is used
84           without the '/' to deliminate between SYSTEM and EVENT, then the filter
85           will be applied to all systems and events that match the given string.
86
87           Whitespace is ignored, such that "sched:next_pid==123" is equivalent to
88           "sched : next_pid == 123".
89
90           STRING is defined with single or double quotes (single quote must end with
91           single quote, and double with double). Whitespace within quotes are not
92           ignored.
93
94           The representation of a SYSTEM or EVENT may also be a regular expression
95           as defined by 'regcomp(3)'.
96
97           The EVENT_FIELD is the name of the field of an event that is being
98           filtered. If the event does not contain the EVENT_FIELD, that part of the
99           equation will be considered false.
100
101               -F 'sched : bogus == 1 || common_pid == 2'
102
103           The "bogus == 1" will always evaluate to FALSE because no event has a
104           field called "bogus", but the "common_pid == 2" will still be evaluated
105           since all events have the field "common_pid". Any "sched" event that was
106           traced by the process with the PID of 2 will be shown.
107
108           Note, the EVENT_FIELD is the field name as shown by an events format
109           (as displayed with *--events*), and not what is found in the output.
110           If the output shows "ID:foo" but the field that "foo" belongs to was
111           called "name" in the event format, then "name" must be used in the filter.
112           The same is true about values. If the value that is displayed is converted
113           by to a string symbol, the filter checks the original value and not the
114           value displayed. For example, to filter on all tasks that were in the
115           running state at a context switch:
116
117               -F 'sched/sched_switch : prev_state==0'
118
119           Although the output displays 'R', having 'prev_stat=="R"' will not work.
120
121           Note: You can also specify 'COMM' as an EVENT_FIELD. This will use the
122           task name (or comm) of the record to compare. For example, to filter out
123           all of the "trace-cmd" tasks:
124
125               -F '.*:COMM != "trace-cmd"'
126
127       -I
128           Do not print events where the HARDIRQ latency flag is set. This
129           will filter out most events that are from interrupt context. Note,
130           it may not filter out function traced functions that are in
131           interrupt context but were called before the kernel "in interrupt"
132           flag was set.
133
134       -S
135           Do not print events where the SOFTIRQ latency flag is set. This
136           will filter out most events that are from soft interrupt context.
137
138       -v
139           This causes the following filters of -F to filter out the matching
140           events.
141
142               -v -F 'sched/sched_switch : prev_state == 0'
143
144           Will not display any sched_switch events that have a prev_state of 0.
145           Removing the *-v* will only print out those events.
146
147       -T
148           Test the filters of -F. After processing a filter string, the
149           resulting filter will be displayed for each event. This is useful
150           for using a filter for more than one event where a field may not
151           exist in all events. Also it can be used to make sure there are no
152           misspelled event field names, as they will simply be ignored.  -T
153           is ignored if -F is not specified.
154
155       -V
156           Show the plugins that are loaded.
157
158       -L
159           This will not load system wide plugins. It loads "local only". That
160           is what it finds in the ~/.trace-cmd/plugins directory.
161
162       -N
163           This will not load any plugins.
164
165       -n event-re
166           This will cause all events that match the option to ignore any
167           registered handler (by the plugins) to print the event. The normal
168           event will be printed instead. The event-re is a regular expression
169           as defined by regcomp(3).
170
171       --profile
172           With the --profile option, "trace-cmd report" will process all the
173           events first, and then output a format showing where tasks have
174           spent their time in the kernel, as well as where they are blocked
175           the most, and where wake up latencies are.
176
177               See trace-cmd-profile(1) for more details and examples.
178
179       -G
180           Set interrupt (soft and hard) events as global (associated to CPU
181           instead of tasks). Only works for --profile.
182
183       -H event-hooks
184           Add custom event matching to connect any two events together.
185
186               See trace-cmd-profile(1) for format.
187
188       -R
189           This will show the events in "raw" format. That is, it will ignore
190           the event’s print formatting and just print the contents of each
191           field.
192
193       -r event-re
194           This will cause all events that match the option to print its raw
195           fields. The event-re is a regular expression as defined by
196           regcomp(3).
197
198       -l
199           This adds a "latency output" format. Information about interrupts
200           being disabled, soft irq being disabled, the "need_resched" flag
201           being set, preempt count, and big kernel lock are all being
202           recorded with every event. But the default display does not show
203           this information. This option will set display this information
204           with 6 characters. When one of the fields is zero or N/A a '.\' is
205           shown.
206
207                 <idle>-0       0d.h1. 106467.859747: function:             ktime_get <-- tick_check_idle
208
209           The 0d.h1. denotes this information. The first character is never a '.'
210           and represents what CPU the trace was recorded on (CPU 0). The 'd' denotes
211           that interrupts were disabled. The 'h' means that this was called inside
212           an interrupt handler. The '1' is the preemption disabled (preempt_count)
213           was set to one.  The two '.'s are "need_resched" flag and kernel lock
214           counter.  If the "need_resched" flag is set, then that character would be a
215           'N'.
216
217       -w
218           If both the sched_switch and sched_wakeup events are enabled, then
219           this option will report the latency between the time the task was
220           first woken, and the time it was scheduled in.
221
222       -q
223           Quiet non critical warnings.
224
225       -O
226           Pass options to the trace-cmd plugins that are loaded.
227
228               -O plugin:var=value
229
230               The 'plugin:' and '=value' are optional. Value may be left off for options
231               that are boolean. If the 'plugin:' is left off, then any variable that matches
232               in all plugins will be set.
233
234               Example:  -O fgraph:tailprint
235
236       --stat
237           If the trace.dat file recorded the final stats (outputed at the end
238           of record) the --stat option can be used to retrieve them.
239
240       --uname
241           If the trace.dat file recorded uname during the run, this will
242           retrieve that information.
243
244       --ts-offset offset
245           Add (or subtract if negative) an offset for all timestamps of the
246           previous data file specified with -i. This is useful to merge sort
247           multiple trace.dat files where the difference in the timestamp is
248           known. For example if a trace is done on a virtual guest, and
249           another trace is done on the host. If the host timestamp is 1000
250           units ahead of the guest, the following can be done:
251
252               trace-cmd report -i host.dat --ts-offset -1000 -i guest.dat
253
254               This will subtract 1000 timestamp units from all the host events as it merges
255               with the guest.dat events. Note, the units is for the raw units recorded in
256               the trace. If the units are nanoseconds, the addition (or subtraction) from
257               the offset will be nanoseconds even if the displayed units are microseconds.
258
259       --ts2secs HZ
260           Convert the current clock source into a second (nanosecond
261           resolution) output. When using clocks like x86-tsc, if the
262           frequency is known, by passing in the clock frequency, this will
263           convert the time to seconds.
264
265               This option affects any trace.dat file given with *-i* proceeding it.
266               If this option comes before any *-i* option, then that value becomes
267               the default conversion for all other trace.dat files. If another
268               --ts2secs option appears after a *-i* trace.dat file, than that option
269               will override the default value.
270
271               Example: On a 3.4 GHz machine
272
273               trace-cmd record -p function -C x86-tsc
274
275               trace-cmd report --ts2ns 3400000000
276
277               The report will convert the cycles timestamps into a readable second
278               display. The default display resolution is microseconds, unless *-t*
279               is used.
280
281               The value of --ts-offset must still be in the raw timestamp units, even
282               with this option. The offset will be converted as well.
283
284       --ts-diff
285           Show the time differences between events. The difference will
286           appear in parenthesis just after the timestamp.
287

EXAMPLES

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

SEE ALSO

426       trace-cmd(1), trace-cmd-record(1), trace-cmd-start(1),
427       trace-cmd-stop(1), trace-cmd-extract(1), trace-cmd-reset(1),
428       trace-cmd-split(1), trace-cmd-list(1), trace-cmd-listen(1),
429       trace-cmd-profile(1)
430

AUTHOR

432       Written by Steven Rostedt, <rostedt@goodmis.org[1]>
433

RESOURCES

435       git://git.kernel.org/pub/scm/linux/kernel/git/rostedt/trace-cmd.git
436

COPYING

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

NOTES

442        1. rostedt@goodmis.org
443           mailto:rostedt@goodmis.org
444
445
446
447                                  05/11/2019               TRACE-CMD-REPORT(1)
Impressum