Introduction¶

Ftrace is an internal tracer designed to help out developers anddesigners of systems to find what is going on inside the kernel.It can be used for debugging or analyzing latencies andperformance issues that take place outside of user-space.

Although ftrace is typically considered the function tracer, itis really a framework of several assorted tracing utilities.There’s latency tracing to examine what occurs between interruptsdisabled and enabled, as well as for preemption and from a timea task is woken to the task is actually scheduled in.

One of the most common uses of ftrace is the event tracing.Throughout the kernel is hundreds of static event points thatcan be enabled via the tracefs file system to see what isgoing on in certain parts of the kernel.

See events.rst for more information.

Implementation Details¶

SeeFunction Tracer Design for details for arch porters and such.

The File System¶

Ftrace uses the tracefs file system to hold the control files aswell as the files to display output.

When tracefs is configured into the kernel (which selecting any ftraceoption will do) the directory /sys/kernel/tracing will be created. To mountthis directory, you can add to your /etc/fstab file:

tracefs       /sys/kernel/tracing       tracefs defaults        0       0

Or you can mount it at run time with:

mount -t tracefs nodev /sys/kernel/tracing

For quicker access to that directory you may want to make a soft link toit:

ln -s /sys/kernel/tracing /tracing

That’s it! (assuming that you have ftrace configured into your kernel)

After mounting tracefs you will have access to the control and output filesof ftrace. Here is a list of some of the key files:

Note: all time values are in microseconds.

current_tracer:

This is used to set or display the current tracerthat is configured. Changing the current tracer clearsthe ring buffer content as well as the “snapshot” buffer.

available_tracers:

This holds the different types of tracers thathave been compiled into the kernel. Thetracers listed here can be configured byechoing their name into current_tracer.

tracing_on:

This sets or displays whether writing to the tracering buffer is enabled. Echo 0 into this file to disablethe tracer or 1 to enable it. Note, this only disableswriting to the ring buffer, the tracing overhead maystill be occurring.

The kernel function tracing_off() can be used within thekernel to disable writing to the ring buffer, which willset this file to “0”. User space can re-enable tracing byechoing “1” into the file.

Note, the function and event trigger “traceoff” will alsoset this file to zero and stop tracing. Which can alsobe re-enabled by user space using this file.

trace:

This file holds the output of the trace in a humanreadable format (described below). Opening this file forwriting with the O_TRUNC flag clears the ring buffer content.Note, this file is not a consumer. If tracing is off(no tracer running, or tracing_on is zero), it will producethe same output each time it is read. When tracing is on,it may produce inconsistent results as it tries to readthe entire buffer without consuming it.

trace_pipe:

The output is the same as the “trace” file but thisfile is meant to be streamed with live tracing.Reads from this file will block until new data isretrieved. Unlike the “trace” file, this file is aconsumer. This means reading from this file causessequential reads to display more current data. Oncedata is read from this file, it is consumed, andwill not be read again with a sequential read. The“trace” file is static, and if the tracer is notadding more data, it will display the sameinformation every time it is read.

trace_options:

This file lets the user control the amount of datathat is displayed in one of the above outputfiles. Options also exist to modify how a traceror events work (stack traces, timestamps, etc).

options:

This is a directory that has a file for every availabletrace option (also in trace_options). Options may also be setor cleared by writing a “1” or “0” respectively into thecorresponding file with the option name.

tracing_max_latency:

Some of the tracers record the max latency.For example, the maximum time that interrupts are disabled.The maximum time is saved in this file. The max trace will also bestored, and displayed by “trace”. A new max trace will only berecorded if the latency is greater than the value in this file(in microseconds).

By echoing in a time into this file, no latency will be recordedunless it is greater than the time in this file.

tracing_thresh:

Some latency tracers will record a trace whenever thelatency is greater than the number in this file.Only active when the file contains a number greater than 0.(in microseconds)

buffer_size_kb:

This sets or displays the number of kilobytes each CPUbuffer holds. By default, the trace buffers are the same sizefor each CPU. The displayed number is the size of theCPU buffer and not total size of all buffers. Thetrace buffers are allocated in pages (blocks of memorythat the kernel uses for allocation, usually 4 KB in size).A few extra pages may be allocated to accommodate buffer managementmeta-data. If the last page allocated has room for more bytesthan requested, the rest of the page will be used,making the actual allocation bigger than requested or shown.( Note, the size may not be a multiple of the page sizedue to buffer management meta-data. )

Buffer sizes for individual CPUs may vary(see “per_cpu/cpu0/buffer_size_kb” below), and if they dothis file will show “X”.

buffer_total_size_kb:

This displays the total combined size of all the trace buffers.

free_buffer:

If a process is performing tracing, and the ring buffer should beshrunk “freed” when the process is finished, even if it were to bekilled by a signal, this file can be used for that purpose. On closeof this file, the ring buffer will be resized to its minimum size.Having a process that is tracing also open this file, when the processexits its file descriptor for this file will be closed, and in doing so,the ring buffer will be “freed”.

It may also stop tracing if disable_on_free option is set.

tracing_cpumask:

This is a mask that lets the user only trace on specified CPUs.The format is a hex string representing the CPUs.

set_ftrace_filter:

When dynamic ftrace is configured in (see thesection below “dynamic ftrace”), the code is dynamicallymodified (code text rewrite) to disable calling of thefunction profiler (mcount). This lets tracing be configuredin with practically no overhead in performance. This alsohas a side effect of enabling or disabling specific functionsto be traced. Echoing names of functions into this filewill limit the trace to only those functions.This influences the tracers “function” and “function_graph”and thus also function profiling (see “function_profile_enabled”).

The functions listed in “available_filter_functions” are whatcan be written into this file.

This interface also allows for commands to be used. See the“Filter commands” section for more details.

As a speed up, since processing strings can be quite expensiveand requires a check of all functions registered to tracing, insteadan index can be written into this file. A number (starting with “1”)written will instead select the same corresponding at the line positionof the “available_filter_functions” file.

set_ftrace_notrace:

This has an effect opposite to that ofset_ftrace_filter. Any function that is added here will notbe traced. If a function exists in both set_ftrace_filterand set_ftrace_notrace, the function will _not_ be traced.

set_ftrace_pid:

Have the function tracer only trace the threads whose PID arelisted in this file.

If the “function-fork” option is set, then when a task whosePID is listed in this file forks, the child’s PID willautomatically be added to this file, and the child will betraced by the function tracer as well. This option will alsocause PIDs of tasks that exit to be removed from the file.

set_ftrace_notrace_pid:

Have the function tracer ignore threads whose PID are listed inthis file.

If the “function-fork” option is set, then when a task whosePID is listed in this file forks, the child’s PID willautomatically be added to this file, and the child will not betraced by the function tracer as well. This option will alsocause PIDs of tasks that exit to be removed from the file.

If a PID is in both this file and “set_ftrace_pid”, then thisfile takes precedence, and the thread will not be traced.

set_event_pid:

Have the events only trace a task with a PID listed in this file.Note, sched_switch and sched_wake_up will also trace eventslisted in this file.

To have the PIDs of children of tasks with their PID in this fileadded on fork, enable the “event-fork” option. That option will alsocause the PIDs of tasks to be removed from this file when the taskexits.

set_event_notrace_pid:

Have the events not trace a task with a PID listed in this file.Note, sched_switch and sched_wakeup will trace threads not listedin this file, even if a thread’s PID is in the file if thesched_switch or sched_wakeup events also trace a thread that shouldbe traced.

To have the PIDs of children of tasks with their PID in this fileadded on fork, enable the “event-fork” option. That option will alsocause the PIDs of tasks to be removed from this file when the taskexits.

set_graph_function:

Functions listed in this file will cause the function graphtracer to only trace these functions and the functions thatthey call. (See the section “dynamic ftrace” for more details).Note, set_ftrace_filter and set_ftrace_notrace still affectswhat functions are being traced.

set_graph_notrace:

Similar to set_graph_function, but will disable function graphtracing when the function is hit until it exits the function.This makes it possible to ignore tracing functions that are calledby a specific function.

available_filter_functions:

This lists the functions that ftrace has processed and can trace.These are the function names that you can pass to“set_ftrace_filter”, “set_ftrace_notrace”,“set_graph_function”, or “set_graph_notrace”.(See the section “dynamic ftrace” below for more details.)

dyn_ftrace_total_info:

This file is for debugging purposes. The number of functions thathave been converted to nops and are available to be traced.

enabled_functions:

This file is more for debugging ftrace, but can also be usefulin seeing if any function has a callback attached to it.Not only does the trace infrastructure use ftrace functiontrace utility, but other subsystems might too. This filedisplays all functions that have a callback attached to themas well as the number of callbacks that have been attached.Note, a callback may also call multiple functions which willnot be listed in this count.

If the callback registered to be traced by a function withthe “save regs” attribute (thus even more overhead), a ‘R’will be displayed on the same line as the function thatis returning registers.

If the callback registered to be traced by a function withthe “ip modify” attribute (thus the regs->ip can be changed),an ‘I’ will be displayed on the same line as the function thatcan be overridden.

If the architecture supports it, it will also show what callbackis being directly called by the function. If the count is greaterthan 1 it most likely will be ftrace_ops_list_func().

If the callback of the function jumps to a trampoline that isspecific to a the callback and not the standard trampoline,its address will be printed as well as the function that thetrampoline calls.

function_profile_enabled:

When set it will enable all functions with either the functiontracer, or if configured, the function graph tracer. It willkeep a histogram of the number of functions that were calledand if the function graph tracer was configured, it will also keeptrack of the time spent in those functions. The histogramcontent can be displayed in the files:

trace_stat/function<cpu> ( function0, function1, etc).

trace_stat:

A directory that holds different tracing stats.

kprobe_events:

Enable dynamic trace points. See kprobetrace.rst.

kprobe_profile:

Dynamic trace points stats. See kprobetrace.rst.

max_graph_depth:

Used with the function graph tracer. This is the max depthit will trace into a function. Setting this to a value ofone will show only the first kernel function that is calledfrom user space.

printk_formats:

This is for tools that read the raw format files. If an event inthe ring buffer references a string, only a pointer to the stringis recorded into the buffer and not the string itself. This preventstools from knowing what that string was. This file displays the stringand address for the string allowing tools to map the pointers to whatthe strings were.

saved_cmdlines:

Only the pid of the task is recorded in a trace event unlessthe event specifically saves the task comm as well. Ftracemakes a cache of pid mappings to comms to try to displaycomms for events. If a pid for a comm is not listed, then“<…>” is displayed in the output.

If the option “record-cmd” is set to “0”, then comms of taskswill not be saved during recording. By default, it is enabled.

saved_cmdlines_size:

By default, 128 comms are saved (see “saved_cmdlines” above). Toincrease or decrease the amount of comms that are cached, echothe number of comms to cache into this file.

saved_tgids:

If the option “record-tgid” is set, on each scheduling context switchthe Task Group ID of a task is saved in a table mapping the PID ofthe thread to its TGID. By default, the “record-tgid” option isdisabled.

snapshot:

This displays the “snapshot” buffer and also lets the usertake a snapshot of the current running trace.See the “Snapshot” section below for more details.

stack_max_size:

When the stack tracer is activated, this will display themaximum stack size it has encountered.See the “Stack Trace” section below.

stack_trace:

This displays the stack back trace of the largest stackthat was encountered when the stack tracer is activated.See the “Stack Trace” section below.

stack_trace_filter:

This is similar to “set_ftrace_filter” but it limits whatfunctions the stack tracer will check.

trace_clock:

Whenever an event is recorded into the ring buffer, a“timestamp” is added. This stamp comes from a specifiedclock. By default, ftrace uses the “local” clock. Thisclock is very fast and strictly per cpu, but on somesystems it may not be monotonic with respect to otherCPUs. In other words, the local clocks may not be in syncwith local clocks on other CPUs.

Usual clocks for tracing:

# cat trace_clock[local] global counter x86-tsc

The clock with the square brackets around it is the one in effect.

local:

Default clock, but may not be in sync across CPUs

global:

This clock is in sync with all CPUs but maybe a bit slower than the local clock.

counter:

This is not a clock at all, but literally an atomiccounter. It counts up one by one, but is in syncwith all CPUs. This is useful when you need toknow exactly the order events occurred with respect toeach other on different CPUs.

uptime:

This uses the jiffies counter and the time stampis relative to the time since boot up.

perf:

This makes ftrace use the same clock that perf uses.Eventually perf will be able to read ftrace buffersand this will help out in interleaving the data.

x86-tsc:

Architectures may define their own clocks. Forexample, x86 uses its own TSC cycle clock here.

ppc-tb:

This uses the powerpc timebase register value.This is in sync across CPUs and can also be usedto correlate events across hypervisor/guest iftb_offset is known.

mono:

This uses the fast monotonic clock (CLOCK_MONOTONIC)which is monotonic and is subject to NTP rate adjustments.

mono_raw:

This is the raw monotonic clock (CLOCK_MONOTONIC_RAW)which is monotonic but is not subject to any rate adjustmentsand ticks at the same rate as the hardware clocksource.

boot:

This is the boot clock (CLOCK_BOOTTIME) and is based on thefast monotonic clock, but also accounts for time spent insuspend. Since the clock access is designed for use intracing in the suspend path, some side effects are possibleif clock is accessed after the suspend time is accounted beforethe fast mono clock is updated. In this case, the clock updateappears to happen slightly sooner than it normally would have.Also on 32-bit systems, it’s possible that the 64-bit boot offsetsees a partial update. These effects are rare and postprocessing should be able to handle them. See comments in thektime_get_boot_fast_ns() function for more information.

To set a clock, simply echo the clock name into this file:

# echo global > trace_clock

Setting a clock clears the ring buffer content as well as the“snapshot” buffer.

trace_marker:

This is a very useful file for synchronizing user spacewith events happening in the kernel. Writing strings intothis file will be written into the ftrace buffer.

It is useful in applications to open this file at the startof the application and just reference the file descriptorfor the file:

void trace_write(const char *fmt, ...){        va_list ap;        char buf[256];        int n;        if (trace_fd < 0)                return;        va_start(ap, fmt);        n = vsnprintf(buf, 256, fmt, ap);        va_end(ap);        write(trace_fd, buf, n);}

start:

trace_fd = open("trace_marker", WR_ONLY);

Note: Writing into the trace_marker file can also initiate triggers

that are written into /sys/kernel/tracing/events/ftrace/print/triggerSee “Event triggers” in Documentation/trace/events.rst and anexample in Documentation/trace/histogram.rst (Section 3.)

trace_marker_raw:

This is similar to trace_marker above, but is meant for binary datato be written to it, where a tool can be used to parse the datafrom trace_pipe_raw.

uprobe_events:

Add dynamic tracepoints in programs.See uprobetracer.rst

uprobe_profile:

Uprobe statistics. See uprobetrace.txt

instances:

This is a way to make multiple trace buffers where differentevents can be recorded in different buffers.See “Instances” section below.

events:

This is the trace event directory. It holds event tracepoints(also known as static tracepoints) that have been compiledinto the kernel. It shows what event tracepoints existand how they are grouped by system. There are “enable”files at various levels that can enable the tracepointswhen a “1” is written to them.

See events.rst for more information.

set_event:

By echoing in the event into this file, will enable that event.

