4 -------------------------------------------
5 Measures the operating system timer latency
6 -------------------------------------------
12 **rtla timerlat top** [*OPTIONS*] ...
17 .. include:: common_timerlat_description.rst
19 The **rtla timerlat top** displays a summary of the periodic output
20 from the *timerlat* tracer. It also provides information for each
21 operating system noise via the **osnoise:** tracepoints that can be
22 seem with the option **-T**.
27 .. include:: common_timerlat_options.rst
29 .. include:: common_top_options.rst
31 .. include:: common_options.rst
33 .. include:: common_timerlat_aa.rst
37 Set stop tracing conditions and run without collecting and displaying statistics.
38 Print the auto-analysis if the system hits the stop tracing condition. This option
39 is useful to reduce rtla timerlat CPU, enabling the debug without the overhead of
40 collecting the statistics.
45 In the example below, the timerlat tracer is dispatched in cpus *1-23* in the
46 automatic trace mode, instructing the tracer to stop if a *40 us* latency or
49 # timerlat -a 40 -c 1-23 -q
51 0 00:00:12 | IRQ Timer Latency (us) | Thread Timer Latency (us)
52 CPU COUNT | cur min avg max | cur min avg max
53 1 #12322 | 0 0 1 15 | 10 3 9 31
54 2 #12322 | 3 0 1 12 | 10 3 9 23
55 3 #12322 | 1 0 1 21 | 8 2 8 34
56 4 #12322 | 1 0 1 17 | 10 2 11 33
57 5 #12322 | 0 0 1 12 | 8 3 8 25
58 6 #12322 | 1 0 1 14 | 16 3 11 35
59 7 #12322 | 0 0 1 14 | 9 2 8 29
60 8 #12322 | 1 0 1 22 | 9 3 9 34
61 9 #12322 | 0 0 1 14 | 8 2 8 24
62 10 #12322 | 1 0 0 12 | 9 3 8 24
63 11 #12322 | 0 0 0 15 | 6 2 7 29
64 12 #12321 | 1 0 0 13 | 5 3 8 23
65 13 #12319 | 0 0 1 14 | 9 3 9 26
66 14 #12321 | 1 0 0 13 | 6 2 8 24
67 15 #12321 | 1 0 1 15 | 12 3 11 27
68 16 #12318 | 0 0 1 13 | 7 3 10 24
69 17 #12319 | 0 0 1 13 | 11 3 9 25
70 18 #12318 | 0 0 0 12 | 8 2 8 20
71 19 #12319 | 0 0 1 18 | 10 2 9 28
72 20 #12317 | 0 0 0 20 | 9 3 8 34
73 21 #12318 | 0 0 0 13 | 8 3 8 28
74 22 #12319 | 0 0 1 11 | 8 3 10 22
75 23 #12320 | 28 0 1 28 | 41 3 11 41
76 rtla timerlat hit stop tracing
77 ## CPU 23 hit stop tracing, analyzing it ##
78 IRQ handler delay: 27.49 us (65.52 %)
80 Timerlat IRQ duration: 9.59 us (22.85 %)
81 Blocking thread: 3.79 us (9.03 %)
83 Blocking thread stacktrace
85 -> __hrtimer_run_queues
87 -> __sysvec_apic_timer_interrupt
88 -> sysvec_apic_timer_interrupt
89 -> asm_sysvec_apic_timer_interrupt
90 -> _raw_spin_unlock_irqrestore
91 -> cgroup_rstat_flush_locked
92 -> cgroup_rstat_flush_irqsafe
93 -> mem_cgroup_flush_stats
94 -> mem_cgroup_wb_stats
95 -> balance_dirty_pages
96 -> balance_dirty_pages_ratelimited_flags
97 -> btrfs_buffered_write
98 -> btrfs_do_write_iter
100 -> __x64_sys_pwrite64
102 -> entry_SYSCALL_64_after_hwframe
103 ------------------------------------------------------------------------
104 Thread latency: 41.96 us (100%)
106 The system has exit from idle latency!
107 Max timerlat IRQ latency from idle: 17.48 us in cpu 4
108 Saving trace to timerlat_trace.txt
110 In this case, the major factor was the delay suffered by the *IRQ handler*
111 that handles **timerlat** wakeup: *65.52%*. This can be caused by the
112 current thread masking interrupts, which can be seen in the blocking
113 thread stacktrace: the current thread (*objtool:49256*) disabled interrupts
114 via *raw spin lock* operations inside mem cgroup, while doing write
115 syscall in a btrfs file system.
117 The raw trace is saved in the **timerlat_trace.txt** file for further analysis.
119 Note that **rtla timerlat** was dispatched without changing *timerlat* tracer
120 threads' priority. That is generally not needed because these threads have
121 priority *FIFO:95* by default, which is a common priority used by real-time
122 kernel developers to analyze scheduling delays.
126 **rtla-timerlat**\(1), **rtla-timerlat-hist**\(1)
128 *timerlat* tracer documentation: <https://www.kernel.org/doc/html/latest/trace/timerlat-tracer.html>
132 Written by Daniel Bristot de Oliveira <bristot@kernel.org>
134 .. include:: common_appendix.rst