3.7. Using the ftrace Utility for Tracing Latencies

One of the diagnostic facilities provided with the MRG Realtime kernel is ftrace, which is used by developers to analyze and debug latency and performance issues that occur outside of user-space. The ftrace utility has a variety of options that allow you to use the utility in a number of different ways. It can be used to trace context switches, measure the time it takes for a high-priority task to wake up, the length of time interrupts are disabled, or list all the kernel functions executed during a given period.
Some tracers, such as the function tracer, will produce exceedingly large amounts of data, which can turn trace log analysis into a time-consuming task. However, it is possible to instruct the tracer to begin and end only when the application reaches critical code paths.

Using the ftrace Utility

  1. Once the trace variant of the MRG Realtime kernel is installed and in use, the ftrace utility can be set up. Mount the kernel to /sys/kernel/debug and instruct it to use the debugfs file system:
    # mount -t debugfs nodev /sys/kernel/debug
    
  2. In the /sys/kernel/debug/tracing/ directory there is a file named available_tracers. This file contains all the available tracers for the installed version of ftrace. To see the list of available tracers, use the cat command to view the contents of the file:
    # cat /sys/kernel/debug/tracing/available_tracers
    events wakeup preemptirqsoff preemptoff irqsoff ftrace sched_switch none
    
    events
    Traces system events such as timers, system calls, interrupts, context switches, process wake up and others
    wakeup
    Traces the maximum latency in between the highest priority process waking up and being scheduled. Only RT tasks are considered by this tracer (SCHED_OTHER tasks are ignored as of now).
    preemptirqsoff
    Traces the areas that disable pre-emption and interrupts and records the maximum amount of time for which pre-emption or interrupts were disabled.
    preemptoff
    Similar to the preemptirqsoff tracer but traces only the maximum interval for which pre-emption was disabled.
    irqsoff
    Similar to the preemptirqsoff tracer but traces only the maximum interval for which interrupts were disabled.
    ftrace
    Records the kernel functions called during a tracing session. The ftrace utility can be run simultaneously with any of the other tracers, except the sched_switch tracer.
    sched_switch
    Traces context switches between tasks.
    none
    Disables tracing.
  3. To manually start a tracing session, first select the tracer you wish to use from the list in available_tracers and then use the echo to insert the name of the tracer into /sys/kernel/debug/tracing/current_tracer:
    # echo events > /sys/kernel/debug/tracing/current_tracer
    
  4. To check if the ftrace utility can be enabled, use the cat command to view the /proc/sys/kernel/ftrace_enabled file. A value of 1 indicates that ftrace can be enabled, and 0 indicates that it has been disabled.
    # cat /proc/sys/kernel/ftrace_enabled
    1
    
    By default, the tracer is enabled. To turn the tracer on or off, echo the appropriate value to the /proc/sys/kernel/ftrace_enabled file.
    # echo 0 > /proc/sys/kernel/ftrace_enabled
    	
    # echo 1 > /proc/sys/kernel/ftrace_enabled
    

    Important

    When using the echo command, ensure you place a space character in between the value and the > character. At the shell prompt, using 0>, 1>, and 2> (without a space character) refers to standard input, standard output and standard error. Using them by mistake could result in unexpected trace output.
  5. Adjust details and parameters of the tracers by changing the values for the various files in the /debugfs/tracing/ directory. Some examples are:
    The irqsoff, preemptoff, preempirqsoff, and wakeup tracers continuously monitor latencies. When they record a latency greater than the one recorded in tracing_max_latency the trace of that latency is recorded, and tracing_max_latency is updated to the new maximum time. In this way, tracing_max_latency will always shows the highest recorded latency sinced it was last reset.
    To reset the maximum latency, echo 0 into the tracing_max_latency file. To see only latencies greater than a set amount, echo the amount in microseconds:
    # echo 0 > /sys/kernel/debug/tracing//tracing_max_latency
    
    When the tracing threshold is set, it overrides the maximum latency setting. When a latency is recorded that is greater than the threshold, it will be recorded regardless of the maximum latency. When reviewing the trace file, only the last recorded latency is shown.
    To set the threshold, echo the number of microseconds above which latencies should be recorded:
    # echo 200 > /sys/kernel/debug/tracing//tracing_thresh
    
  6. View the trace logs:
    # cat /sys/kernel/debug/tracing//trace
    
    # cat /sys/kernel/debug/tracing//latency_trace
    
  7. To store the trace logs, copy them to another file:
    # cat /sys/kernel/debug/tracing//latency_trace > /tmp/lat_trace_log
  8. There are a number of options available for changing the format of the output. These options are stored in /debug/tracing/iter_ctrl:
    print-parent Show the parent functions
    sym-offset Show the hex offset into the function
    sym-addr Show the full address and name of a function
    verbose Show more data in the tracer output
    stacktrace Show a stacktrace in the tracer output. This effects the runtime tracing, and not just the output.
  9. Use the cat command to view the current configuration:
    # cat /sys/kernel/debug/tracing/iter_ctrl
    
    To set a single option on the tracer output configuration, echo the option name to the /sys/kernel/debug/tracing/iter_ctrl file.
    # echo verbose > /sys/kernel/debug/tracing/iter_ctrl
    
    To disable a single option on the tracing output configuration, echo the option name with the test no before it to the /sys/kernel/debug/tracing/iter_ctrl file.
    # echo noverbose > /sys/kernel/debug/tracing/iter_ctrl
    
  10. The ftrace utility can be filtered by altering the settings in the /sys/kernel/debug/tracing/set_ftrace_filter file. If no filters are specified in the file, all processes are traced. Use the cat to view the current filters:
    # cat /sys/kernel/debug/tracing/set_ftrace_filter
    
  11. To change the filters, echo the name of the function to be traced. The filter allows the use of a * wildcard at the beginning or end of a search term.
    The * wildcard can also be used at both the beginning and end of a word. For example: *irq* will select all functions that contain irq in the name.
    Encasing the search term and the wildcard character in double quotation marks ensures that that shell will not attempt to expand the search to the present working directory.
    Some examples of filters are:
    • Trace only the schedule process:
      # echo schedule > /sys/kernel/debug/tracing/set_ftrace_filter
      
    • Trace all processes that end with lock:
      # echo "*lock" > /sys/kernel/debug/tracing/set_ftrace_filter
      
    • Trace all processes that start with spin_:
      # echo "spin_*" > /sys/kernel/debug/tracing/set_ftrace_filter
      
    • Trace all processes with cpu in the name:
      # echo "*cpu*" > /sys/kernel/debug/tracing/set_ftrace_filter
      

    Note

    If you use a single > with the echo command, it will override any existing value in the file. If you wish to append the value to the file, use >> instead.