1====================
2rtla-timerlat-top
3====================
4-------------------------------------------
5Measures the operating system timer latency
6-------------------------------------------
7
8:Manual section: 1
9
10SYNOPSIS
11========
12**rtla timerlat top** [*OPTIONS*] ...
13
14DESCRIPTION
15===========
16
17.. include:: common_timerlat_description.rst
18
19The **rtla timerlat top** displays a summary of the periodic output
20from the *timerlat* tracer. It also provides information for each
21operating system noise via the **osnoise:** tracepoints that can be
22seem with the option **-T**.
23
24OPTIONS
25=======
26
27.. include:: common_timerlat_options.rst
28
29.. include:: common_top_options.rst
30
31.. include:: common_options.rst
32
33.. include:: common_timerlat_aa.rst
34
35**--aa-only** *us*
36
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.
41
42EXAMPLE
43=======
44
45In the example below, the timerlat tracer is dispatched in cpus *1-23* in the
46automatic trace mode, instructing the tracer to stop if a *40 us* latency or
47higher is found::
48
49  # timerlat -a 40 -c 1-23 -q
50                                     Timer Latency
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 %)
79  IRQ latency:                                              28.13 us
80  Timerlat IRQ duration:                                     9.59 us (22.85 %)
81  Blocking thread:                                           3.79 us (9.03 %)
82                         objtool:49256                       3.79 us
83    Blocking thread stacktrace
84                -> timerlat_irq
85                -> __hrtimer_run_queues
86                -> hrtimer_interrupt
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
99                -> vfs_write
100                -> __x64_sys_pwrite64
101                -> do_syscall_64
102                -> entry_SYSCALL_64_after_hwframe
103  ------------------------------------------------------------------------
104    Thread latency:                                          41.96 us (100%)
105
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
109
110In this case, the major factor was the delay suffered by the *IRQ handler*
111that handles **timerlat** wakeup: *65.52%*. This can be caused by the
112current thread masking interrupts, which can be seen in the blocking
113thread stacktrace: the current thread (*objtool:49256*) disabled interrupts
114via *raw spin lock* operations inside mem cgroup, while doing write
115syscall in a btrfs file system.
116
117The raw trace is saved in the **timerlat_trace.txt** file for further analysis.
118
119Note that **rtla timerlat** was dispatched without changing *timerlat* tracer
120threads' priority. That is generally not needed because these threads hava
121priority *FIFO:95* by default, which is a common priority used by real-time
122kernel developers to analyze scheduling delays.
123
124SEE ALSO
125--------
126**rtla-timerlat**\(1), **rtla-timerlat-hist**\(1)
127
128*timerlat* tracer documentation: <https://www.kernel.org/doc/html/latest/trace/timerlat-tracer.html>
129
130AUTHOR
131------
132Written by Daniel Bristot de Oliveira <bristot@kernel.org>
133
134.. include:: common_appendix.rst
135