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
35EXAMPLE
36=======
37
38In the example below, the timerlat tracer is dispatched in cpus *1-23* in the
39automatic trace mode, instructing the tracer to stop if a *40 us* latency or
40higher is found::
41
42  # timerlat -a 40 -c 1-23 -q
43                                     Timer Latency
44    0 00:00:12   |          IRQ Timer Latency (us)        |         Thread Timer Latency (us)
45  CPU COUNT      |      cur       min       avg       max |      cur       min       avg       max
46    1 #12322     |        0         0         1        15 |       10         3         9        31
47    2 #12322     |        3         0         1        12 |       10         3         9        23
48    3 #12322     |        1         0         1        21 |        8         2         8        34
49    4 #12322     |        1         0         1        17 |       10         2        11        33
50    5 #12322     |        0         0         1        12 |        8         3         8        25
51    6 #12322     |        1         0         1        14 |       16         3        11        35
52    7 #12322     |        0         0         1        14 |        9         2         8        29
53    8 #12322     |        1         0         1        22 |        9         3         9        34
54    9 #12322     |        0         0         1        14 |        8         2         8        24
55   10 #12322     |        1         0         0        12 |        9         3         8        24
56   11 #12322     |        0         0         0        15 |        6         2         7        29
57   12 #12321     |        1         0         0        13 |        5         3         8        23
58   13 #12319     |        0         0         1        14 |        9         3         9        26
59   14 #12321     |        1         0         0        13 |        6         2         8        24
60   15 #12321     |        1         0         1        15 |       12         3        11        27
61   16 #12318     |        0         0         1        13 |        7         3        10        24
62   17 #12319     |        0         0         1        13 |       11         3         9        25
63   18 #12318     |        0         0         0        12 |        8         2         8        20
64   19 #12319     |        0         0         1        18 |       10         2         9        28
65   20 #12317     |        0         0         0        20 |        9         3         8        34
66   21 #12318     |        0         0         0        13 |        8         3         8        28
67   22 #12319     |        0         0         1        11 |        8         3        10        22
68   23 #12320     |       28         0         1        28 |       41         3        11        41
69  rtla timerlat hit stop tracing
70  ## CPU 23 hit stop tracing, analyzing it ##
71  IRQ handler delay:                                        27.49 us (65.52 %)
72  IRQ latency:                                              28.13 us
73  Timerlat IRQ duration:                                     9.59 us (22.85 %)
74  Blocking thread:                                           3.79 us (9.03 %)
75                         objtool:49256                       3.79 us
76    Blocking thread stacktrace
77                -> timerlat_irq
78                -> __hrtimer_run_queues
79                -> hrtimer_interrupt
80                -> __sysvec_apic_timer_interrupt
81                -> sysvec_apic_timer_interrupt
82                -> asm_sysvec_apic_timer_interrupt
83                -> _raw_spin_unlock_irqrestore
84                -> cgroup_rstat_flush_locked
85                -> cgroup_rstat_flush_irqsafe
86                -> mem_cgroup_flush_stats
87                -> mem_cgroup_wb_stats
88                -> balance_dirty_pages
89                -> balance_dirty_pages_ratelimited_flags
90                -> btrfs_buffered_write
91                -> btrfs_do_write_iter
92                -> vfs_write
93                -> __x64_sys_pwrite64
94                -> do_syscall_64
95                -> entry_SYSCALL_64_after_hwframe
96  ------------------------------------------------------------------------
97    Thread latency:                                          41.96 us (100%)
98
99  The system has exit from idle latency!
100    Max timerlat IRQ latency from idle: 17.48 us in cpu 4
101  Saving trace to timerlat_trace.txt
102
103In this case, the major factor was the delay suffered by the *IRQ handler*
104that handles **timerlat** wakeup: *65.52%*. This can be caused by the
105current thread masking interrupts, which can be seen in the blocking
106thread stacktrace: the current thread (*objtool:49256*) disabled interrupts
107via *raw spin lock* operations inside mem cgroup, while doing write
108syscall in a btrfs file system.
109
110The raw trace is saved in the **timerlat_trace.txt** file for further analysis.
111
112Note that **rtla timerlat** was dispatched without changing *timerlat* tracer
113threads' priority. That is generally not needed because these threads hava
114priority *FIFO:95* by default, which is a common priority used by real-time
115kernel developers to analyze scheduling delays.
116
117SEE ALSO
118--------
119**rtla-timerlat**\(1), **rtla-timerlat-hist**\(1)
120
121*timerlat* tracer documentation: <https://www.kernel.org/doc/html/latest/trace/timerlat-tracer.html>
122
123AUTHOR
124------
125Written by Daniel Bristot de Oliveira <bristot@kernel.org>
126
127.. include:: common_appendix.rst
128