OSADL Linux Add-on Patch: Latency histograms with culprit/victim info

Linux kernel latency histograms are used to determine the duration of certain pathways that contribute to the preemption latency. As a side effect, the data stored along with the histogram data may allow to discover the source of an unusual long latency, since these data include the name and characteristic data of the previous and the next task of a delayed scheduling action. The original latency histograms were made available in the RT patch set in 2005; a number of additions were made since then:

• Separate histograms of shared vs. non-shared priority tasks
• Separate recording of “victim” and “culprit” of the highest latency
• Additional histogram to record latency of missed timers
• Additional histogram to record the sum of timer and wakeup latency
• Additional histogram to record duration of context switch
• Additional histogram to record the sum of timer, wakeup and context switch latency

Thus, the current version of the patch covers histograms to investigate the entire time span from the wake up trigger of an RT task to its execution continuation in user space as depicted below:

Configure

CONFIG_PREEMPT_OFF_HIST=y
CONFIG_INTERRUPT_OFF_HIST=y
CONFIG_MISSED_TIMER_OFFSETS_HIST=y
CONFIG_WAKEUP_LATENCY_HIST=y
CONFIG_SWITCHTIME_HIST=y

Enable

enabledir=/sys/kernel/debug/latency_hist/enable
for i in wakeup missed_timer_offsets timerandwakeup switchtime timerwakeupswitch
do
  enable=$enabledir/$i
  if test -f $enable
  then
    echo 1 >$enable
  fi
done

Usage example (core #0)

cd /sys/kernel/debug/latency_hist/timerwakeupswitch
cat CPU0
#Minimum latency: 0 microseconds
#Average latency: 0 microseconds
#Maximum latency: 42 microseconds
#Total samples: 917647
#There are 0 samples lower than 0 microseconds.
#There are 0 samples greater or equal than 10240 microseconds.
#usecs             samples
     0              784721
     1               80668
     2               37626
     3                6354
     4                3249
     5                1747
     6                 960
     7                 543
     8                 412
     9                 310
    10                 256
    11                 169
    12                 146
    13                 118
    14                  82
    15                  75
    16                  50
    17                  30
    18                  27
    19                  25
    20                  14
    21                  11
    22                  10
    23                  12
    24                   7
    25                   2
    26                   2
    27                   1
    28                   4
    29                   2
    30                   2
    31                   2
    32                   4
    34                   2
    35                   1
    39                   1
    41                   1
    42                   1

Display culprit and victim of longest latency (core #0)

cat /sys/kernel/debug/latency_hist/timerwakeupswitch/max_latency-CPU0
13457 99 42 (2,9) cyclictest <- 6681 5 alsa-sink-HDMI  1164604.885757 SyS_clock_nanosleep

This article may provide some more details on the usefulness of latency histograms.

Latency histograms