==================== rtla-timerlat-top

Measures the operating system timer latency

:Manual section: 1

SYNOPSIS

rtla timerlat top [OPTIONS] ...

DESCRIPTION

.. include:: common_timerlat_description.rst

The rtla timerlat top displays a summary of the periodic output from the timerlat tracer. It also provides information for each operating system noise via the osnoise: tracepoints that can be seem with the option -T.

OPTIONS

.. include:: common_timerlat_options.rst

.. include:: common_top_options.rst

.. include:: common_options.rst

.. include:: common_timerlat_aa.rst

--aa-only us

    Set stop tracing conditions and run without collecting and displaying statistics.
    Print the auto-analysis if the system hits the stop tracing condition. This option
    is useful to reduce rtla timerlat CPU, enabling the debug without the overhead of
    collecting the statistics.

EXAMPLE

In the example below, the timerlat tracer is dispatched in cpus 1-23 in the automatic trace mode, instructing the tracer to stop if a 40 us latency or higher is found::

timerlat -a 40 -c 1-23 -q

                                 Timer Latency
0 00:00:12   |          IRQ Timer Latency (us)        |         Thread Timer Latency (us)

CPU COUNT | cur min avg max | cur min avg max 1 #12322 | 0 0 1 15 | 10 3 9 31 2 #12322 | 3 0 1 12 | 10 3 9 23 3 #12322 | 1 0 1 21 | 8 2 8 34 4 #12322 | 1 0 1 17 | 10 2 11 33 5 #12322 | 0 0 1 12 | 8 3 8 25 6 #12322 | 1 0 1 14 | 16 3 11 35 7 #12322 | 0 0 1 14 | 9 2 8 29 8 #12322 | 1 0 1 22 | 9 3 9 34 9 #12322 | 0 0 1 14 | 8 2 8 24 10 #12322 | 1 0 0 12 | 9 3 8 24 11 #12322 | 0 0 0 15 | 6 2 7 29 12 #12321 | 1 0 0 13 | 5 3 8 23 13 #12319 | 0 0 1 14 | 9 3 9 26 14 #12321 | 1 0 0 13 | 6 2 8 24 15 #12321 | 1 0 1 15 | 12 3 11 27 16 #12318 | 0 0 1 13 | 7 3 10 24 17 #12319 | 0 0 1 13 | 11 3 9 25 18 #12318 | 0 0 0 12 | 8 2 8 20 19 #12319 | 0 0 1 18 | 10 2 9 28 20 #12317 | 0 0 0 20 | 9 3 8 34 21 #12318 | 0 0 0 13 | 8 3 8 28 22 #12319 | 0 0 1 11 | 8 3 10 22 23 #12320 | 28 0 1 28 | 41 3 11 41 rtla timerlat hit stop tracing

CPU 23 hit stop tracing, analyzing it

IRQ handler delay: 27.49 us (65.52 %) IRQ latency: 28.13 us Timerlat IRQ duration: 9.59 us (22.85 %) Blocking thread: 3.79 us (9.03 %) objtool:49256 3.79 us Blocking thread stacktrace -> timerlat_irq -> __hrtimer_run_queues -> hrtimer_interrupt -> __sysvec_apic_timer_interrupt -> sysvec_apic_timer_interrupt -> asm_sysvec_apic_timer_interrupt -> _raw_spin_unlock_irqrestore -> cgroup_rstat_flush_locked -> cgroup_rstat_flush_irqsafe -> mem_cgroup_flush_stats -> mem_cgroup_wb_stats -> balance_dirty_pages -> balance_dirty_pages_ratelimited_flags -> btrfs_buffered_write -> btrfs_do_write_iter -> vfs_write -> __x64_sys_pwrite64 -> do_syscall_64 -> entry_SYSCALL_64_after_hwframe

Thread latency:                                          41.96 us (100%)

The system has exit from idle latency! Max timerlat IRQ latency from idle: 17.48 us in cpu 4 Saving trace to timerlat_trace.txt

In this case, the major factor was the delay suffered by the IRQ handler that handles timerlat wakeup: 65.52%. This can be caused by the current thread masking interrupts, which can be seen in the blocking thread stacktrace: the current thread (objtool:49256) disabled interrupts via raw spin lock operations inside mem cgroup, while doing write syscall in a btrfs file system.

The raw trace is saved in the timerlat_trace.txt file for further analysis.

Note that rtla timerlat was dispatched without changing timerlat tracer threads' priority. That is generally not needed because these threads have priority FIFO:95 by default, which is a common priority used by real-time kernel developers to analyze scheduling delays.

SEE ALSO

rtla-timerlat(1), rtla-timerlat-hist(1)

timerlat tracer documentation: https://www.kernel.org/doc/html/latest/trace/timerlat-tracer.html

AUTHOR

Written by Daniel Bristot de Oliveira [email protected]

.. include:: common_appendix.rst