1TRACE-CMD-REPORT(1) [FIXME: 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 functions that have been recorded in the
28 file.
29 -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 -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 --events
40 This will list the event formats that are stored in the trace.dat
41 file.
42 --check-events
44 This will parse the event format strings that are stored in the
45 trace.dat file and return whether the formats can be parsed
46 correctly. It will load plugins unless -N is specified.
47 -t
49 Print the full timestamp. The timestamps in the data file are
50 usually recorded to the nanosecond. But the default display of the
51 timestamp is only to the microsecond. To see the full timestamp,
52 add the -t option.
53 -F filter
55 Add a filter to limit what events are displayed. The format of the
56 filter is:
57 <events> ´:´ <filter>
59 <events> = SYSTEM´/´EVENT | SYSTEM | EVENT | <events> ´,´ <events>
60 <filter> = EVENT_FIELD <op> <value> | <filter> ´&&´ <filter> |
61 <filter> ´||´ <filter> | ´(´ <filter> ´)´ | ´!´ <filter>
62 <op> = ´==´ | ´!=´ | ´>=´ | ´<=´ | ´>´ | ´<´ | ´&´ | ´|´ | ´^´ |
63 ´+´ | ´-´ | ´*´ | ´/´ | ´%´
64 <value> = NUM | STRING | EVENT_FIELD
65 SYSTEM is the name of the system to filter on. If the EVENT is left out,
67 then it applies to all events under the SYSTEM. If only one string is used
68 without the ´/´ to deliminate between SYSTEM and EVENT, then the filter
69 will be applied to all systems and events that match the given string.
70 Whitespace is ignored, such that "sched:next_pid==123" is equivalent to
72 "sched : next_pid == 123".
73 STRING is defined with single or double quotes (single quote must end with
75 single quote, and double with double). Whitespace within quotes are not
76 ignored.
77 The representation of a SYSTEM or EVENT may also be a regular expression
79 as defined by ´regcomp(3)´.
80 The EVENT_FIELD is the name of the field of an event that is being
82 filtered. If the event does not contain the EVENT_FIELD, that part of the
83 equation will be considered false.
84 -F ´sched : bogus == 1 || common_pid == 2´
86 The "bogus == 1" will always evaluate to FALSE because no event has a
88 field called "bogus", but the "common_pid == 2" will still be evaluated
89 since all events have the field "common_pid". Any "sched" event that was
90 traced by the process with the PID of 2 will be shown.
91 Note, the EVENT_FIELD is the field name as shown by an events format
93 (as displayed with *--events*), and not what is found in the output.
94 If the output shows "ID:foo" but the field that "foo" belongs to was
95 called "name" in the event format, then "name" must be used in the filter.
96 The same is true about values. If the value that is displayed is converted
97 by to a string symbol, the filter checks the original value and not the
98 value displayed. For example, to filter on all tasks that were in the
99 running state at a context switch:
100 -F ´sched/sched_switch : prev_state==0´
102 Although the output displays ´R´, having ´prev_stat=="R"´ will not work.
104 Note: You can also specify ´COMM´ as an EVENT_FIELD. This will use the
106 task name (or comm) of the record to compare. For example, to filter out
107 all of the "trace-cmd" tasks:
108 -F ´.*:COMM != "trace-cmd"´
110 -v
112 This causes the following filters of -F to filter out the matching
113 events.
114 -v -F ´sched/sched_switch : prev_state == 0´
116 Will not display any sched_switch events that have a prev_state of 0.
118 Removing the *-v* will only print out those events.
119 -T
121 Test the filters of -F. After processing a filter string, the
122 resulting filter will be displayed for each event. This is useful
123 for using a filter for more than one event where a field may not
124 exist in all events. Also it can be used to make sure there are no
125 misspelled event field names, as they will simply be ignored. -T
126 is ignored if -F is not specified.
127 -V
129 Show the plugins that are loaded.
130 -L
132 This will not load system wide plugins. It loads "local only". That
133 is what it finds in the ~/.trace-cmd/plugins directory.
134 -N
136 This will not load any plugins.
137 -n event-re
139 This will cause all events that match the option to ignore any
140 registered handler (by the plugins) to print the event. The normal
141 event will be printed instead. The event-re is a regular expression
142 as defined by regcomp(3).
143 -R
145 This will show the events in "raw" format. That is, it will ignore
146 the event’s print formatting and just print the contents of each
147 field.
148 -r event-re
150 This will cause all events that match the option to print its raw
151 fields. The event-re is a regular expression as defined by
152 regcomp(3).
153 -l
155 This adds a "latency output" format. Information about interrupts
156 being disabled, soft irq being disabled, the "need_resched" flag
157 being set, preempt count, and big kernel lock are all being
158 recorded with every event. But the default display does not show
159 this information. This option will set display this information
160 with 6 characters. When one of the fields is zero or N/A a ´.\´ is
161 shown.
162 <idle>-0 0d.h1. 106467.859747: function: ktime_get <-- tick_check_idle
164 The 0d.h1. denotes this information. The first character is never a ´.´
166 and represents what CPU the trace was recorded on (CPU 0). The ´d´ denotes
167 that interrupts were disabled. The ´h´ means that this was called inside
168 an interrupt handler. The ´1´ is the preemption disabled (preempt_count)
169 was set to one. The two ´.´s are "need_resched" flag and kernel lock
170 counter. If the "need_resched" flag is set, then that character would be a
171 ´N´.
172 -w
174 If both the sched_switch and sched_wakeup events are enabled, then
175 this option will report the latency between the time the task was
176 first woken, and the time it was scheduled in.
177 -q
179 Quiet non critical warnings.
180 -O
182 Pass options to the trace-cmd plugins that are loaded.
183 -O plugin:var=value
185 The ´plugin:´ and ´=value´ are optional. Value may be left off for options
187 that are boolean. If the ´plugin:´ is left off, then any variable that matches
188 in all plugins will be set.
189 Example: -O fgraph:tailprint
191 --stat
193 If the trace.dat file recorded the final stats (outputed at the end
194 of record) the --stat option can be used to retrieve them.
195
197 Using a trace.dat file that was created with:
198 # trace-cmd record -p function -e all sleep 5
200 The default report shows:
202 # trace-cmd report
204 trace-cmd-16129 [002] 158126.498411: function: __mutex_unlock_slowpath <-- mutex_unlock
205 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
206 trace-cmd-16130 [003] 158126.498411: function: do_splice_to <-- sys_splice
207 sleep-16133 [001] 158126.498412: function: inotify_inode_queue_event <-- vfs_write
208 trace-cmd-16129 [002] 158126.498420: lock_release: 0xffff88003f1fa4f8 &sb->s_type->i_mutex_key
209 trace-cmd-16131 [000] 158126.498421: function: security_file_alloc <-- get_empty_filp
210 sleep-16133 [001] 158126.498422: function: __fsnotify_parent <-- vfs_write
211 trace-cmd-16130 [003] 158126.498422: function: rw_verify_area <-- do_splice_to
212 trace-cmd-16131 [000] 158126.498424: function: cap_file_alloc_security <-- security_file_alloc
213 trace-cmd-16129 [002] 158126.498425: function: syscall_trace_leave <-- int_check_syscall_exit_work
214 sleep-16133 [001] 158126.498426: function: inotify_dentry_parent_queue_event <-- vfs_write
215 trace-cmd-16130 [003] 158126.498426: function: security_file_permission <-- rw_verify_area
216 trace-cmd-16129 [002] 158126.498428: function: audit_syscall_exit <-- syscall_trace_leave
217 [...]
218 To see everything but the function traces:
220 # trace-cmd report -v -F ´function´
222 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
223 trace-cmd-16129 [002] 158126.498420: lock_release: 0xffff88003f1fa4f8 &sb->s_type->i_mutex_key
224 trace-cmd-16130 [003] 158126.498436: lock_acquire: 0xffffffff8166bf78 read all_cpu_access_lock
225 trace-cmd-16131 [000] 158126.498438: lock_acquire: 0xffff88003df5b520 read &fs->lock
226 trace-cmd-16129 [002] 158126.498446: kfree: call_site=810a7abb ptr=0x0
227 trace-cmd-16130 [003] 158126.498448: lock_acquire: 0xffff880002250a80 &per_cpu(cpu_access_lock, cpu)
228 trace-cmd-16129 [002] 158126.498450: sys_exit_splice: 0xfffffff5
229 trace-cmd-16131 [000] 158126.498454: lock_release: 0xffff88003df5b520 &fs->lock
230 sleep-16133 [001] 158126.498456: kfree: call_site=810a7abb ptr=0x0
231 sleep-16133 [001] 158126.498460: sys_exit_write: 0x1
232 trace-cmd-16130 [003] 158126.498462: kmalloc: call_site=810bf95b ptr=0xffff88003dedc040 bytes_req=24 bytes_alloc=32 gfp_flags=GFP_KERNEL|GFP_ZERO
233 To see only the kmalloc calls that were greater than 1000 bytes:
235 #trace-cmd report -F ´kmalloc: bytes_req > 1000´
237 <idle>-0 [000] 158128.126641: kmalloc: call_site=81330635 ptr=0xffff88003c2fd000 bytes_req=2096 bytes_alloc=4096 gfp_flags=GFP_ATOMIC
238 To see wakeups and sched switches that left the previous task in the
240 running state:
241 # trace-cmd report -F ´sched: prev_state == 0 || (success == 1)´
243 trace-cmd-16132 [002] 158126.499951: sched_wakeup: comm=trace-cmd pid=16129 prio=120 success=1 target_cpu=002
244 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
245 <idle>-0 [003] 158126.500585: sched_wakeup: comm=trace-cmd pid=16130 prio=120 success=1 target_cpu=003
246 <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
247 trace-cmd-16132 [000] 158126.502475: sched_wakeup: comm=trace-cmd pid=16131 prio=120 success=1 target_cpu=000
248 trace-cmd-16131 [002] 158126.506516: sched_wakeup: comm=trace-cmd pid=16129 prio=120 success=1 target_cpu=002
249 <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
250 trace-cmd-16131 [003] 158126.570243: sched_wakeup: comm=trace-cmd pid=16129 prio=120 success=1 target_cpu=003
251 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
252 trace-cmd-16129 [003] 158126.622379: sched_wakeup: comm=trace-cmd pid=16131 prio=120 success=1 target_cpu=003
253 trace-cmd-16129 [000] 158126.649287: sched_wakeup: comm=trace-cmd pid=16131 prio=120 success=1 target_cpu=000
254 The above needs a little explanation. The filter specifies the "sched"
256 subsystem, which includes both sched_switch and sched_wakeup events.
257 Any event that does not have the format field "prev_state" or
258 "success", will evaluate those expressions as FALSE, and will not
259 produce a match. Using "||" will have the "prev_state" test happen for
260 the "sched_switch" event and the "success" test happen for the
261 "sched_wakeup" event.
262 # trace-cmd report -w -F ´sched_switch, sched_wakeup.*´
264 [...]
265 trace-cmd-16130 [003] 158131.580616: sched_wakeup: comm=trace-cmd pid=16131 prio=120 success=1 target_cpu=003
266 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
267 trace-cmd-16131 [000] 158131.582414: sched_wakeup: comm=trace-cmd pid=16129 prio=120 success=1 target_cpu=000
268 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
269 sleep-16133 [002] 158131.584121: sched_wakeup: comm=trace-cmd pid=16120 prio=120 success=1 target_cpu=002
270 trace-cmd-16129 [001] 158131.584128: sched_wakeup: comm=trace-cmd pid=16132 prio=120 success=1 target_cpu=001
271 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
272 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
273 Average wakeup latency: 26626.656 usecs
275 The above trace produces the wakeup latencies of the tasks. The
277 "sched_switch" event reports each individual latency after writing the
278 event information. At the end of the report, the average wakeup latency
279 is reported.
280 # trace-cmd report -w -F ´sched_switch, sched_wakeup.*: prio < 100 || next_prio < 100´
282 <idle>-0 [003] 158131.516753: sched_wakeup: comm=ksoftirqd/3 pid=13 prio=49 success=1 target_cpu=003
283 <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
284 <idle>-0 [003] 158131.533781: sched_wakeup: comm=ksoftirqd/3 pid=13 prio=49 success=1 target_cpu=003
285 <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
286 <idle>-0 [003] 158131.569730: sched_wakeup: comm=ksoftirqd/3 pid=13 prio=49 success=1 target_cpu=003
287 <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
288 Average wakeup latency: 110.021 usecs
290 The above version will only show the wakeups and context switches of
292 Real Time tasks. The prio used inside the kernel starts at 0 for
293 highest priority. That is prio 0 is equivalent to user space real time
294 priority 99, and priority 98 is equivalent to user space real time
295 priority 1. Prios less than 100 represent Real Time tasks.
296
298 trace-cmd(1), trace-cmd-record(1), trace-cmd-start(1),
299 trace-cmd-stop(1), trace-cmd-extract(1), trace-cmd-reset(1),
300 trace-cmd-split(1), trace-cmd-list(1), trace-cmd-listen(1)
301
303 Written by Steven Rostedt, <rostedt@goodmis.org[1]>
304
306 git://git.kernel.org/pub/scm/linux/kernel/git/rostedt/trace-cmd.git
307
309 Copyright (C) 2010 Red Hat, Inc. Free use of this software is granted
310 under the terms of the GNU Public License (GPL).
311
313 1. rostedt@goodmis.org
314 mailto:rostedt@goodmis.org
315[FIXME: source] 03/23/2017 TRACE-CMD-REPORT(1)