See events.rst for more information.

available_events:

A list of events that can be enabled in tracing.

See events.rst for more information.

timestamp_mode:

Certain tracers may change the timestamp mode used whenlogging trace events into the event buffer. Events withdifferent modes can coexist within a buffer but the mode ineffect when an event is logged determines which timestamp modeis used for that event. The default timestamp mode is‘delta’.

Usual timestamp modes for tracing:

# cat timestamp_mode[delta] absolute

The timestamp mode with the square brackets around it is theone in effect.

delta: Default timestamp mode - timestamp is a delta against

a per-buffer timestamp.

absolute: The timestamp is a full timestamp, not a delta

against some other value. As such it takes up morespace and is less efficient.

hwlat_detector:

Directory for the Hardware Latency Detector.See “Hardware Latency Detector” section below.

per_cpu:

This is a directory that contains the trace per_cpu information.

per_cpu/cpu0/buffer_size_kb:

The ftrace buffer is defined per_cpu. That is, there’s a separatebuffer for each CPU to allow writes to be done atomically,and free from cache bouncing. These buffers may have differentsize buffers. This file is similar to the buffer_size_kbfile, but it only displays or sets the buffer size for thespecific CPU. (here cpu0).

per_cpu/cpu0/trace:

This is similar to the “trace” file, but it will only displaythe data specific for the CPU. If written to, it only clearsthe specific CPU buffer.

per_cpu/cpu0/trace_pipe

This is similar to the “trace_pipe” file, and is a consumingread, but it will only display (and consume) the data specificfor the CPU.

per_cpu/cpu0/trace_pipe_raw

For tools that can parse the ftrace ring buffer binary format,the trace_pipe_raw file can be used to extract the datafrom the ring buffer directly. With the use of the splice()system call, the buffer data can be quickly transferred toa file or to the network where a server is collecting thedata.

Like trace_pipe, this is a consuming reader, where multiplereads will always produce different data.

per_cpu/cpu0/snapshot:

This is similar to the main “snapshot” file, but will onlysnapshot the current CPU (if supported). It only displaysthe content of the snapshot for a given CPU, and ifwritten to, only clears this CPU buffer.

per_cpu/cpu0/snapshot_raw:

Similar to the trace_pipe_raw, but will read the binary formatfrom the snapshot buffer for the given CPU.

per_cpu/cpu0/stats:

This displays certain stats about the ring buffer:

entries:

The number of events that are still in the buffer.

overrun:

The number of lost events due to overwriting whenthe buffer was full.

commit overrun:

Should always be zero.This gets set if so many events happened within a nestedevent (ring buffer is re-entrant), that it fills thebuffer and starts dropping events.

bytes:

Bytes actually read (not overwritten).

oldest event ts:

The oldest timestamp in the buffer

now ts:

The current timestamp

dropped events:

Events lost due to overwrite option being off.

read events:

The number of events read.

The Tracers¶

Here is the list of current tracers that may be configured.

“function”

Function call tracer to trace all kernel functions.

“function_graph”

Similar to the function tracer except that thefunction tracer probes the functions on their entrywhereas the function graph tracer traces on both entryand exit of the functions. It then provides the abilityto draw a graph of function calls similar to C codesource.

“blk”

The block tracer. The tracer used by the blktrace userapplication.

“hwlat”

The Hardware Latency tracer is used to detect if the hardwareproduces any latency. See “Hardware Latency Detector” sectionbelow.

“irqsoff”

Traces the areas that disable interrupts and savesthe trace with the longest max latency.See tracing_max_latency. When a new max is recorded,it replaces the old trace. It is best to view thistrace with the latency-format option enabled, whichhappens automatically when the tracer is selected.

“preemptoff”

Similar to irqsoff but traces and records the amount oftime for which preemption is disabled.

“preemptirqsoff”

Similar to irqsoff and preemptoff, but traces andrecords the largest time for which irqs and/or preemptionis disabled.

“wakeup”

Traces and records the max latency that it takes forthe highest priority task to get scheduled afterit has been woken up.Traces all tasks as an average developer would expect.

“wakeup_rt”

Traces and records the max latency that it takes for justRT tasks (as the current “wakeup” does). This is usefulfor those interested in wake up timings of RT tasks.

“wakeup_dl”

Traces and records the max latency that it takes fora SCHED_DEADLINE task to be woken (as the “wakeup” and“wakeup_rt” does).

“mmiotrace”

A special tracer that is used to trace binary module.It will trace all the calls that a module makes to thehardware. Everything it writes and reads from the I/Oas well.

“branch”

This tracer can be configured when tracing likely/unlikelycalls within the kernel. It will trace when a likely andunlikely branch is hit and if it was correct in its predictionof being correct.

“nop”

This is the “trace nothing” tracer. To remove alltracers from tracing simply echo “nop” intocurrent_tracer.

Error conditions¶

For most ftrace commands, failure modes are obvious and communicatedusing standard return codes.

For other more involved commands, extended error information may beavailable via the tracing/error_log file. For the commands thatsupport it, reading the tracing/error_log file after an error willdisplay more detailed information about what went wrong, ifinformation is available. The tracing/error_log file is a circularerror log displaying a small number (currently, 8) of ftrace errorsfor the last (8) failed commands.

The extended error information and usage takes the form shown inthis example:

# echo xxx > /sys/kernel/debug/tracing/events/sched/sched_wakeup/triggerecho: write error: Invalid argument# cat /sys/kernel/debug/tracing/error_log[ 5348.887237] location: error: Couldn't yyy: zzz  Command: xxx           ^[ 7517.023364] location: error: Bad rrr: sss  Command: ppp qqq               ^

To clear the error log, echo the empty string into it:

# echo > /sys/kernel/debug/tracing/error_log

Examples of using the tracer¶

Here are typical examples of using the tracers when controllingthem only with the tracefs interface (without using anyuser-land utilities).

Output format:¶

Here is an example of the output format of the file “trace”:

# tracer: function## entries-in-buffer/entries-written: 140080/250280   #P:4##                              _-----=> irqs-off#                             / _----=> need-resched#                            | / _---=> hardirq/softirq#                            || / _--=> preempt-depth#                            ||| /     delay#           TASK-PID   CPU#  ||||    TIMESTAMP  FUNCTION#              | |       |   ||||       |         |            bash-1977  [000] .... 17284.993652: sys_close <-system_call_fastpath            bash-1977  [000] .... 17284.993653: __close_fd <-sys_close            bash-1977  [000] .... 17284.993653: _raw_spin_lock <-__close_fd            sshd-1974  [003] .... 17284.993653: __srcu_read_unlock <-fsnotify            bash-1977  [000] .... 17284.993654: add_preempt_count <-_raw_spin_lock            bash-1977  [000] ...1 17284.993655: _raw_spin_unlock <-__close_fd            bash-1977  [000] ...1 17284.993656: sub_preempt_count <-_raw_spin_unlock            bash-1977  [000] .... 17284.993657: filp_close <-__close_fd            bash-1977  [000] .... 17284.993657: dnotify_flush <-filp_close            sshd-1974  [003] .... 17284.993658: sys_select <-system_call_fastpath            ....

A header is printed with the tracer name that is represented bythe trace. In this case the tracer is “function”. Then it shows thenumber of events in the buffer as well as the total number of entriesthat were written. The difference is the number of entries that werelost due to the buffer filling up (250280 - 140080 = 110200 eventslost).

The header explains the content of the events. Task name “bash”, the taskPID “1977”, the CPU that it was running on “000”, the latency format(explained below), the timestamp in <secs>.<usecs> format, thefunction name that was traced “sys_close” and the parent function thatcalled this function “system_call_fastpath”. The timestamp is the timeat which the function was entered.

Latency trace format¶

When the latency-format option is enabled or when one of the latencytracers is set, the trace file gives somewhat more information to seewhy a latency happened. Here is a typical trace:

# tracer: irqsoff## irqsoff latency trace v1.1.5 on 3.8.0-test+# --------------------------------------------------------------------# latency: 259 us, #4/4, CPU#2 | (M:preempt VP:0, KP:0, SP:0 HP:0 #P:4)#    -----------------#    | task: ps-6143 (uid:0 nice:0 policy:0 rt_prio:0)#    -----------------#  => started at: __lock_task_sighand#  => ended at:   _raw_spin_unlock_irqrestore###                  _------=> CPU##                 / _-----=> irqs-off#                | / _----=> need-resched#                || / _---=> hardirq/softirq#                ||| / _--=> preempt-depth#                |||| /     delay#  cmd     pid   ||||| time  |   caller#     \   /      |||||  \    |   /      ps-6143    2d...    0us!: trace_hardirqs_off <-__lock_task_sighand      ps-6143    2d..1  259us+: trace_hardirqs_on <-_raw_spin_unlock_irqrestore      ps-6143    2d..1  263us+: time_hardirqs_on <-_raw_spin_unlock_irqrestore      ps-6143    2d..1  306us : <stack trace> => trace_hardirqs_on_caller => trace_hardirqs_on => _raw_spin_unlock_irqrestore => do_task_stat => proc_tgid_stat => proc_single_show => seq_read => vfs_read => sys_read => system_call_fastpath

This shows that the current tracer is “irqsoff” tracing the timefor which interrupts were disabled. It gives the trace version (whichnever changes) and the version of the kernel upon which this was executed on(3.8). Then it displays the max latency in microseconds (259 us). The numberof trace entries displayed and the total number (both are four: #4/4).VP, KP, SP, and HP are always zero and are reserved for later use.#P is the number of online CPUs (#P:4).

The task is the process that was running when the latencyoccurred. (ps pid: 6143).

The start and stop (the functions in which the interrupts weredisabled and enabled respectively) that caused the latencies:

• __lock_task_sighand is where the interrupts were disabled.
• _raw_spin_unlock_irqrestore is where they were enabled again.

The next lines after the header are the trace itself. The headerexplains which is which.

cmd: The name of the process in the trace.

pid: The PID of that process.

CPU#: The CPU which the process was running on.

irqs-off: ‘d’ interrupts are disabled. ‘.’ otherwise.

Caution

If the architecture does not support a way toread the irq flags variable, an ‘X’ will alwaysbe printed here.

need-resched:

• ‘N’ both TIF_NEED_RESCHED and PREEMPT_NEED_RESCHED is set,
• ‘n’ only TIF_NEED_RESCHED is set,
• ‘p’ only PREEMPT_NEED_RESCHED is set,
• ‘.’ otherwise.

hardirq/softirq:

• ‘Z’ - NMI occurred inside a hardirq
• ‘z’ - NMI is running
• ‘H’ - hard irq occurred inside a softirq.
• ‘h’ - hard irq is running
• ‘s’ - soft irq is running
• ‘.’ - normal context.

preempt-depth: The level of preempt_disabled

The above is mostly meaningful for kernel developers.

time:

When the latency-format option is enabled, the trace fileoutput includes a timestamp relative to the start of thetrace. This differs from the output when latency-formatis disabled, which includes an absolute timestamp.

delay:

This is just to help catch your eye a bit better. Andneeds to be fixed to be only relative to the same CPU.The marks are determined by the difference between thiscurrent trace and the next trace.

• ‘$’ - greater than 1 second
• ‘@’ - greater than 100 millisecond
• ‘*’ - greater than 10 millisecond
• ‘#’ - greater than 1000 microsecond
• ‘!’ - greater than 100 microsecond
• ‘+’ - greater than 10 microsecond
• ‘ ‘ - less than or equal to 10 microsecond.

The rest is the same as the ‘trace’ file.

Note, the latency tracers will usually end with a back traceto easily find where the latency occurred.

trace_options¶

The trace_options file (or the options directory) is used to controlwhat gets printed in the trace output, or manipulate the tracers.To see what is available, simply cat the file:

cat trace_options      print-parent      nosym-offset      nosym-addr      noverbose      noraw      nohex      nobin      noblock      trace_printk      annotate      nouserstacktrace      nosym-userobj      noprintk-msg-only      context-info      nolatency-format      record-cmd      norecord-tgid      overwrite      nodisable_on_free      irq-info      markers      noevent-fork      function-trace      nofunction-fork      nodisplay-graph      nostacktrace      nobranch

To disable one of the options, echo in the option prepended with“no”:

echo noprint-parent > trace_options

To enable an option, leave off the “no”:

echo sym-offset > trace_options

Here are the available options:

print-parent

On function traces, display the calling (parent)function as well as the function being traced.

print-parent: bash-4000  [01]  1477.606694: simple_strtoul <-kstrtoulnoprint-parent: bash-4000  [01]  1477.606694: simple_strtoul

sym-offset

Display not only the function name, but also theoffset in the function. For example, instead ofseeing just “ktime_get”, you will see“ktime_get+0xb/0x20”.

sym-offset: bash-4000  [01]  1477.606694: simple_strtoul+0x6/0xa0

sym-addr

This will also display the function address as wellas the function name.

sym-addr: bash-4000  [01]  1477.606694: simple_strtoul <c0339346>

verbose

This deals with the trace file when thelatency-format option is enabled.

bash  4000 1 0 00000000 00010a95 [58127d26] 1720.415ms \(+0.000ms): simple_strtoul (kstrtoul)

raw

This will display raw numbers. This option is best foruse with user applications that can translate the rawnumbers better than having it done in the kernel.

hex

Similar to raw, but the numbers will be in a hexadecimal format.

bin

This will print out the formats in raw binary.

block

When set, reading trace_pipe will not block when polled.

trace_printk

Can disabletrace_printk() from writing into the buffer.

annotate

It is sometimes confusing when the CPU buffers are fulland one CPU buffer had a lot of events recently, thusa shorter time frame, were another CPU may have only hada few events, which lets it have older events. Whenthe trace is reported, it shows the oldest events first,and it may look like only one CPU ran (the one with theoldest events). When the annotate option is set, it willdisplay when a new CPU buffer started:

          <idle>-0     [001] dNs4 21169.031481: wake_up_idle_cpu <-add_timer_on          <idle>-0     [001] dNs4 21169.031482: _raw_spin_unlock_irqrestore <-add_timer_on          <idle>-0     [001] .Ns4 21169.031484: sub_preempt_count <-_raw_spin_unlock_irqrestore##### CPU 2 buffer started ####          <idle>-0     [002] .N.1 21169.031484: rcu_idle_exit <-cpu_idle          <idle>-0     [001] .Ns3 21169.031484: _raw_spin_unlock <-clocksource_watchdog          <idle>-0     [001] .Ns3 21169.031485: sub_preempt_count <-_raw_spin_unlock

userstacktrace

This option changes the trace. It records astacktrace of the current user space thread aftereach trace event.

sym-userobj

when user stacktrace are enabled, look up whichobject the address belongs to, and print arelative address. This is especially useful whenASLR is on, otherwise you don’t get a chance toresolve the address to object/file/line afterthe app is no longer running

The lookup is performed when you readtrace,trace_pipe. Example:

a.out-1623  [000] 40874.465068: /root/a.out[+0x480] <-/root/a.out[+0x494] <- /root/a.out[+0x4a8] <- /lib/libc-2.7.so[+0x1e1a6]

printk-msg-only

When set,trace_printk()s will only show the formatand not their parameters (if trace_bprintk() ortrace_bputs() was used to save thetrace_printk()).

context-info

Show only the event data. Hides the comm, PID,timestamp, CPU, and other useful data.

latency-format

This option changes the trace output. When it is enabled,the trace displays additional information about thelatency, as described in “Latency trace format”.

pause-on-trace

When set, opening the trace file for read, will pausewriting to the ring buffer (as if tracing_on was set to zero).This simulates the original behavior of the trace file.When the file is closed, tracing will be enabled again.

record-cmd

When any event or tracer is enabled, a hook is enabledin the sched_switch trace point to fill comm cachewith mapped pids and comms. But this may cause someoverhead, and if you only care about pids, and not thename of the task, disabling this option can lower theimpact of tracing. See “saved_cmdlines”.

record-tgid

When any event or tracer is enabled, a hook is enabledin the sched_switch trace point to fill the cache ofmapped Thread Group IDs (TGID) mapping to pids. See“saved_tgids”.

overwrite

This controls what happens when the trace buffer isfull. If “1” (default), the oldest events arediscarded and overwritten. If “0”, then the newestevents are discarded.(see per_cpu/cpu0/stats for overrun and dropped)

disable_on_free

When the free_buffer is closed, tracing willstop (tracing_on set to 0).

irq-info

Shows the interrupt, preempt count, need resched data.When disabled, the trace looks like:

# tracer: function## entries-in-buffer/entries-written: 144405/9452052   #P:4##           TASK-PID   CPU#      TIMESTAMP  FUNCTION#              | |       |          |         |          <idle>-0     [002]  23636.756054: ttwu_do_activate.constprop.89 <-try_to_wake_up          <idle>-0     [002]  23636.756054: activate_task <-ttwu_do_activate.constprop.89          <idle>-0     [002]  23636.756055: enqueue_task <-activate_task

markers

When set, the trace_marker is writable (only by root).When disabled, the trace_marker will error with EINVALon write.

event-fork

When set, tasks with PIDs listed in set_event_pid will havethe PIDs of their children added to set_event_pid when thosetasks fork. Also, when tasks with PIDs in set_event_pid exit,their PIDs will be removed from the file.

This affects PIDs listed in set_event_notrace_pid as well.

function-trace

The latency tracers will enable function tracingif this option is enabled (default it is). Whenit is disabled, the latency tracers do not tracefunctions. This keeps the overhead of the tracer downwhen performing latency tests.

function-fork

When set, tasks with PIDs listed in set_ftrace_pid willhave the PIDs of their children added to set_ftrace_pidwhen those tasks fork. Also, when tasks with PIDs inset_ftrace_pid exit, their PIDs will be removed from thefile.

This affects PIDs in set_ftrace_notrace_pid as well.

display-graph

When set, the latency tracers (irqsoff, wakeup, etc) willuse function graph tracing instead of function tracing.

stacktrace

When set, a stack trace is recorded after any trace eventis recorded.

branch

Enable branch tracing with the tracer. This enables branchtracer along with the currently set tracer. Enabling thiswith the “nop” tracer is the same as just enabling the“branch” tracer.

Here are the per tracer options:

Options for function tracer:

func_stack_trace

When set, a stack trace is recorded after everyfunction that is recorded. NOTE! Limit the functionsthat are recorded before enabling this, with“set_ftrace_filter” otherwise the system performancewill be critically degraded. Remember to disablethis option before clearing the function filter.

Options for function_graph tracer:

Since the function_graph tracer has a slightly different outputit has its own options to control what is displayed.

funcgraph-overrun

When set, the “overrun” of the graph stack isdisplayed after each function traced. Theoverrun, is when the stack depth of the callsis greater than what is reserved for each task.Each task has a fixed array of functions totrace in the call graph. If the depth of thecalls exceeds that, the function is not traced.The overrun is the number of functions misseddue to exceeding this array.

funcgraph-cpu

When set, the CPU number of the CPU where the traceoccurred is displayed.

funcgraph-overhead

When set, if the function takes longer thanA certain amount, then a delay marker isdisplayed. See “delay” above, under theheader description.

funcgraph-proc

Unlike other tracers, the process’ command lineis not displayed by default, but instead onlywhen a task is traced in and out during a contextswitch. Enabling this options has the commandof each process displayed at every line.

funcgraph-duration

At the end of each function (the return)the duration of the amount of time in thefunction is displayed in microseconds.

funcgraph-abstime

When set, the timestamp is displayed at each line.

funcgraph-irqs

When disabled, functions that happen inside aninterrupt will not be traced.

funcgraph-tail

When set, the return event will include the functionthat it represents. By default this is off, andonly a closing curly bracket “}” is displayed forthe return of a function.

