--- name: "rtla-timerlat-top" section: "1" platform: "linux" package: "rtla" version: "6.12.107-1" release: "Debian 13 (Trixie)" platforms: ["linux"] url: "https://new.carta.tech/rtla-timerlat-top" --- # rtla-timerlat-top(1) Measures the operating system timer latency ## NAME rtla-timerlat-top - Measures the operating system timer latency ## SYNOPSIS **rtla timerlat top** \[*OPTIONS*\] ... ## DESCRIPTION The **rtla timerlat** tool is an interface for the *timerlat* tracer. The *timerlat* tracer dispatches a kernel thread per-cpu. These threads set a periodic timer to wake themselves up and go back to sleep. After the wakeup, they collect and generate useful information for the debugging of operating system timer latency. The *timerlat* tracer outputs information in two ways. It periodically prints the timer latency at the timer *IRQ* handler and the *Thread* handler. It also enable the trace of the most relevant information via **osnoise:** tracepoints. 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 - **-a**, **--auto** *us* Set the automatic trace mode. This mode sets some commonly used options while debugging the system. It is equivalent to use **-T** *us* **-s** *us* **-t**. By default, *timerlat* tracer uses FIFO:95 for *timerlat* threads, thus equilavent to **-P** *f:95*. - **-p**, **--period** *us* Set the *timerlat* tracer period in microseconds. - **-i**, **--irq** *us* Stop trace if the *IRQ* latency is higher than the argument in us. - **-T**, **--thread** *us* Stop trace if the *Thread* latency is higher than the argument in us. - **-s**, **--stack** *us* Save the stack trace at the *IRQ* if a *Thread* latency is higher than the argument in us. - **-t**, **--trace** \[*file*\] Save the stopped trace to \[*file\|timerlat\_trace.txt*\]. - **--dma-latency *us*** Set the /dev/cpu\_dma\_latency to *us*, aiming to bound exit from idle latencies. *cyclictest* sets this value to *0* by default, use **--dma-latency** *0* to have similar results. - **-k**, **--kernel-threads** Use timerlat kernel-space threads, in contrast of **-u**. - **-u**, **--user-threads** Set timerlat to run without a workload, and then dispatches user-space workloads to wait on the timerlat\_fd. Once the workload is awakes, it goes to sleep again adding so the measurement for the kernel-to-user and user-to-kernel to the tracer output. **--user-threads** will be used unless the user specify **-k**. - **-U**, **--user-load** Set timerlat to run without workload, waiting for the user to dispatch a per-cpu task that waits for a new period on the tracing/osnoise/per\_cpu/cpu$ID/timerlat\_fd. See linux/tools/rtla/sample/timerlat\_load.py for an example of user-load code. - **-q**, **--quiet** Print only a summary at the end of the session. - **-c**, **--cpus** *cpu-list* Set the osnoise tracer to run the sample threads in the cpu-list. - **-H**, **--house-keeping** *cpu-list* Run rtla control threads only on the given cpu-list. - **-d**, **--duration** *time\[s\|m\|h\|d\]* Set the duration of the session. - **-D**, **--debug** Print debug info. - **-e**, **--event** *sys:event* Enable an event in the trace (**-t**) session. The argument can be a specific event, e.g., **-e** *sched:sched\_switch*, or all events of a system group, e.g., **-e** *sched*. Multiple **-e** are allowed. It is only active when **-t** or **-a** are set. - **--filter** *\* Filter the previous **-e** *sys:event* event with *\*. For further information about event filtering see \ . - **--trigger *\*** Enable a trace event trigger to the previous **-e** *sys:event*. If the *hist:* trigger is activated, the output histogram will be automatically saved to a file named *system\_event\_hist.txt*. For example, the command: rtla \ \ -t -e osnoise:irq\_noise --trigger="hist:key=desc,duration/1000:sort=desc,duration/1000:vals=hitcount" Will automatically save the content of the histogram associated to *osnoise:irq\_noise* event in *osnoise\_irq\_noise\_hist.txt*. For further information about event trigger see \ . - **-P**, **--priority** *o:prio\|r:prio\|f:prio\|d:runtime:period* Set scheduling parameters to the osnoise tracer threads, the format to set the priority are: - • *o:prio* - use SCHED\_OTHER with *prio*; - • *r:prio* - use SCHED\_RR with *prio*; - • *f:prio* - use SCHED\_FIFO with *prio*; - • *d:runtime\[us\|ms\|s\]:period\[us\|ms\|s\]* - use SCHED\_DEADLINE with *runtime* and *period* in nanoseconds. - **-C**, **--cgroup**\[*=cgroup*\] Set a *cgroup* to the tracer's threads. If the **-C** option is passed without arguments, the tracer's thread will inherit **rtla**'s *cgroup*. Otherwise, the threads will be placed on the *cgroup* passed to the option. - **--warm-up** *s* After starting the workload, let it run for *s* seconds before starting collecting the data, allowing the system to warm-up. Statistical data generated during warm-up is discarded. - **--trace-buffer-size *kB*** Set the per-cpu trace buffer size in kB for the tracing output. - **-h**, **--help** Print help menu. - **--dump-tasks** prints the task running on all CPUs if stop conditions are met (depends on !--no-aa) - **--no-aa** disable auto-analysis, reducing rtla timerlat cpu usage - **--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/1.md), [**rtla-timerlat-hist**(1)](/rtla-timerlat-hist/1.md) *timerlat* tracer documentation: \< \ \> ### AUTHOR Written by Daniel Bristot de Oliveira \< \ \> ## REPORTING BUGS Report bugs to \< \ \> and \< \ \> ## LICENSE **rtla** is Free Software licensed under the GNU GPLv2 ## COPYING Copyright (C) 2021 Red Hat, Inc. Free use of this software is granted under the terms of the GNU Public License (GPL).