'\" t
.\" Title: trace-cmd-report
.\" Author: [see the "AUTHOR" section]
.\" Generator: DocBook XSL Stylesheets vsnapshot
.\" Date: 02/10/2024
.\" Manual: libtracefs Manual
.\" Source: libtracefs
.\" Language: English
.\"
.TH "TRACE\-CMD\-REPORT" "1" "02/10/2024" "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]
.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
trace\-cmd\-16129 [002] 158126\&.498411: function: __mutex_unlock_slowpath <\-\- mutex_unlock
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
trace\-cmd\-16130 [003] 158126\&.498411: function: do_splice_to <\-\- sys_splice
sleep\-16133 [001] 158126\&.498412: function: inotify_inode_queue_event <\-\- vfs_write
trace\-cmd\-16129 [002] 158126\&.498420: lock_release: 0xffff88003f1fa4f8 &sb\->s_type\->i_mutex_key
trace\-cmd\-16131 [000] 158126\&.498421: function: security_file_alloc <\-\- get_empty_filp
sleep\-16133 [001] 158126\&.498422: function: __fsnotify_parent <\-\- vfs_write
trace\-cmd\-16130 [003] 158126\&.498422: function: rw_verify_area <\-\- do_splice_to
trace\-cmd\-16131 [000] 158126\&.498424: function: cap_file_alloc_security <\-\- security_file_alloc
trace\-cmd\-16129 [002] 158126\&.498425: function: syscall_trace_leave <\-\- int_check_syscall_exit_work
sleep\-16133 [001] 158126\&.498426: function: inotify_dentry_parent_queue_event <\-\- vfs_write
trace\-cmd\-16130 [003] 158126\&.498426: function: security_file_permission <\-\- rw_verify_area
trace\-cmd\-16129 [002] 158126\&.498428: function: audit_syscall_exit <\-\- syscall_trace_leave
[\&.\&.\&.]
.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
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
trace\-cmd\-16129 [002] 158126\&.498420: lock_release: 0xffff88003f1fa4f8 &sb\->s_type\->i_mutex_key
trace\-cmd\-16130 [003] 158126\&.498436: lock_acquire: 0xffffffff8166bf78 read all_cpu_access_lock
trace\-cmd\-16131 [000] 158126\&.498438: lock_acquire: 0xffff88003df5b520 read &fs\->lock
trace\-cmd\-16129 [002] 158126\&.498446: kfree: call_site=810a7abb ptr=0x0
trace\-cmd\-16130 [003] 158126\&.498448: lock_acquire: 0xffff880002250a80 &per_cpu(cpu_access_lock, cpu)
trace\-cmd\-16129 [002] 158126\&.498450: sys_exit_splice: 0xfffffff5
trace\-cmd\-16131 [000] 158126\&.498454: lock_release: 0xffff88003df5b520 &fs\->lock
sleep\-16133 [001] 158126\&.498456: kfree: call_site=810a7abb ptr=0x0
sleep\-16133 [001] 158126\&.498460: sys_exit_write: 0x1
trace\-cmd\-16130 [003] 158126\&.498462: kmalloc: call_site=810bf95b ptr=0xffff88003dedc040 bytes_req=24 bytes_alloc=32 gfp_flags=GFP_KERNEL|GFP_ZERO
.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
\-0 [000] 158128\&.126641: kmalloc: call_site=81330635 ptr=0xffff88003c2fd000 bytes_req=2096 bytes_alloc=4096 gfp_flags=GFP_ATOMIC
.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 || (success == 1)\*(Aq
trace\-cmd\-16132 [002] 158126\&.499951: sched_wakeup: comm=trace\-cmd pid=16129 prio=120 success=1 target_cpu=002
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
\-0 [003] 158126\&.500585: sched_wakeup: comm=trace\-cmd pid=16130 prio=120 success=1 target_cpu=003
\-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
trace\-cmd\-16132 [000] 158126\&.502475: sched_wakeup: comm=trace\-cmd pid=16131 prio=120 success=1 target_cpu=000
trace\-cmd\-16131 [002] 158126\&.506516: sched_wakeup: comm=trace\-cmd pid=16129 prio=120 success=1 target_cpu=002
\-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
trace\-cmd\-16131 [003] 158126\&.570243: sched_wakeup: comm=trace\-cmd pid=16129 prio=120 success=1 target_cpu=003
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
trace\-cmd\-16129 [003] 158126\&.622379: sched_wakeup: comm=trace\-cmd pid=16131 prio=120 success=1 target_cpu=003
trace\-cmd\-16129 [000] 158126\&.649287: sched_wakeup: comm=trace\-cmd pid=16131 prio=120 success=1 target_cpu=000
.fi
.if n \{\
.RE
.\}
.sp
The above needs a little explanation\&. The filter specifies the "sched" subsystem, which includes both sched_switch and sched_wakeup events\&. Any event that does not have the format field "prev_state" or "success", will evaluate those expressions as FALSE, and will not produce a match\&. Using "||" will have the "prev_state" test happen for the "sched_switch" event and the "success" test happen for the "sched_wakeup" event\&.
.sp
.if n \{\
.RS 4
.\}
.nf
# trace\-cmd report \-w \-F \*(Aqsched_switch, sched_wakeup\&.*\*(Aq
[\&.\&.\&.]
trace\-cmd\-16130 [003] 158131\&.580616: sched_wakeup: comm=trace\-cmd pid=16131 prio=120 success=1 target_cpu=003
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
trace\-cmd\-16131 [000] 158131\&.582414: sched_wakeup: comm=trace\-cmd pid=16129 prio=120 success=1 target_cpu=000
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
sleep\-16133 [002] 158131\&.584121: sched_wakeup: comm=trace\-cmd pid=16120 prio=120 success=1 target_cpu=002
trace\-cmd\-16129 [001] 158131\&.584128: sched_wakeup: comm=trace\-cmd pid=16132 prio=120 success=1 target_cpu=001
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
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
Average wakeup latency: 26626\&.656 usecs
.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\&.
.sp
.if n \{\
.RS 4
.\}
.nf
# trace\-cmd report \-w \-F \*(Aqsched_switch, sched_wakeup\&.*: prio < 100 || next_prio < 100\*(Aq
\-0 [003] 158131\&.516753: sched_wakeup: comm=ksoftirqd/3 pid=13 prio=49 success=1 target_cpu=003
\-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
\-0 [003] 158131\&.533781: sched_wakeup: comm=ksoftirqd/3 pid=13 prio=49 success=1 target_cpu=003
\-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
\-0 [003] 158131\&.569730: sched_wakeup: comm=ksoftirqd/3 pid=13 prio=49 success=1 target_cpu=003
\-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
Average wakeup latency: 110\&.021 usecs
.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\&.
.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