1TRACE-CMD-RECORD(1)                                        TRACE-CMD-RECORD(1)
2
3
4

NAME

6       trace-cmd-record - record a trace from the Ftrace Linux internal tracer
7

SYNOPSIS

9       trace-cmd record [OPTIONS] [command]
10

DESCRIPTION

12       The trace-cmd(1) record command will set up the Ftrace Linux kernel
13       tracer to record the specified plugins or events that happen while the
14       command executes. If no command is given, then it will record until the
15       user hits Ctrl-C.
16
17       The record command of trace-cmd will set up the Ftrace tracer to start
18       tracing the various events or plugins that are given on the command
19       line. It will then create a number of tracing processes (one per CPU)
20       that will start recording from the kernel ring buffer straight into
21       temporary files. When the command is complete (or Ctrl-C is hit) all
22       the files will be combined into a trace.dat file that can later be read
23       (see trace-cmd-report(1)).
24

OPTIONS

26       -p plugin
27           Specify a trace plugin. Plugins are special Ftrace tracers that
28           usually do more than just trace an event. Common plugins are
29           function, function_graph, preemptirqsoff, irqsoff, preemptoff, and
30           wakeup. A plugin must be supported by the running kernel. To see a
31           list of available plugins, see trace-cmd-list(1).
32
33       -e event
34           Specify an event to trace. Various static trace points have been
35           added to the Linux kernel. They are grouped by subsystem where you
36           can enable all events of a given subsystem or specify specific
37           events to be enabled. The event is of the format
38           "subsystem:event-name". You can also just specify the subsystem
39           without the :event-name or the event-name without the "subsystem:".
40           Using "-e sched_switch" will enable the "sched_switch" event where
41           as, "-e sched" will enable all events under the "sched" subsystem.
42
43               The 'event' can also contain glob expressions. That is, "*stat*" will
44               select all events (or subsystems) that have the characters "stat" in their
45               names.
46
47               The keyword 'all' can be used to enable all events.
48
49       -a
50           Every event that is being recorded has its output format file saved
51           in the output file to be able to display it later. But if other
52           events are enabled in the trace without trace-cmd’s knowledge, the
53           formats of those events will not be recorded and trace-cmd report
54           will not be able to display them. If this is the case, then specify
55           the -a option and the format for all events in the system will be
56           saved.
57
58       -T
59           Enable a stacktrace on each event. For example:
60
61                         <idle>-0     [003] 58549.289091: sched_switch:         kworker/0:1:0 [120] R ==> trace-cmd:2603 [120]
62                         <idle>-0     [003] 58549.289092: kernel_stack:         <stack trace>
63               => schedule (ffffffff814b260e)
64               => cpu_idle (ffffffff8100a38c)
65               => start_secondary (ffffffff814ab828)
66
67       --func-stack
68           Enable a stack trace on all functions. Note this is only applicable
69           for the "function" plugin tracer, and will only take effect if the
70           -l option is used and succeeds in limiting functions. If the
71           function tracer is not filtered, and the stack trace is enabled,
72           you can live lock the machine.
73
74       -f filter
75           Specify a filter for the previous event. This must come after a -e.
76           This will filter what events get recorded based on the content of
77           the event. Filtering is passed to the kernel directly so what
78           filtering is allowed may depend on what version of the kernel you
79           have. Basically, it will let you use C notation to check if an
80           event should be processed or not.
81
82               ==, >=, <=, >, <, &, |, && and ||
83
84           The above are usually safe to use to compare fields.
85
86       -R trigger
87           Specify a trigger for the previous event. This must come after a
88           -e. This will add a given trigger to the given event. To only
89           enable the trigger and not the event itself, then place the event
90           after the -v option.
91
92               See Documentation/trace/events.txt in the Linux kernel source for more
93               information on triggers.
94
95       -v
96           This will cause all events specified after it on the command line
97           to not be traced. This is useful for selecting a subsystem to be
98           traced but to leave out various events. For Example: "-e sched -v
99           -e "*stat\*"" will enable all events in the sched subsystem except
100           those that have "stat" in their names.
101
102               Note: the *-v* option was taken from the way grep(1) inverts the following
103               matches.
104
105       -F
106           This will filter only the executable that is given on the command
107           line. If no command is given, then it will filter itself (pretty
108           pointless). Using -F will let you trace only events that are caused
109           by the given command.
110
111       -P pid
112           Similar to -F but lets you specify a process ID to trace.
113
114       -c
115           Used with either -F to trace the process' children too.
116
117       -C clock
118           Set the trace clock to "clock".
119
120               Use trace-cmd(1) list -C to see what clocks are available.
121
122       -o output-file
123           By default, trace-cmd report will create a trace.dat file. You can
124           specify a different file to write to with the -o option.
125
126       -l function-name
127           This will limit the function and function_graph tracers to only
128           trace the given function name. More than one -l may be specified on
129           the command line to trace more than one function. The limited use
130           of glob expressions are also allowed. These are match* to only
131           filter functions that start with match.  *match to only filter
132           functions that end with match.  *match\* to only filter on
133           functions that contain match.
134
135       -g function-name
136           This option is for the function_graph plugin. It will graph the
137           given function. That is, it will only trace the function and all
138           functions that it calls. You can have more than one -g on the
139           command line.
140
141       -n function-name
142           This has the opposite effect of -l. The function given with the -n
143           option will not be traced. This takes precedence, that is, if you
144           include the same function for both -n and -l, it will not be
145           traced.
146
147       -d
148           Some tracer plugins enable the function tracer by default. Like the
149           latency tracers. This option prevents the function tracer from
150           being enabled at start up.
151
152       -D
153           The option -d will try to use the function-trace option to disable
154           the function tracer (if available), otherwise it defaults to the
155           proc file: /proc/sys/kernel/ftrace_enabled, but will not touch it
156           if the function-trace option is available. The -D option will
157           disable both the ftrace_enabled proc file as well as the
158           function-trace option if it exists.
159
160               Note, this disable function tracing for all users, which includes users
161               outside of ftrace tracers (stack_tracer, perf, etc).
162
163       -O option
164           Ftrace has various options that can be enabled or disabled. This
165           allows you to set them. Appending the text no to an option disables
166           it. For example: "-O nograph-time" will disable the "graph-time"
167           Ftrace option.
168
169       -s interval
170           The processes that trace-cmd creates to record from the ring buffer
171           need to wake up to do the recording. Setting the interval to zero
172           will cause the processes to wakeup every time new data is written
173           into the buffer. But since Ftrace is recording kernel activity, the
174           act of this processes going back to sleep may cause new events into
175           the ring buffer which will wake the process back up. This will
176           needlessly add extra data into the ring buffer.
177
178               The 'interval' metric is microseconds. The default is set to 1000 (1 ms).
179               This is the time each recording process will sleep before waking up to
180               record any new data that was written to the ring buffer.
181
182       -r priority
183           The priority to run the capture threads at. In a busy system the
184           trace capturing threads may be staved and events can be lost. This
185           increases the priority of those threads to the real time (FIFO)
186           priority. But use this option with care, it can also change the
187           behaviour of the system being traced.
188
189       -b size
190           This sets the ring buffer size to size kilobytes. Because the
191           Ftrace ring buffer is per CPU, this size is the size of each per
192           CPU ring buffer inside the kernel. Using "-b 10000" on a machine
193           with 4 CPUs will make Ftrace have a total buffer size of 40 Megs.
194
195       -B buffer-name
196           If the kernel supports multiple buffers, this will add a buffer
197           with the given name. If the buffer name already exists, that buffer
198           is just reset and will not be deleted at the end of record
199           execution. If the buffer is created, it will be removed at the end
200           of execution (unless the -k is set, or start command was used).
201
202               After a buffer name is stated, all events added after that will be
203               associated with that buffer. If no buffer is specified, or an event
204               is specified before a buffer name, it will be associated with the
205               main (toplevel) buffer.
206
207               trace-cmd record -e sched -B block -e block -B time -e timer sleep 1
208
209               The above is will enable all sched events in the main buffer. It will
210               then create a 'block' buffer instance and enable all block events within
211               that buffer. A 'time' buffer instance is created and all timer events
212               will be enabled for that event.
213
214       -m size
215           The max size in kilobytes that a per cpu buffer should be. Note,
216           due to rounding to page size, the number may not be totally
217           correct. Also, this is performed by switching between two buffers
218           that are half the given size thus the output may not be of the
219           given size even if much more was written.
220
221               Use this to prevent running out of diskspace for long runs.
222
223       -M cpumask
224           Set the cpumask for to trace. It only affects the last buffer
225           instance given. If supplied before any buffer instance, then it
226           affects the main buffer. The value supplied must be a hex number.
227
228               trace-cmd record -p function -M c -B events13 -e all -M 5
229
230               If the -M is left out, then the mask stays the same. To enable all
231               CPUs, pass in a value of '-1'.
232
233       -k
234           By default, when trace-cmd is finished tracing, it will reset the
235           buffers and disable all the tracing that it enabled. This option
236           keeps trace-cmd from disabling the tracer and reseting the buffer.
237           This option is useful for debugging trace-cmd.
238
239               Note: usually trace-cmd will set the "tracing_on" file back to what it
240               was before it was called. This option will leave that file set to zero.
241
242       -i
243           By default, if an event is listed that trace-cmd does not find, it
244           will exit with an error. This option will just ignore events that
245           are listed on the command line but are not found on the system.
246
247       -N host:port
248           If another machine is running "trace-cmd listen", this option is
249           used to have the data sent to that machine with UDP packets.
250           Instead of writing to an output file, the data is sent off to a
251           remote box. This is ideal for embedded machines with little
252           storage, or having a single machine that will keep all the data in
253           a single repository.
254
255               Note: This option is not supported with latency tracer plugins:
256                 wakeup, wakeup_rt, irqsoff, preemptoff and preemptirqsoff
257
258       -t
259           This option is used with -N, when there’s a need to send the live
260           data with TCP packets instead of UDP. Although TCP is not nearly as
261           fast as sending the UDP packets, but it may be needed if the
262           network is not that reliable, the amount of data is not that
263           intensive, and a guarantee is needed that all traced information is
264           transfered successfully.
265
266       --date
267           With the --date option, "trace-cmd" will write timestamps into the
268           trace buffer after it has finished recording. It will then map the
269           timestamp to gettimeofday which will allow wall time output from
270           the timestamps reading the created trace.dat file.
271
272       --max-graph-depth depth
273           Set the maximum depth the function_graph tracer will trace into a
274           function. A value of one will only show where userspace enters the
275           kernel but not any functions called in the kernel. The default is
276           zero, which means no limit.
277
278       --profile
279           With the --profile option, "trace-cmd" will enable tracing that can
280           be used with trace-cmd-report(1) --profile option. If a tracer -p
281           is not set, and function graph depth is supported by the kernel,
282           then the function_graph tracer will be enabled with a depth of one
283           (only show where userspace enters into the kernel). It will also
284           enable various tracepoints with stack tracing such that the report
285           can show where tasks have been blocked for the longest time.
286
287               See trace-cmd-profile(1) for more details and examples.
288
289       -H event-hooks
290           Add custom event matching to connect any two events together. When
291           not used with --profile, it will save the parameter and this will
292           be used by trace-cmd report --profile, too. That is:
293
294               trace-cmd record -H hrtimer_expire_entry,hrtimer/hrtimer_expire_exit,hrtimer,sp
295               trace-cmd report --profile
296
297               Will profile hrtimer_expire_entry and hrtimer_expire_ext times.
298
299               See trace-cmd-profile(1) for format.
300
301       --ts-offset offset
302           Add an offset for the timestamp in the trace.dat file. This will
303           add a offset option into the trace.dat file such that a trace-cmd
304           report will offset all the timestamps of the events by the given
305           offset. The offset is in raw units. That is, if the event
306           timestamps are in nanoseconds the offset will also be in
307           nanoseconds even if the displayed units are in microseconds.
308
309       --stderr
310           Have output go to stderr instead of stdout, but the output of the
311           command executed will not be changed. This is useful if you want to
312           monitor the output of the command being executed, but not see the
313           output from trace-cmd.
314