sleep-time

When running function graph tracer, to includethe time a task schedules out in its function.When enabled, it will account time the task has beenscheduled out as part of the function call.

graph-time

When running function profiler with function graph tracer,to include the time to call nested functions. When this isnot set, the time reported for the function will onlyinclude the time the function itself executed for, not thetime for functions that it called.

Options for blk tracer:

blk_classic

Shows a more minimalistic output.

irqsoff¶

When interrupts are disabled, the CPU can not react to any otherexternal event (besides NMIs and SMIs). This prevents the timerinterrupt from triggering or the mouse interrupt from lettingthe kernel know of a new mouse event. The result is a latencywith the reaction time.

The irqsoff tracer tracks the time for which interrupts aredisabled. When a new maximum latency is hit, the tracer savesthe trace leading up to that latency point so that every time anew maximum is reached, the old saved trace is discarded and thenew trace is saved.

To reset the maximum, echo 0 into tracing_max_latency. Here isan example:

# echo 0 > options/function-trace# echo irqsoff > current_tracer# echo 1 > tracing_on# echo 0 > tracing_max_latency# ls -ltr[...]# echo 0 > tracing_on# cat trace# tracer: irqsoff## irqsoff latency trace v1.1.5 on 3.8.0-test+# --------------------------------------------------------------------# latency: 16 us, #4/4, CPU#0 | (M:preempt VP:0, KP:0, SP:0 HP:0 #P:4)#    -----------------#    | task: swapper/0-0 (uid:0 nice:0 policy:0 rt_prio:0)#    -----------------#  => started at: run_timer_softirq#  => ended at:   run_timer_softirq###                  _------=> CPU##                 / _-----=> irqs-off#                | / _----=> need-resched#                || / _---=> hardirq/softirq#                ||| / _--=> preempt-depth#                |||| /     delay#  cmd     pid   ||||| time  |   caller#     \   /      |||||  \    |   /  <idle>-0       0d.s2    0us+: _raw_spin_lock_irq <-run_timer_softirq  <idle>-0       0dNs3   17us : _raw_spin_unlock_irq <-run_timer_softirq  <idle>-0       0dNs3   17us+: trace_hardirqs_on <-run_timer_softirq  <idle>-0       0dNs3   25us : <stack trace> => _raw_spin_unlock_irq => run_timer_softirq => __do_softirq => call_softirq => do_softirq => irq_exit => smp_apic_timer_interrupt => apic_timer_interrupt => rcu_idle_exit => cpu_idle => rest_init => start_kernel => x86_64_start_reservations => x86_64_start_kernel

Here we see that we had a latency of 16 microseconds (which isvery good). The _raw_spin_lock_irq in run_timer_softirq disabledinterrupts. The difference between the 16 and the displayedtimestamp 25us occurred because the clock was incrementedbetween the time of recording the max latency and the time ofrecording the function that had that latency.

Note the above example had function-trace not set. If we setfunction-trace, we get a much larger output:

with echo 1 > options/function-trace # tracer: irqsoff # # irqsoff latency trace v1.1.5 on 3.8.0-test+ # -------------------------------------------------------------------- # latency: 71 us, #168/168, CPU#3 | (M:preempt VP:0, KP:0, SP:0 HP:0 #P:4) #    ----------------- #    | task: bash-2042 (uid:0 nice:0 policy:0 rt_prio:0) #    ----------------- #  => started at: ata_scsi_queuecmd #  => ended at:   ata_scsi_queuecmd # # #                  _------=> CPU# #                 / _-----=> irqs-off #                | / _----=> need-resched #                || / _---=> hardirq/softirq #                ||| / _--=> preempt-depth #                |||| /     delay #  cmd     pid   ||||| time  |   caller #     \   /      |||||  \    |   /     bash-2042    3d...    0us : _raw_spin_lock_irqsave <-ata_scsi_queuecmd     bash-2042    3d...    0us : add_preempt_count <-_raw_spin_lock_irqsave     bash-2042    3d..1    1us : ata_scsi_find_dev <-ata_scsi_queuecmd     bash-2042    3d..1    1us : __ata_scsi_find_dev <-ata_scsi_find_dev     bash-2042    3d..1    2us : ata_find_dev.part.14 <-__ata_scsi_find_dev     bash-2042    3d..1    2us : ata_qc_new_init <-__ata_scsi_queuecmd     bash-2042    3d..1    3us : ata_sg_init <-__ata_scsi_queuecmd     bash-2042    3d..1    4us : ata_scsi_rw_xlat <-__ata_scsi_queuecmd     bash-2042    3d..1    4us : ata_build_rw_tf <-ata_scsi_rw_xlat [...]     bash-2042    3d..1   67us : delay_tsc <-__delay     bash-2042    3d..1   67us : add_preempt_count <-delay_tsc     bash-2042    3d..2   67us : sub_preempt_count <-delay_tsc     bash-2042    3d..1   67us : add_preempt_count <-delay_tsc     bash-2042    3d..2   68us : sub_preempt_count <-delay_tsc     bash-2042    3d..1   68us+: ata_bmdma_start <-ata_bmdma_qc_issue     bash-2042    3d..1   71us : _raw_spin_unlock_irqrestore <-ata_scsi_queuecmd     bash-2042    3d..1   71us : _raw_spin_unlock_irqrestore <-ata_scsi_queuecmd     bash-2042    3d..1   72us+: trace_hardirqs_on <-ata_scsi_queuecmd     bash-2042    3d..1  120us : <stack trace>  => _raw_spin_unlock_irqrestore  => ata_scsi_queuecmd  => scsi_dispatch_cmd  => scsi_request_fn  => __blk_run_queue_uncond  => __blk_run_queue  => blk_queue_bio  => submit_bio_noacct  => submit_bio  => submit_bh  => __ext3_get_inode_loc  => ext3_iget  => ext3_lookup  => lookup_real  => __lookup_hash  => walk_component  => lookup_last  => path_lookupat  => filename_lookup  => user_path_at_empty  => user_path_at  => vfs_fstatat  => vfs_stat  => sys_newstat  => system_call_fastpath

Here we traced a 71 microsecond latency. But we also see all thefunctions that were called during that time. Note that byenabling function tracing, we incur an added overhead. Thisoverhead may extend the latency times. But nevertheless, thistrace has provided some very helpful debugging information.

If we prefer function graph output instead of function, we can setdisplay-graph option:

with echo 1 > options/display-graph # tracer: irqsoff # # irqsoff latency trace v1.1.5 on 4.20.0-rc6+ # -------------------------------------------------------------------- # latency: 3751 us, #274/274, CPU#0 | (M:desktop VP:0, KP:0, SP:0 HP:0 #P:4) #    ----------------- #    | task: bash-1507 (uid:0 nice:0 policy:0 rt_prio:0) #    ----------------- #  => started at: free_debug_processing #  => ended at:   return_to_handler # # #                                       _-----=> irqs-off #                                      / _----=> need-resched #                                     | / _---=> hardirq/softirq #                                     || / _--=> preempt-depth #                                     ||| / #   REL TIME      CPU  TASK/PID       ||||     DURATION                  FUNCTION CALLS #      |          |     |    |        ||||      |   |                     |   |   |   |         0 us |   0)   bash-1507    |  d... |   0.000 us    |  _raw_spin_lock_irqsave();         0 us |   0)   bash-1507    |  d..1 |   0.378 us    |    do_raw_spin_trylock();         1 us |   0)   bash-1507    |  d..2 |               |    set_track() {         2 us |   0)   bash-1507    |  d..2 |               |      save_stack_trace() {         2 us |   0)   bash-1507    |  d..2 |               |        __save_stack_trace() {         3 us |   0)   bash-1507    |  d..2 |               |          __unwind_start() {         3 us |   0)   bash-1507    |  d..2 |               |            get_stack_info() {         3 us |   0)   bash-1507    |  d..2 |   0.351 us    |              in_task_stack();         4 us |   0)   bash-1507    |  d..2 |   1.107 us    |            } [...]      3750 us |   0)   bash-1507    |  d..1 |   0.516 us    |      do_raw_spin_unlock();      3750 us |   0)   bash-1507    |  d..1 |   0.000 us    |  _raw_spin_unlock_irqrestore();      3764 us |   0)   bash-1507    |  d..1 |   0.000 us    |  tracer_hardirqs_on();     bash-1507    0d..1 3792us : <stack trace>  => free_debug_processing  => __slab_free  => kmem_cache_free  => vm_area_free  => remove_vma  => exit_mmap  => mmput  => begin_new_exec  => load_elf_binary  => search_binary_handler  => __do_execve_file.isra.32  => __x64_sys_execve  => do_syscall_64  => entry_SYSCALL_64_after_hwframe

preemptoff¶

When preemption is disabled, we may be able to receiveinterrupts but the task cannot be preempted and a higherpriority task must wait for preemption to be enabled againbefore it can preempt a lower priority task.

The preemptoff tracer traces the places that disable preemption.Like the irqsoff tracer, it records the maximum latency forwhich preemption was disabled. The control of preemptoff traceris much like the irqsoff tracer.

# echo 0 > options/function-trace# echo preemptoff > current_tracer# echo 1 > tracing_on# echo 0 > tracing_max_latency# ls -ltr[...]# echo 0 > tracing_on# cat trace# tracer: preemptoff## preemptoff latency trace v1.1.5 on 3.8.0-test+# --------------------------------------------------------------------# latency: 46 us, #4/4, CPU#1 | (M:preempt VP:0, KP:0, SP:0 HP:0 #P:4)#    -----------------#    | task: sshd-1991 (uid:0 nice:0 policy:0 rt_prio:0)#    -----------------#  => started at: do_IRQ#  => ended at:   do_IRQ###                  _------=> CPU##                 / _-----=> irqs-off#                | / _----=> need-resched#                || / _---=> hardirq/softirq#                ||| / _--=> preempt-depth#                |||| /     delay#  cmd     pid   ||||| time  |   caller#     \   /      |||||  \    |   /    sshd-1991    1d.h.    0us+: irq_enter <-do_IRQ    sshd-1991    1d..1   46us : irq_exit <-do_IRQ    sshd-1991    1d..1   47us+: trace_preempt_on <-do_IRQ    sshd-1991    1d..1   52us : <stack trace> => sub_preempt_count => irq_exit => do_IRQ => ret_from_intr

This has some more changes. Preemption was disabled when aninterrupt came in (notice the ‘h’), and was enabled on exit.But we also see that interrupts have been disabled when enteringthe preempt off section and leaving it (the ‘d’). We do not know ifinterrupts were enabled in the mean time or shortly after thiswas over.

