1TRACE-CMD-REPORT(1) 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 --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 trace-cmd report --event sys:read
50 The above will only match events where the system name contains "sys"
52 and the event name contains "read".
53 trace-cmd report --event read
55 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 --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 -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 -F filter
71 Add a filter to limit what events are displayed. The format of the
72 filter is:
73 <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 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 Whitespace is ignored, such that "sched:next_pid==123" is equivalent to
88 "sched : next_pid == 123".
89 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 The representation of a SYSTEM or EVENT may also be a regular expression
95 as defined by 'regcomp(3)'.
96 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 -F 'sched : bogus == 1 || common_pid == 2'
102 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 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 -F 'sched/sched_switch : prev_state==0'
118 Although the output displays 'R', having 'prev_stat=="R"' will not work.
120 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 -F '.*:COMM != "trace-cmd"'
126 -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 -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 -v
139 This causes the following filters of -F to filter out the matching
140 events.
141 -v -F 'sched/sched_switch : prev_state == 0'
143 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 -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 -V
156 Show the plugins that are loaded.
157 -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 -N
163 This will not load any plugins.
164 -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 --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 See trace-cmd-profile(1) for more details and examples.
178 -G
180 Set interrupt (soft and hard) events as global (associated to CPU
181 instead of tasks). Only works for --profile.
182 -H event-hooks
184 Add custom event matching to connect any two events together.
185 See trace-cmd-profile(1) for format.
187 -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 -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 -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 <idle>-0 0d.h1. 106467.859747: function: ktime_get <-- tick_check_idle
208 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 -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 -q
223 Quiet non critical warnings.
224 -O
226 Pass options to the trace-cmd plugins that are loaded.
227 -O plugin:var=value
229 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 Example: -O fgraph:tailprint
235 --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 --uname
241 If the trace.dat file recorded uname during the run, this will
242 retrieve that information.
243 --version
245 If the trace.dat file recorded the version of the executable used
246 to create it, report that version.
247 --ts-offset offset
249 Add (or subtract if negative) an offset for all timestamps of the
250 previous data file specified with -i. This is useful to merge sort
251 multiple trace.dat files where the difference in the timestamp is
252 known. For example if a trace is done on a virtual guest, and
253 another trace is done on the host. If the host timestamp is 1000
254 units ahead of the guest, the following can be done:
255 trace-cmd report -i host.dat --ts-offset -1000 -i guest.dat
257 This will subtract 1000 timestamp units from all the host events as it merges
259 with the guest.dat events. Note, the units is for the raw units recorded in
260 the trace. If the units are nanoseconds, the addition (or subtraction) from
261 the offset will be nanoseconds even if the displayed units are microseconds.
262 --ts2secs HZ
264 Convert the current clock source into a second (nanosecond
265 resolution) output. When using clocks like x86-tsc, if the
266 frequency is known, by passing in the clock frequency, this will
267 convert the time to seconds.
268 This option affects any trace.dat file given with *-i* proceeding it.
270 If this option comes before any *-i* option, then that value becomes
271 the default conversion for all other trace.dat files. If another
272 --ts2secs option appears after a *-i* trace.dat file, than that option
273 will override the default value.
274 Example: On a 3.4 GHz machine
276 trace-cmd record -p function -C x86-tsc
278 trace-cmd report --ts2ns 3400000000
280 The report will convert the cycles timestamps into a readable second
282 display. The default display resolution is microseconds, unless *-t*
283 is used.
284 The value of --ts-offset must still be in the raw timestamp units, even
286 with this option. The offset will be converted as well.
287 --ts-diff
289 Show the time differences between events. The difference will
290 appear in parenthesis just after the timestamp.
291
293 Using a trace.dat file that was created with:
294 # trace-cmd record -p function -e all sleep 5
296 The default report shows:
298 # trace-cmd report
300 trace-cmd-16129 [002] 158126.498411: function: __mutex_unlock_slowpath <-- mutex_unlock
301 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
302 trace-cmd-16130 [003] 158126.498411: function: do_splice_to <-- sys_splice
303 sleep-16133 [001] 158126.498412: function: inotify_inode_queue_event <-- vfs_write
304 trace-cmd-16129 [002] 158126.498420: lock_release: 0xffff88003f1fa4f8 &sb->s_type->i_mutex_key
305 trace-cmd-16131 [000] 158126.498421: function: security_file_alloc <-- get_empty_filp
306 sleep-16133 [001] 158126.498422: function: __fsnotify_parent <-- vfs_write
307 trace-cmd-16130 [003] 158126.498422: function: rw_verify_area <-- do_splice_to
308 trace-cmd-16131 [000] 158126.498424: function: cap_file_alloc_security <-- security_file_alloc
309 trace-cmd-16129 [002] 158126.498425: function: syscall_trace_leave <-- int_check_syscall_exit_work
310 sleep-16133 [001] 158126.498426: function: inotify_dentry_parent_queue_event <-- vfs_write
311 trace-cmd-16130 [003] 158126.498426: function: security_file_permission <-- rw_verify_area
312 trace-cmd-16129 [002] 158126.498428: function: audit_syscall_exit <-- syscall_trace_leave
313 [...]
314 To see everything but the function traces:
316 # trace-cmd report -v -F 'function'
318 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
319 trace-cmd-16129 [002] 158126.498420: lock_release: 0xffff88003f1fa4f8 &sb->s_type->i_mutex_key
320 trace-cmd-16130 [003] 158126.498436: lock_acquire: 0xffffffff8166bf78 read all_cpu_access_lock
321 trace-cmd-16131 [000] 158126.498438: lock_acquire: 0xffff88003df5b520 read &fs->lock
322 trace-cmd-16129 [002] 158126.498446: kfree: call_site=810a7abb ptr=0x0
323 trace-cmd-16130 [003] 158126.498448: lock_acquire: 0xffff880002250a80 &per_cpu(cpu_access_lock, cpu)
324 trace-cmd-16129 [002] 158126.498450: sys_exit_splice: 0xfffffff5
325 trace-cmd-16131 [000] 158126.498454: lock_release: 0xffff88003df5b520 &fs->lock
326 sleep-16133 [001] 158126.498456: kfree: call_site=810a7abb ptr=0x0
327 sleep-16133 [001] 158126.498460: sys_exit_write: 0x1
328 trace-cmd-16130 [003] 158126.498462: kmalloc: call_site=810bf95b ptr=0xffff88003dedc040 bytes_req=24 bytes_alloc=32 gfp_flags=GFP_KERNEL|GFP_ZERO
329 To see only the kmalloc calls that were greater than 1000 bytes:
331 #trace-cmd report -F 'kmalloc: bytes_req > 1000'
333 <idle>-0 [000] 158128.126641: kmalloc: call_site=81330635 ptr=0xffff88003c2fd000 bytes_req=2096 bytes_alloc=4096 gfp_flags=GFP_ATOMIC
334 To see wakeups and sched switches that left the previous task in the
336 running state:
337 # trace-cmd report -F 'sched: prev_state == 0 || (success == 1)'
339 trace-cmd-16132 [002] 158126.499951: sched_wakeup: comm=trace-cmd pid=16129 prio=120 success=1 target_cpu=002
340 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
341 <idle>-0 [003] 158126.500585: sched_wakeup: comm=trace-cmd pid=16130 prio=120 success=1 target_cpu=003
342 <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
343 trace-cmd-16132 [000] 158126.502475: sched_wakeup: comm=trace-cmd pid=16131 prio=120 success=1 target_cpu=000
344 trace-cmd-16131 [002] 158126.506516: sched_wakeup: comm=trace-cmd pid=16129 prio=120 success=1 target_cpu=002
345 <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
346 trace-cmd-16131 [003] 158126.570243: sched_wakeup: comm=trace-cmd pid=16129 prio=120 success=1 target_cpu=003
347 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
348 trace-cmd-16129 [003] 158126.622379: sched_wakeup: comm=trace-cmd pid=16131 prio=120 success=1 target_cpu=003
349 trace-cmd-16129 [000] 158126.649287: sched_wakeup: comm=trace-cmd pid=16131 prio=120 success=1 target_cpu=000
350 The above needs a little explanation. The filter specifies the "sched"
352 subsystem, which includes both sched_switch and sched_wakeup events.
353 Any event that does not have the format field "prev_state" or
354 "success", will evaluate those expressions as FALSE, and will not
355 produce a match. Using "||" will have the "prev_state" test happen for
356 the "sched_switch" event and the "success" test happen for the
357 "sched_wakeup" event.
358 # trace-cmd report -w -F 'sched_switch, sched_wakeup.*'
360 [...]
361 trace-cmd-16130 [003] 158131.580616: sched_wakeup: comm=trace-cmd pid=16131 prio=120 success=1 target_cpu=003
362 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
363 trace-cmd-16131 [000] 158131.582414: sched_wakeup: comm=trace-cmd pid=16129 prio=120 success=1 target_cpu=000
364 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
365 sleep-16133 [002] 158131.584121: sched_wakeup: comm=trace-cmd pid=16120 prio=120 success=1 target_cpu=002
366 trace-cmd-16129 [001] 158131.584128: sched_wakeup: comm=trace-cmd pid=16132 prio=120 success=1 target_cpu=001
367 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
368 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
369 Average wakeup latency: 26626.656 usecs
371 The above trace produces the wakeup latencies of the tasks. The
373 "sched_switch" event reports each individual latency after writing the
374 event information. At the end of the report, the average wakeup latency
375 is reported.
376 # trace-cmd report -w -F 'sched_switch, sched_wakeup.*: prio < 100 || next_prio < 100'
378 <idle>-0 [003] 158131.516753: sched_wakeup: comm=ksoftirqd/3 pid=13 prio=49 success=1 target_cpu=003
379 <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
380 <idle>-0 [003] 158131.533781: sched_wakeup: comm=ksoftirqd/3 pid=13 prio=49 success=1 target_cpu=003
381 <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
382 <idle>-0 [003] 158131.569730: sched_wakeup: comm=ksoftirqd/3 pid=13 prio=49 success=1 target_cpu=003
383 <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
384 Average wakeup latency: 110.021 usecs
386 The above version will only show the wakeups and context switches of
388 Real Time tasks. The prio used inside the kernel starts at 0 for
389 highest priority. That is prio 0 is equivalent to user space real time
390 priority 99, and priority 98 is equivalent to user space real time
391 priority 1. Prios less than 100 represent Real Time tasks.
392 An example of the profile:
394 # trace-cmd record --profile sleep 1
396 # trace-cmd report --profile --comm sleep
397 task: sleep-21611
398 Event: sched_switch:R (1) Total: 99442 Avg: 99442 Max: 99442 Min:99442
399 <stack> 1 total:99442 min:99442 max:99442 avg=99442
400 => ftrace_raw_event_sched_switch (0xffffffff8105f812)
401 => __schedule (0xffffffff8150810a)
402 => preempt_schedule (0xffffffff8150842e)
403 => ___preempt_schedule (0xffffffff81273354)
404 => cpu_stop_queue_work (0xffffffff810b03c5)
405 => stop_one_cpu (0xffffffff810b063b)
406 => sched_exec (0xffffffff8106136d)
407 => do_execve_common.isra.27 (0xffffffff81148c89)
408 => do_execve (0xffffffff811490b0)
409 => SyS_execve (0xffffffff811492c4)
410 => return_to_handler (0xffffffff8150e3c8)
411 => stub_execve (0xffffffff8150c699)
412 Event: sched_switch:S (1) Total: 1000506680 Avg: 1000506680 Max: 1000506680 Min:1000506680
413 <stack> 1 total:1000506680 min:1000506680 max:1000506680 avg=1000506680
414 => ftrace_raw_event_sched_switch (0xffffffff8105f812)
415 => __schedule (0xffffffff8150810a)
416 => schedule (0xffffffff815084b8)
417 => do_nanosleep (0xffffffff8150b22c)
418 => hrtimer_nanosleep (0xffffffff8108d647)
419 => SyS_nanosleep (0xffffffff8108d72c)
420 => return_to_handler (0xffffffff8150e3c8)
421 => tracesys_phase2 (0xffffffff8150c304)
422 Event: sched_wakeup:21611 (1) Total: 30326 Avg: 30326 Max: 30326 Min:30326
423 <stack> 1 total:30326 min:30326 max:30326 avg=30326
424 => ftrace_raw_event_sched_wakeup_template (0xffffffff8105f653)
425 => ttwu_do_wakeup (0xffffffff810606eb)
426 => ttwu_do_activate.constprop.124 (0xffffffff810607c8)
427 => try_to_wake_up (0xffffffff8106340a)
428
430 trace-cmd(1), trace-cmd-record(1), trace-cmd-start(1),
431 trace-cmd-stop(1), trace-cmd-extract(1), trace-cmd-reset(1),
432 trace-cmd-split(1), trace-cmd-list(1), trace-cmd-listen(1),
433 trace-cmd-profile(1)
434
436 Written by Steven Rostedt, <rostedt@goodmis.org[1]>
437
439 git://git.kernel.org/pub/scm/linux/kernel/git/rostedt/trace-cmd.git
440
442 Copyright (C) 2010 Red Hat, Inc. Free use of this software is granted
443 under the terms of the GNU Public License (GPL).
444
446 1. rostedt@goodmis.org
447 mailto:rostedt@goodmis.org
448 02/08/2020 TRACE-CMD-REPORT(1)