TRACE-CMD-RECORD(1) | [FIXME: manual] | TRACE-CMD-RECORD(1) |
NAME¶
trace-cmd-record - record a trace from the Ftrace Linux internal tracer
SYNOPSIS¶
trace-cmd record [OPTIONS] [command]
DESCRIPTION¶
The trace-cmd(1) record command will set up the Ftrace Linux kernel tracer to record the specified plugins or events that happen while the command executes. If no command is given, then it will record until the user hits Ctrl-C.
The record command of trace-cmd will set up the Ftrace tracer to start tracing the various events or plugins that are given on the command line. It will then create a number of tracing processes (one per CPU) that will start recording from the kernel ring buffer straight into temporary files. When the command is complete (or Ctrl-C is hit) all the files will be combined into a trace.dat file that can later be read (see trace-cmd-report(1)).
OPTIONS¶
-p plugin
-e event
The ´event´ can also contain glob expressions. That is, "*stat*" will select all events (or subsystems) that have the characters "stat" in their names.
The keyword ´all´ can be used to enable all events.
-a
-T
<idle>-0 [003] 58549.289091: sched_switch: kworker/0:1:0 [120] R ==> trace-cmd:2603 [120]
<idle>-0 [003] 58549.289092: kernel_stack: <stack trace> => schedule (ffffffff814b260e) => cpu_idle (ffffffff8100a38c) => start_secondary (ffffffff814ab828)
--func-stack
-f filter
==, >=, <=, >, <, &, |, && and ||
The above are usually safe to use to compare fields.
-v
Note: the *-v* option was taken from the way grep(1) inverts the following matches.
-F
-P pid
-c
-o output-file
-l function-name
-g function-name
-n function-name
-d
-O option
-s interval
The ´interval´ metric is microseconds. The default is set to 1000 (1 ms). This is the time each recording process will sleep before waking up to record any new data that was written to the ring buffer.
-r priority
-b size
-k
Note: usually trace-cmd will set the "tracing_on" file back to what it was before it was called. This option will leave that file set to zero.
-i
-N host:port
Note: This option is not supported with latency tracer plugins:
wakeup, wakeup_rt, irqsoff, preemptoff and preemptirqsoff
-t
--date
EXAMPLES¶
The basic way to trace all events:
# trace-cmd record -e all ls > /dev/null
# trace-cmd report
trace-cmd-13541 [003] 106260.693809: filemap_fault: address=0x128122 offset=0xce
trace-cmd-13543 [001] 106260.693809: kmalloc: call_site=81128dd4 ptr=0xffff88003dd83800 bytes_req=768 bytes_alloc=1024 gfp_flags=GFP_KERNEL|GFP_ZERO
ls-13545 [002] 106260.693809: kfree: call_site=810a7abb ptr=0x0
ls-13545 [002] 106260.693818: sys_exit_write: 0x1
To use the function tracer with sched switch tracing:
# trace-cmd record -p function -e sched_switch ls > /dev/null
# trace-cmd report
ls-13587 [002] 106467.860310: function: hrtick_start_fair <-- pick_next_task_fair
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
trace-cmd-13585 [001] 106467.860314: function: native_set_pte_at <-- __do_fault
trace-cmd-13586 [003] 106467.860314: function: up_read <-- do_page_fault
ls-13587 [002] 106467.860317: function: __phys_addr <-- schedule
trace-cmd-13585 [001] 106467.860318: function: _raw_spin_unlock <-- __do_fault
ls-13587 [002] 106467.860320: function: native_load_sp0 <-- __switch_to
trace-cmd-13586 [003] 106467.860322: function: down_read_trylock <-- do_page_fault
Here is a nice way to find what interrupts have the highest latency:
# trace-cmd record -p function_graph -e irq_handler_entry -l do_IRQ sleep 10
# trace-cmd report
<idle>-0 [000] 157412.933969: funcgraph_entry: | do_IRQ() {
<idle>-0 [000] 157412.933974: irq_handler_entry: irq=48 name=eth0
<idle>-0 [000] 157412.934004: funcgraph_exit: + 36.358 us | }
<idle>-0 [000] 157413.895004: funcgraph_entry: | do_IRQ() {
<idle>-0 [000] 157413.895011: irq_handler_entry: irq=48 name=eth0
<idle>-0 [000] 157413.895026: funcgraph_exit: + 24.014 us | }
<idle>-0 [000] 157415.891762: funcgraph_entry: | do_IRQ() {
<idle>-0 [000] 157415.891769: irq_handler_entry: irq=48 name=eth0
<idle>-0 [000] 157415.891784: funcgraph_exit: + 22.928 us | }
<idle>-0 [000] 157415.934869: funcgraph_entry: | do_IRQ() {
<idle>-0 [000] 157415.934874: irq_handler_entry: irq=48 name=eth0
<idle>-0 [000] 157415.934906: funcgraph_exit: + 37.512 us | }
<idle>-0 [000] 157417.888373: funcgraph_entry: | do_IRQ() {
<idle>-0 [000] 157417.888381: irq_handler_entry: irq=48 name=eth0
<idle>-0 [000] 157417.888398: funcgraph_exit: + 25.943 us | }
SEE ALSO¶
trace-cmd(1), trace-cmd-report(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
03/22/2017 | [FIXME: source] |