# tracer: preemptoff## preemptoff latency trace v1.1.5 on 3.8.0-test+# --------------------------------------------------------------------# latency: 83 us, #241/241, CPU#1 | (M:preempt VP:0, KP:0, SP:0 HP:0 #P:4)#    -----------------#    | task: bash-1994 (uid:0 nice:0 policy:0 rt_prio:0)#    -----------------#  => started at: wake_up_new_task#  => ended at:   task_rq_unlock###                  _------=> CPU##                 / _-----=> irqs-off#                | / _----=> need-resched#                || / _---=> hardirq/softirq#                ||| / _--=> preempt-depth#                |||| /     delay#  cmd     pid   ||||| time  |   caller#     \   /      |||||  \    |   /    bash-1994    1d..1    0us : _raw_spin_lock_irqsave <-wake_up_new_task    bash-1994    1d..1    0us : select_task_rq_fair <-select_task_rq    bash-1994    1d..1    1us : __rcu_read_lock <-select_task_rq_fair    bash-1994    1d..1    1us : source_load <-select_task_rq_fair    bash-1994    1d..1    1us : source_load <-select_task_rq_fair[...]    bash-1994    1d..1   12us : irq_enter <-smp_apic_timer_interrupt    bash-1994    1d..1   12us : rcu_irq_enter <-irq_enter    bash-1994    1d..1   13us : add_preempt_count <-irq_enter    bash-1994    1d.h1   13us : exit_idle <-smp_apic_timer_interrupt    bash-1994    1d.h1   13us : hrtimer_interrupt <-smp_apic_timer_interrupt    bash-1994    1d.h1   13us : _raw_spin_lock <-hrtimer_interrupt    bash-1994    1d.h1   14us : add_preempt_count <-_raw_spin_lock    bash-1994    1d.h2   14us : ktime_get_update_offsets <-hrtimer_interrupt[...]    bash-1994    1d.h1   35us : lapic_next_event <-clockevents_program_event    bash-1994    1d.h1   35us : irq_exit <-smp_apic_timer_interrupt    bash-1994    1d.h1   36us : sub_preempt_count <-irq_exit    bash-1994    1d..2   36us : do_softirq <-irq_exit    bash-1994    1d..2   36us : __do_softirq <-call_softirq    bash-1994    1d..2   36us : __local_bh_disable <-__do_softirq    bash-1994    1d.s2   37us : add_preempt_count <-_raw_spin_lock_irq    bash-1994    1d.s3   38us : _raw_spin_unlock <-run_timer_softirq    bash-1994    1d.s3   39us : sub_preempt_count <-_raw_spin_unlock    bash-1994    1d.s2   39us : call_timer_fn <-run_timer_softirq[...]    bash-1994    1dNs2   81us : cpu_needs_another_gp <-rcu_process_callbacks    bash-1994    1dNs2   82us : __local_bh_enable <-__do_softirq    bash-1994    1dNs2   82us : sub_preempt_count <-__local_bh_enable    bash-1994    1dN.2   82us : idle_cpu <-irq_exit    bash-1994    1dN.2   83us : rcu_irq_exit <-irq_exit    bash-1994    1dN.2   83us : sub_preempt_count <-irq_exit    bash-1994    1.N.1   84us : _raw_spin_unlock_irqrestore <-task_rq_unlock    bash-1994    1.N.1   84us+: trace_preempt_on <-task_rq_unlock    bash-1994    1.N.1  104us : <stack trace> => sub_preempt_count => _raw_spin_unlock_irqrestore => task_rq_unlock => wake_up_new_task => do_fork => sys_clone => stub_clone

The above is an example of the preemptoff trace withfunction-trace set. Here we see that interrupts were not disabledthe entire time. The irq_enter code lets us know that we enteredan interrupt ‘h’. Before that, the functions being traced stillshow that it is not in an interrupt, but we can see from thefunctions themselves that this is not the case.

preemptirqsoff¶

Knowing the locations that have interrupts disabled orpreemption disabled for the longest times is helpful. Butsometimes we would like to know when either preemption and/orinterrupts are disabled.

Consider the following code:

local_irq_disable();call_function_with_irqs_off();preempt_disable();call_function_with_irqs_and_preemption_off();local_irq_enable();call_function_with_preemption_off();preempt_enable();

The irqsoff tracer will record the total length ofcall_function_with_irqs_off() andcall_function_with_irqs_and_preemption_off().

The preemptoff tracer will record the total length ofcall_function_with_irqs_and_preemption_off() andcall_function_with_preemption_off().

But neither will trace the time that interrupts and/orpreemption is disabled. This total time is the time that we cannot schedule. To record this time, use the preemptirqsofftracer.

Again, using this trace is much like the irqsoff and preemptofftracers.

# echo 0 > options/function-trace# echo preemptirqsoff > current_tracer# echo 1 > tracing_on# echo 0 > tracing_max_latency# ls -ltr[...]# echo 0 > tracing_on# cat trace# tracer: preemptirqsoff## preemptirqsoff latency trace v1.1.5 on 3.8.0-test+# --------------------------------------------------------------------# latency: 100 us, #4/4, CPU#3 | (M:preempt VP:0, KP:0, SP:0 HP:0 #P:4)#    -----------------#    | task: ls-2230 (uid:0 nice:0 policy:0 rt_prio:0)#    -----------------#  => started at: ata_scsi_queuecmd#  => ended at:   ata_scsi_queuecmd###                  _------=> CPU##                 / _-----=> irqs-off#                | / _----=> need-resched#                || / _---=> hardirq/softirq#                ||| / _--=> preempt-depth#                |||| /     delay#  cmd     pid   ||||| time  |   caller#     \   /      |||||  \    |   /      ls-2230    3d...    0us+: _raw_spin_lock_irqsave <-ata_scsi_queuecmd      ls-2230    3...1  100us : _raw_spin_unlock_irqrestore <-ata_scsi_queuecmd      ls-2230    3...1  101us+: trace_preempt_on <-ata_scsi_queuecmd      ls-2230    3...1  111us : <stack trace> => sub_preempt_count => _raw_spin_unlock_irqrestore => ata_scsi_queuecmd => scsi_dispatch_cmd => scsi_request_fn => __blk_run_queue_uncond => __blk_run_queue => blk_queue_bio => submit_bio_noacct => submit_bio => submit_bh => ext3_bread => ext3_dir_bread => htree_dirblock_to_tree => ext3_htree_fill_tree => ext3_readdir => vfs_readdir => sys_getdents => system_call_fastpath

The trace_hardirqs_off_thunk is called from assembly on x86 wheninterrupts are disabled in the assembly code. Without thefunction tracing, we do not know if interrupts were enabledwithin the preemption points. We do see that it started withpreemption enabled.

Here is a trace with function-trace set:

# tracer: preemptirqsoff## preemptirqsoff latency trace v1.1.5 on 3.8.0-test+# --------------------------------------------------------------------# latency: 161 us, #339/339, CPU#3 | (M:preempt VP:0, KP:0, SP:0 HP:0 #P:4)#    -----------------#    | task: ls-2269 (uid:0 nice:0 policy:0 rt_prio:0)#    -----------------#  => started at: schedule#  => ended at:   mutex_unlock###                  _------=> CPU##                 / _-----=> irqs-off#                | / _----=> need-resched#                || / _---=> hardirq/softirq#                ||| / _--=> preempt-depth#                |||| /     delay#  cmd     pid   ||||| time  |   caller#     \   /      |||||  \    |   /kworker/-59      3...1    0us : __schedule <-schedulekworker/-59      3d..1    0us : rcu_preempt_qs <-rcu_note_context_switchkworker/-59      3d..1    1us : add_preempt_count <-_raw_spin_lock_irqkworker/-59      3d..2    1us : deactivate_task <-__schedulekworker/-59      3d..2    1us : dequeue_task <-deactivate_taskkworker/-59      3d..2    2us : update_rq_clock <-dequeue_taskkworker/-59      3d..2    2us : dequeue_task_fair <-dequeue_taskkworker/-59      3d..2    2us : update_curr <-dequeue_task_fairkworker/-59      3d..2    2us : update_min_vruntime <-update_currkworker/-59      3d..2    3us : cpuacct_charge <-update_currkworker/-59      3d..2    3us : __rcu_read_lock <-cpuacct_chargekworker/-59      3d..2    3us : __rcu_read_unlock <-cpuacct_chargekworker/-59      3d..2    3us : update_cfs_rq_blocked_load <-dequeue_task_fairkworker/-59      3d..2    4us : clear_buddies <-dequeue_task_fairkworker/-59      3d..2    4us : account_entity_dequeue <-dequeue_task_fairkworker/-59      3d..2    4us : update_min_vruntime <-dequeue_task_fairkworker/-59      3d..2    4us : update_cfs_shares <-dequeue_task_fairkworker/-59      3d..2    5us : hrtick_update <-dequeue_task_fairkworker/-59      3d..2    5us : wq_worker_sleeping <-__schedulekworker/-59      3d..2    5us : kthread_data <-wq_worker_sleepingkworker/-59      3d..2    5us : put_prev_task_fair <-__schedulekworker/-59      3d..2    6us : pick_next_task_fair <-pick_next_taskkworker/-59      3d..2    6us : clear_buddies <-pick_next_task_fairkworker/-59      3d..2    6us : set_next_entity <-pick_next_task_fairkworker/-59      3d..2    6us : update_stats_wait_end <-set_next_entity      ls-2269    3d..2    7us : finish_task_switch <-__schedule      ls-2269    3d..2    7us : _raw_spin_unlock_irq <-finish_task_switch      ls-2269    3d..2    8us : do_IRQ <-ret_from_intr      ls-2269    3d..2    8us : irq_enter <-do_IRQ      ls-2269    3d..2    8us : rcu_irq_enter <-irq_enter      ls-2269    3d..2    9us : add_preempt_count <-irq_enter      ls-2269    3d.h2    9us : exit_idle <-do_IRQ[...]      ls-2269    3d.h3   20us : sub_preempt_count <-_raw_spin_unlock      ls-2269    3d.h2   20us : irq_exit <-do_IRQ      ls-2269    3d.h2   21us : sub_preempt_count <-irq_exit      ls-2269    3d..3   21us : do_softirq <-irq_exit      ls-2269    3d..3   21us : __do_softirq <-call_softirq      ls-2269    3d..3   21us+: __local_bh_disable <-__do_softirq      ls-2269    3d.s4   29us : sub_preempt_count <-_local_bh_enable_ip      ls-2269    3d.s5   29us : sub_preempt_count <-_local_bh_enable_ip      ls-2269    3d.s5   31us : do_IRQ <-ret_from_intr      ls-2269    3d.s5   31us : irq_enter <-do_IRQ      ls-2269    3d.s5   31us : rcu_irq_enter <-irq_enter[...]      ls-2269    3d.s5   31us : rcu_irq_enter <-irq_enter      ls-2269    3d.s5   32us : add_preempt_count <-irq_enter      ls-2269    3d.H5   32us : exit_idle <-do_IRQ      ls-2269    3d.H5   32us : handle_irq <-do_IRQ      ls-2269    3d.H5   32us : irq_to_desc <-handle_irq      ls-2269    3d.H5   33us : handle_fasteoi_irq <-handle_irq[...]      ls-2269    3d.s5  158us : _raw_spin_unlock_irqrestore <-rtl8139_poll      ls-2269    3d.s3  158us : net_rps_action_and_irq_enable.isra.65 <-net_rx_action      ls-2269    3d.s3  159us : __local_bh_enable <-__do_softirq      ls-2269    3d.s3  159us : sub_preempt_count <-__local_bh_enable      ls-2269    3d..3  159us : idle_cpu <-irq_exit      ls-2269    3d..3  159us : rcu_irq_exit <-irq_exit      ls-2269    3d..3  160us : sub_preempt_count <-irq_exit      ls-2269    3d...  161us : __mutex_unlock_slowpath <-mutex_unlock      ls-2269    3d...  162us+: trace_hardirqs_on <-mutex_unlock      ls-2269    3d...  186us : <stack trace> => __mutex_unlock_slowpath => mutex_unlock => process_output => n_tty_write => tty_write => vfs_write => sys_write => system_call_fastpath

This is an interesting trace. It started with kworker running andscheduling out and ls taking over. But as soon as ls released therq lock and enabled interrupts (but not preemption) an interrupttriggered. When the interrupt finished, it started running softirqs.But while the softirq was running, another interrupt triggered.When an interrupt is running inside a softirq, the annotation is ‘H’.

wakeup¶

One common case that people are interested in tracing is thetime it takes for a task that is woken to actually wake up.Now for non Real-Time tasks, this can be arbitrary. But tracingit none the less can be interesting.

Without function tracing:

# echo 0 > options/function-trace# echo wakeup > current_tracer# echo 1 > tracing_on# echo 0 > tracing_max_latency# chrt -f 5 sleep 1# echo 0 > tracing_on# cat trace# tracer: wakeup## wakeup latency trace v1.1.5 on 3.8.0-test+# --------------------------------------------------------------------# latency: 15 us, #4/4, CPU#3 | (M:preempt VP:0, KP:0, SP:0 HP:0 #P:4)#    -----------------#    | task: kworker/3:1H-312 (uid:0 nice:-20 policy:0 rt_prio:0)#    -----------------##                  _------=> CPU##                 / _-----=> irqs-off#                | / _----=> need-resched#                || / _---=> hardirq/softirq#                ||| / _--=> preempt-depth#                |||| /     delay#  cmd     pid   ||||| time  |   caller#     \   /      |||||  \    |   /  <idle>-0       3dNs7    0us :      0:120:R   + [003]   312:100:R kworker/3:1H  <idle>-0       3dNs7    1us+: ttwu_do_activate.constprop.87 <-try_to_wake_up  <idle>-0       3d..3   15us : __schedule <-schedule  <idle>-0       3d..3   15us :      0:120:R ==> [003]   312:100:R kworker/3:1H

The tracer only traces the highest priority task in the systemto avoid tracing the normal circumstances. Here we see thatthe kworker with a nice priority of -20 (not very nice), tookjust 15 microseconds from the time it woke up, to the time itran.

Non Real-Time tasks are not that interesting. A more interestingtrace is to concentrate only on Real-Time tasks.

wakeup_rt¶

In a Real-Time environment it is very important to know thewakeup time it takes for the highest priority task that is wokenup to the time that it executes. This is also known as “schedulelatency”. I stress the point that this is about RT tasks. It isalso important to know the scheduling latency of non-RT tasks,but the average schedule latency is better for non-RT tasks.Tools like LatencyTop are more appropriate for suchmeasurements.

Real-Time environments are interested in the worst case latency.That is the longest latency it takes for something to happen,and not the average. We can have a very fast scheduler that mayonly have a large latency once in a while, but that would notwork well with Real-Time tasks. The wakeup_rt tracer was designedto record the worst case wakeups of RT tasks. Non-RT tasks arenot recorded because the tracer only records one worst case andtracing non-RT tasks that are unpredictable will overwrite theworst case latency of RT tasks (just run the normal wakeuptracer for a while to see that effect).

Since this tracer only deals with RT tasks, we will run thisslightly differently than we did with the previous tracers.Instead of performing an ‘ls’, we will run ‘sleep 1’ under‘chrt’ which changes the priority of the task.

