trace-cmd(1) [centos man page]

TRACE-CMD(1)															      TRACE-CMD(1)

NAME

       trace-cmd - interacts with Ftrace Linux kernel internal tracer

SYNOPSIS

       trace-cmd COMMAND [OPTIONS]

DESCRIPTION

       The trace-cmd(1) command interacts with the Ftrace tracer that is built inside the Linux kernel. It interfaces with the Ftrace specific
       files found in the debugfs file system under the tracing directory. A COMMAND must be specified to tell trace-cmd what to do.

COMMANDS

	   record  - record a live trace and write a trace.dat file to the
		     local disk or to the network.

	   report  - reads a trace.dat file and converts the binary data to a
		     ASCII text readable format.

	   hist    - show a histogram of the events.

	   options - list the plugin options that are available to *report*

	   start   - start the tracing without recording to a trace.dat file.

	   stop    - stop tracing (only disables recording, overhead of tracer
		     is still in effect)

	   extract - extract the data from the kernel buffer and create a trace.dat
		     file.

	   reset   - disables all tracing and gives back the system performance.
		     (clears all data from the kernel buffers)

	   split   - splits a trace.dat file into smaller files.

	   list    - list the available plugins or events that can be recorded.

	   listen  - open up a port to listen for remote tracing connections.

	   restore - restore the data files of a crashed run of trace-cmd record

	   stack   - run and display the stack tracer

	   check-events - parse format strings for all trace events and return
			  whether all formats are parseable

OPTIONS

       -h, --help
	   Display the help text.

       Other options see the man page for the corresponding command.

SEE ALSO

       trace-cmd-record(1), trace-cmd-report(1), trace-cmd-hist(1), trace-cmd-start(1), trace-cmd-stop(1), trace-cmd-extract(1),
       trace-cmd-reset(1), trace-cmd-restore(1), trace-cmd-stack(1), trace-cmd-split(1), trace-cmd-list(1), trace-cmd-listen(1), trace-cmd.dat(5),
       trace-cmd-check-events(1)

AUTHOR

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

RESOURCES

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

COPYING

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

NOTES

	1. rostedt@goodmis.org
	   mailto:rostedt@goodmis.org

								    06/11/2014							      TRACE-CMD(1)

TRACE-CMD-REPORT(1)													       TRACE-CMD-REPORT(1)

NAME

       trace-cmd-report - show in ASCII a trace created by trace-cmd record

SYNOPSIS

       trace-cmd report [OPTIONS] [input-file]

DESCRIPTION

       The trace-cmd(1) report command will output a human readable report of a trace created by trace-cmd record.

