1 ###############
2 Timerlat tracer
3 ###############
4
5 The timerlat tracer aims to help the preemptiv
6 find sources of wakeup latencies of real-time
7 the tracer sets a periodic timer that wakes up
8 computes a *wakeup latency* value as the diffe
9 time* and the *absolute time* that the timer w
10 goal of timerlat is tracing in such a way to h
11
12 Usage
13 -----
14
15 Write the ASCII text "timerlat" into the curre
16 tracing system (generally mounted at /sys/kern
17
18 For example::
19
20 [root@f32 ~]# cd /sys/kernel/tracing/
21 [root@f32 tracing]# echo timerlat > cu
22
23 It is possible to follow the trace by reading
24
25 [root@f32 tracing]# cat trace
26 # tracer: timerlat
27 #
28 # _-----=> irqs
29 # / _----=> need
30 # | / _---=> hard
31 # || / _--=> pree
32 # || /
33 # ||||
34 # TASK-PID CPU# |||| TIMESTAM
35 # | | | |||| |
36 <idle>-0 [000] d.h1 54.0293
37 <...>-867 [000] .... 54.0293
38 <idle>-0 [001] dNh1 54.0293
39 <...>-868 [001] .... 54.0293
40 <idle>-0 [000] d.h1 54.0303
41 <...>-867 [000] .... 54.0303
42 <idle>-0 [001] d.h1 54.0303
43 <...>-868 [001] .... 54.0303
44
45
46 The tracer creates a per-cpu kernel thread wit
47 prints two lines at every activation. The firs
48 observed at the *hardirq* context before the a
49 The second is the *timer latency* observed by
50 ID field serves to relate the *irq* execution
51 execution.
52
53 The *irq*/*thread* splitting is important to c
54 the unexpected high value is coming from. The
55 delayed by hardware-related actions, such as S
56 or by thread masking interrupts. Once the time
57 can also be influenced by blocking caused by t
58 postponing the scheduler execution via preempt
59 execution, or masking interrupts. Threads can
60 interference from other threads and IRQs.
61
62 Tracer options
63 ---------------------
64
65 The timerlat tracer is built on top of osnoise
66 So its configuration is also done in the osnoi
67 directory. The timerlat configs are:
68
69 - cpus: CPUs at which a timerlat thread will
70 - timerlat_period_us: the period of the timer
71 - stop_tracing_us: stop the system tracing if
72 timer latency at the *irq* context higher t
73 value happens. Writing 0 disables this opti
74 - stop_tracing_total_us: stop the system trac
75 timer latency at the *thread* context is hi
76 value happens. Writing 0 disables this opti
77 - print_stack: save the stack of the IRQ occu
78 after the *thread context* event, or at the
79 is hit.
80
81 timerlat and osnoise
82 ----------------------------
83
84 The timerlat can also take advantage of the os
85 For example::
86
87 [root@f32 ~]# cd /sys/kernel/tracing/
88 [root@f32 tracing]# echo timerlat > cu
89 [root@f32 tracing]# echo 1 > events/os
90 [root@f32 tracing]# echo 25 > osnoise/
91 [root@f32 tracing]# tail -10 trace
92 cc1-87882 [005] d..h... 548.7
93 cc1-87882 [005] dNLh1.. 548.7
94 cc1-87882 [005] dNLh2.. 548.7
95 cc1-87882 [005] d...3.. 548.7
96 timerlat/5-1035 [005] ....... 548.7
97
98 In this case, the root cause of the timer late
99 single cause but to multiple ones. Firstly, th
100 for 13 us, which may point to a long IRQ disab
101 stacktrace section). Then the timer interrupt
102 thread took 7597 ns, and the qxl:21 device IRQ
103 the cc1 thread noise took 9909 ns of time befo
104 Such pieces of evidence are useful for the dev
105 tracing methods to figure out how to debug and
106
107 It is worth mentioning that the *duration* val
108 by the osnoise: events are *net* values. For e
109 thread_noise does not include the duration of
110 by the IRQ execution (which indeed accounted f
111 the values reported by the timerlat tracer (ti
112 are *gross* values.
113
114 The art below illustrates a CPU timeline and h
115 observes it at the top and the osnoise: events
116 in the timelines means circa 1 us, and the tim
117
118 External timer irq
119 clock latency
120 event 13585 ns
121 | ^
122 v |
123 |-------------|
124 |-------------+----------------------
125 ^
126 ============================================
127 [tmr irq] [dev irq]
128 [another thread...^ v..^ v......
129 ============================================
130 |-------| |-------|
131 |--^ v------
132 | |
133 | |
134 | +-> irq
135 +-> irq_noise: 759
136
137 IRQ stacktrace
138 ---------------------------
139
140 The osnoise/print_stack option is helpful for
141 noise causes the major factor for the timer la
142 irq disabled. For example::
143
144 [root@f32 tracing]# echo 500 > osnoise
145 [root@f32 tracing]# echo 500 > osnoise
146 [root@f32 tracing]# echo timerlat > cu
147 [root@f32 tracing]# tail -21 per_cpu/c
148 insmod-1026 [007] dN.h1.. 200.2
149 insmod-1026 [007] d..h1.. 200.2
150 insmod-1026 [007] dN.h2.. 200.2
151 insmod-1026 [007] dN.h3.. 200.2
152 insmod-1026 [007] d...3.. 200.2
153 timerlat/7-1001 [007] ....... 200.2
154 timerlat/7-1001 [007] ....1.. 200.2
155 => timerlat_irq
156 => __hrtimer_run_queues
157 => hrtimer_interrupt
158 => __sysvec_apic_timer_interrupt
159 => asm_call_irq_on_stack
160 => sysvec_apic_timer_interrupt
161 => asm_sysvec_apic_timer_interrupt
162 => delay_tsc
163 => dummy_load_1ms_pd_init
164 => do_one_initcall
165 => do_init_module
166 => __do_sys_finit_module
167 => do_syscall_64
168 => entry_SYSCALL_64_after_hwframe
169
170 In this case, it is possible to see that the t
171 contribution to the *timer latency* and the st
172 the timerlat IRQ handler, points to a function
173 dummy_load_1ms_pd_init, which had the followin
174
175 static int __init dummy_load_1ms_pd_in
176 {
177 preempt_disable();
178 mdelay(1);
179 preempt_enable();
180 return 0;
181
182 }
183
184 User-space interface
185 ---------------------------
186
187 Timerlat allows user-space threads to use time
188 measure scheduling latency. This interface is
189 file descriptor inside $tracing_dir/osnoise/pe
190
191 This interface is accessible under the followi
192
193 - timerlat tracer is enable
194 - osnoise workload option is set to NO_OSNOIS
195 - The user-space thread is affined to a singl
196 - The thread opens the file associated with i
197 - Only one thread can access the file at a ti
198
199 The open() syscall will fail if any of these c
200 After opening the file descriptor, the user sp
201
202 The read() system call will run a timerlat cod
203 timer in the future and wait for it as the reg
204
205 When the timer IRQ fires, the timerlat IRQ wil
206 IRQ latency and wake up the thread waiting in
207 scheduled and report the thread latency via tr
208 thread.
209
210 The difference from the in-kernel timerlat is
211 the timer, timerlat will return to the read()
212 the user can run any code.
213
214 If the application rereads the file timerlat f
215 will report the return from user-space latency
216 latency. If this is the end of the work, it ca
217 response time for the request.
218
219 After reporting the total latency, timerlat wi
220 a timer, and go to sleep for the following act
221
222 If at any time one of the conditions is broken
223 while in user space, or the timerlat tracer is
224 signal will be sent to the user-space thread.
225
226 Here is an basic example of user-space code fo
227
228 int main(void)
229 {
230 char buffer[1024];
231 int timerlat_fd;
232 int retval;
233 long cpu = 0; /* place in CPU 0 */
234 cpu_set_t set;
235
236 CPU_ZERO(&set);
237 CPU_SET(cpu, &set);
238
239 if (sched_setaffinity(gettid(), sizeof
240 return 1;
241
242 snprintf(buffer, sizeof(buffer),
243 "/sys/kernel/tracing/osnoise/p
244 cpu);
245
246 timerlat_fd = open(buffer, O_RDONLY);
247 if (timerlat_fd < 0) {
248 printf("error opening %s: %s\n
249 exit(1);
250 }
251
252 for (;;) {
253 retval = read(timerlat_fd, buf
254 if (retval < 0)
255 break;
256 }
257
258 close(timerlat_fd);
259 exit(0);
260 }
Linux® is a registered trademark of Linus Torvalds in the United States and other countries.
TOMOYO® is a registered trademark of NTT DATA CORPORATION.