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       -u, --user-threads
54          Set  timerlat  to  run  without  a  workload,  and  then  dispatches
55          user-space workloads to wait on the timerlat_fd. Once  the  workload
56          is  awakes, it goes to sleep again adding so the measurement for the
57          kernel-to-user and user-to-kernel to the tracer output.
58
59       -q, --quiet
60          Print only a summary at the end of the session.
61
62       -c, --cpus cpu-list
63          Set the osnoise tracer to run the sample threads in the cpu-list.
64
65       -H, --house-keeping cpu-list
66          Run rtla control threads only on the given cpu-list.
67
68       -d, --duration time[s|m|h|d]
69          Set the duration of the session.
70
71       -D, --debug
72          Print debug info.
73
74       -t, --trace[=file]
75          Save the stopped trace to [file|osnoise_trace.txt].
76
77       -e, --event sys:event
78          Enable an event in the trace (-t) session. The  argument  can  be  a
79          specific event, e.g., -e sched:sched_switch, or all events of a sys‐
80          tem group, e.g., -e sched. Multiple -e are allowed. It is  only  ac‐
81          tive when -t or -a are set.
82
83       --filter <filter>
84          Filter  the  previous  -e sys:event event with <filter>. For further
85          information        about         event         filtering         see
86          https://www.kernel.org/doc/html/latest/trace/events.html#event-filtering.
87
88       --trigger <trigger>
89              Enable a trace event trigger to the previous -e  sys:event.   If
90              the hist: trigger is activated, the output histogram will be au‐
91              tomatically saved to a file  named  system_event_hist.txt.   For
92              example, the command:
93
94              rtla   <command>   <mode>   -t   -e   osnoise:irq_noise  --trig‐
95              ger="hist:key=desc,duration/1000:sort=desc,dura‐
96              tion/1000:vals=hitcount"
97
98              Will  automatically save the content of the histogram associated
99              to osnoise:irq_noise event in osnoise_irq_noise_hist.txt.
100
101              For   further    information    about    event    trigger    see
102              https://www.kernel.org/doc/html/latest/trace/events.html#event-triggers.
103
104       -P, --priority o:prio|r:prio|f:prio|d:runtime:period
105          Set scheduling parameters to the osnoise tracer threads, the  format
106          to set the priority are:
107
108o:prio - use SCHED_OTHER with prio;
109
110r:prio - use SCHED_RR with prio;
111
112f:prio - use SCHED_FIFO with prio;
113
114d:runtime[us|ms|s]:period[us|ms|s]  - use SCHED_DEADLINE with run‐
115            time and period in nanoseconds.
116
117       -C, --cgroup[=cgroup]
118          Set a cgroup to the tracer's threads. If the  -C  option  is  passed
119          without  arguments,  the tracer's thread will inherit rtla's cgroup.
120          Otherwise, the threads will be placed on the cgroup  passed  to  the
121          option.
122
123       -h, --help
124          Print help menu.
125
126       --dump-tasks
127          prints  the task running on all CPUs if stop conditions are met (de‐
128          pends on !--no-aa)
129
130       --no-aa
131          disable auto-analysis, reducing rtla timerlat cpu usage
132
133       --aa-only us
134          Set stop tracing conditions and run without collecting and  display‐
135          ing statistics.  Print the auto-analysis if the system hits the stop
136          tracing condition. This option is useful  to  reduce  rtla  timerlat
137          CPU,  enabling the debug without the overhead of collecting the sta‐
138          tistics.
139

EXAMPLE