# echo 0 > options/function-trace# echo wakeup_rt > current_tracer# echo 1 > tracing_on# echo 0 > tracing_max_latency# chrt -f 5 sleep 1# echo 0 > tracing_on# cat trace# tracer: wakeup## tracer: wakeup_rt## wakeup_rt latency trace v1.1.5 on 3.8.0-test+# --------------------------------------------------------------------# latency: 5 us, #4/4, CPU#3 | (M:preempt VP:0, KP:0, SP:0 HP:0 #P:4)#    -----------------#    | task: sleep-2389 (uid:0 nice:0 policy:1 rt_prio:5)#    -----------------##                  _------=> CPU##                 / _-----=> irqs-off#                | / _----=> need-resched#                || / _---=> hardirq/softirq#                ||| / _--=> preempt-depth#                |||| /     delay#  cmd     pid   ||||| time  |   caller#     \   /      |||||  \    |   /  <idle>-0       3d.h4    0us :      0:120:R   + [003]  2389: 94:R sleep  <idle>-0       3d.h4    1us+: ttwu_do_activate.constprop.87 <-try_to_wake_up  <idle>-0       3d..3    5us : __schedule <-schedule  <idle>-0       3d..3    5us :      0:120:R ==> [003]  2389: 94:R sleep

Running this on an idle system, we see that it only took 5 microsecondsto perform the task switch. Note, since the trace point in the scheduleis before the actual “switch”, we stop the tracing when the recorded taskis about to schedule in. This may change if we add a new marker at theend of the scheduler.

Notice that the recorded task is ‘sleep’ with the PID of 2389and it has an rt_prio of 5. This priority is user-space priorityand not the internal kernel priority. The policy is 1 forSCHED_FIFO and 2 for SCHED_RR.

Note, that the trace data shows the internal priority (99 - rtprio).

<idle>-0       3d..3    5us :      0:120:R ==> [003]  2389: 94:R sleep

The 0:120:R means idle was running with a nice priority of 0 (120 - 120)and in the running state ‘R’. The sleep task was scheduled in with2389: 94:R. That is the priority is the kernel rtprio (99 - 5 = 94)and it too is in the running state.

Doing the same with chrt -r 5 and function-trace set.

echo 1 > options/function-trace# tracer: wakeup_rt## wakeup_rt latency trace v1.1.5 on 3.8.0-test+# --------------------------------------------------------------------# latency: 29 us, #85/85, CPU#3 | (M:preempt VP:0, KP:0, SP:0 HP:0 #P:4)#    -----------------#    | task: sleep-2448 (uid:0 nice:0 policy:1 rt_prio:5)#    -----------------##                  _------=> CPU##                 / _-----=> irqs-off#                | / _----=> need-resched#                || / _---=> hardirq/softirq#                ||| / _--=> preempt-depth#                |||| /     delay#  cmd     pid   ||||| time  |   caller#     \   /      |||||  \    |   /  <idle>-0       3d.h4    1us+:      0:120:R   + [003]  2448: 94:R sleep  <idle>-0       3d.h4    2us : ttwu_do_activate.constprop.87 <-try_to_wake_up  <idle>-0       3d.h3    3us : check_preempt_curr <-ttwu_do_wakeup  <idle>-0       3d.h3    3us : resched_curr <-check_preempt_curr  <idle>-0       3dNh3    4us : task_woken_rt <-ttwu_do_wakeup  <idle>-0       3dNh3    4us : _raw_spin_unlock <-try_to_wake_up  <idle>-0       3dNh3    4us : sub_preempt_count <-_raw_spin_unlock  <idle>-0       3dNh2    5us : ttwu_stat <-try_to_wake_up  <idle>-0       3dNh2    5us : _raw_spin_unlock_irqrestore <-try_to_wake_up  <idle>-0       3dNh2    6us : sub_preempt_count <-_raw_spin_unlock_irqrestore  <idle>-0       3dNh1    6us : _raw_spin_lock <-__run_hrtimer  <idle>-0       3dNh1    6us : add_preempt_count <-_raw_spin_lock  <idle>-0       3dNh2    7us : _raw_spin_unlock <-hrtimer_interrupt  <idle>-0       3dNh2    7us : sub_preempt_count <-_raw_spin_unlock  <idle>-0       3dNh1    7us : tick_program_event <-hrtimer_interrupt  <idle>-0       3dNh1    7us : clockevents_program_event <-tick_program_event  <idle>-0       3dNh1    8us : ktime_get <-clockevents_program_event  <idle>-0       3dNh1    8us : lapic_next_event <-clockevents_program_event  <idle>-0       3dNh1    8us : irq_exit <-smp_apic_timer_interrupt  <idle>-0       3dNh1    9us : sub_preempt_count <-irq_exit  <idle>-0       3dN.2    9us : idle_cpu <-irq_exit  <idle>-0       3dN.2    9us : rcu_irq_exit <-irq_exit  <idle>-0       3dN.2   10us : rcu_eqs_enter_common.isra.45 <-rcu_irq_exit  <idle>-0       3dN.2   10us : sub_preempt_count <-irq_exit  <idle>-0       3.N.1   11us : rcu_idle_exit <-cpu_idle  <idle>-0       3dN.1   11us : rcu_eqs_exit_common.isra.43 <-rcu_idle_exit  <idle>-0       3.N.1   11us : tick_nohz_idle_exit <-cpu_idle  <idle>-0       3dN.1   12us : menu_hrtimer_cancel <-tick_nohz_idle_exit  <idle>-0       3dN.1   12us : ktime_get <-tick_nohz_idle_exit  <idle>-0       3dN.1   12us : tick_do_update_jiffies64 <-tick_nohz_idle_exit  <idle>-0       3dN.1   13us : cpu_load_update_nohz <-tick_nohz_idle_exit  <idle>-0       3dN.1   13us : _raw_spin_lock <-cpu_load_update_nohz  <idle>-0       3dN.1   13us : add_preempt_count <-_raw_spin_lock  <idle>-0       3dN.2   13us : __cpu_load_update <-cpu_load_update_nohz  <idle>-0       3dN.2   14us : sched_avg_update <-__cpu_load_update  <idle>-0       3dN.2   14us : _raw_spin_unlock <-cpu_load_update_nohz  <idle>-0       3dN.2   14us : sub_preempt_count <-_raw_spin_unlock  <idle>-0       3dN.1   15us : calc_load_nohz_stop <-tick_nohz_idle_exit  <idle>-0       3dN.1   15us : touch_softlockup_watchdog <-tick_nohz_idle_exit  <idle>-0       3dN.1   15us : hrtimer_cancel <-tick_nohz_idle_exit  <idle>-0       3dN.1   15us : hrtimer_try_to_cancel <-hrtimer_cancel  <idle>-0       3dN.1   16us : lock_hrtimer_base.isra.18 <-hrtimer_try_to_cancel  <idle>-0       3dN.1   16us : _raw_spin_lock_irqsave <-lock_hrtimer_base.isra.18  <idle>-0       3dN.1   16us : add_preempt_count <-_raw_spin_lock_irqsave  <idle>-0       3dN.2   17us : __remove_hrtimer <-remove_hrtimer.part.16  <idle>-0       3dN.2   17us : hrtimer_force_reprogram <-__remove_hrtimer  <idle>-0       3dN.2   17us : tick_program_event <-hrtimer_force_reprogram  <idle>-0       3dN.2   18us : clockevents_program_event <-tick_program_event  <idle>-0       3dN.2   18us : ktime_get <-clockevents_program_event  <idle>-0       3dN.2   18us : lapic_next_event <-clockevents_program_event  <idle>-0       3dN.2   19us : _raw_spin_unlock_irqrestore <-hrtimer_try_to_cancel  <idle>-0       3dN.2   19us : sub_preempt_count <-_raw_spin_unlock_irqrestore  <idle>-0       3dN.1   19us : hrtimer_forward <-tick_nohz_idle_exit  <idle>-0       3dN.1   20us : ktime_add_safe <-hrtimer_forward  <idle>-0       3dN.1   20us : ktime_add_safe <-hrtimer_forward  <idle>-0       3dN.1   20us : hrtimer_start_range_ns <-hrtimer_start_expires.constprop.11  <idle>-0       3dN.1   20us : __hrtimer_start_range_ns <-hrtimer_start_range_ns  <idle>-0       3dN.1   21us : lock_hrtimer_base.isra.18 <-__hrtimer_start_range_ns  <idle>-0       3dN.1   21us : _raw_spin_lock_irqsave <-lock_hrtimer_base.isra.18  <idle>-0       3dN.1   21us : add_preempt_count <-_raw_spin_lock_irqsave  <idle>-0       3dN.2   22us : ktime_add_safe <-__hrtimer_start_range_ns  <idle>-0       3dN.2   22us : enqueue_hrtimer <-__hrtimer_start_range_ns  <idle>-0       3dN.2   22us : tick_program_event <-__hrtimer_start_range_ns  <idle>-0       3dN.2   23us : clockevents_program_event <-tick_program_event  <idle>-0       3dN.2   23us : ktime_get <-clockevents_program_event  <idle>-0       3dN.2   23us : lapic_next_event <-clockevents_program_event  <idle>-0       3dN.2   24us : _raw_spin_unlock_irqrestore <-__hrtimer_start_range_ns  <idle>-0       3dN.2   24us : sub_preempt_count <-_raw_spin_unlock_irqrestore  <idle>-0       3dN.1   24us : account_idle_ticks <-tick_nohz_idle_exit  <idle>-0       3dN.1   24us : account_idle_time <-account_idle_ticks  <idle>-0       3.N.1   25us : sub_preempt_count <-cpu_idle  <idle>-0       3.N..   25us : schedule <-cpu_idle  <idle>-0       3.N..   25us : __schedule <-preempt_schedule  <idle>-0       3.N..   26us : add_preempt_count <-__schedule  <idle>-0       3.N.1   26us : rcu_note_context_switch <-__schedule  <idle>-0       3.N.1   26us : rcu_sched_qs <-rcu_note_context_switch  <idle>-0       3dN.1   27us : rcu_preempt_qs <-rcu_note_context_switch  <idle>-0       3.N.1   27us : _raw_spin_lock_irq <-__schedule  <idle>-0       3dN.1   27us : add_preempt_count <-_raw_spin_lock_irq  <idle>-0       3dN.2   28us : put_prev_task_idle <-__schedule  <idle>-0       3dN.2   28us : pick_next_task_stop <-pick_next_task  <idle>-0       3dN.2   28us : pick_next_task_rt <-pick_next_task  <idle>-0       3dN.2   29us : dequeue_pushable_task <-pick_next_task_rt  <idle>-0       3d..3   29us : __schedule <-preempt_schedule  <idle>-0       3d..3   30us :      0:120:R ==> [003]  2448: 94:R sleep

This isn’t that big of a trace, even with function tracing enabled,so I included the entire trace.

The interrupt went off while when the system was idle. Somewherebefore task_woken_rt() was called, the NEED_RESCHED flag was set,this is indicated by the first occurrence of the ‘N’ flag.

Latency tracing and events¶

As function tracing can induce a much larger latency, but withoutseeing what happens within the latency it is hard to know whatcaused it. There is a middle ground, and that is with enablingevents.

# echo 0 > options/function-trace# echo wakeup_rt > current_tracer# echo 1 > events/enable# echo 1 > tracing_on# echo 0 > tracing_max_latency# chrt -f 5 sleep 1# echo 0 > tracing_on# cat trace# tracer: wakeup_rt## wakeup_rt latency trace v1.1.5 on 3.8.0-test+# --------------------------------------------------------------------# latency: 6 us, #12/12, CPU#2 | (M:preempt VP:0, KP:0, SP:0 HP:0 #P:4)#    -----------------#    | task: sleep-5882 (uid:0 nice:0 policy:1 rt_prio:5)#    -----------------##                  _------=> CPU##                 / _-----=> irqs-off#                | / _----=> need-resched#                || / _---=> hardirq/softirq#                ||| / _--=> preempt-depth#                |||| /     delay#  cmd     pid   ||||| time  |   caller#     \   /      |||||  \    |   /  <idle>-0       2d.h4    0us :      0:120:R   + [002]  5882: 94:R sleep  <idle>-0       2d.h4    0us : ttwu_do_activate.constprop.87 <-try_to_wake_up  <idle>-0       2d.h4    1us : sched_wakeup: comm=sleep pid=5882 prio=94 success=1 target_cpu=002  <idle>-0       2dNh2    1us : hrtimer_expire_exit: hrtimer=ffff88007796feb8  <idle>-0       2.N.2    2us : power_end: cpu_id=2  <idle>-0       2.N.2    3us : cpu_idle: state=4294967295 cpu_id=2  <idle>-0       2dN.3    4us : hrtimer_cancel: hrtimer=ffff88007d50d5e0  <idle>-0       2dN.3    4us : hrtimer_start: hrtimer=ffff88007d50d5e0 function=tick_sched_timer expires=34311211000000 softexpires=34311211000000  <idle>-0       2.N.2    5us : rcu_utilization: Start context switch  <idle>-0       2.N.2    5us : rcu_utilization: End context switch  <idle>-0       2d..3    6us : __schedule <-schedule  <idle>-0       2d..3    6us :      0:120:R ==> [002]  5882: 94:R sleep

Hardware Latency Detector¶

The hardware latency detector is executed by enabling the “hwlat” tracer.

NOTE, this tracer will affect the performance of the system as it willperiodically make a CPU constantly busy with interrupts disabled.

# echo hwlat > current_tracer# sleep 100# cat trace# tracer: hwlat## entries-in-buffer/entries-written: 13/13   #P:8##                              _-----=> irqs-off#                             / _----=> need-resched#                            | / _---=> hardirq/softirq#                            || / _--=> preempt-depth#                            ||| /     delay#           TASK-PID   CPU#  ||||    TIMESTAMP  FUNCTION#              | |       |   ||||       |         |           <...>-1729  [001] d...   678.473449: #1     inner/outer(us):   11/12    ts:1581527483.343962693 count:6           <...>-1729  [004] d...   689.556542: #2     inner/outer(us):   16/9     ts:1581527494.889008092 count:1           <...>-1729  [005] d...   714.756290: #3     inner/outer(us):   16/16    ts:1581527519.678961629 count:5           <...>-1729  [001] d...   718.788247: #4     inner/outer(us):    9/17    ts:1581527523.889012713 count:1           <...>-1729  [002] d...   719.796341: #5     inner/outer(us):   13/9     ts:1581527524.912872606 count:1           <...>-1729  [006] d...   844.787091: #6     inner/outer(us):    9/12    ts:1581527649.889048502 count:2           <...>-1729  [003] d...   849.827033: #7     inner/outer(us):   18/9     ts:1581527654.889013793 count:1           <...>-1729  [007] d...   853.859002: #8     inner/outer(us):    9/12    ts:1581527658.889065736 count:1           <...>-1729  [001] d...   855.874978: #9     inner/outer(us):    9/11    ts:1581527660.861991877 count:1           <...>-1729  [001] d...   863.938932: #10    inner/outer(us):    9/11    ts:1581527668.970010500 count:1 nmi-total:7 nmi-count:1           <...>-1729  [007] d...   878.050780: #11    inner/outer(us):    9/12    ts:1581527683.385002600 count:1 nmi-total:5 nmi-count:1           <...>-1729  [007] d...   886.114702: #12    inner/outer(us):    9/12    ts:1581527691.385001600 count:1

The above output is somewhat the same in the header. All events will haveinterrupts disabled ‘d’. Under the FUNCTION title there is:

#1

This is the count of events recorded that were greater than thetracing_threshold (See below).

