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
36 In the example below, the *timerlat* tracer is set to capture the stack trace at
37 the IRQ handler, printing it to the buffer if the *Thread* timer latency is
38 higher than *30 us*. It is also set to stop the session if a *Thread* timer
39 latency higher than *30 us* is hit. Finally, it is set to save the trace
40 buffer if the stop condition is hit::
42 [root@alien ~]# rtla timerlat top -s 30 -T 30 -t
44 0 00:00:59 | IRQ Timer Latency (us) | Thread Timer Latency (us)
45 CPU COUNT | cur min avg max | cur min avg max
46 0 #58634 | 1 0 1 10 | 11 2 10 23
47 1 #58634 | 1 0 1 9 | 12 2 9 23
48 2 #58634 | 0 0 1 11 | 10 2 9 23
49 3 #58634 | 1 0 1 11 | 11 2 9 24
50 4 #58634 | 1 0 1 10 | 11 2 9 26
51 5 #58634 | 1 0 1 8 | 10 2 9 25
52 6 #58634 | 12 0 1 12 | 30 2 10 30 <--- CPU with spike
53 7 #58634 | 1 0 1 9 | 11 2 9 23
54 8 #58633 | 1 0 1 9 | 11 2 9 26
55 9 #58633 | 1 0 1 9 | 10 2 9 26
56 10 #58633 | 1 0 1 13 | 11 2 9 28
57 11 #58633 | 1 0 1 13 | 12 2 9 24
58 12 #58633 | 1 0 1 8 | 10 2 9 23
59 13 #58633 | 1 0 1 10 | 10 2 9 22
60 14 #58633 | 1 0 1 18 | 12 2 9 27
61 15 #58633 | 1 0 1 10 | 11 2 9 28
62 16 #58633 | 0 0 1 11 | 7 2 9 26
63 17 #58633 | 1 0 1 13 | 10 2 9 24
64 18 #58633 | 1 0 1 9 | 13 2 9 22
65 19 #58633 | 1 0 1 10 | 11 2 9 23
66 20 #58633 | 1 0 1 12 | 11 2 9 28
67 21 #58633 | 1 0 1 14 | 11 2 9 24
68 22 #58633 | 1 0 1 8 | 11 2 9 22
69 23 #58633 | 1 0 1 10 | 11 2 9 27
70 timerlat hit stop tracing
71 saving trace to timerlat_trace.txt
72 [root@alien bristot]# tail -60 timerlat_trace.txt
74 timerlat/5-79755 [005] ....... 426.271226: #58634 context thread timer_latency 10823 ns
75 sh-109404 [006] dnLh213 426.271247: #58634 context irq timer_latency 12505 ns
76 sh-109404 [006] dNLh313 426.271258: irq_noise: local_timer:236 start 426.271245463 duration 12553 ns
77 sh-109404 [006] d...313 426.271263: thread_noise: sh:109404 start 426.271245853 duration 4769 ns
78 timerlat/6-79756 [006] ....... 426.271264: #58634 context thread timer_latency 30328 ns
79 timerlat/6-79756 [006] ....1.. 426.271265: <stack trace>
81 => __hrtimer_run_queues
83 => __sysvec_apic_timer_interrupt
84 => sysvec_apic_timer_interrupt
85 => asm_sysvec_apic_timer_interrupt
86 => _raw_spin_unlock_irqrestore <---- spinlock that disabled interrupt.
88 => autoremove_wake_function
90 => __wake_up_common_lock
93 => __wake_up_common_lock
95 => inotify_handle_inode_event
100 => exit_to_user_mode_prepare
101 => syscall_exit_to_user_mode
103 => entry_SYSCALL_64_after_hwframe
112 bash-109109 [007] d..h... 426.271265: #58634 context irq timer_latency 1211 ns
113 timerlat/6-79756 [006] ....... 426.271267: timerlat_main: stop tracing hit on cpu 6
115 In the trace, it is possible the notice that the *IRQ* timer latency was
116 already high, accounting *12505 ns*. The IRQ delay was caused by the
117 *bash-109109* process that disabled IRQs in the wake-up path
118 (*_try_to_wake_up()* function). The duration of the IRQ handler that woke
119 up the timerlat thread, informed with the **osnoise:irq_noise** event, was
120 also high and added more *12553 ns* to the Thread latency. Finally, the
121 **osnoise:thread_noise** added by the currently running thread (including
122 the scheduling overhead) added more *4769 ns*. Summing up these values,
123 the *Thread* timer latency accounted for *30328 ns*.
125 The primary reason for this high value is the wake-up path that was hit
126 twice during this case: when the *bash-109109* was waking up a thread
127 and then when the *timerlat* thread was awakened. This information can
128 then be used as the starting point of a more fine-grained analysis.
130 Note that **rtla timerlat** was dispatched without changing *timerlat* tracer
131 threads' priority. That is generally not needed because these threads hava
132 priority *FIFO:95* by default, which is a common priority used by real-time
133 kernel developers to analyze scheduling delays.
137 **rtla-timerlat**\(1), **rtla-timerlat-hist**\(1)
139 *timerlat* tracer documentation: <https://www.kernel.org/doc/html/latest/trace/timerlat-tracer.html>
143 Written by Daniel Bristot de Oliveira <bristot@kernel.org>
145 .. include:: common_appendix.rst