OPTIONS

       -i input-file
	   By default, trace-cmd report will read the file trace.dat. But the -i option open up the given input-file instead. Note, the input file
	   may also be specified as the last item on the command line.

       -e
	   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.

       -f
	   This outputs the list of functions that have been recorded in the file.

       -P
	   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.

       -E
	   This lists the possible events in the file (but this list is not necessarily the list of events in the file).

       --events
	   This will list the event formats that are stored in the trace.dat file.

       --check-events
	   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 -N is specified.

       -t
	   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 -t option.

       -F filter
	   Add a filter to limit what events are displayed. The format of the filter is:

	       <events> ':' <filter>
	       <events> = SYSTEM'/'EVENT  | SYSTEM | EVENT | <events> ',' <events>
	       <filter> = EVENT_FIELD <op> <value> | <filter> '&&' <filter> |
			  <filter> '||' <filter> | '(' <filter> ')' | '!' <filter>
	       <op> = '==' | '!=' | '>=' | '<=' | '>' | '<' | '&' | '|' | '^' |
		      '+' | '-' | '*' | '/' | '%'
	       <value> = NUM | STRING | EVENT_FIELD

	   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 '/' to deliminate between SYSTEM and EVENT, then the filter
	   will be applied to all systems and events that match the given string.

	   Whitespace is ignored, such that "sched:next_pid==123" is equivalent to
	   "sched : next_pid == 123".

	   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.

	   The representation of a SYSTEM or EVENT may also be a regular expression
	   as defined by 'regcomp(3)'.

	   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.

	       -F 'sched : bogus == 1 || common_pid == 2'

	   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.

	   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:

	       -F 'sched/sched_switch : prev_state==0'

	   Although the output displays 'R', having 'prev_stat=="R"' will not work.

	   Note: You can also specify 'COMM' 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:

	       -F '.*:COMM != "trace-cmd"'

       -v
	   This causes the following filters of -F to filter out the matching events.

	       -v -F 'sched/sched_switch : prev_state == 0'

	   Will not display any sched_switch events that have a prev_state of 0.
	   Removing the *-v* will only print out those events.

       -T
	   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.  -T is ignored if -F is not specified.

       -V
	   Show the plugins that are loaded.

       -L
	   This will not load system wide plugins. It loads "local only". That is what it finds in the ~/.trace-cmd/plugins directory.

       -N
	   This will not load any plugins.

       -n event-re
	   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 event-re is a regular expression as defined by regcomp(3).

       -R
	   This will show the events in "raw" format. That is, it will ignore the event's print formatting and just print the contents of each
	   field.

       -r event-re
	   This will cause all events that match the option to print its raw fields. The event-re is a regular expression as defined by
	   regcomp(3).

       -l
	   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 '.' is shown.

		 <idle>-0	0d.h1. 106467.859747: function: 	    ktime_get <-- tick_check_idle

	   The 0d.h1. denotes this information. The first character is never a '.'
	   and represents what CPU the trace was recorded on (CPU 0). The 'd' denotes
	   that interrupts were disabled. The 'h' means that this was called inside
	   an interrupt handler. The '1' is the preemption disabled (preempt_count)
	   was set to one.  The two '.'s are "need_resched" flag and kernel lock
	   counter.  If the "need_resched" flag is set, then that character would be a
	   'N'.

       -w
	   If both the sched_switch and sched_wakeup 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.

       -q
	   Quiet non critical warnings.

       -O
	   Pass options to the trace-cmd plugins that are loaded.

	       -O plugin:var=value

	       The 'plugin:' and '=value' are optional. Value may be left off for options
	       that are boolean. If the 'plugin:' is left off, then any variable that matches
	       in all plugins will be set.

	       Example:  -O fgraph:tailprint

       --stat
	   If the trace.dat file recorded the final stats (outputed at the end of record) the --stat option can be used to retrieve them.

EXAMPLES

       Using a trace.dat file that was created with:

	       # trace-cmd record -p function -e all sleep 5

       The default report shows:

	    # 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
	   [...]

       To see everything but the function traces:

	    # trace-cmd report -v -F 'function'
		  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

       To see only the kmalloc calls that were greater than 1000 bytes:

	    #trace-cmd report -F 'kmalloc: bytes_req > 1000'
		     <idle>-0	  [000] 158128.126641: kmalloc: call_site=81330635 ptr=0xffff88003c2fd000 bytes_req=2096 bytes_alloc=4096 gfp_flags=GFP_ATOMIC

       To see wakeups and sched switches that left the previous task in the running state:

	    # trace-cmd report -F 'sched: prev_state == 0 || (success == 1)'
		  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
		     <idle>-0	  [003] 158126.500585: sched_wakeup: comm=trace-cmd pid=16130 prio=120 success=1 target_cpu=003
		     <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
		  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
		     <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
		  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

       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.

	     # trace-cmd report -w -F 'sched_switch, sched_wakeup.*'
	   [...]
		  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

       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.

	     # trace-cmd report -w -F 'sched_switch, sched_wakeup.*: prio < 100 || next_prio < 100'
		     <idle>-0	  [003] 158131.516753: sched_wakeup: comm=ksoftirqd/3 pid=13 prio=49 success=1 target_cpu=003
		     <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
		     <idle>-0	  [003] 158131.533781: sched_wakeup: comm=ksoftirqd/3 pid=13 prio=49 success=1 target_cpu=003
		     <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
		     <idle>-0	  [003] 158131.569730: sched_wakeup: comm=ksoftirqd/3 pid=13 prio=49 success=1 target_cpu=003
		     <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

	   Average wakeup latency: 110.021 usecs

       The above version will only show the wakeups and context switches of Real Time tasks. The prio used inside the kernel starts at 0 for
       highest priority. That is prio 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.

SEE ALSO

       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)

AUTHOR

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

RESOURCES

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

COPYING

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

NOTES

	1. rostedt@goodmis.org
	   mailto:rostedt@goodmis.org

								    06/11/2014						       TRACE-CMD-REPORT(1)