1 ==================== 1 ====================
2 rtla-timerlat-top 2 rtla-timerlat-top
3 ==================== 3 ====================
4 ------------------------------------------- 4 -------------------------------------------
5 Measures the operating system timer latency 5 Measures the operating system timer latency
6 ------------------------------------------- 6 -------------------------------------------
7 7
8 :Manual section: 1 8 :Manual section: 1
9 9
10 SYNOPSIS 10 SYNOPSIS
11 ======== 11 ========
12 **rtla timerlat top** [*OPTIONS*] ... 12 **rtla timerlat top** [*OPTIONS*] ...
13 13
14 DESCRIPTION 14 DESCRIPTION
15 =========== 15 ===========
16 16
17 .. include:: common_timerlat_description.rst 17 .. include:: common_timerlat_description.rst
18 18
19 The **rtla timerlat top** displays a summary o 19 The **rtla timerlat top** displays a summary of the periodic output
20 from the *timerlat* tracer. It also provides i 20 from the *timerlat* tracer. It also provides information for each
21 operating system noise via the **osnoise:** tr 21 operating system noise via the **osnoise:** tracepoints that can be
22 seem with the option **-T**. 22 seem with the option **-T**.
23 23
24 OPTIONS 24 OPTIONS
25 ======= 25 =======
26 26
27 .. include:: common_timerlat_options.rst 27 .. include:: common_timerlat_options.rst
28 28
29 .. include:: common_top_options.rst 29 .. include:: common_top_options.rst
30 30
31 .. include:: common_options.rst 31 .. include:: common_options.rst
32 32
33 .. include:: common_timerlat_aa.rst 33 .. include:: common_timerlat_aa.rst
34 34
35 **--aa-only** *us* <<
36 <<
37 Set stop tracing conditions and run wi <<
38 Print the auto-analysis if the system <<
39 is useful to reduce rtla timerlat CPU, <<
40 collecting the statistics. <<
41 <<
42 EXAMPLE 35 EXAMPLE
43 ======= 36 =======
44 37
45 In the example below, the timerlat tracer is d 38 In the example below, the timerlat tracer is dispatched in cpus *1-23* in the
46 automatic trace mode, instructing the tracer t 39 automatic trace mode, instructing the tracer to stop if a *40 us* latency or
47 higher is found:: 40 higher is found::
48 41
49 # timerlat -a 40 -c 1-23 -q 42 # timerlat -a 40 -c 1-23 -q
50 Timer Lat 43 Timer Latency
51 0 00:00:12 | IRQ Timer Latency 44 0 00:00:12 | IRQ Timer Latency (us) | Thread Timer Latency (us)
52 CPU COUNT | cur min av 45 CPU COUNT | cur min avg max | cur min avg max
53 1 #12322 | 0 0 46 1 #12322 | 0 0 1 15 | 10 3 9 31
54 2 #12322 | 3 0 47 2 #12322 | 3 0 1 12 | 10 3 9 23
55 3 #12322 | 1 0 48 3 #12322 | 1 0 1 21 | 8 2 8 34
56 4 #12322 | 1 0 49 4 #12322 | 1 0 1 17 | 10 2 11 33
57 5 #12322 | 0 0 50 5 #12322 | 0 0 1 12 | 8 3 8 25
58 6 #12322 | 1 0 51 6 #12322 | 1 0 1 14 | 16 3 11 35
59 7 #12322 | 0 0 52 7 #12322 | 0 0 1 14 | 9 2 8 29
60 8 #12322 | 1 0 53 8 #12322 | 1 0 1 22 | 9 3 9 34
61 9 #12322 | 0 0 54 9 #12322 | 0 0 1 14 | 8 2 8 24
62 10 #12322 | 1 0 55 10 #12322 | 1 0 0 12 | 9 3 8 24
63 11 #12322 | 0 0 56 11 #12322 | 0 0 0 15 | 6 2 7 29
64 12 #12321 | 1 0 57 12 #12321 | 1 0 0 13 | 5 3 8 23
65 13 #12319 | 0 0 58 13 #12319 | 0 0 1 14 | 9 3 9 26
66 14 #12321 | 1 0 59 14 #12321 | 1 0 0 13 | 6 2 8 24
67 15 #12321 | 1 0 60 15 #12321 | 1 0 1 15 | 12 3 11 27
68 16 #12318 | 0 0 61 16 #12318 | 0 0 1 13 | 7 3 10 24
69 17 #12319 | 0 0 62 17 #12319 | 0 0 1 13 | 11 3 9 25
70 18 #12318 | 0 0 63 18 #12318 | 0 0 0 12 | 8 2 8 20
71 19 #12319 | 0 0 64 19 #12319 | 0 0 1 18 | 10 2 9 28
72 20 #12317 | 0 0 65 20 #12317 | 0 0 0 20 | 9 3 8 34
73 21 #12318 | 0 0 66 21 #12318 | 0 0 0 13 | 8 3 8 28
74 22 #12319 | 0 0 67 22 #12319 | 0 0 1 11 | 8 3 10 22
75 23 #12320 | 28 0 68 23 #12320 | 28 0 1 28 | 41 3 11 41
76 rtla timerlat hit stop tracing 69 rtla timerlat hit stop tracing
77 ## CPU 23 hit stop tracing, analyzing it ## 70 ## CPU 23 hit stop tracing, analyzing it ##
78 IRQ handler delay: 71 IRQ handler delay: 27.49 us (65.52 %)
79 IRQ latency: 72 IRQ latency: 28.13 us
80 Timerlat IRQ duration: 73 Timerlat IRQ duration: 9.59 us (22.85 %)
81 Blocking thread: 74 Blocking thread: 3.79 us (9.03 %)
82 objtool:49256 75 objtool:49256 3.79 us
83 Blocking thread stacktrace 76 Blocking thread stacktrace
84 -> timerlat_irq 77 -> timerlat_irq
85 -> __hrtimer_run_queues 78 -> __hrtimer_run_queues
86 -> hrtimer_interrupt 79 -> hrtimer_interrupt
87 -> __sysvec_apic_timer_interru 80 -> __sysvec_apic_timer_interrupt
88 -> sysvec_apic_timer_interrupt 81 -> sysvec_apic_timer_interrupt
89 -> asm_sysvec_apic_timer_inter 82 -> asm_sysvec_apic_timer_interrupt
90 -> _raw_spin_unlock_irqrestore 83 -> _raw_spin_unlock_irqrestore
91 -> cgroup_rstat_flush_locked 84 -> cgroup_rstat_flush_locked
92 -> cgroup_rstat_flush_irqsafe 85 -> cgroup_rstat_flush_irqsafe
93 -> mem_cgroup_flush_stats 86 -> mem_cgroup_flush_stats
94 -> mem_cgroup_wb_stats 87 -> mem_cgroup_wb_stats
95 -> balance_dirty_pages 88 -> balance_dirty_pages
96 -> balance_dirty_pages_ratelim 89 -> balance_dirty_pages_ratelimited_flags
97 -> btrfs_buffered_write 90 -> btrfs_buffered_write
98 -> btrfs_do_write_iter 91 -> btrfs_do_write_iter
99 -> vfs_write 92 -> vfs_write
100 -> __x64_sys_pwrite64 93 -> __x64_sys_pwrite64
101 -> do_syscall_64 94 -> do_syscall_64
102 -> entry_SYSCALL_64_after_hwfr 95 -> entry_SYSCALL_64_after_hwframe
103 -------------------------------------------- 96 ------------------------------------------------------------------------
104 Thread latency: 97 Thread latency: 41.96 us (100%)
105 98
106 The system has exit from idle latency! 99 The system has exit from idle latency!
107 Max timerlat IRQ latency from idle: 17.48 100 Max timerlat IRQ latency from idle: 17.48 us in cpu 4
108 Saving trace to timerlat_trace.txt 101 Saving trace to timerlat_trace.txt
109 102
110 In this case, the major factor was the delay s 103 In this case, the major factor was the delay suffered by the *IRQ handler*
111 that handles **timerlat** wakeup: *65.52%*. Th 104 that handles **timerlat** wakeup: *65.52%*. This can be caused by the
112 current thread masking interrupts, which can b 105 current thread masking interrupts, which can be seen in the blocking
113 thread stacktrace: the current thread (*objtoo 106 thread stacktrace: the current thread (*objtool:49256*) disabled interrupts
114 via *raw spin lock* operations inside mem cgro 107 via *raw spin lock* operations inside mem cgroup, while doing write
115 syscall in a btrfs file system. 108 syscall in a btrfs file system.
116 109
117 The raw trace is saved in the **timerlat_trace 110 The raw trace is saved in the **timerlat_trace.txt** file for further analysis.
118 111
119 Note that **rtla timerlat** was dispatched wit 112 Note that **rtla timerlat** was dispatched without changing *timerlat* tracer
120 threads' priority. That is generally not neede !! 113 threads' priority. That is generally not needed because these threads hava
121 priority *FIFO:95* by default, which is a comm 114 priority *FIFO:95* by default, which is a common priority used by real-time
122 kernel developers to analyze scheduling delays 115 kernel developers to analyze scheduling delays.
123 116
124 SEE ALSO 117 SEE ALSO
125 -------- 118 --------
126 **rtla-timerlat**\(1), **rtla-timerlat-hist**\ 119 **rtla-timerlat**\(1), **rtla-timerlat-hist**\(1)
127 120
128 *timerlat* tracer documentation: <https://www. 121 *timerlat* tracer documentation: <https://www.kernel.org/doc/html/latest/trace/timerlat-tracer.html>
129 122
130 AUTHOR 123 AUTHOR
131 ------ 124 ------
132 Written by Daniel Bristot de Oliveira <bristot@ 125 Written by Daniel Bristot de Oliveira <bristot@kernel.org>
133 126
134 .. include:: common_appendix.rst 127 .. include:: common_appendix.rst
Linux® is a registered trademark of Linus Torvalds in the United States and other countries.
TOMOYO® is a registered trademark of NTT DATA CORPORATION.