141       In the example below, the timerlat tracer is dispatched in cpus 1-23 in
142       the automatic trace mode, instructing the tracer to stop if a 40 us la‐
143       tency or higher is found:
144
145          # timerlat -a 40 -c 1-23 -q
146                                             Timer Latency
147            0 00:00:12   |          IRQ Timer Latency (us)        |         Thread Timer Latency (us)
148          CPU COUNT      |      cur       min       avg       max |      cur       min       avg       max
149            1 #12322     |        0         0         1        15 |       10         3         9        31
150            2 #12322     |        3         0         1        12 |       10         3         9        23
151            3 #12322     |        1         0         1        21 |        8         2         8        34
152            4 #12322     |        1         0         1        17 |       10         2        11        33
153            5 #12322     |        0         0         1        12 |        8         3         8        25
154            6 #12322     |        1         0         1        14 |       16         3        11        35
155            7 #12322     |        0         0         1        14 |        9         2         8        29
156            8 #12322     |        1         0         1        22 |        9         3         9        34
157            9 #12322     |        0         0         1        14 |        8         2         8        24
158           10 #12322     |        1         0         0        12 |        9         3         8        24
159           11 #12322     |        0         0         0        15 |        6         2         7        29
160           12 #12321     |        1         0         0        13 |        5         3         8        23
161           13 #12319     |        0         0         1        14 |        9         3         9        26
162           14 #12321     |        1         0         0        13 |        6         2         8        24
163           15 #12321     |        1         0         1        15 |       12         3        11        27
164           16 #12318     |        0         0         1        13 |        7         3        10        24
165           17 #12319     |        0         0         1        13 |       11         3         9        25
166           18 #12318     |        0         0         0        12 |        8         2         8        20
167           19 #12319     |        0         0         1        18 |       10         2         9        28
168           20 #12317     |        0         0         0        20 |        9         3         8        34
169           21 #12318     |        0         0         0        13 |        8         3         8        28
170           22 #12319     |        0         0         1        11 |        8         3        10        22
171           23 #12320     |       28         0         1        28 |       41         3        11        41
172          rtla timerlat hit stop tracing
173          ## CPU 23 hit stop tracing, analyzing it ##
174          IRQ handler delay:                                        27.49 us (65.52 %)
175          IRQ latency:                                              28.13 us
176          Timerlat IRQ duration:                                     9.59 us (22.85 %)
177          Blocking thread:                                           3.79 us (9.03 %)
178                                 objtool:49256                       3.79 us
179            Blocking thread stacktrace
180                        -> timerlat_irq
181                        -> __hrtimer_run_queues
182                        -> hrtimer_interrupt
183                        -> __sysvec_apic_timer_interrupt
184                        -> sysvec_apic_timer_interrupt
185                        -> asm_sysvec_apic_timer_interrupt
186                        -> _raw_spin_unlock_irqrestore
187                        -> cgroup_rstat_flush_locked
188                        -> cgroup_rstat_flush_irqsafe
189                        -> mem_cgroup_flush_stats
190                        -> mem_cgroup_wb_stats
191                        -> balance_dirty_pages
192                        -> balance_dirty_pages_ratelimited_flags
193                        -> btrfs_buffered_write
194                        -> btrfs_do_write_iter
195                        -> vfs_write
196                        -> __x64_sys_pwrite64
197                        -> do_syscall_64
198                        -> entry_SYSCALL_64_after_hwframe
199          ------------------------------------------------------------------------
200            Thread latency:                                          41.96 us (100%)
201
202          The system has exit from idle latency!
203            Max timerlat IRQ latency from idle: 17.48 us in cpu 4
204          Saving trace to timerlat_trace.txt
205
206       In this case, the major factor was the delay suffered by the  IRQ  han‐
207       dler  that  handles  timerlat wakeup: 65.52%. This can be caused by the
208       current thread masking interrupts, which can be seen  in  the  blocking
209       thread  stacktrace:  the current thread (objtool:49256) disabled inter‐
210       rupts via raw spin lock operations inside mem cgroup, while doing write
211       syscall in a btrfs file system.
212
213       The  raw  trace  is  saved  in  the timerlat_trace.txt file for further
214       analysis.
215
216       Note that rtla timerlat was dispatched without changing timerlat tracer
217       threads'  priority.  That is generally not needed because these threads
218       have priority FIFO:95 by default, which is a common  priority  used  by
219       real-time kernel developers to analyze scheduling delays.
220
221   SEE ALSO
222       rtla-timerlat(1), rtla-timerlat-hist(1)
223
224       timerlat              tracer              documentation:             <‐
225       https://www.kernel.org/doc/html/latest/trace/timerlat-tracer.html>
226
227   AUTHOR
228       Written by Daniel Bristot de Oliveira <bristot@kernel.org>
229

REPORTING BUGS

231       Report    bugs     to     <linux-kernel@vger.kernel.org>     and     <‐
232       linux-trace-devel@vger.kernel.org>
233

LICENSE

235       rtla is Free Software licensed under the GNU GPLv2
236

COPYING

238       Copyright  (C)  2021 Red Hat, Inc. Free use of this software is granted
239       under the terms of the GNU Public License (GPL).
240
241
242
243
244                                                          RTLA-TIMERLAT-TOP(1)
Impressum