EXAMPLES

316       The basic way to trace all events:
317
318            # trace-cmd record -e all ls > /dev/null
319            # trace-cmd report
320                  trace-cmd-13541 [003] 106260.693809: filemap_fault: address=0x128122 offset=0xce
321                  trace-cmd-13543 [001] 106260.693809: kmalloc: call_site=81128dd4 ptr=0xffff88003dd83800 bytes_req=768 bytes_alloc=1024 gfp_flags=GFP_KERNEL|GFP_ZERO
322                         ls-13545 [002] 106260.693809: kfree: call_site=810a7abb ptr=0x0
323                         ls-13545 [002] 106260.693818: sys_exit_write:       0x1
324
325       To use the function tracer with sched switch tracing:
326
327            # trace-cmd record -p function -e sched_switch ls > /dev/null
328            # trace-cmd report
329                         ls-13587 [002] 106467.860310: function: hrtick_start_fair <-- pick_next_task_fair
330                         ls-13587 [002] 106467.860313: sched_switch: prev_comm=trace-cmd prev_pid=13587 prev_prio=120 prev_state=R ==> next_comm=trace-cmd next_pid=13583 next_prio=120
331                  trace-cmd-13585 [001] 106467.860314: function: native_set_pte_at <-- __do_fault
332                  trace-cmd-13586 [003] 106467.860314: function:             up_read <-- do_page_fault
333                         ls-13587 [002] 106467.860317: function:             __phys_addr <-- schedule
334                  trace-cmd-13585 [001] 106467.860318: function: _raw_spin_unlock <-- __do_fault
335                         ls-13587 [002] 106467.860320: function: native_load_sp0 <-- __switch_to
336                  trace-cmd-13586 [003] 106467.860322: function: down_read_trylock <-- do_page_fault
337
338       Here is a nice way to find what interrupts have the highest latency:
339
340            # trace-cmd record -p function_graph -e irq_handler_entry  -l do_IRQ sleep 10
341            # trace-cmd report
342                     <idle>-0     [000] 157412.933969: funcgraph_entry:                  |  do_IRQ() {
343                     <idle>-0     [000] 157412.933974: irq_handler_entry:    irq=48 name=eth0
344                     <idle>-0     [000] 157412.934004: funcgraph_exit:       + 36.358 us |  }
345                     <idle>-0     [000] 157413.895004: funcgraph_entry:                  |  do_IRQ() {
346                     <idle>-0     [000] 157413.895011: irq_handler_entry:    irq=48 name=eth0
347                     <idle>-0     [000] 157413.895026: funcgraph_exit:                        + 24.014 us |  }
348                     <idle>-0     [000] 157415.891762: funcgraph_entry:                  |  do_IRQ() {
349                     <idle>-0     [000] 157415.891769: irq_handler_entry:    irq=48 name=eth0
350                     <idle>-0     [000] 157415.891784: funcgraph_exit:       + 22.928 us |  }
351                     <idle>-0     [000] 157415.934869: funcgraph_entry:                  |  do_IRQ() {
352                     <idle>-0     [000] 157415.934874: irq_handler_entry:    irq=48 name=eth0
353                     <idle>-0     [000] 157415.934906: funcgraph_exit:       + 37.512 us |  }
354                     <idle>-0     [000] 157417.888373: funcgraph_entry:                  |  do_IRQ() {
355                     <idle>-0     [000] 157417.888381: irq_handler_entry:    irq=48 name=eth0
356                     <idle>-0     [000] 157417.888398: funcgraph_exit:       + 25.943 us |  }
357
358       An example of the profile:
359
360            # trace-cmd record --profile sleep 1
361            # trace-cmd report --profile --comm sleep
362           task: sleep-21611
363             Event: sched_switch:R (1) Total: 99442 Avg: 99442 Max: 99442 Min:99442
364                <stack> 1 total:99442 min:99442 max:99442 avg=99442
365                  => ftrace_raw_event_sched_switch (0xffffffff8105f812)
366                  => __schedule (0xffffffff8150810a)
367                  => preempt_schedule (0xffffffff8150842e)
368                  => ___preempt_schedule (0xffffffff81273354)
369                  => cpu_stop_queue_work (0xffffffff810b03c5)
370                  => stop_one_cpu (0xffffffff810b063b)
371                  => sched_exec (0xffffffff8106136d)
372                  => do_execve_common.isra.27 (0xffffffff81148c89)
373                  => do_execve (0xffffffff811490b0)
374                  => SyS_execve (0xffffffff811492c4)
375                  => return_to_handler (0xffffffff8150e3c8)
376                  => stub_execve (0xffffffff8150c699)
377             Event: sched_switch:S (1) Total: 1000506680 Avg: 1000506680 Max: 1000506680 Min:1000506680
378                <stack> 1 total:1000506680 min:1000506680 max:1000506680 avg=1000506680
379                  => ftrace_raw_event_sched_switch (0xffffffff8105f812)
380                  => __schedule (0xffffffff8150810a)
381                  => schedule (0xffffffff815084b8)
382                  => do_nanosleep (0xffffffff8150b22c)
383                  => hrtimer_nanosleep (0xffffffff8108d647)
384                  => SyS_nanosleep (0xffffffff8108d72c)
385                  => return_to_handler (0xffffffff8150e3c8)
386                  => tracesys_phase2 (0xffffffff8150c304)
387             Event: sched_wakeup:21611 (1) Total: 30326 Avg: 30326 Max: 30326 Min:30326
388                <stack> 1 total:30326 min:30326 max:30326 avg=30326
389                  => ftrace_raw_event_sched_wakeup_template (0xffffffff8105f653)
390                  => ttwu_do_wakeup (0xffffffff810606eb)
391                  => ttwu_do_activate.constprop.124 (0xffffffff810607c8)
392                  => try_to_wake_up (0xffffffff8106340a)
393

SEE ALSO

395       trace-cmd(1), trace-cmd-report(1), trace-cmd-start(1),
396       trace-cmd-stop(1), trace-cmd-extract(1), trace-cmd-reset(1),
397       trace-cmd-split(1), trace-cmd-list(1), trace-cmd-listen(1),
398       trace-cmd-profile(1)
399

AUTHOR

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

RESOURCES

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

COPYING

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

NOTES

411        1. rostedt@goodmis.org
412           mailto:rostedt@goodmis.org
413
414
415
416                                  04/11/2018               TRACE-CMD-RECORD(1)
Impressum