inner/outer(us): 11/11

This shows two numbers as “inner latency” and “outer latency”. The testruns in a loop checking a timestamp twice. The latency detected withinthe two timestamps is the “inner latency” and the latency detectedafter the previous timestamp and the next timestamp in the loop isthe “outer latency”.

ts:1581527483.343962693

The absolute timestamp that the first latency was recorded in the window.

count:6

The number of times a latency was detected during the window.

nmi-total:7 nmi-count:1

On architectures that support it, if an NMI comes in during thetest, the time spent in NMI is reported in “nmi-total” (inmicroseconds).

All architectures that have NMIs will show the “nmi-count” if anNMI comes in during the test.

hwlat files:

tracing_threshold

This gets automatically set to “10” to represent 10microseconds. This is the threshold of latency thatneeds to be detected before the trace will be recorded.

Note, when hwlat tracer is finished (another tracer iswritten into “current_tracer”), the original value fortracing_threshold is placed back into this file.

hwlat_detector/width

The length of time the test runs with interrupts disabled.

hwlat_detector/window

The length of time of the window which the testruns. That is, the test will run for “width”microseconds per “window” microseconds

tracing_cpumask

When the test is started. A kernel thread is created thatruns the test. This thread will alternate between CPUslisted in the tracing_cpumask between each period(one “window”). To limit the test to specific CPUsset the mask in this file to only the CPUs that the testshould run on.

function¶

This tracer is the function tracer. Enabling the function tracercan be done from the debug file system. Make sure theftrace_enabled is set; otherwise this tracer is a nop.See the “ftrace_enabled” section below.

# sysctl kernel.ftrace_enabled=1# echo function > current_tracer# echo 1 > tracing_on# usleep 1# echo 0 > tracing_on# cat trace# tracer: function## entries-in-buffer/entries-written: 24799/24799   #P:4##                              _-----=> irqs-off#                             / _----=> need-resched#                            | / _---=> hardirq/softirq#                            || / _--=> preempt-depth#                            ||| /     delay#           TASK-PID   CPU#  ||||    TIMESTAMP  FUNCTION#              | |       |   ||||       |         |            bash-1994  [002] ....  3082.063030: mutex_unlock <-rb_simple_write            bash-1994  [002] ....  3082.063031: __mutex_unlock_slowpath <-mutex_unlock            bash-1994  [002] ....  3082.063031: __fsnotify_parent <-fsnotify_modify            bash-1994  [002] ....  3082.063032: fsnotify <-fsnotify_modify            bash-1994  [002] ....  3082.063032: __srcu_read_lock <-fsnotify            bash-1994  [002] ....  3082.063032: add_preempt_count <-__srcu_read_lock            bash-1994  [002] ...1  3082.063032: sub_preempt_count <-__srcu_read_lock            bash-1994  [002] ....  3082.063033: __srcu_read_unlock <-fsnotify[...]

Note: function tracer uses ring buffers to store the aboveentries. The newest data may overwrite the oldest data.Sometimes using echo to stop the trace is not sufficient becausethe tracing could have overwritten the data that you wanted torecord. For this reason, it is sometimes better to disabletracing directly from a program. This allows you to stop thetracing at the point that you hit the part that you areinterested in. To disable the tracing directly from a C program,something like following code snippet can be used:

int trace_fd;[...]int main(int argc, char *argv[]) {        [...]        trace_fd = open(tracing_file("tracing_on"), O_WRONLY);        [...]        if (condition_hit()) {                write(trace_fd, "0", 1);        }        [...]}

Single thread tracing¶

By writing into set_ftrace_pid you can trace asingle thread. For example:

# cat set_ftrace_pidno pid# echo 3111 > set_ftrace_pid# cat set_ftrace_pid3111# echo function > current_tracer# cat trace | head# tracer: function##           TASK-PID    CPU#    TIMESTAMP  FUNCTION#              | |       |          |         |    yum-updatesd-3111  [003]  1637.254676: finish_task_switch <-thread_return    yum-updatesd-3111  [003]  1637.254681: hrtimer_cancel <-schedule_hrtimeout_range    yum-updatesd-3111  [003]  1637.254682: hrtimer_try_to_cancel <-hrtimer_cancel    yum-updatesd-3111  [003]  1637.254683: lock_hrtimer_base <-hrtimer_try_to_cancel    yum-updatesd-3111  [003]  1637.254685: fget_light <-do_sys_poll    yum-updatesd-3111  [003]  1637.254686: pipe_poll <-do_sys_poll# echo > set_ftrace_pid# cat trace |head# tracer: function##           TASK-PID    CPU#    TIMESTAMP  FUNCTION#              | |       |          |         |##### CPU 3 buffer started ####    yum-updatesd-3111  [003]  1701.957688: free_poll_entry <-poll_freewait    yum-updatesd-3111  [003]  1701.957689: remove_wait_queue <-free_poll_entry    yum-updatesd-3111  [003]  1701.957691: fput <-free_poll_entry    yum-updatesd-3111  [003]  1701.957692: audit_syscall_exit <-sysret_audit    yum-updatesd-3111  [003]  1701.957693: path_put <-audit_syscall_exit

If you want to trace a function when executing, you could usesomething like this simple program.

#include <stdio.h>#include <stdlib.h>#include <sys/types.h>#include <sys/stat.h>#include <fcntl.h>#include <unistd.h>#include <string.h>#define _STR(x) #x#define STR(x) _STR(x)#define MAX_PATH 256const char *find_tracefs(void){       static char tracefs[MAX_PATH+1];       static int tracefs_found;       char type[100];       FILE *fp;       if (tracefs_found)               return tracefs;       if ((fp = fopen("/proc/mounts","r")) == NULL) {               perror("/proc/mounts");               return NULL;       }       while (fscanf(fp, "%*s %"                     STR(MAX_PATH)                     "s %99s %*s %*d %*d\n",                     tracefs, type) == 2) {               if (strcmp(type, "tracefs") == 0)                       break;       }       fclose(fp);       if (strcmp(type, "tracefs") != 0) {               fprintf(stderr, "tracefs not mounted");               return NULL;       }       strcat(tracefs, "/tracing/");       tracefs_found = 1;       return tracefs;}const char *tracing_file(const char *file_name){       static char trace_file[MAX_PATH+1];       snprintf(trace_file, MAX_PATH, "%s/%s", find_tracefs(), file_name);       return trace_file;}int main (int argc, char **argv){        if (argc < 1)                exit(-1);        if (fork() > 0) {                int fd, ffd;                char line[64];                int s;                ffd = open(tracing_file("current_tracer"), O_WRONLY);                if (ffd < 0)                        exit(-1);                write(ffd, "nop", 3);                fd = open(tracing_file("set_ftrace_pid"), O_WRONLY);                s = sprintf(line, "%d\n", getpid());                write(fd, line, s);                write(ffd, "function", 8);                close(fd);                close(ffd);                execvp(argv[1], argv+1);        }        return 0;}

Or this simple script!

#!/bin/bashtracefs=`sed -ne 's/^tracefs \(.*\) tracefs.*/\1/p' /proc/mounts`echo nop > $tracefs/tracing/current_tracerecho 0 > $tracefs/tracing/tracing_onecho $$ > $tracefs/tracing/set_ftrace_pidecho function > $tracefs/tracing/current_tracerecho 1 > $tracefs/tracing/tracing_onexec "$@"

function graph tracer¶

This tracer is similar to the function tracer except that itprobes a function on its entry and its exit. This is done byusing a dynamically allocated stack of return addresses in eachtask_struct. On function entry the tracer overwrites the returnaddress of each function traced to set a custom probe. Thus theoriginal return address is stored on the stack of return addressin the task_struct.

Probing on both ends of a function leads to special featuressuch as:

• measure of a function’s time execution
• having a reliable call stack to draw function calls graph

This tracer is useful in several situations:

• you want to find the reason of a strange kernel behavior andneed to see what happens in detail on any areas (or specificones).
• you are experiencing weird latencies but it’s difficult tofind its origin.
• you want to find quickly which path is taken by a specificfunction
• you just want to peek inside a working kernel and want to seewhat happens there.

# tracer: function_graph## CPU  DURATION                  FUNCTION CALLS# |     |   |                     |   |   |   | 0)               |  sys_open() { 0)               |    do_sys_open() { 0)               |      getname() { 0)               |        kmem_cache_alloc() { 0)   1.382 us    |          __might_sleep(); 0)   2.478 us    |        } 0)               |        strncpy_from_user() { 0)               |          might_fault() { 0)   1.389 us    |            __might_sleep(); 0)   2.553 us    |          } 0)   3.807 us    |        } 0)   7.876 us    |      } 0)               |      alloc_fd() { 0)   0.668 us    |        _spin_lock(); 0)   0.570 us    |        expand_files(); 0)   0.586 us    |        _spin_unlock();

There are several columns that can be dynamicallyenabled/disabled. You can use every combination of options youwant, depending on your needs.

• The cpu number on which the function executed is defaultenabled. It is sometimes better to only trace one cpu (seetracing_cpu_mask file) or you might sometimes see unorderedfunction calls while cpu tracing switch.

  • hide: echo nofuncgraph-cpu > trace_options
  • show: echo funcgraph-cpu > trace_options

• The duration (function’s time of execution) is displayed onthe closing bracket line of a function or on the same linethan the current function in case of a leaf one. It is defaultenabled.

  • hide: echo nofuncgraph-duration > trace_options
  • show: echo funcgraph-duration > trace_options

• The overhead field precedes the duration field in case ofreached duration thresholds.

  • hide: echo nofuncgraph-overhead > trace_options
  • show: echo funcgraph-overhead > trace_options
  • depends on: funcgraph-duration

  ie:

  3) # 1837.709 us |          } /* __switch_to */3)               |          finish_task_switch() {3)   0.313 us    |            _raw_spin_unlock_irq();3)   3.177 us    |          }3) # 1889.063 us |        } /* __schedule */3) ! 140.417 us  |      } /* __schedule */3) # 2034.948 us |    } /* schedule */3) * 33998.59 us |  } /* schedule_preempt_disabled */[...]1)   0.260 us    |              msecs_to_jiffies();1)   0.313 us    |              __rcu_read_unlock();1) + 61.770 us   |            }1) + 64.479 us   |          }1)   0.313 us    |          rcu_bh_qs();1)   0.313 us    |          __local_bh_enable();1) ! 217.240 us  |        }1)   0.365 us    |        idle_cpu();1)               |        rcu_irq_exit() {1)   0.417 us    |          rcu_eqs_enter_common.isra.47();1)   3.125 us    |        }1) ! 227.812 us  |      }1) ! 457.395 us  |    }1) @ 119760.2 us |  }[...]2)               |    handle_IPI() {1)   6.979 us    |                  }2)   0.417 us    |      scheduler_ipi();1)   9.791 us    |                }1) + 12.917 us   |              }2)   3.490 us    |    }1) + 15.729 us   |            }1) + 18.542 us   |          }2) $ 3594274 us  |  }

Flags:

+ means that the function exceeded 10 usecs.! means that the function exceeded 100 usecs.# means that the function exceeded 1000 usecs.* means that the function exceeded 10 msecs.@ means that the function exceeded 100 msecs.$ means that the function exceeded 1 sec.

• The task/pid field displays the thread cmdline and pid whichexecuted the function. It is default disabled.

  • hide: echo nofuncgraph-proc > trace_options
  • show: echo funcgraph-proc > trace_options

  ie:

  # tracer: function_graph## CPU  TASK/PID        DURATION                  FUNCTION CALLS# |    |    |           |   |                     |   |   |   |0)    sh-4802     |               |                  d_free() {0)    sh-4802     |               |                    call_rcu() {0)    sh-4802     |               |                      __call_rcu() {0)    sh-4802     |   0.616 us    |                        rcu_process_gp_end();0)    sh-4802     |   0.586 us    |                        check_for_new_grace_period();0)    sh-4802     |   2.899 us    |                      }0)    sh-4802     |   4.040 us    |                    }0)    sh-4802     |   5.151 us    |                  }0)    sh-4802     | + 49.370 us   |                }

• The absolute time field is an absolute timestamp given by thesystem clock since it started. A snapshot of this time isgiven on each entry/exit of functions

  • hide: echo nofuncgraph-abstime > trace_options
  • show: echo funcgraph-abstime > trace_options

  ie:

  ##      TIME       CPU  DURATION                  FUNCTION CALLS#       |         |     |   |                     |   |   |   |360.774522 |   1)   0.541 us    |                                          }360.774522 |   1)   4.663 us    |                                        }360.774523 |   1)   0.541 us    |                                        __wake_up_bit();360.774524 |   1)   6.796 us    |                                      }360.774524 |   1)   7.952 us    |                                    }360.774525 |   1)   9.063 us    |                                  }360.774525 |   1)   0.615 us    |                                  journal_mark_dirty();360.774527 |   1)   0.578 us    |                                  __brelse();360.774528 |   1)               |                                  reiserfs_prepare_for_journal() {360.774528 |   1)               |                                    unlock_buffer() {360.774529 |   1)               |                                      wake_up_bit() {360.774529 |   1)               |                                        bit_waitqueue() {360.774530 |   1)   0.594 us    |                                          __phys_addr();

The function name is always displayed after the closing bracketfor a function if the start of that function is not in thetrace buffer.

Display of the function name after the closing bracket may beenabled for functions whose start is in the trace buffer,allowing easier searching with grep for function durations.It is default disabled.

• hide: echo nofuncgraph-tail > trace_options
• show: echo funcgraph-tail > trace_options

Example with nofuncgraph-tail (default):

0)               |      putname() {0)               |        kmem_cache_free() {0)   0.518 us    |          __phys_addr();0)   1.757 us    |        }0)   2.861 us    |      }

Example with funcgraph-tail:

0)               |      putname() {0)               |        kmem_cache_free() {0)   0.518 us    |          __phys_addr();0)   1.757 us    |        } /* kmem_cache_free() */0)   2.861 us    |      } /* putname() */

You can put some comments on specific functions by usingtrace_printk() For example, if you want to put a comment insidethe __might_sleep() function, you just have to include<linux/ftrace.h> and calltrace_printk() inside __might_sleep():

trace_printk("I'm a comment!\n")

will produce:

1)               |             __might_sleep() {1)               |                /* I'm a comment! */1)   1.449 us    |             }

You might find other useful features for this tracer in thefollowing “dynamic ftrace” section such as tracing only specificfunctions or tasks.

dynamic ftrace¶

If CONFIG_DYNAMIC_FTRACE is set, the system will run withvirtually no overhead when function tracing is disabled. The waythis works is the mcount function call (placed at the start ofevery kernel function, produced by the -pg switch in gcc),starts of pointing to a simple return. (Enabling FTRACE willinclude the -pg switch in the compiling of the kernel.)

At compile time every C file object is run through therecordmcount program (located in the scripts directory). Thisprogram will parse the ELF headers in the C object to find allthe locations in the .text section that call mcount. Startingwith gcc version 4.6, the -mfentry has been added for x86, whichcalls “__fentry__” instead of “mcount”. Which is called beforethe creation of the stack frame.

Note, not all sections are traced. They may be prevented by eithera notrace, or blocked another way and all inline functions are nottraced. Check the “available_filter_functions” file to see what functionscan be traced.

