1RTLA-TIMERLAT-TOP(1) RTLA-TIMERLAT-TOP(1)
2
6 rtla-timerlat-top - Measures the operating system timer latency
7
9 rtla timerlat top [OPTIONS] ...
10
12 The rtla timerlat tool is an interface for the timerlat tracer. The
13 timerlat tracer dispatches a kernel thread per-cpu. These threads set a
14 periodic timer to wake themselves up and go back to sleep. After the
15 wakeup, they collect and generate useful information for the debugging
16 of operating system timer latency.
17 The timerlat tracer outputs information in two ways. It periodically
19 prints the timer latency at the timer IRQ handler and the Thread han‐
20 dler. It also enable the trace of the most relevant information via os‐
21 noise: tracepoints.
22 The rtla timerlat top displays a summary of the periodic output from
24 the timerlat tracer. It also provides information for each operating
25 system noise via the osnoise: tracepoints that can be seem with the op‐
26 tion -T.
27
29 -a, --auto us
30 Set the automatic trace mode. This mode sets some commonly used op‐
31 tions while debugging the system. It is equivalent to use -T us -s
32 us -t. By default, timerlat tracer uses FIFO:95 for timerlat
33 threads, thus equilavent to -P f:95.
34 -p, --period us
36 Set the timerlat tracer period in microseconds.
37 -i, --irq us
39 Stop trace if the IRQ latency is higher than the argument in us.
40 -T, --thread us
42 Stop trace if the Thread latency is higher than the argument in us.
43 -s, --stack us
45 Save the stack trace at the IRQ if a Thread latency is higher than
46 the argument in us.
47 --dma-latency us
49 Set the /dev/cpu_dma_latency to us, aiming to bound exit from
50 idle latencies. cyclictest sets this value to 0 by default, use
51 --dma-latency 0 to have similar results.
52 -q, --quiet
54 Print only a summary at the end of the session.
55 -c, --cpus cpu-list
57 Set the osnoise tracer to run the sample threads in the cpu-list.
58 -d, --duration time[s|m|h|d]
60 Set the duration of the session.
61 -D, --debug
63 Print debug info.
64 -t, --trace[=file]
66 Save the stopped trace to [file|osnoise_trace.txt].
67 -e, --event sys:event
69 Enable an event in the trace (-t) session. The argument can be a
70 specific event, e.g., -e sched:sched_switch, or all events of a sys‐
71 tem group, e.g., -e sched. Multiple -e are allowed. It is only ac‐
72 tive when -t or -a are set.
73 --filter <filter>
75 Filter the previous -e sys:event event with <filter>. For further
76 information about event filtering see
77 https://www.kernel.org/doc/html/latest/trace/events.html#event-filtering.
78 --trigger <trigger>
80 Enable a trace event trigger to the previous -e sys:event. If
81 the hist: trigger is activated, the output histogram will be au‐
82 tomatically saved to a file named system_event_hist.txt. For
83 example, the command:
84 rtla <command> <mode> -t -e osnoise:irq_noise --trig‐
86 ger="hist:key=desc,duration/1000:sort=desc,dura‐
87 tion/1000:vals=hitcount"
88 Will automatically save the content of the histogram associated
90 to osnoise:irq_noise event in osnoise_irq_noise_hist.txt.
91 For further information about event trigger see
93 https://www.kernel.org/doc/html/latest/trace/events.html#event-triggers.
94 -P, --priority o:prio|r:prio|f:prio|d:runtime:period
96 Set scheduling parameters to the osnoise tracer threads, the format
97 to set the priority are:
98 • o:prio - use SCHED_OTHER with prio;
100 • r:prio - use SCHED_RR with prio;
102 • f:prio - use SCHED_FIFO with prio;
104 • d:runtime[us|ms|s]:period[us|ms|s] - use SCHED_DEADLINE with run‐
106 time and period in nanoseconds.
107 -h, --help
109 Print help menu.
110
112 In the example below, the timerlat tracer is set to capture the stack
113 trace at the IRQ handler, printing it to the buffer if the Thread timer
114 latency is higher than 30 us. It is also set to stop the session if a
115 Thread timer latency higher than 30 us is hit. Finally, it is set to
116 save the trace buffer if the stop condition is hit:
117 [root@alien ~]# rtla timerlat top -s 30 -t 30 -T
119 Timer Latency
120 0 00:00:59 | IRQ Timer Latency (us) | Thread Timer Latency (us)
121 CPU COUNT | cur min avg max | cur min avg max
122 0 #58634 | 1 0 1 10 | 11 2 10 23
123 1 #58634 | 1 0 1 9 | 12 2 9 23
124 2 #58634 | 0 0 1 11 | 10 2 9 23
125 3 #58634 | 1 0 1 11 | 11 2 9 24
126 4 #58634 | 1 0 1 10 | 11 2 9 26
127 5 #58634 | 1 0 1 8 | 10 2 9 25
128 6 #58634 | 12 0 1 12 | 30 2 10 30 <--- CPU with spike
129 7 #58634 | 1 0 1 9 | 11 2 9 23
130 8 #58633 | 1 0 1 9 | 11 2 9 26
131 9 #58633 | 1 0 1 9 | 10 2 9 26
132 10 #58633 | 1 0 1 13 | 11 2 9 28
133 11 #58633 | 1 0 1 13 | 12 2 9 24
134 12 #58633 | 1 0 1 8 | 10 2 9 23
135 13 #58633 | 1 0 1 10 | 10 2 9 22
136 14 #58633 | 1 0 1 18 | 12 2 9 27
137 15 #58633 | 1 0 1 10 | 11 2 9 28
138 16 #58633 | 0 0 1 11 | 7 2 9 26
139 17 #58633 | 1 0 1 13 | 10 2 9 24
140 18 #58633 | 1 0 1 9 | 13 2 9 22
141 19 #58633 | 1 0 1 10 | 11 2 9 23
142 20 #58633 | 1 0 1 12 | 11 2 9 28
143 21 #58633 | 1 0 1 14 | 11 2 9 24
144 22 #58633 | 1 0 1 8 | 11 2 9 22
145 23 #58633 | 1 0 1 10 | 11 2 9 27
146 timerlat hit stop tracing
147 saving trace to timerlat_trace.txt
148 [root@alien bristot]# tail -60 timerlat_trace.txt
149 [...]
150 timerlat/5-79755 [005] ....... 426.271226: #58634 context thread timer_latency 10823 ns
151 sh-109404 [006] dnLh213 426.271247: #58634 context irq timer_latency 12505 ns
152 sh-109404 [006] dNLh313 426.271258: irq_noise: local_timer:236 start 426.271245463 duration 12553 ns
153 sh-109404 [006] d...313 426.271263: thread_noise: sh:109404 start 426.271245853 duration 4769 ns
154 timerlat/6-79756 [006] ....... 426.271264: #58634 context thread timer_latency 30328 ns
155 timerlat/6-79756 [006] ....1.. 426.271265: <stack trace>
156 => timerlat_irq
157 => __hrtimer_run_queues
158 => hrtimer_interrupt
159 => __sysvec_apic_timer_interrupt
160 => sysvec_apic_timer_interrupt
161 => asm_sysvec_apic_timer_interrupt
162 => _raw_spin_unlock_irqrestore <---- spinlock that disabled interrupt.
163 => try_to_wake_up
164 => autoremove_wake_function
165 => __wake_up_common
166 => __wake_up_common_lock
167 => ep_poll_callback
168 => __wake_up_common
169 => __wake_up_common_lock
170 => fsnotify_add_event
171 => inotify_handle_inode_event
172 => fsnotify
173 => __fsnotify_parent
174 => __fput
175 => task_work_run
176 => exit_to_user_mode_prepare
177 => syscall_exit_to_user_mode
178 => do_syscall_64
179 => entry_SYSCALL_64_after_hwframe
180 => 0x7265000001378c
181 => 0x10000cea7
182 => 0x25a00000204a
183 => 0x12e302d00000000
184 => 0x19b51010901b6
185 => 0x283ce00726500
186 => 0x61ea308872
187 => 0x00000fe3
188 bash-109109 [007] d..h... 426.271265: #58634 context irq timer_latency 1211 ns
189 timerlat/6-79756 [006] ....... 426.271267: timerlat_main: stop tracing hit on cpu 6
190 In the trace, it is possible the notice that the IRQ timer latency was
192 already high, accounting 12505 ns. The IRQ delay was caused by the
193 bash-109109 process that disabled IRQs in the wake-up path
194 (_try_to_wake_up() function). The duration of the IRQ handler that woke
195 up the timerlat thread, informed with the osnoise:irq_noise event, was
196 also high and added more 12553 ns to the Thread latency. Finally, the
197 osnoise:thread_noise added by the currently running thread (including
198 the scheduling overhead) added more 4769 ns. Summing up these values,
199 the Thread timer latency accounted for 30328 ns.
200 The primary reason for this high value is the wake-up path that was hit
202 twice during this case: when the bash-109109 was waking up a thread and
203 then when the timerlat thread was awakened. This information can then
204 be used as the starting point of a more fine-grained analysis.
205 Note that rtla timerlat was dispatched without changing timerlat tracer
207 threads' priority. That is generally not needed because these threads
208 hava priority FIFO:95 by default, which is a common priority used by
209 real-time kernel developers to analyze scheduling delays.
210 SEE ALSO
212 rtla-timerlat(1), rtla-timerlat-hist(1)
213 timerlat tracer documentation: <‐
215 https://www.kernel.org/doc/html/latest/trace/timerlat-tracer.html>
216 AUTHOR
218 Written by Daniel Bristot de Oliveira <bristot@kernel.org>
219
221 Report bugs to <lkml@vger.kernel.org>
222
224 rtla is Free Software licensed under the GNU GPLv2
225
227 Copyright (C) 2021 Red Hat, Inc. Free use of this software is granted
228 under the terms of the GNU Public License (GPL).
229 RTLA-TIMERLAT-TOP(1)