'\" t
.\" Title: trace-cmd-report
.\" Author: [see the "AUTHOR" section]
.\" Generator: DocBook XSL Stylesheets vsnapshot
.\" Date: 03/09/2026
.\" Manual: libtracefs Manual
.\" Source: libtracefs
.\" Language: English
.\"
.TH "TRACE\-CMD\-REPORT" "1" "03/09/2026" "libtracefs" "libtracefs Manual"
.\" -----------------------------------------------------------------
.\" * Define some portability stuff
.\" -----------------------------------------------------------------
.\" ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
.\" http://bugs.debian.org/507673
.\" http://lists.gnu.org/archive/html/groff/2009-02/msg00013.html
.\" ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
.ie \n(.g .ds Aq \(aq
.el .ds Aq '
.\" -----------------------------------------------------------------
.\" * set default formatting
.\" -----------------------------------------------------------------
.\" disable hyphenation
.nh
.\" disable justification (adjust text to left margin only)
.ad l
.\" -----------------------------------------------------------------
.\" * MAIN CONTENT STARTS HERE *
.\" -----------------------------------------------------------------
.SH "NAME"
trace-cmd-report \- show in ASCII a trace created by trace\-cmd record
.SH "SYNOPSIS"
.sp
\fBtrace\-cmd report\fR [\fIOPTIONS\fR] [\fIinput\-file\fR [\fIinput\-file\fR \&...]]
.SH "DESCRIPTION"
.sp
The trace\-cmd(1) report command will output a human readable report of a trace created by trace\-cmd record\&.
.SH "OPTIONS"
.PP
\fB\-i\fR \fIinput\-file\fR
.RS 4
By default, trace\-cmd report will read the file
\fItrace\&.dat\fR\&. But the
\fB\-i\fR
option open up the given
\fIinput\-file\fR
instead\&. Note, the input file may also be specified as the last item on the command line\&.
.RE
.PP
\fB\-e\fR
.RS 4
This outputs the endianess of the file\&. trace\-cmd report is smart enough to be able to read big endian files on little endian machines, and vise versa\&.
.RE
.PP
\fB\-f\fR
.RS 4
This outputs the list of all functions that have been mapped in the trace\&.dat file\&. Note, this list may contain functions that may not appear in the trace, as it is the list of mappings to translate function addresses into function names\&.
.RE
.PP
\fB\-P\fR
.RS 4
This outputs the list of "trace_printk()" data\&. The raw trace data points to static pointers in the kernel\&. This must be stored in the trace\&.dat file\&.
.RE
.PP
\fB\-E\fR
.RS 4
This lists the possible events in the file (but this list is not necessarily the list of events in the file)\&.
.RE
.PP
\fB\-\-events\fR
.RS 4
This will list the event formats that are stored in the trace\&.dat file\&.
.RE
.PP
\fB\-\-event\fR regex
.RS 4
This will print events that match the given regex\&. If a colon is specified, then the characters before the colon will be used to match the system and the characters after the colon will match the event\&.
.sp
.if n \{\
.RS 4
.\}
.nf
trace\-cmd report \-\-event sys:read
.fi
.if n \{\
.RE
.\}
.sp
.if n \{\
.RS 4
.\}
.nf
The above will only match events where the system name contains "sys"
and the event name contains "read"\&.
.fi
.if n \{\
.RE
.\}
.sp
.if n \{\
.RS 4
.\}
.nf
trace\-cmd report \-\-event read
.fi
.if n \{\
.RE
.\}
.sp
.if n \{\
.RS 4
.\}
.nf
The above will match all events that contain "read" in its name\&. Also it
may list all events of a system that contains "read" as well\&.
.fi
.if n \{\
.RE
.\}
.RE
.PP
\fB\-\-check\-events\fR
.RS 4
This will parse the event format strings that are stored in the trace\&.dat file and return whether the formats can be parsed correctly\&. It will load plugins unless
\fB\-N\fR
is specified\&.
.RE
.PP
\fB\-t\fR
.RS 4
Print the full timestamp\&. The timestamps in the data file are usually recorded to the nanosecond\&. But the default display of the timestamp is only to the microsecond\&. To see the full timestamp, add the
\fB\-t\fR
option\&.
.RE
.PP
\fB\-F\fR \fIfilter\fR
.RS 4
Add a filter to limit what events are displayed\&. Filters defined after an input file (specified with
\fB\-i\fR) only apply to that input file\&. Filters provided before any input file is given are considered global and apply to all input files\&.
.sp
.if n \{\
.RS 4
.\}
.nf
The format of the filter is:
.fi
.if n \{\
.RE
.\}
.RE
.sp
.if n \{\
.RS 4
.\}
.nf
\*(Aq:\*(Aq
= SYSTEM\*(Aq/\*(AqEVENT | SYSTEM | EVENT | \*(Aq,\*(Aq
= EVENT_FIELD | \*(Aq&&\*(Aq |
\*(Aq||\*(Aq | \*(Aq(\*(Aq \*(Aq)\*(Aq | \*(Aq!\*(Aq
= \*(Aq==\*(Aq | \*(Aq!=\*(Aq | \*(Aq>=\*(Aq | \*(Aq<=\*(Aq | \*(Aq>\*(Aq | \*(Aq<\*(Aq | \*(Aq&\*(Aq | \*(Aq|\*(Aq | \*(Aq^\*(Aq |
\*(Aq+\*(Aq | \*(Aq\-\*(Aq | \*(Aq*\*(Aq | \*(Aq/\*(Aq | \*(Aq%\*(Aq
= NUM | STRING | EVENT_FIELD
.fi
.if n \{\
.RE
.\}
.sp
.if n \{\
.RS 4
.\}
.nf
SYSTEM is the name of the system to filter on\&. If the EVENT is left out,
then it applies to all events under the SYSTEM\&. If only one string is used
without the \*(Aq/\*(Aq to deliminate between SYSTEM and EVENT, then the filter
will be applied to all systems and events that match the given string\&.
.fi
.if n \{\
.RE
.\}
.sp
.if n \{\
.RS 4
.\}
.nf
Whitespace is ignored, such that "sched:next_pid==123" is equivalent to
"sched : next_pid == 123"\&.
.fi
.if n \{\
.RE
.\}
.sp
.if n \{\
.RS 4
.\}
.nf
STRING is defined with single or double quotes (single quote must end with
single quote, and double with double)\&. Whitespace within quotes are not
ignored\&.
.fi
.if n \{\
.RE
.\}
.sp
.if n \{\
.RS 4
.\}
.nf
The representation of a SYSTEM or EVENT may also be a regular expression
as defined by \*(Aqregcomp(3)\*(Aq\&.
.fi
.if n \{\
.RE
.\}
.sp
.if n \{\
.RS 4
.\}
.nf
The EVENT_FIELD is the name of the field of an event that is being
filtered\&. If the event does not contain the EVENT_FIELD, that part of the
equation will be considered false\&.
.fi
.if n \{\
.RE
.\}
.sp
.if n \{\
.RS 4
.\}
.nf
\-F \*(Aqsched : bogus == 1 || common_pid == 2\*(Aq
.fi
.if n \{\
.RE
.\}
.sp
.if n \{\
.RS 4
.\}
.nf
The "bogus == 1" will always evaluate to FALSE because no event has a
field called "bogus", but the "common_pid == 2" will still be evaluated
since all events have the field "common_pid"\&. Any "sched" event that was
traced by the process with the PID of 2 will be shown\&.
.fi
.if n \{\
.RE
.\}
.sp
.if n \{\
.RS 4
.\}
.nf
Note, the EVENT_FIELD is the field name as shown by an events format
(as displayed with *\-\-events*), and not what is found in the output\&.
If the output shows "ID:foo" but the field that "foo" belongs to was
called "name" in the event format, then "name" must be used in the filter\&.
The same is true about values\&. If the value that is displayed is converted
by to a string symbol, the filter checks the original value and not the
value displayed\&. For example, to filter on all tasks that were in the
running state at a context switch:
.fi
.if n \{\
.RE
.\}
.sp
.if n \{\
.RS 4
.\}
.nf
\-F \*(Aqsched/sched_switch : prev_state==0\*(Aq
.fi
.if n \{\
.RE
.\}
.sp
.if n \{\
.RS 4
.\}
.nf
Although the output displays \*(AqR\*(Aq, having \*(Aqprev_stat=="R"\*(Aq will not work\&.
.fi
.if n \{\
.RE
.\}
.sp
.if n \{\
.RS 4
.\}
.nf
Note: You can also specify \*(AqCOMM\*(Aq as an EVENT_FIELD\&. This will use the
task name (or comm) of the record to compare\&. For example, to filter out
all of the "trace\-cmd" tasks:
.fi
.if n \{\
.RE
.\}
.sp
.if n \{\
.RS 4
.\}
.nf
\-F \*(Aq\&.*:COMM != "trace\-cmd"\*(Aq
.fi
.if n \{\
.RE
.\}
.PP
\fB\-I\fR
.RS 4
Do not print events where the HARDIRQ latency flag is set\&. This will filter out most events that are from interrupt context\&. Note, it may not filter out function traced functions that are in interrupt context but were called before the kernel "in interrupt" flag was set\&.
.RE
.PP
\fB\-S\fR
.RS 4
Do not print events where the SOFTIRQ latency flag is set\&. This will filter out most events that are from soft interrupt context\&.
.RE
.PP
\fB\-v\fR
.RS 4
This causes the following filters of
\fB\-F\fR
to filter out the matching events\&.
.RE
.sp
.if n \{\
.RS 4
.\}
.nf
\-v \-F \*(Aqsched/sched_switch : prev_state == 0\*(Aq
.fi
.if n \{\
.RE
.\}
.sp
.if n \{\
.RS 4
.\}
.nf
Will not display any sched_switch events that have a prev_state of 0\&.
Removing the *\-v* will only print out those events\&.
.fi
.if n \{\
.RE
.\}
.PP
\fB\-T\fR
.RS 4
Test the filters of \-F\&. After processing a filter string, the resulting filter will be displayed for each event\&. This is useful for using a filter for more than one event where a field may not exist in all events\&. Also it can be used to make sure there are no misspelled event field names, as they will simply be ignored\&.
\fB\-T\fR
is ignored if
\fB\-F\fR
is not specified\&.
.RE
.PP
\fB\-V\fR
.RS 4
Show verbose messages (see
\fB\-\-verbose\fR
but only for the numbers)
.RE
.PP
\fB\-L\fR
.RS 4
This will not load system wide plugins\&. It loads "local only"\&. That is what it finds in the ~/\&.trace\-cmd/plugins directory\&.
.RE
.PP
\fB\-N\fR
.RS 4
This will not load any plugins\&.
.RE
.PP
\fB\-n\fR \fIevent\-re\fR
.RS 4
This will cause all events that match the option to ignore any registered handler (by the plugins) to print the event\&. The normal event will be printed instead\&. The
\fIevent\-re\fR
is a regular expression as defined by
\fIregcomp(3)\fR\&.
.RE
.PP
\fB\-\-profile\fR
.RS 4
With the
\fB\-\-profile\fR
option, "trace\-cmd report" will process all the events first, and then output a format showing where tasks have spent their time in the kernel, as well as where they are blocked the most, and where wake up latencies are\&.
.sp
.if n \{\
.RS 4
.\}
.nf
See trace\-cmd\-profile(1) for more details and examples\&.
.fi
.if n \{\
.RE
.\}
.RE
.PP
\fB\-G\fR
.RS 4
Set interrupt (soft and hard) events as global (associated to CPU instead of tasks)\&. Only works for \-\-profile\&.
.RE
.PP
\fB\-H\fR \fIevent\-hooks\fR
.RS 4
Add custom event matching to connect any two events together\&.
.sp
.if n \{\
.RS 4
.\}
.nf
See trace\-cmd\-profile(1) for format\&.
.fi
.if n \{\
.RE
.\}
.RE
.PP
\fB\-R\fR
.RS 4
This will show the events in "raw" format\&. That is, it will ignore the event\(cqs print formatting and just print the contents of each field\&.
.RE
.PP
\fB\-r\fR \fIevent\-re\fR
.RS 4
This will cause all events that match the option to print its raw fields\&. The
\fIevent\-re\fR
is a regular expression as defined by
\fIregcomp(3)\fR\&.
.RE
.PP
\fB\-l\fR
.RS 4
This adds a "latency output" format\&. Information about interrupts being disabled, soft irq being disabled, the "need_resched" flag being set, preempt count, and big kernel lock are all being recorded with every event\&. But the default display does not show this information\&. This option will set display this information with 6 characters\&. When one of the fields is zero or N/A a \*(Aq\&.\e\*(Aq is shown\&.
.RE
.sp
.if n \{\
.RS 4
.\}
.nf
\-0 0d\&.h1\&. 106467\&.859747: function: ktime_get <\-\- tick_check_idle
.fi
.if n \{\
.RE
.\}
.sp
.if n \{\
.RS 4
.\}
.nf
The 0d\&.h1\&. denotes this information\&.
.fi
.if n \{\
.RE
.\}
.sp
.if n \{\
.RS 4
.\}
.nf
It starts with a number\&. This represents the CPU number that the event occurred
on\&.
.fi
.if n \{\
.RE
.\}
.sp
.if n \{\
.RS 4
.\}
.nf
The second character is one of the following:
.fi
.if n \{\
.RE
.\}
.sp
.if n \{\
.RS 4
.\}
.nf
\*(Aqd\*(Aq \- Interrupts are disabled
\*(Aq\&.\*(Aq \- Interrupts are enabled
\*(AqX\*(Aq \- Has flags that are not yet known by trace\-cmd
.fi
.if n \{\
.RE
.\}
.sp
.if n \{\
.RS 4
.\}
.nf
The third character is the "need rescheduling" flag\&.
.fi
.if n \{\
.RE
.\}
.sp
.if n \{\
.RS 4
.\}
.nf
\*(AqN\*(Aq \- A schedule is set to take place
\*(Aq\&.\*(Aq \- No scheduling is set
.fi
.if n \{\
.RE
.\}
.sp
.if n \{\
.RS 4
.\}
.nf
The fourth character represents the context the event was in when it triggered
.fi
.if n \{\
.RE
.\}
.sp
.if n \{\
.RS 4
.\}
.nf
\*(Aqh\*(Aq \- Hard interrupt context
\*(Aqs\*(Aq \- Soft interrupt context
\*(AqH\*(Aq \- Hard interrupt context that interrupted a soft interrupt
\*(Aq\&.\*(Aq \- Normal context
.fi
.if n \{\
.RE
.\}
.sp
.if n \{\
.RS 4
.\}
.nf
The next is a number (should be less than 10), that represents the preemption
depth (the number of times preempt_disable() is called without preempt_enable())\&.
\*(Aq\&.\*(Aq means preemption is enabled\&.
.fi
.if n \{\
.RE
.\}
.sp
.if n \{\
.RS 4
.\}
.nf
On some systems, "migrate disable" may exist, in which case a number will be
shown for that, or \*(Aq\&.\*(Aq meaning migration is enabled\&.
.fi
.if n \{\
.RE
.\}
.sp
.if n \{\
.RS 4
.\}
.nf
If lockdep in enabled on the system, then the number represents the depth of
locks that are held when the event triggered\&. \*(Aq\&.\*(Aq means no locks are held\&.
.fi
.if n \{\
.RE
.\}
.PP
\fB\-w\fR
.RS 4
If both the
\fIsched_switch\fR
and
\fIsched_wakeup\fR
events are enabled, then this option will report the latency between the time the task was first woken, and the time it was scheduled in\&.
.RE
.PP
\fB\-q\fR
.RS 4
Quiet non critical warnings\&.
.RE
.PP
\fB\-O\fR
.RS 4
Pass options to the trace\-cmd plugins that are loaded\&.
.sp
.if n \{\
.RS 4
.\}
.nf
\-O plugin:var=value
.fi
.if n \{\
.RE
.\}
.sp
.if n \{\
.RS 4
.\}
.nf
The \*(Aqplugin:\*(Aq and \*(Aq=value\*(Aq are optional\&. Value may be left off for options
that are boolean\&. If the \*(Aqplugin:\*(Aq is left off, then any variable that matches
in all plugins will be set\&.
.fi
.if n \{\
.RE
.\}
.sp
.if n \{\
.RS 4
.\}
.nf
Example: \-O fgraph:tailprint
.fi
.if n \{\
.RE
.\}
.RE
.PP
\fB\-\-cpu\fR
.RS 4
List of CPUs, separated by "," or ":", used for filtering the events\&. A range of CPUs can be specified using "cpuX\-cpuY" notation, where all CPUs in the range between cpuX and cpuY will be included in the list\&. The order of CPUs in the list must be from lower to greater\&.
.sp
.if n \{\
.RS 4
.\}
.nf
Example: "\-\-cpu 0,3" \- show events from CPUs 0 and 3
"\-\-cpu 2\-4" \- show events from CPUs 2, 3 and 4
.fi
.if n \{\
.RE
.\}
.RE
.PP
\fB\-\-cpus\fR
.RS 4
List the CPUs that have data in the trace file then exit\&.
.RE
.PP
\fB\-\-first\-event\fR
.RS 4
Show the timestamp of the first event of all CPUs that have data\&.
.RE
.PP
\fB\-\-last\-event\fR
.RS 4
Show the timestamp of the last event of all CPUs that have data\&.
.RE
.PP
\fB\-\-stat\fR
.RS 4
If the trace\&.dat file recorded the final stats (outputed at the end of record) the
\fB\-\-stat\fR
option can be used to retrieve them\&.
.RE
.PP
\fB\-\-uname\fR
.RS 4
If the trace\&.dat file recorded uname during the run, this will retrieve that information\&.
.RE
.PP
\fB\-\-version\fR
.RS 4
If the trace\&.dat file recorded the version of the executable used to create it, report that version\&.
.RE
.PP
\fB\-\-ts\-offset\fR offset
.RS 4
Add (or subtract if negative) an offset for all timestamps of the previous data file specified with
\fB\-i\fR\&. This is useful to merge sort multiple trace\&.dat files where the difference in the timestamp is known\&. For example if a trace is done on a virtual guest, and another trace is done on the host\&. If the host timestamp is 1000 units ahead of the guest, the following can be done:
.sp
.if n \{\
.RS 4
.\}
.nf
trace\-cmd report \-i host\&.dat \-\-ts\-offset \-1000 \-i guest\&.dat
.fi
.if n \{\
.RE
.\}
.sp
.if n \{\
.RS 4
.\}
.nf
This will subtract 1000 timestamp units from all the host events as it merges
with the guest\&.dat events\&. Note, the units is for the raw units recorded in
the trace\&. If the units are nanoseconds, the addition (or subtraction) from
the offset will be nanoseconds even if the displayed units are microseconds\&.
.fi
.if n \{\
.RE
.\}
.RE
.PP
\fB\-\-ts2secs\fR HZ
.RS 4
Convert the current clock source into a second (nanosecond resolution) output\&. When using clocks like x86\-tsc, if the frequency is known, by passing in the clock frequency, this will convert the time to seconds\&.
.sp
.if n \{\
.RS 4
.\}
.nf
This option affects any trace\&.dat file given with *\-i* proceeding it\&.
If this option comes before any *\-i* option, then that value becomes
the default conversion for all other trace\&.dat files\&. If another
\-\-ts2secs option appears after a *\-i* trace\&.dat file, than that option
will override the default value\&.
.fi
.if n \{\
.RE
.\}
.sp
.if n \{\
.RS 4
.\}
.nf
Example: On a 3\&.4 GHz machine
.fi
.if n \{\
.RE
.\}
.sp
.if n \{\
.RS 4
.\}
.nf
trace\-cmd record \-p function \-C x86\-tsc
.fi
.if n \{\
.RE
.\}
.sp
.if n \{\
.RS 4
.\}
.nf
trace\-cmd report \-\-ts2ns 3400000000
.fi
.if n \{\
.RE
.\}
.sp
.if n \{\
.RS 4
.\}
.nf
The report will convert the cycles timestamps into a readable second
display\&. The default display resolution is microseconds, unless *\-t*
is used\&.
.fi
.if n \{\
.RE
.\}
.sp
.if n \{\
.RS 4
.\}
.nf
The value of \-\-ts\-offset must still be in the raw timestamp units, even
with this option\&. The offset will be converted as well\&.
.fi
.if n \{\
.RE
.\}
.RE
.PP
\fB\-\-ts\-diff\fR
.RS 4
Show the time differences between events\&. The difference will appear in parenthesis just after the timestamp\&.
.RE
.PP
\fB\-\-ts\-check\fR
.RS 4
Make sure no timestamp goes backwards, and if it does, print out a warning message of the fact\&.
.RE
.PP
\fB\-\-nodate\fR
.RS 4
Ignore converting the timestamps to the date set by
\fBtrace\-cmd record\fR(3) \-\-date option\&.
.RE
.PP
\fB\-\-raw\-ts\fR
.RS 4
Display raw timestamps, without any corrections\&.
.RE
.PP
\fB\-\-align\-ts\fR
.RS 4
Display timestamps aligned to the first event\&.
.RE
.PP
\fB\-\-verbose\fR[=\fIlevel\fR]
.RS 4
Set the log level\&. Supported log levels are "none", "crit", "err", "warn", "info", "debug", "all" or their identifiers "0", "1", "2", "3", "4", "5", "6"\&. Setting the log level to specific value enables all logs from that and all previous levels\&. The level will default to "info" if one is not specified\&.
.sp
.if n \{\
.RS 4
.\}
.nf
Example: enable all critical, error and warning logs
.fi
.if n \{\
.RE
.\}
.sp
.if n \{\
.RS 4
.\}
.nf
trace\-cmd report \-\-verbose=warning
.fi
.if n \{\
.RE
.\}
.RE
.SH "EXAMPLES"
.sp
Using a trace\&.dat file that was created with:
.sp
.if n \{\
.RS 4
.\}
.nf
# trace\-cmd record \-p function \-e all sleep 5
.fi
.if n \{\
.RE
.\}
.sp
The default report shows:
.sp
.if n \{\
.RS 4
.\}
.nf
# trace\-cmd report
cpus=8
sleep\-89142 [001] \&.\&.\&.1\&. 162573\&.215752: function: mutex_unlock
sleep\-89142 [001] \&.\&.\&.1\&. 162573\&.215754: function: __mutex_unlock_slowpath
sleep\-89142 [001] \&.\&.\&.\&.\&. 162573\&.215755: lock_release: 0xffffffff855e7448 trace_types_lock
sleep\-89142 [001] \&.\&.\&.\&.\&. 162573\&.215757: lock_release: 0xffff892a01b54420 sb_writers
sleep\-89142 [001] \&.\&.\&.1\&. 162573\&.215757: function: preempt_count_add
sleep\-89142 [001] \&.\&.\&.1\&. 162573\&.215758: preempt_disable: caller=vfs_write+0x147 parent=vfs_write+0x147
sleep\-89142 [001] \&.\&.\&.2\&. 162573\&.215758: function: rcu_read_lock_any_held
sleep\-89142 [001] \&.\&.\&.2\&. 162573\&.215759: function: rcu_lockdep_current_cpu_online
sleep\-89142 [001] \&.\&.\&.2\&. 162573\&.215759: function: preempt_count_sub
sleep\-89142 [001] \&.\&.\&.1\&. 162573\&.215760: preempt_enable: caller=vfs_write+0x176 parent=vfs_write+0x176
sleep\-89142 [001] \&.\&.\&.1\&. 162573\&.215761: function: __f_unlock_pos
sleep\-89142 [001] \&.\&.\&.1\&. 162573\&.215761: function: mutex_unlock
[\&.\&.\&.]
.fi
.if n \{\
.RE
.\}
.sp
The note on the third column:
.sp
.if n \{\
.RS 4
.\}
.nf
sleep\-89998 [002] \&.\&.\&.1\&. 223087\&.004011: lock_acquire: 0xffff892b7cf32c20 lock
sleep\-89998 [002] \&.\&.\&.1\&. 223087\&.004011: lock_acquire: 0xffffffff85517f00 read rcu_read_lock
\-0 [005] dNh2\&. 223087\&.004012: sched_wakeup: trace\-cmd:89992 [120] CPU:005
sleep\-89998 [002] \&.\&.\&.1\&. 223087\&.004012: lock_acquire: 0xffffffff85517f00 read rcu_read_lock
sleep\-89998 [002] \&.\&.\&.1\&. 223087\&.004013: lock_release: 0xffffffff85517f00 rcu_read_lock
.fi
.if n \{\
.RE
.\}
.sp
It follows the same as shown in the Linux kernel /sys/kernel/tracing/trace file\&.
.sp
.if n \{\
.RS 4
.\}
.nf
# cat /sys/kernel/tracing/trace
# tracer: nop
#
# entries\-in\-buffer/entries\-written: 0/0 #P:8
#
# _\-\-\-\-\-=> irqs\-off/BH\-disabled
# / _\-\-\-\-=> need\-resched
# | / _\-\-\-=> hardirq/softirq
# || / _\-\-=> preempt\-depth
# ||| / _\-=> migrate\-disable
# |||| / delay
# TASK\-PID CPU# ||||| TIMESTAMP FUNCTION
# | | | ||||| | |
.fi
.if n \{\
.RE
.\}
.sp
Is the same as explained in the \fB\-l\fR option\&. Where the first position is:
.sp
.if n \{\
.RS 4
.\}
.nf
\*(Aq\&.\*(Aq \- means interrupts and bottom halves enabled
\*(Aqd\*(Aq \- means interrupts and bottom halves are disabled
.fi
.if n \{\
.RE
.\}
.sp
The second position:
.sp
.if n \{\
.RS 4
.\}
.nf
\*(AqN\*(Aq \- means that the "NEED_RESCHED" flag is set and the kernel should try to
schedule as soon as possible\&.
.fi
.if n \{\
.RE
.\}
.sp
The third position:
.sp
.if n \{\
.RS 4
.\}
.nf
\*(Aq\&.\*(Aq \- In normal/schedulable context
\*(Aqs\*(Aq \- In soft interrupt context
\*(Aqh\*(Aq \- In hard interrupt context
\*(AqH\*(Aq \- in hard interrupt context that interrupted a soft interrupt
.fi
.if n \{\
.RE
.\}
.sp
The forth position is the preempt count depth:
.sp
.if n \{\
.RS 4
.\}
.nf
\*(Aqpass:[\&.]\*(Aq \- preemption is enabled
\*(Aq#\*(Aq \- the depth of preemption disabled (nested)
.fi
.if n \{\
.RE
.\}
.sp
The fifth column is the migration disabled counter:
.sp
.if n \{\
.RS 4
.\}
.nf
\*(Aq\&.\*(Aq \- migration is enabled
\*(Aq#\*(Aq \- the depth of migration being disabled (nested)
.fi
.if n \{\
.RE
.\}
.sp
To see everything but the function traces:
.sp
.if n \{\
.RS 4
.\}
.nf
# trace\-cmd report \-v \-F \*(Aqfunction\*(Aq
cpus=8
sleep\-89142 [001] \&.\&.\&.\&.\&. 162573\&.215755: lock_release: 0xffffffff855e7448 trace_types_lock
sleep\-89142 [001] \&.\&.\&.\&.\&. 162573\&.215757: lock_release: 0xffff892a01b54420 sb_writers
sleep\-89142 [001] \&.\&.\&.1\&. 162573\&.215758: preempt_disable: caller=vfs_write+0x147 parent=vfs_write+0x147
sleep\-89142 [001] \&.\&.\&.1\&. 162573\&.215760: preempt_enable: caller=vfs_write+0x176 parent=vfs_write+0x176
sleep\-89142 [001] \&.\&.\&.\&.\&. 162573\&.215762: lock_release: 0xffff892a19601ac8 &f\->f_pos_lock
sleep\-89142 [001] \&.\&.\&.\&.\&. 162573\&.215764: sys_exit: NR 1 = 1
sleep\-89142 [001] \&.\&.\&.\&.\&. 162573\&.215766: sys_exit_write: 0x1
sleep\-89142 [001] d\&.\&.\&.\&. 162573\&.215767: irq_disable: caller=syscall_exit_to_user_mode+0x15 parent=0x0
sleep\-89142 [001] d\&.\&.\&.\&. 162573\&.215768: irq_enable: caller=syscall_exit_to_user_mode+0xed parent=0x0
sleep\-89142 [001] \&.\&.\&.\&.\&. 162573\&.215773: lock_acquire: 0xffff892a4ad29318 read &mm\->mmap_lock
sleep\-89142 [001] \&.\&.\&.\&.\&. 162573\&.215775: lock_release: 0xffff892a4ad29318 &mm\->mmap_lock
sleep\-89142 [001] \&.\&.\&.\&.\&. 162573\&.215778: lock_acquire: 0xffff892a4ad29318 read &mm\->mmap_lock
[\&.\&.\&.]
.fi
.if n \{\
.RE
.\}
.sp
To see only the kmalloc calls that were greater than 1000 bytes:
.sp
.if n \{\
.RS 4
.\}
.nf
# trace\-cmd report \-F \*(Aqkmalloc: bytes_req > 1000\*(Aq
cpus=8
sleep\-89142 [001] \&.\&.\&.\&.\&. 162573\&.219401: kmalloc: (tomoyo_find_next_domain+0x84) call_site=tomoyo_find_next_domain+0x84 ptr=0xffff892a176c0000 bytes_req=4096 bytes_alloc=4096 gfp_flags=0xd40 node=\-1 accounted=false
sleep\-89142 [001] \&.\&.\&.\&.\&. 162573\&.219511: kmalloc: (tomoyo_realpath_from_path+0x42) call_site=tomoyo_realpath_from_path+0x42 ptr=0xffff892a176c6000 bytes_req=4096 bytes_alloc=4096 gfp_flags=0xc40 node=\-1 accounted=false
trace\-cmd\-89135 [000] \&.\&.\&.\&.\&. 162573\&.244301: kmalloc: (kvmalloc_node_noprof+0x43) call_site=kvmalloc_node_noprof+0x43 ptr=0xffff892a63f84000 bytes_req=8193 bytes_alloc=16384 gfp_flags=0x12dc0 node=\-1 accounted=false
trace\-cmd\-89135 [000] \&.\&.\&.\&.\&. 162573\&.244471: kmalloc: (kvmalloc_node_noprof+0x43) call_site=kvmalloc_node_noprof+0x43 ptr=0xffff892a63f84000 bytes_req=8193 bytes_alloc=16384 gfp_flags=0x12dc0 node=\-1 accounted=false
trace\-cmd\-89134 [007] \&.\&.\&.\&.\&. 162573\&.267148: kmalloc: (kvmalloc_node_noprof+0x43) call_site=kvmalloc_node_noprof+0x43 ptr=0xffff892a628d4000 bytes_req=8193 bytes_alloc=16384 gfp_flags=0x12dc0 node=\-1 accounted=false
trace\-cmd\-89134 [007] \&.\&.\&.\&.\&. 162573\&.267403: kmalloc: (kvmalloc_node_noprof+0x43) call_site=kvmalloc_node_noprof+0x43 ptr=0xffff892a628d4000 bytes_req=8193 bytes_alloc=16384 gfp_flags=0x12dc0 node=\-1 accounted=false
trace\-cmd\-89141 [002] \&.\&.\&.\&.\&. 162573\&.290583: kmalloc: (kvmalloc_node_noprof+0x43) call_site=kvmalloc_node_noprof+0x43 ptr=0xffff892a12d3c000 bytes_req=8193 bytes_alloc=16384 gfp_flags=0x12dc0 node=\-1 accounted=false
trace\-cmd\-89141 [002] \&.\&.\&.\&.\&. 162573\&.290754: kmalloc: (kvmalloc_node_noprof+0x43) call_site=kvmalloc_node_noprof+0x43 ptr=0xffff892a12d3c000 bytes_req=8193 bytes_alloc=16384 gfp_flags=0x12dc0 node=\-1 accounted=false
trace\-cmd\-89139 [004] \&.\&.\&.\&.\&. 162573\&.784636: kmalloc: (kvmalloc_node_noprof+0x43) call_site=kvmalloc_node_noprof+0x43 ptr=0xffff892a63d70000 bytes_req=8193 bytes_alloc=16384 gfp_flags=0x12dc0 node=\-1 accounted=false
[\&.\&.\&.]
.fi
.if n \{\
.RE
.\}
.sp
To see wakeups and sched switches that left the previous task in the running state:
.sp
.if n \{\
.RS 4
.\}
.nf
# trace\-cmd report \-F \*(Aqsched: prev_state == 0\*(Aq \-F \*(Aqsched_waking\*(Aq
cpus=8
sleep\-89142 [001] d\&.h6\&. 162573\&.215941: sched_waking: comm=trace\-cmd pid=89135 prio=120 target_cpu=000
\-0 [000] dNh7\&. 162573\&.216219: sched_waking: comm=trace\-cmd pid=89134 prio=120 target_cpu=007
\-0 [000] d\&.\&.2\&. 162573\&.216423: sched_switch: swapper/0:0 [120] R ==> trace\-cmd:89135 [120]
\-0 [007] dNh7\&. 162573\&.216511: sched_waking: comm=trace\-cmd pid=89141 prio=120 target_cpu=002
\-0 [007] d\&.\&.2\&. 162573\&.216698: sched_switch: swapper/7:0 [120] R ==> trace\-cmd:89134 [120]
\-0 [002] dNh7\&. 162573\&.216776: sched_waking: comm=trace\-cmd pid=89136 prio=120 target_cpu=001
\-0 [002] d\&.\&.2\&. 162573\&.216951: sched_switch: swapper/2:0 [120] R ==> trace\-cmd:89141 [120]
sleep\-89142 [001] d\&.s3\&. 162573\&.231260: sched_waking: comm=rcu_preempt pid=17 prio=120 target_cpu=002
\-0 [002] d\&.\&.2\&. 162573\&.231568: sched_switch: swapper/2:0 [120] R ==> rcu_preempt:17 [120]
sleep\-89142 [001] d\&.s2\&. 162573\&.240425: sched_waking: comm=rcu_preempt pid=17 prio=120 target_cpu=002
\-0 [002] d\&.\&.2\&. 162573\&.240719: sched_switch: swapper/2:0 [120] R ==> rcu_preempt:17 [120]
sleep\-89142 [001] d\&.h7\&. 162573\&.241983: sched_waking: comm=trace\-cmd pid=89135 prio=120 target_cpu=000
.fi
.if n \{\
.RE
.\}
.sp
The above needs a little explanation\&. The filter specifies the "sched" subsystem, which includes all scheduling events\&. Any event that does not have the format field "prev_state", will evaluate those expressions as FALSE, and will not produce a match\&. Only the sched_switch event will match that\&. The second "\-F" will include the sched_waking event\&.
.sp
.if n \{\
.RS 4
.\}
.nf
# trace\-cmd report \-w \-F \*(Aqsched_switch, sched_wakeup\&.*\*(Aq
[\&.\&.\&.]
trace\-cmd\-89141 [007] d\&.\&.2\&. 162583\&.263060: sched_switch: trace\-cmd:89141 [120] R ==> trace\-cmd:89135 [120]
kworker/u36:1\-51219 [000] d\&.\&.2\&. 162583\&.266957: sched_switch: kworker/u36:1:51219 [120] R ==> kworker/u33:2:49692 [120] Latency: 4024\&.977 usecs
trace\-cmd\-89135 [007] d\&.\&.2\&. 162583\&.267109: sched_switch: trace\-cmd:89135 [120] R ==> trace\-cmd:89141 [120]
trace\-cmd\-89139 [001] d\&.\&.2\&. 162583\&.267147: sched_switch: trace\-cmd:89139 [120] D ==> swapper/1:0 [120]
kworker/u36:2\-88857 [002] d\&.\&.2\&. 162583\&.267913: sched_switch: kworker/u36:2:88857 [120] R ==> trace\-cmd:89136 [120]
kworker/u33:2\-49692 [000] d\&.\&.2\&. 162583\&.268334: sched_switch: kworker/u33:2:49692 [120] I ==> kworker/u36:1:51219 [120]
\-0 [001] dNh4\&. 162583\&.268747: sched_wakeup: sleep:89142 [120] CPU:001
\-0 [001] d\&.\&.2\&. 162583\&.268833: sched_switch: swapper/1:0 [120] R ==> sleep:89142 [120] Latency: 85\&.751 usecs
sleep\-89142 [001] d\&.h4\&. 162583\&.269022: sched_wakeup: trace\-cmd:89139 [120] CPU:001
trace\-cmd\-89141 [007] d\&.\&.2\&. 162583\&.271009: sched_switch: trace\-cmd:89141 [120] R ==> trace\-cmd:89135 [120]
trace\-cmd\-89136 [002] d\&.\&.2\&. 162583\&.271020: sched_switch: trace\-cmd:89136 [120] R ==> kworker/u36:2:88857 [120]
kworker/u36:2\-88857 [002] d\&.\&.2\&. 162583\&.271079: sched_switch: kworker/u36:2:88857 [120] I ==> trace\-cmd:89136 [120]
trace\-cmd\-89137 [006] d\&.h2\&. 162583\&.273950: sched_wakeup: trace\-cmd:89133 [120] CPU:006
sleep\-89142 [001] d\&.\&.2\&. 162583\&.274064: sched_switch: sleep:89142 [120] Z ==> trace\-cmd:89139 [120] Latency: 5042\&.285 usecs
trace\-cmd\-89135 [007] d\&.\&.2\&. 162583\&.275043: sched_switch: trace\-cmd:89135 [120] R ==> trace\-cmd:89141 [120]
trace\-cmd\-89137 [006] d\&.\&.2\&. 162583\&.275158: sched_switch: trace\-cmd:89137 [120] R ==> trace\-cmd:89133 [120] Latency: 1207\&.327 usecs
trace\-cmd\-89136 [002] dNh3\&. 162583\&.275229: sched_wakeup: rcu_preempt:17 [120] CPU:002
trace\-cmd\-89136 [002] d\&.\&.2\&. 162583\&.275294: sched_switch: trace\-cmd:89136 [120] R ==> rcu_preempt:17 [120] Latency: 65\&.255 usecs
rcu_preempt\-17 [002] d\&.\&.2\&. 162583\&.275399: sched_switch: rcu_preempt:17 [120] I ==> trace\-cmd:89136 [120]
Average wakeup latency: 20082\&.580 usecs
Maximum Latency: 1032049\&.277 usecs at timestamp: 162574\&.787022
Minimum Latency: 29\&.023 usecs at timestamp: 162583\&.189731
RT task timings:
Average wakeup latency: 139\&.568 usecs
Maximum Latency: 220\&.583 usecs at timestamp: 162577\&.347038
Minimum Latency: 75\&.902 usecs at timestamp: 162577\&.719121
.fi
.if n \{\
.RE
.\}
.sp
The above trace produces the wakeup latencies of the tasks\&. The "sched_switch" event reports each individual latency after writing the event information\&. At the end of the report, the average wakeup latency is reported, as well as the maxim and minimum latency and the timestamp they happened at\&. It does this for both normal tasks as well as real\-time tasks\&.
.sp
.if n \{\
.RS 4
.\}
.nf
# trace\-cmd report \-w \-F \*(Aqsched_switch, sched_wakeup\&.*: prio < 100 || next_prio < 100\*(Aq
cpus=8
\-0 [001] dNh5\&. 162573\&.291142: sched_wakeup: migration/1:23 [0] CPU:001
\-0 [001] d\&.\&.2\&. 162573\&.291237: sched_switch: swapper/1:0 [120] R ==> migration/1:23 [0] Latency: 94\&.643 usecs
trace\-cmd\-89141 [002] dNh6\&. 162573\&.346785: sched_wakeup: migration/2:28 [0] CPU:002
trace\-cmd\-89141 [002] d\&.\&.2\&. 162573\&.346929: sched_switch: trace\-cmd:89141 [120] R ==> migration/2:28 [0] Latency: 143\&.971 usecs
trace\-cmd\-89134 [003] dNh4\&. 162573\&.410852: sched_wakeup: migration/3:33 [0] CPU:003
trace\-cmd\-89134 [003] d\&.\&.2\&. 162573\&.411039: sched_switch: trace\-cmd:89134 [120] R ==> migration/3:33 [0] Latency: 187\&.640 usecs
\-0 [004] dNh5\&. 162573\&.490944: sched_wakeup: migration/4:38 [0] CPU:004
\-0 [004] d\&.\&.2\&. 162573\&.491098: sched_switch: swapper/4:0 [120] R ==> migration/4:38 [0] Latency: 153\&.913 usecs
\-0 [005] dNh5\&. 162573\&.574955: sched_wakeup: migration/5:43 [0] CPU:005
\-0 [005] d\&.\&.2\&. 162573\&.575107: sched_switch: swapper/5:0 [120] R ==> migration/5:43 [0] Latency: 152\&.875 usecs
\-0 [006] dNh5\&. 162573\&.646878: sched_wakeup: migration/6:48 [0] CPU:006
\-0 [006] d\&.\&.2\&. 162573\&.646992: sched_switch: swapper/6:0 [120] R ==> migration/6:48 [0] Latency: 113\&.788 usecs
trace\-cmd\-89140 [002] dNh7\&. 162577\&.346818: sched_wakeup: migration/2:28 [0] CPU:002
trace\-cmd\-89140 [002] d\&.\&.2\&. 162577\&.347038: sched_switch: trace\-cmd:89140 [120] R ==> migration/2:28 [0] Latency: 220\&.583 usecs
trace\-cmd\-89134 [003] dNh5\&. 162577\&.410869: sched_wakeup: migration/3:33 [0] CPU:003
trace\-cmd\-89141 [005] dNh6\&. 162577\&.574792: sched_wakeup: migration/5:43 [0] CPU:005
trace\-cmd\-89141 [005] d\&.\&.2\&. 162577\&.574915: sched_switch: trace\-cmd:89141 [120] R ==> migration/5:43 [0] Latency: 122\&.648 usecs
trace\-cmd\-89136 [007] dNh6\&. 162577\&.719045: sched_wakeup: migration/7:53 [0] CPU:007
trace\-cmd\-89136 [007] d\&.\&.2\&. 162577\&.719121: sched_switch: trace\-cmd:89136 [120] R ==> migration/7:53 [0] Latency: 75\&.902 usecs
trace\-cmd\-89140 [005] dNh4\&. 162581\&.574827: sched_wakeup: migration/5:43 [0] CPU:005
trace\-cmd\-89140 [005] d\&.\&.2\&. 162581\&.574957: sched_switch: trace\-cmd:89140 [120] R ==> migration/5:43 [0] Latency: 129\&.717 usecs
kworker/u46:1\-51211 [006] dNh4\&. 162581\&.646809: sched_wakeup: migration/6:48 [0] CPU:006
Average wakeup latency: 139\&.568 usecs
Maximum Latency: 220\&.583 usecs at timestamp: 162577\&.347038
Minimum Latency: 75\&.902 usecs at timestamp: 162577\&.719121
RT task timings:
Average wakeup latency: 139\&.568 usecs
Maximum Latency: 220\&.583 usecs at timestamp: 162577\&.347038
Minimum Latency: 75\&.902 usecs at timestamp: 162577\&.719121
.fi
.if n \{\
.RE
.\}
.sp
The above version will only show the wakeups and context switches of Real Time tasks\&. The \fIprio\fR used inside the kernel starts at 0 for highest priority\&. That is \fIprio\fR 0 is equivalent to user space real time priority 99, and priority 98 is equivalent to user space real time priority 1\&. Prios less than 100 represent Real Time tasks\&. Notice that the total wake up timings are identical to the RT task timings\&.
.sp
An example of the profile:
.sp
.if n \{\
.RS 4
.\}
.nf
# trace\-cmd record \-\-profile sleep 1
# trace\-cmd report \-\-profile \-\-comm sleep
task: sleep\-21611
Event: sched_switch:R (1) Total: 99442 Avg: 99442 Max: 99442 Min:99442
1 total:99442 min:99442 max:99442 avg=99442
=> ftrace_raw_event_sched_switch (0xffffffff8105f812)
=> __schedule (0xffffffff8150810a)
=> preempt_schedule (0xffffffff8150842e)
=> ___preempt_schedule (0xffffffff81273354)
=> cpu_stop_queue_work (0xffffffff810b03c5)
=> stop_one_cpu (0xffffffff810b063b)
=> sched_exec (0xffffffff8106136d)
=> do_execve_common\&.isra\&.27 (0xffffffff81148c89)
=> do_execve (0xffffffff811490b0)
=> SyS_execve (0xffffffff811492c4)
=> return_to_handler (0xffffffff8150e3c8)
=> stub_execve (0xffffffff8150c699)
Event: sched_switch:S (1) Total: 1000506680 Avg: 1000506680 Max: 1000506680 Min:1000506680
1 total:1000506680 min:1000506680 max:1000506680 avg=1000506680
=> ftrace_raw_event_sched_switch (0xffffffff8105f812)
=> __schedule (0xffffffff8150810a)
=> schedule (0xffffffff815084b8)
=> do_nanosleep (0xffffffff8150b22c)
=> hrtimer_nanosleep (0xffffffff8108d647)
=> SyS_nanosleep (0xffffffff8108d72c)
=> return_to_handler (0xffffffff8150e3c8)
=> tracesys_phase2 (0xffffffff8150c304)
Event: sched_wakeup:21611 (1) Total: 30326 Avg: 30326 Max: 30326 Min:30326
1 total:30326 min:30326 max:30326 avg=30326
=> ftrace_raw_event_sched_wakeup_template (0xffffffff8105f653)
=> ttwu_do_wakeup (0xffffffff810606eb)
=> ttwu_do_activate\&.constprop\&.124 (0xffffffff810607c8)
=> try_to_wake_up (0xffffffff8106340a)
.fi
.if n \{\
.RE
.\}
.SH "SEE ALSO"
.sp
trace\-cmd(1), trace\-cmd\-record(1), trace\-cmd\-start(1), trace\-cmd\-stop(1), trace\-cmd\-extract(1), trace\-cmd\-reset(1), trace\-cmd\-split(1), trace\-cmd\-list(1), trace\-cmd\-listen(1), trace\-cmd\-profile(1)
.SH "AUTHOR"
.sp
Written by Steven Rostedt, <\m[blue]\fBrostedt@goodmis\&.org\fR\m[]\&\s-2\u[1]\d\s+2>
.SH "RESOURCES"
.sp
\m[blue]\fBhttps://git\&.kernel\&.org/pub/scm/utils/trace\-cmd/trace\-cmd\&.git/\fR\m[]
.SH "COPYING"
.sp
Copyright (C) 2010 Red Hat, Inc\&. Free use of this software is granted under the terms of the GNU Public License (GPL)\&.
.SH "NOTES"
.IP " 1." 4
rostedt@goodmis.org
.RS 4
\%mailto:rostedt@goodmis.org
.RE