A section called “__mcount_loc” is created that holdsreferences to all the mcount/fentry call sites in the .text section.The recordmcount program re-links this section back into theoriginal object. The final linking stage of the kernel will add all thesereferences into a single table.

On boot up, before SMP is initialized, the dynamic ftrace codescans this table and updates all the locations into nops. Italso records the locations, which are added to theavailable_filter_functions list. Modules are processed as theyare loaded and before they are executed. When a module isunloaded, it also removes its functions from the ftrace functionlist. This is automatic in the module unload code, and themodule author does not need to worry about it.

When tracing is enabled, the process of modifying the functiontracepoints is dependent on architecture. The old method is to usekstop_machine to prevent races with the CPUs executing code beingmodified (which can cause the CPU to do undesirable things, especiallyif the modified code crosses cache (or page) boundaries), and the nops arepatched back to calls. But this time, they do not call mcount(which is just a function stub). They now call into the ftraceinfrastructure.

The new method of modifying the function tracepoints is to placea breakpoint at the location to be modified, sync all CPUs, modifythe rest of the instruction not covered by the breakpoint. Syncall CPUs again, and then remove the breakpoint with the finishedversion to the ftrace call site.

Some archs do not even need to monkey around with the synchronization,and can just slap the new code on top of the old without anyproblems with other CPUs executing it at the same time.

One special side-effect to the recording of the functions beingtraced is that we can now selectively choose which functions wewish to trace and which ones we want the mcount calls to remainas nops.

Two files are used, one for enabling and one for disabling thetracing of specified functions. They are:

set_ftrace_filter

and

set_ftrace_notrace

A list of available functions that you can add to these files islisted in:

available_filter_functions

# cat available_filter_functionsput_prev_task_idlekmem_cache_createpick_next_task_rtget_online_cpuspick_next_task_fairmutex_lock[...]

If I am only interested in sys_nanosleep and hrtimer_interrupt:

# echo sys_nanosleep hrtimer_interrupt > set_ftrace_filter# echo function > current_tracer# echo 1 > tracing_on# usleep 1# echo 0 > tracing_on# cat trace# tracer: function## entries-in-buffer/entries-written: 5/5   #P:4##                              _-----=> irqs-off#                             / _----=> need-resched#                            | / _---=> hardirq/softirq#                            || / _--=> preempt-depth#                            ||| /     delay#           TASK-PID   CPU#  ||||    TIMESTAMP  FUNCTION#              | |       |   ||||       |         |          usleep-2665  [001] ....  4186.475355: sys_nanosleep <-system_call_fastpath          <idle>-0     [001] d.h1  4186.475409: hrtimer_interrupt <-smp_apic_timer_interrupt          usleep-2665  [001] d.h1  4186.475426: hrtimer_interrupt <-smp_apic_timer_interrupt          <idle>-0     [003] d.h1  4186.475426: hrtimer_interrupt <-smp_apic_timer_interrupt          <idle>-0     [002] d.h1  4186.475427: hrtimer_interrupt <-smp_apic_timer_interrupt

To see which functions are being traced, you can cat the file:

# cat set_ftrace_filterhrtimer_interruptsys_nanosleep

Perhaps this is not enough. The filters also allow glob(7) matching.

<match>*

will match functions that begin with <match>

*<match>

will match functions that end with <match>

*<match>*

will match functions that have <match> in it

<match1>*<match2>

will match functions that begin with <match1> and end with <match2>

# echo 'hrtimer_*' > set_ftrace_filter

Produces:

# tracer: function## entries-in-buffer/entries-written: 897/897   #P:4##                              _-----=> irqs-off#                             / _----=> need-resched#                            | / _---=> hardirq/softirq#                            || / _--=> preempt-depth#                            ||| /     delay#           TASK-PID   CPU#  ||||    TIMESTAMP  FUNCTION#              | |       |   ||||       |         |          <idle>-0     [003] dN.1  4228.547803: hrtimer_cancel <-tick_nohz_idle_exit          <idle>-0     [003] dN.1  4228.547804: hrtimer_try_to_cancel <-hrtimer_cancel          <idle>-0     [003] dN.2  4228.547805: hrtimer_force_reprogram <-__remove_hrtimer          <idle>-0     [003] dN.1  4228.547805: hrtimer_forward <-tick_nohz_idle_exit          <idle>-0     [003] dN.1  4228.547805: hrtimer_start_range_ns <-hrtimer_start_expires.constprop.11          <idle>-0     [003] d..1  4228.547858: hrtimer_get_next_event <-get_next_timer_interrupt          <idle>-0     [003] d..1  4228.547859: hrtimer_start <-__tick_nohz_idle_enter          <idle>-0     [003] d..2  4228.547860: hrtimer_force_reprogram <-__rem

Notice that we lost the sys_nanosleep.

# cat set_ftrace_filterhrtimer_run_queueshrtimer_run_pendinghrtimer_inithrtimer_cancelhrtimer_try_to_cancelhrtimer_forwardhrtimer_starthrtimer_reprogramhrtimer_force_reprogramhrtimer_get_next_eventhrtimer_interrupthrtimer_nanosleephrtimer_wakeuphrtimer_get_remaininghrtimer_get_reshrtimer_init_sleeper

This is because the ‘>’ and ‘>>’ act just like they do in bash.To rewrite the filters, use ‘>’To append to the filters, use ‘>>’

To clear out a filter so that all functions will be recordedagain:

# echo > set_ftrace_filter# cat set_ftrace_filter#

Again, now we want to append.

# echo sys_nanosleep > set_ftrace_filter# cat set_ftrace_filtersys_nanosleep# echo 'hrtimer_*' >> set_ftrace_filter# cat set_ftrace_filterhrtimer_run_queueshrtimer_run_pendinghrtimer_inithrtimer_cancelhrtimer_try_to_cancelhrtimer_forwardhrtimer_starthrtimer_reprogramhrtimer_force_reprogramhrtimer_get_next_eventhrtimer_interruptsys_nanosleephrtimer_nanosleephrtimer_wakeuphrtimer_get_remaininghrtimer_get_reshrtimer_init_sleeper

The set_ftrace_notrace prevents those functions from beingtraced.

# echo '*preempt*' '*lock*' > set_ftrace_notrace

Produces:

# tracer: function## entries-in-buffer/entries-written: 39608/39608   #P:4##                              _-----=> irqs-off#                             / _----=> need-resched#                            | / _---=> hardirq/softirq#                            || / _--=> preempt-depth#                            ||| /     delay#           TASK-PID   CPU#  ||||    TIMESTAMP  FUNCTION#              | |       |   ||||       |         |            bash-1994  [000] ....  4342.324896: file_ra_state_init <-do_dentry_open            bash-1994  [000] ....  4342.324897: open_check_o_direct <-do_last            bash-1994  [000] ....  4342.324897: ima_file_check <-do_last            bash-1994  [000] ....  4342.324898: process_measurement <-ima_file_check            bash-1994  [000] ....  4342.324898: ima_get_action <-process_measurement            bash-1994  [000] ....  4342.324898: ima_match_policy <-ima_get_action            bash-1994  [000] ....  4342.324899: do_truncate <-do_last            bash-1994  [000] ....  4342.324899: should_remove_suid <-do_truncate            bash-1994  [000] ....  4342.324899: notify_change <-do_truncate            bash-1994  [000] ....  4342.324900: current_fs_time <-notify_change            bash-1994  [000] ....  4342.324900: current_kernel_time <-current_fs_time            bash-1994  [000] ....  4342.324900: timespec_trunc <-current_fs_time

We can see that there’s no more lock or preempt tracing.

Selecting function filters via index¶

Because processing of strings is expensive (the address of the functionneeds to be looked up before comparing to the string being passed in),an index can be used as well to enable functions. This is useful in thecase of setting thousands of specific functions at a time. By passingin a list of numbers, no string processing will occur. Instead, the functionat the specific location in the internal array (which corresponds to thefunctions in the “available_filter_functions” file), is selected.

# echo 1 > set_ftrace_filter

Will select the first function listed in “available_filter_functions”

# head -1 available_filter_functionstrace_initcall_finish_cb# cat set_ftrace_filtertrace_initcall_finish_cb# head -50 available_filter_functions | tail -1x86_pmu_commit_txn# echo 1 50 > set_ftrace_filter# cat set_ftrace_filtertrace_initcall_finish_cbx86_pmu_commit_txn

Dynamic ftrace with the function graph tracer¶

Although what has been explained above concerns both thefunction tracer and the function-graph-tracer, there are somespecial features only available in the function-graph tracer.

If you want to trace only one function and all of its children,you just have to echo its name into set_graph_function:

echo __do_fault > set_graph_function

will produce the following “expanded” trace of the __do_fault()function:

0)               |  __do_fault() {0)               |    filemap_fault() {0)               |      find_lock_page() {0)   0.804 us    |        find_get_page();0)               |        __might_sleep() {0)   1.329 us    |        }0)   3.904 us    |      }0)   4.979 us    |    }0)   0.653 us    |    _spin_lock();0)   0.578 us    |    page_add_file_rmap();0)   0.525 us    |    native_set_pte_at();0)   0.585 us    |    _spin_unlock();0)               |    unlock_page() {0)   0.541 us    |      page_waitqueue();0)   0.639 us    |      __wake_up_bit();0)   2.786 us    |    }0) + 14.237 us   |  }0)               |  __do_fault() {0)               |    filemap_fault() {0)               |      find_lock_page() {0)   0.698 us    |        find_get_page();0)               |        __might_sleep() {0)   1.412 us    |        }0)   3.950 us    |      }0)   5.098 us    |    }0)   0.631 us    |    _spin_lock();0)   0.571 us    |    page_add_file_rmap();0)   0.526 us    |    native_set_pte_at();0)   0.586 us    |    _spin_unlock();0)               |    unlock_page() {0)   0.533 us    |      page_waitqueue();0)   0.638 us    |      __wake_up_bit();0)   2.793 us    |    }0) + 14.012 us   |  }

You can also expand several functions at once:

echo sys_open > set_graph_functionecho sys_close >> set_graph_function

Now if you want to go back to trace all functions you can clearthis special filter via:

echo > set_graph_function

ftrace_enabled¶

Note, the proc sysctl ftrace_enable is a big on/off switch for thefunction tracer. By default it is enabled (when function tracing isenabled in the kernel). If it is disabled, all function tracing isdisabled. This includes not only the function tracers for ftrace, butalso for any other uses (perf, kprobes, stack tracing, profiling, etc). Itcannot be disabled if there is a callback with FTRACE_OPS_FL_PERMANENT setregistered.

Please disable this with care.

This can be disable (and enabled) with:

 sysctl kernel.ftrace_enabled=0 sysctl kernel.ftrace_enabled=1or echo 0 > /proc/sys/kernel/ftrace_enabled echo 1 > /proc/sys/kernel/ftrace_enabled

Filter commands¶

A few commands are supported by the set_ftrace_filter interface.Trace commands have the following format:

<function>:<command>:<parameter>

The following commands are supported:

• mod:This command enables function filtering per module. Theparameter defines the module. For example, if only the write*functions in the ext3 module are desired, run:

  echo ‘write*:mod:ext3’ > set_ftrace_filter

  This command interacts with the filter in the same way asfiltering based on function names. Thus, adding more functionsin a different module is accomplished by appending (>>) to thefilter file. Remove specific module functions by prepending‘!’:

  echo '!writeback*:mod:ext3' >> set_ftrace_filter

  Mod command supports module globbing. Disable tracing for allfunctions except a specific module:

  echo '!*:mod:!ext3' >> set_ftrace_filter

  Disable tracing for all modules, but still trace kernel:

  echo '!*:mod:*' >> set_ftrace_filter

  Enable filter only for kernel:

  echo '*write*:mod:!*' >> set_ftrace_filter

  Enable filter for module globbing:

  echo '*write*:mod:*snd*' >> set_ftrace_filter

• traceon/traceoff:These commands turn tracing on and off when the specifiedfunctions are hit. The parameter determines how many times thetracing system is turned on and off. If unspecified, there isno limit. For example, to disable tracing when a schedule bugis hit the first 5 times, run:

  echo '__schedule_bug:traceoff:5' > set_ftrace_filter

  To always disable tracing when __schedule_bug is hit:

  echo '__schedule_bug:traceoff' > set_ftrace_filter

  These commands are cumulative whether or not they are appendedto set_ftrace_filter. To remove a command, prepend it by ‘!’and drop the parameter:

  echo '!__schedule_bug:traceoff:0' > set_ftrace_filter

  The above removes the traceoff command for __schedule_bugthat have a counter. To remove commands without counters:

  echo '!__schedule_bug:traceoff' > set_ftrace_filter

• snapshot:Will cause a snapshot to be triggered when the function is hit.

  echo 'native_flush_tlb_others:snapshot' > set_ftrace_filter

  To only snapshot once:

  echo 'native_flush_tlb_others:snapshot:1' > set_ftrace_filter

  To remove the above commands:

  echo '!native_flush_tlb_others:snapshot' > set_ftrace_filterecho '!native_flush_tlb_others:snapshot:0' > set_ftrace_filter

• enable_event/disable_event:These commands can enable or disable a trace event. Note, becausefunction tracing callbacks are very sensitive, when these commandsare registered, the trace point is activated, but disabled ina “soft” mode. That is, the tracepoint will be called, butjust will not be traced. The event tracepoint stays in this modeas long as there’s a command that triggers it.

  echo 'try_to_wake_up:enable_event:sched:sched_switch:2' > \      set_ftrace_filter

  The format is:

  <function>:enable_event:<system>:<event>[:count]<function>:disable_event:<system>:<event>[:count]

  To remove the events commands:

  echo '!try_to_wake_up:enable_event:sched:sched_switch:0' > \      set_ftrace_filterecho '!schedule:disable_event:sched:sched_switch' > \      set_ftrace_filter

• dump:When the function is hit, it will dump the contents of the ftracering buffer to the console. This is useful if you need to debugsomething, and want to dump the trace when a certain functionis hit. Perhaps it’s a function that is called before a triplefault happens and does not allow you to get a regular dump.

• cpudump:When the function is hit, it will dump the contents of the ftracering buffer for the current CPU to the console. Unlike the “dump”command, it only prints out the contents of the ring buffer for theCPU that executed the function that triggered the dump.

• stacktrace:When the function is hit, a stack trace is recorded.

trace_pipe¶

The trace_pipe outputs the same content as the trace file, butthe effect on the tracing is different. Every read fromtrace_pipe is consumed. This means that subsequent reads will bedifferent. The trace is live.

# echo function > current_tracer# cat trace_pipe > /tmp/trace.out &[1] 4153# echo 1 > tracing_on# usleep 1# echo 0 > tracing_on# cat trace# tracer: function## entries-in-buffer/entries-written: 0/0   #P:4##                              _-----=> irqs-off#                             / _----=> need-resched#                            | / _---=> hardirq/softirq#                            || / _--=> preempt-depth#                            ||| /     delay#           TASK-PID   CPU#  ||||    TIMESTAMP  FUNCTION#              | |       |   ||||       |         |## cat /tmp/trace.out           bash-1994  [000] ....  5281.568961: mutex_unlock <-rb_simple_write           bash-1994  [000] ....  5281.568963: __mutex_unlock_slowpath <-mutex_unlock           bash-1994  [000] ....  5281.568963: __fsnotify_parent <-fsnotify_modify           bash-1994  [000] ....  5281.568964: fsnotify <-fsnotify_modify           bash-1994  [000] ....  5281.568964: __srcu_read_lock <-fsnotify           bash-1994  [000] ....  5281.568964: add_preempt_count <-__srcu_read_lock           bash-1994  [000] ...1  5281.568965: sub_preempt_count <-__srcu_read_lock           bash-1994  [000] ....  5281.568965: __srcu_read_unlock <-fsnotify           bash-1994  [000] ....  5281.568967: sys_dup2 <-system_call_fastpath

