bd09c0556e
s/RUNTIME IN USE/RUNTIME IN US/
Link: https://lkml.kernel.org/r/43e5160422a967218aa651c47f523e8d32d6a59e.1624872608.git.bristot@redhat.com
Fixes: bce29ac9ce ("trace: Add osnoise tracer")
Signed-off-by: Daniel Bristot de Oliveira <bristot@redhat.com>
Signed-off-by: Steven Rostedt (VMware) <rostedt@goodmis.org>
153 lines
8.3 KiB
ReStructuredText
153 lines
8.3 KiB
ReStructuredText
==============
|
|
OSNOISE Tracer
|
|
==============
|
|
|
|
In the context of high-performance computing (HPC), the Operating System
|
|
Noise (*osnoise*) refers to the interference experienced by an application
|
|
due to activities inside the operating system. In the context of Linux,
|
|
NMIs, IRQs, SoftIRQs, and any other system thread can cause noise to the
|
|
system. Moreover, hardware-related jobs can also cause noise, for example,
|
|
via SMIs.
|
|
|
|
hwlat_detector is one of the tools used to identify the most complex
|
|
source of noise: *hardware noise*.
|
|
|
|
In a nutshell, the hwlat_detector creates a thread that runs
|
|
periodically for a given period. At the beginning of a period, the thread
|
|
disables interrupt and starts sampling. While running, the hwlatd
|
|
thread reads the time in a loop. As interrupts are disabled, threads,
|
|
IRQs, and SoftIRQs cannot interfere with the hwlatd thread. Hence, the
|
|
cause of any gap between two different reads of the time roots either on
|
|
NMI or in the hardware itself. At the end of the period, hwlatd enables
|
|
interrupts and reports the max observed gap between the reads. It also
|
|
prints a NMI occurrence counter. If the output does not report NMI
|
|
executions, the user can conclude that the hardware is the culprit for
|
|
the latency. The hwlat detects the NMI execution by observing
|
|
the entry and exit of a NMI.
|
|
|
|
The osnoise tracer leverages the hwlat_detector by running a
|
|
similar loop with preemption, SoftIRQs and IRQs enabled, thus allowing
|
|
all the sources of *osnoise* during its execution. Using the same approach
|
|
of hwlat, osnoise takes note of the entry and exit point of any
|
|
source of interferences, increasing a per-cpu interference counter. The
|
|
osnoise tracer also saves an interference counter for each source of
|
|
interference. The interference counter for NMI, IRQs, SoftIRQs, and
|
|
threads is increased anytime the tool observes these interferences' entry
|
|
events. When a noise happens without any interference from the operating
|
|
system level, the hardware noise counter increases, pointing to a
|
|
hardware-related noise. In this way, osnoise can account for any
|
|
source of interference. At the end of the period, the osnoise tracer
|
|
prints the sum of all noise, the max single noise, the percentage of CPU
|
|
available for the thread, and the counters for the noise sources.
|
|
|
|
Usage
|
|
-----
|
|
|
|
Write the ASCII text "osnoise" into the current_tracer file of the
|
|
tracing system (generally mounted at /sys/kernel/tracing).
|
|
|
|
For example::
|
|
|
|
[root@f32 ~]# cd /sys/kernel/tracing/
|
|
[root@f32 tracing]# echo osnoise > current_tracer
|
|
|
|
It is possible to follow the trace by reading the trace trace file::
|
|
|
|
[root@f32 tracing]# cat trace
|
|
# tracer: osnoise
|
|
#
|
|
# _-----=> irqs-off
|
|
# / _----=> need-resched
|
|
# | / _---=> hardirq/softirq
|
|
# || / _--=> preempt-depth MAX
|
|
# || / SINGLE Interference counters:
|
|
# |||| RUNTIME NOISE % OF CPU NOISE +-----------------------------+
|
|
# TASK-PID CPU# |||| TIMESTAMP IN US IN US AVAILABLE IN US HW NMI IRQ SIRQ THREAD
|
|
# | | | |||| | | | | | | | | | |
|
|
<...>-859 [000] .... 81.637220: 1000000 190 99.98100 9 18 0 1007 18 1
|
|
<...>-860 [001] .... 81.638154: 1000000 656 99.93440 74 23 0 1006 16 3
|
|
<...>-861 [002] .... 81.638193: 1000000 5675 99.43250 202 6 0 1013 25 21
|
|
<...>-862 [003] .... 81.638242: 1000000 125 99.98750 45 1 0 1011 23 0
|
|
<...>-863 [004] .... 81.638260: 1000000 1721 99.82790 168 7 0 1002 49 41
|
|
<...>-864 [005] .... 81.638286: 1000000 263 99.97370 57 6 0 1006 26 2
|
|
<...>-865 [006] .... 81.638302: 1000000 109 99.98910 21 3 0 1006 18 1
|
|
<...>-866 [007] .... 81.638326: 1000000 7816 99.21840 107 8 0 1016 39 19
|
|
|
|
In addition to the regular trace fields (from TASK-PID to TIMESTAMP), the
|
|
tracer prints a message at the end of each period for each CPU that is
|
|
running an osnoise/ thread. The osnoise specific fields report:
|
|
|
|
- The RUNTIME IN US reports the amount of time in microseconds that
|
|
the osnoise thread kept looping reading the time.
|
|
- The NOISE IN US reports the sum of noise in microseconds observed
|
|
by the osnoise tracer during the associated runtime.
|
|
- The % OF CPU AVAILABLE reports the percentage of CPU available for
|
|
the osnoise thread during the runtime window.
|
|
- The MAX SINGLE NOISE IN US reports the maximum single noise observed
|
|
during the runtime window.
|
|
- The Interference counters display how many each of the respective
|
|
interference happened during the runtime window.
|
|
|
|
Note that the example above shows a high number of HW noise samples.
|
|
The reason being is that this sample was taken on a virtual machine,
|
|
and the host interference is detected as a hardware interference.
|
|
|
|
Tracer options
|
|
---------------------
|
|
|
|
The tracer has a set of options inside the osnoise directory, they are:
|
|
|
|
- osnoise/cpus: CPUs at which a osnoise thread will execute.
|
|
- osnoise/period_us: the period of the osnoise thread.
|
|
- osnoise/runtime_us: how long an osnoise thread will look for noise.
|
|
- osnoise/stop_tracing_us: stop the system tracing if a single noise
|
|
higher than the configured value happens. Writing 0 disables this
|
|
option.
|
|
- osnoise/stop_tracing_total_us: stop the system tracing if total noise
|
|
higher than the configured value happens. Writing 0 disables this
|
|
option.
|
|
- tracing_threshold: the minimum delta between two time() reads to be
|
|
considered as noise, in us. When set to 0, the default value will
|
|
will be used, which is currently 5 us.
|
|
|
|
Additional Tracing
|
|
------------------
|
|
|
|
In addition to the tracer, a set of tracepoints were added to
|
|
facilitate the identification of the osnoise source.
|
|
|
|
- osnoise:sample_threshold: printed anytime a noise is higher than
|
|
the configurable tolerance_ns.
|
|
- osnoise:nmi_noise: noise from NMI, including the duration.
|
|
- osnoise:irq_noise: noise from an IRQ, including the duration.
|
|
- osnoise:softirq_noise: noise from a SoftIRQ, including the
|
|
duration.
|
|
- osnoise:thread_noise: noise from a thread, including the duration.
|
|
|
|
Note that all the values are *net values*. For example, if while osnoise
|
|
is running, another thread preempts the osnoise thread, it will start a
|
|
thread_noise duration at the start. Then, an IRQ takes place, preempting
|
|
the thread_noise, starting a irq_noise. When the IRQ ends its execution,
|
|
it will compute its duration, and this duration will be subtracted from
|
|
the thread_noise, in such a way as to avoid the double accounting of the
|
|
IRQ execution. This logic is valid for all sources of noise.
|
|
|
|
Here is one example of the usage of these tracepoints::
|
|
|
|
osnoise/8-961 [008] d.h. 5789.857532: irq_noise: local_timer:236 start 5789.857529929 duration 1845 ns
|
|
osnoise/8-961 [008] dNh. 5789.858408: irq_noise: local_timer:236 start 5789.858404871 duration 2848 ns
|
|
migration/8-54 [008] d... 5789.858413: thread_noise: migration/8:54 start 5789.858409300 duration 3068 ns
|
|
osnoise/8-961 [008] .... 5789.858413: sample_threshold: start 5789.858404555 duration 8812 ns interferences 2
|
|
|
|
In this example, a noise sample of 8 microseconds was reported in the last
|
|
line, pointing to two interferences. Looking backward in the trace, the
|
|
two previous entries were about the migration thread running after a
|
|
timer IRQ execution. The first event is not part of the noise because
|
|
it took place one millisecond before.
|
|
|
|
It is worth noticing that the sum of the duration reported in the
|
|
tracepoints is smaller than eight us reported in the sample_threshold.
|
|
The reason roots in the overhead of the entry and exit code that happens
|
|
before and after any interference execution. This justifies the dual
|
|
approach: measuring thread and tracing.
|