1RTLA-TIMERLAT-TOP(1)                                      RTLA-TIMERLAT-TOP(1)
2
3
4

NAME

6       rtla-timerlat-top - Measures the operating system timer latency
7

SYNOPSIS

9       rtla timerlat top [OPTIONS] ...
10

DESCRIPTION

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
18       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
23       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

OPTIONS

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
35       -p, --period us
36          Set the timerlat tracer period in microseconds.
37
38       -i, --irq us
39          Stop trace if the IRQ latency is higher than the argument in us.
40
41       -T, --thread us
42          Stop trace if the Thread latency is higher than the argument in us.
43
44       -s, --stack us
45          Save the stack trace at the IRQ if a Thread latency is  higher  than
46          the argument in us.
47
48       --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
53       -q, --quiet
54          Print only a summary at the end of the session.
55
56       -c, --cpus cpu-list
57          Set the osnoise tracer to run the sample threads in the cpu-list.
58
59       -d, --duration time[s|m|h|d]
60          Set the duration of the session.
61
62       -D, --debug
63          Print debug info.
64
65       -t, --trace[=file]
66          Save the stopped trace to [file|osnoise_trace.txt].
67
68       -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
74       --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
79       --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
85              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
89              Will automatically save the content of the histogram  associated
90              to osnoise:irq_noise event in osnoise_irq_noise_hist.txt.
91
92              For    further    information    about    event    trigger   see
93              https://www.kernel.org/doc/html/latest/trace/events.html#event-triggers.
94
95       -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
99o:prio - use SCHED_OTHER with prio;
100
101r:prio - use SCHED_RR with prio;
102
103f:prio - use SCHED_FIFO with prio;
104
105d:runtime[us|ms|s]:period[us|ms|s] - use SCHED_DEADLINE with  run‐
106            time and period in nanoseconds.
107
108       -h, --help
109          Print help menu.
110

EXAMPLE

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
118          [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
191       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
201       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
206       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
211   SEE ALSO
212       rtla-timerlat(1), rtla-timerlat-hist(1)
213
214       timerlat              tracer              documentation:             <‐
215       https://www.kernel.org/doc/html/latest/trace/timerlat-tracer.html>
216
217   AUTHOR
218       Written by Daniel Bristot de Oliveira <bristot@kernel.org>
219

REPORTING BUGS

221       Report    bugs     to     <linux-kernel@vger.kernel.org>     and     <‐
222       linux-trace-devel@vger.kernel.org>
223

LICENSE

225       rtla is Free Software licensed under the GNU GPLv2
226

COPYING

228       Copyright  (C)  2021 Red Hat, Inc. Free use of this software is granted
229       under the terms of the GNU Public License (GPL).
230
231
232
233
234                                                          RTLA-TIMERLAT-TOP(1)
Impressum