Note, reading the trace_pipe file will block until more input isadded. This is contrary to the trace file. If any process openedthe trace file for reading, it will actually disable tracing andprevent new entries from being added. The trace_pipe file doesnot have this limitation.

trace entries¶

Having too much or not enough data can be troublesome indiagnosing an issue in the kernel. The file buffer_size_kb isused to modify the size of the internal trace buffers. Thenumber listed is the number of entries that can be recorded perCPU. To know the full size, multiply the number of possible CPUswith the number of entries.

# cat buffer_size_kb1408 (units kilobytes)

Or simply read buffer_total_size_kb

# cat buffer_total_size_kb5632

To modify the buffer, simple echo in a number (in 1024 byte segments).

# echo 10000 > buffer_size_kb# cat buffer_size_kb10000 (units kilobytes)

It will try to allocate as much as possible. If you allocate toomuch, it can cause Out-Of-Memory to trigger.

# echo 1000000000000 > buffer_size_kb-bash: echo: write error: Cannot allocate memory# cat buffer_size_kb85

The per_cpu buffers can be changed individually as well:

# echo 10000 > per_cpu/cpu0/buffer_size_kb# echo 100 > per_cpu/cpu1/buffer_size_kb

When the per_cpu buffers are not the same, the buffer_size_kbat the top level will just show an X

# cat buffer_size_kbX

This is where the buffer_total_size_kb is useful:

# cat buffer_total_size_kb12916

Writing to the top level buffer_size_kb will reset all the buffersto be the same again.

Snapshot¶

CONFIG_TRACER_SNAPSHOT makes a generic snapshot featureavailable to all non latency tracers. (Latency tracers whichrecord max latency, such as “irqsoff” or “wakeup”, can’t usethis feature, since those are already using the snapshotmechanism internally.)

Snapshot preserves a current trace buffer at a particular pointin time without stopping tracing. Ftrace swaps the currentbuffer with a spare buffer, and tracing continues in the newcurrent (=previous spare) buffer.

The following tracefs files in “tracing” are related to thisfeature:

snapshot:

This is used to take a snapshot and to read the outputof the snapshot. Echo 1 into this file to allocate aspare buffer and to take a snapshot (swap), then readthe snapshot from this file in the same format as“trace” (described above in the section “The FileSystem”). Both reads snapshot and tracing are executablein parallel. When the spare buffer is allocated, echoing0 frees it, and echoing else (positive) values clear thesnapshot contents.More details are shown in the table below.

status\input	0	1	else
not allocated	(do nothing)	alloc+swap	(do nothing)
allocated	free	swap	clear

Here is an example of using the snapshot feature.

# echo 1 > events/sched/enable# echo 1 > snapshot# cat snapshot# tracer: nop## entries-in-buffer/entries-written: 71/71   #P:8##                              _-----=> irqs-off#                             / _----=> need-resched#                            | / _---=> hardirq/softirq#                            || / _--=> preempt-depth#                            ||| /     delay#           TASK-PID   CPU#  ||||    TIMESTAMP  FUNCTION#              | |       |   ||||       |         |          <idle>-0     [005] d...  2440.603828: sched_switch: prev_comm=swapper/5 prev_pid=0 prev_prio=120   prev_state=R ==> next_comm=snapshot-test-2 next_pid=2242 next_prio=120           sleep-2242  [005] d...  2440.603846: sched_switch: prev_comm=snapshot-test-2 prev_pid=2242 prev_prio=120   prev_state=R ==> next_comm=kworker/5:1 next_pid=60 next_prio=120[...]        <idle>-0     [002] d...  2440.707230: sched_switch: prev_comm=swapper/2 prev_pid=0 prev_prio=120 prev_state=R ==> next_comm=snapshot-test-2 next_pid=2229 next_prio=120# cat trace# tracer: nop## entries-in-buffer/entries-written: 77/77   #P:8##                              _-----=> irqs-off#                             / _----=> need-resched#                            | / _---=> hardirq/softirq#                            || / _--=> preempt-depth#                            ||| /     delay#           TASK-PID   CPU#  ||||    TIMESTAMP  FUNCTION#              | |       |   ||||       |         |          <idle>-0     [007] d...  2440.707395: sched_switch: prev_comm=swapper/7 prev_pid=0 prev_prio=120 prev_state=R ==> next_comm=snapshot-test-2 next_pid=2243 next_prio=120 snapshot-test-2-2229  [002] d...  2440.707438: sched_switch: prev_comm=snapshot-test-2 prev_pid=2229 prev_prio=120 prev_state=S ==> next_comm=swapper/2 next_pid=0 next_prio=120[...]

If you try to use this snapshot feature when current tracer isone of the latency tracers, you will get the following results.

# echo wakeup > current_tracer# echo 1 > snapshotbash: echo: write error: Device or resource busy# cat snapshotcat: snapshot: Device or resource busy

Instances¶

In the tracefs tracing directory is a directory called “instances”.This directory can have new directories created inside of it usingmkdir, and removing directories with rmdir. The directory createdwith mkdir in this directory will already contain files and otherdirectories after it is created.

# mkdir instances/foo# ls instances/foobuffer_size_kb  buffer_total_size_kb  events  free_buffer  per_cpuset_event  snapshot  trace  trace_clock  trace_marker  trace_optionstrace_pipe  tracing_on

As you can see, the new directory looks similar to the tracing directoryitself. In fact, it is very similar, except that the buffer andevents are agnostic from the main directory, or from any otherinstances that are created.

The files in the new directory work just like the files with thesame name in the tracing directory except the buffer that is usedis a separate and new buffer. The files affect that buffer but do notaffect the main buffer with the exception of trace_options. Currently,the trace_options affect all instances and the top level bufferthe same, but this may change in future releases. That is, optionsmay become specific to the instance they reside in.

Notice that none of the function tracer files are there, nor iscurrent_tracer and available_tracers. This is because the bufferscan currently only have events enabled for them.

# mkdir instances/foo# mkdir instances/bar# mkdir instances/zoot# echo 100000 > buffer_size_kb# echo 1000 > instances/foo/buffer_size_kb# echo 5000 > instances/bar/per_cpu/cpu1/buffer_size_kb# echo function > current_trace# echo 1 > instances/foo/events/sched/sched_wakeup/enable# echo 1 > instances/foo/events/sched/sched_wakeup_new/enable# echo 1 > instances/foo/events/sched/sched_switch/enable# echo 1 > instances/bar/events/irq/enable# echo 1 > instances/zoot/events/syscalls/enable# cat trace_pipeCPU:2 [LOST 11745 EVENTS]            bash-2044  [002] .... 10594.481032: _raw_spin_lock_irqsave <-get_page_from_freelist            bash-2044  [002] d... 10594.481032: add_preempt_count <-_raw_spin_lock_irqsave            bash-2044  [002] d..1 10594.481032: __rmqueue <-get_page_from_freelist            bash-2044  [002] d..1 10594.481033: _raw_spin_unlock <-get_page_from_freelist            bash-2044  [002] d..1 10594.481033: sub_preempt_count <-_raw_spin_unlock            bash-2044  [002] d... 10594.481033: get_pageblock_flags_group <-get_pageblock_migratetype            bash-2044  [002] d... 10594.481034: __mod_zone_page_state <-get_page_from_freelist            bash-2044  [002] d... 10594.481034: zone_statistics <-get_page_from_freelist            bash-2044  [002] d... 10594.481034: __inc_zone_state <-zone_statistics            bash-2044  [002] d... 10594.481034: __inc_zone_state <-zone_statistics            bash-2044  [002] .... 10594.481035: arch_dup_task_struct <-copy_process[...]# cat instances/foo/trace_pipe            bash-1998  [000] d..4   136.676759: sched_wakeup: comm=kworker/0:1 pid=59 prio=120 success=1 target_cpu=000            bash-1998  [000] dN.4   136.676760: sched_wakeup: comm=bash pid=1998 prio=120 success=1 target_cpu=000          <idle>-0     [003] d.h3   136.676906: sched_wakeup: comm=rcu_preempt pid=9 prio=120 success=1 target_cpu=003          <idle>-0     [003] d..3   136.676909: sched_switch: prev_comm=swapper/3 prev_pid=0 prev_prio=120 prev_state=R ==> next_comm=rcu_preempt next_pid=9 next_prio=120     rcu_preempt-9     [003] d..3   136.676916: sched_switch: prev_comm=rcu_preempt prev_pid=9 prev_prio=120 prev_state=S ==> next_comm=swapper/3 next_pid=0 next_prio=120            bash-1998  [000] d..4   136.677014: sched_wakeup: comm=kworker/0:1 pid=59 prio=120 success=1 target_cpu=000            bash-1998  [000] dN.4   136.677016: sched_wakeup: comm=bash pid=1998 prio=120 success=1 target_cpu=000            bash-1998  [000] d..3   136.677018: sched_switch: prev_comm=bash prev_pid=1998 prev_prio=120 prev_state=R+ ==> next_comm=kworker/0:1 next_pid=59 next_prio=120     kworker/0:1-59    [000] d..4   136.677022: sched_wakeup: comm=sshd pid=1995 prio=120 success=1 target_cpu=001     kworker/0:1-59    [000] d..3   136.677025: sched_switch: prev_comm=kworker/0:1 prev_pid=59 prev_prio=120 prev_state=S ==> next_comm=bash next_pid=1998 next_prio=120[...]# cat instances/bar/trace_pipe     migration/1-14    [001] d.h3   138.732674: softirq_raise: vec=3 [action=NET_RX]          <idle>-0     [001] dNh3   138.732725: softirq_raise: vec=3 [action=NET_RX]            bash-1998  [000] d.h1   138.733101: softirq_raise: vec=1 [action=TIMER]            bash-1998  [000] d.h1   138.733102: softirq_raise: vec=9 [action=RCU]            bash-1998  [000] ..s2   138.733105: softirq_entry: vec=1 [action=TIMER]            bash-1998  [000] ..s2   138.733106: softirq_exit: vec=1 [action=TIMER]            bash-1998  [000] ..s2   138.733106: softirq_entry: vec=9 [action=RCU]            bash-1998  [000] ..s2   138.733109: softirq_exit: vec=9 [action=RCU]            sshd-1995  [001] d.h1   138.733278: irq_handler_entry: irq=21 name=uhci_hcd:usb4            sshd-1995  [001] d.h1   138.733280: irq_handler_exit: irq=21 ret=unhandled            sshd-1995  [001] d.h1   138.733281: irq_handler_entry: irq=21 name=eth0            sshd-1995  [001] d.h1   138.733283: irq_handler_exit: irq=21 ret=handled[...]# cat instances/zoot/trace# tracer: nop## entries-in-buffer/entries-written: 18996/18996   #P:4##                              _-----=> irqs-off#                             / _----=> need-resched#                            | / _---=> hardirq/softirq#                            || / _--=> preempt-depth#                            ||| /     delay#           TASK-PID   CPU#  ||||    TIMESTAMP  FUNCTION#              | |       |   ||||       |         |            bash-1998  [000] d...   140.733501: sys_write -> 0x2            bash-1998  [000] d...   140.733504: sys_dup2(oldfd: a, newfd: 1)            bash-1998  [000] d...   140.733506: sys_dup2 -> 0x1            bash-1998  [000] d...   140.733508: sys_fcntl(fd: a, cmd: 1, arg: 0)            bash-1998  [000] d...   140.733509: sys_fcntl -> 0x1            bash-1998  [000] d...   140.733510: sys_close(fd: a)            bash-1998  [000] d...   140.733510: sys_close -> 0x0            bash-1998  [000] d...   140.733514: sys_rt_sigprocmask(how: 0, nset: 0, oset: 6e2768, sigsetsize: 8)            bash-1998  [000] d...   140.733515: sys_rt_sigprocmask -> 0x0            bash-1998  [000] d...   140.733516: sys_rt_sigaction(sig: 2, act: 7fff718846f0, oact: 7fff71884650, sigsetsize: 8)            bash-1998  [000] d...   140.733516: sys_rt_sigaction -> 0x0

You can see that the trace of the top most trace buffer shows onlythe function tracing. The foo instance displays wakeups and taskswitches.

To remove the instances, simply delete their directories:

# rmdir instances/foo# rmdir instances/bar# rmdir instances/zoot

Note, if a process has a trace file open in one of the instancedirectories, the rmdir will fail with EBUSY.

Stack trace¶

Since the kernel has a fixed sized stack, it is important not towaste it in functions. A kernel developer must be conscience ofwhat they allocate on the stack. If they add too much, the systemcan be in danger of a stack overflow, and corruption will occur,usually leading to a system panic.

There are some tools that check this, usually with interruptsperiodically checking usage. But if you can perform a checkat every function call that will become very useful. As ftrace providesa function tracer, it makes it convenient to check the stack sizeat every function call. This is enabled via the stack tracer.

CONFIG_STACK_TRACER enables the ftrace stack tracing functionality.To enable it, write a ‘1’ into /proc/sys/kernel/stack_tracer_enabled.

# echo 1 > /proc/sys/kernel/stack_tracer_enabled

You can also enable it from the kernel command line to tracethe stack size of the kernel during boot up, by adding “stacktrace”to the kernel command line parameter.

After running it for a few minutes, the output looks like:

# cat stack_max_size2928# cat stack_trace        Depth    Size   Location    (18 entries)        -----    ----   --------  0)     2928     224   update_sd_lb_stats+0xbc/0x4ac  1)     2704     160   find_busiest_group+0x31/0x1f1  2)     2544     256   load_balance+0xd9/0x662  3)     2288      80   idle_balance+0xbb/0x130  4)     2208     128   __schedule+0x26e/0x5b9  5)     2080      16   schedule+0x64/0x66  6)     2064     128   schedule_timeout+0x34/0xe0  7)     1936     112   wait_for_common+0x97/0xf1  8)     1824      16   wait_for_completion+0x1d/0x1f  9)     1808     128   flush_work+0xfe/0x119 10)     1680      16   tty_flush_to_ldisc+0x1e/0x20 11)     1664      48   input_available_p+0x1d/0x5c 12)     1616      48   n_tty_poll+0x6d/0x134 13)     1568      64   tty_poll+0x64/0x7f 14)     1504     880   do_select+0x31e/0x511 15)      624     400   core_sys_select+0x177/0x216 16)      224      96   sys_select+0x91/0xb9 17)      128     128   system_call_fastpath+0x16/0x1b

Note, if -mfentry is being used by gcc, functions get traced beforethey set up the stack frame. This means that leaf level functionsare not tested by the stack tracer when -mfentry is used.

Currently, -mfentry is used by gcc 4.6.0 and above on x86 only.

More¶

More details can be found in the source code, in thekernel/trace/*.c files.