How rtla timerlat Measures Kernel Latency: Principles and Analysis

Introduction

This part explains the latency‑testing mechanism of rtla timerlat and the meaning of each value shown in the analysis results.

cyclictest Principle

Traditional Linux scheduling‑latency tool cyclictest creates one or more high‑priority loop tasks. Each loop sets a timer, sleeps, and wakes when the timer expires. The difference between the actual wake‑up time and the scheduled wake‑up time forms a latency sample. Aggregating samples yields minimum, maximum, and average latency.

rtla timerlat Principle

rtla timerlat consists of a kernel‑mode tracer and a user‑space application. The kernel component ( timerlat tracer ) performs the same loop but runs in kernel space, allowing it to capture finer‑grained data such as IRQ latency and the final thread latency.

Enabling timerlat tracer

# mount -t tracefs none /sys/kernel/tracing
# echo timerlat > /sys/kernel/tracing/current_tracer
# echo 1 > /sys/kernel/tracing/tracing_on

After enabling, the kernel executes timerlat_main in /kernel/trace/trace_osnoise.c. It initializes a high‑resolution timer:

// /kernel/trace/trace_osnoise.c:1891
hrtimer_init(&tlat->timer, CLOCK_MONOTONIC, HRTIMER_MODE_ABS_PINNED_HARD);
tlat->timer.function = timerlat_irq;
tlat->kthread = current;
... 
wait_next_period(tlat);

The helper wait_next_period computes the next absolute period, starts the timer, puts the thread to sleep, and returns after the timer fires:

static int wait_next_period(struct timerlat_variables *tlat) {
    ktime_t next_abs_period, now;
    u64 rel_period = osnoise_data.timerlat_period * 1000;
    now = hrtimer_cb_get_time(&tlat->timer);
    next_abs_period = ns_to_ktime(tlat->abs_period + rel_period);
    set_current_state(TASK_INTERRUPTIBLE);
    hrtimer_start(&tlat->timer, next_abs_period, HRTIMER_MODE_ABS_PINNED_HARD);
    schedule();
    return 1;
}

When the thread wakes, it computes the difference between the current time and the scheduled wake‑up time and stores it in diff. This value is reported as Thread Latency .

The timer interrupt handler timerlat_irq runs in IRQ context, records the same time difference, and sets s.context = IRQ_CONTEXT, labeling the sample as IRQ latency .

rtla User‑Space Application

The user‑space part receives kernel‑collected data via libtraceevent. It registers handlers for the timerlat trace event:

// /tools/tracing/rtla/src/timerlat_aa.c:937
static int timerlat_aa_register_events(struct osnoise_tool *tool, int dump_tasks) {
    int retval;
    tep_register_event_handler(tool->trace.tep, -1, "ftrace", "timerlat",
        timerlat_aa_handler, tool);
    ...
}

When a timerlat event occurs, timerlat_aa_handler extracts the context field and dispatches to the appropriate processor:

// /tools/tracing/rtla/src/timerlat_aa.c:241
static int timerlat_aa_handler(struct trace_seq *s, struct tep_record *record,
    struct tep_event *event, void *context) {
    ...
    tep_get_field_val(s, event, "context", record, &thread, 1);
    if (!thread)
        return timerlat_aa_irq_latency(taa_data, s, record, event);
    else
        return timerlat_aa_thread_latency(taa_data, s, record, event);
}

Fields such as timer_latency and seqnum are extracted with tep_get_field_val and correspond directly to the variables recorded by the kernel tracer.

Latency Analysis Example

# rtla timerlat top -T 500 -s 500 -t -k -P f:95
  0 00:00:01   |          IRQ Timer Latency (us)        |          Thread Timer Latency (us)
CPU COUNT      |      cur   min   avg   max|      cur   min   avg   max
| 0 #1015      | 236   37   42  236| 594  213  227  594 |
|----------------|-----------------------------------|-----------------------------------|
| ALL #1015 e0 | 37   42   236   | 213   227   594   |
rtla timerlat hit stop tracing
## CPU 0 hit stop tracing, analyzing it ##
  IRQ handler delay:                               157.68 us (26.52 %)
  IRQ latency:                                      236.24 us
  Timerlat IRQ duration:                            242.08 us (40.72 %)
  Blocking thread:                                 101.84 us (17.13 %)
    rtla:145                                       101.84 us
  Blocking thread stack trace
    -> stack_trace_save
    -> timerlat_save_stack.constprop.0
    -> timerlat_irq
    -> trace_event_buffer_commit
    -> __hrtimer_run_queues.constprop.0
    -> hrtimer_interrupt
    -> riscv_timer_interrupt
    -> handle_percpu_devid_irq
    -> ring_buffer_map
    -> handle_irq_desc
    -> riscv_intc_irq
    -> handle_riscv_irq
------------------------------------------------------------------------
  Thread latency:                                   594.48 us (100%)

The report lists several latency components:

IRQ handler delay – time from entry into the interrupt handler until the timer interrupt is reached; sourced from timer_irq_start_delay in struct timerlat_aa_data and the irq_handler_exit trace event (see kernel/irq/chip.c:924).

IRQ latency – total time from the interrupt being raised to the timer’s wake‑up, which includes the handler delay.

Timerlat IRQ duration – interval between trace_irq_handler_entry and trace_irq_handler_exit, i.e., the full interrupt‑handler execution time.

Blocking thread – after the interrupt handler finishes, if another thread runs before timerlat_main is scheduled, the time this thread spends on‑CPU is measured via the sched_switch trace event.

Thread latency – the final latency measured by the kernel‑mode tracer, reported as “Thread Timer Latency”.

Metric Source Mapping

IRQ Handler delay – kernel/irq/chip.c, function handle_percpu_devid_irq line 941.

IRQ Latency – kernel/trace/trace_osnoise.c, function timerlat_irq line 1801.

Timerlat IRQ duration – kernel/irq/chip.c, function handle_percpu_devid_irq lines 941‑944.

Blocking thread latency – /kernel/sched/core.c, function __schedule line 6526.

Thread Latency – kernel/trace/trace_osnoise.c, function timerlat_main line 1921.

Conclusion

Compared with cyclictest, the kernel‑mode tracer in rtla timerlat provides richer latency information—IRQ latency, thread latency, handler delay, and blocking‑thread cost—enabling more precise analysis of system latency.

References

Linux scheduling latency debug and analysis

libtraceevent(3) — Linux manual page

timerlat tracer source code

rtla source code