Tracing is useful when trying to determine the cause of a latency because it can reveal relevant details about execution. There are several options in Cyclictest that can be used to capture traces in combination with Ftrace.

Information about how to set up Ftrace as well as how to view traces taken with Ftrace can be found here.

A trace can be collected through Cyclictest by using the break trace (–breaktrace) option together with the –tracemark option. These options will stop tracing and end Cyclictest if it detects a latency that is longer than a specified limit. The ftrace must be started before Cyclictest is executed.

Ftrace provides a selection of tracers and instrumentation. These options are described in the Ftrace documentation here. The most important things to keep in mind when choosing instrumentation are the trace detail and the resulting overhead. A trace with more detail will require a higher overhead. In general, it is effective to corner the source of the latency over several iterations of tracing and analysis while gradually increasing the trace detail. Start with a small amount of instrumentation, which produces a simple trace. One good option would be to start by eliminating the most obvious possible sources of latency by tracing when interrupts or preemption are disabled.

It can sometimes be tempting to immediately jump to enabling function tracing. A full function trace is highly detailed because it includes all of the function calls that were made in the kernel. Function tracing can be very useful in the debugging process, but starting with such a highly detailed trace is not recommended. Analyzing a full function trace can be time consuming and confusing, especially if the latency's cause is complex. Additionally, function tracing has a significant overhead so it has a higher chance of affecting the behavior of the system. Because of this high overhead, in some cases it is possible that the targeted latency will not occur when function tracing is enabled.

Function tracing can be particularly useful for identifying latencies that are caused by the firmware or the hardware such as SMI related latencies. However, these kinds of latencies are not that common so it is not recommended to start by exploring this possibility.

There are a couple of steps that can help correctly produce a trace that includes the relevant latency. The following tips are relevant if the goal is to obtain a trace that includes the system's maximum latency. In general, it is a good idea to start by resolving the longest latencies in a system and to work down towards solving the shorter latencies.

Before tracing, make sure that the correct options for measuring the latency have been chosen and that Cyclictest detects the latency without having any tracing enabled. If the latency is not detected without any instrumentation, adding tracing will not help because the cause of the investigated latency will usually not be present in the resulting trace. Some suggestions for choosing the right Cyclictest options for a particular situation can be found on the Cyclictest Test Design page.

When trying to produce a trace that includes a specific latency, it is important to always adjust the break trace limit based on the observed tracing overhead. When tracing is enabled, the normal operation of the system will take longer and so the system's latencies will increase in length. For example, a system with an average latency of 1 us could have an average latency of 10 us with tracing enabled. If a maximum latency of around 130 us was observed without tracing, the maximum latency with tracing could be 200 us.

The easiest way to measure the overhead for a specific set of tracing instrumentation is to run Cyclictest with the desired tracing options and with a break trace limit that is much longer than the original maximum latency. Under these conditions, the new maximum latency measured with Cyclictest will include the original maximum latency and the tracing overhead.

For example, if the following Cyclictest command is run on a certain system:

cyclictest --mlockall --smp --priority=80 --interval=200 --distance=0

and after a couple hours a maximum latency of 130 us is detected. To measure the value of the maximum latency with the overhead from function tracing, ftrace can be enabled and then the following Cyclictest command could be run:

cyclictest --mlockall --smp --priority=80 --interval=200 --distance=0 --breaktrace=2000 --tracemark

After a few hours a latency of 190 us is detected. The maximum latency observed during this overhead measuring test will be used to determine the appropriate break trace limit for tracing the original latency. This process is explained in the next section.

Since the intent of this step is just to observe the overhead, the break trace limit should be much longer than the length of the expected latencies and the tracing should never actually break. If the tracing does break, Cyclictest should be run again with a higher break trace limit. The magnitude of the increase of the maximum latency due to tracing depends on what generates the latency, so it is important to be critical and to make sure that the high latency has actually occurred and the suspected spike is not just an elevated baseline due to the tracing. If the latency spikes at a similar time or in a similar situation as before the tracing was enabled, it is a good sign that it is the same latency as before.

Finally, a trace that includes the latency can be produced by starting ftrace and then running Cyclictest with a break trace limit that is slightly below the maximum latency value that was observed with tracing enabled. Continuing the example from the previous section, if the maximum latency with the overhead from function tracing is 190 us then the following command could be used to produce the trace:

cyclictest --mlockall --smp --priority=80 --interval=200 --distance=0 --breaktrace=180 --tracemark

using a break trace limit of 180 us. This new limit will cause Cyclictest to stop when the maximum latency occurs and will produce the relevant trace. This trace can then be viewed via tracefs in the same way as other Ftrace traces.