Lines Matching +full:wakeup +full:- +full:latency +full:- +full:us
6 find sources of wakeup latencies of real-time threads. Like cyclictest,
8 computes a *wakeup latency* value as the difference between the *current
13 -----
28 # _-----=> irqs-off
29 # / _----=> need-resched
30 # | / _---=> hardirq/softirq
31 # || / _--=> preempt-depth
34 # TASK-PID CPU# |||| TIMESTAMP ID CONTEXT LATENCY
36 <idle>-0 [000] d.h1 54.029328: #1 context irq timer_latency 932 ns
37 <...>-867 [000] .... 54.029339: #1 context thread timer_latency 11700 ns
38 <idle>-0 [001] dNh1 54.029346: #1 context irq timer_latency 2833 ns
39 <...>-868 [001] .... 54.029353: #1 context thread timer_latency 9820 ns
40 <idle>-0 [000] d.h1 54.030328: #2 context irq timer_latency 769 ns
41 <...>-867 [000] .... 54.030330: #2 context thread timer_latency 3070 ns
42 <idle>-0 [001] d.h1 54.030344: #2 context irq timer_latency 935 ns
43 <...>-868 [001] .... 54.030347: #2 context thread timer_latency 4351 ns
46 The tracer creates a per-cpu kernel thread with real-time priority that
47 prints two lines at every activation. The first is the *timer latency*
49 The second is the *timer latency* observed by the thread. The ACTIVATION
55 delayed by hardware-related actions, such as SMIs, NMIs, IRQs,
63 ---------------------
69 - cpus: CPUs at which a timerlat thread will execute.
70 - timerlat_period_us: the period of the timerlat thread.
71 - stop_tracing_us: stop the system tracing if a
72 timer latency at the *irq* context higher than the configured
74 - stop_tracing_total_us: stop the system tracing if a
75 timer latency at the *thread* context is higher than the configured
77 - print_stack: save the stack of the IRQ occurrence. The stack is printed
82 ----------------------------
91 [root@f32 tracing]# tail -10 trace
92 … cc1-87882 [005] d..h... 548.771078: #402268 context irq timer_latency 13585 ns
93 …cc1-87882 [005] dNLh1.. 548.771082: irq_noise: local_timer:236 start 548.771077442 duration 75…
94 … cc1-87882 [005] dNLh2.. 548.771099: irq_noise: qxl:21 start 548.771085017 duration 7139 ns
95 …cc1-87882 [005] d...3.. 548.771102: thread_noise: cc1:87882 start 548.771078243 duration …
96 … timerlat/5-1035 [005] ....... 548.771104: #402268 context thread timer_latency 39960 ns
98 In this case, the root cause of the timer latency does not point to a
100 for 13 us, which may point to a long IRQ disabled section (see IRQ
115 observes it at the top and the osnoise: events at the bottom. Each "-"
116 in the timelines means circa 1 us, and the time moves ==>::
119 clock latency latency
123 |-------------| |
124 |-------------+-------------------------|
128 [another thread...^ v..^ v.......][timerlat/ thread] <-- CPU timeline
130 |-------| |-------|
131 |--^ v-------|
134 | +-> irq_noise: 6139 ns
135 +-> irq_noise: 7597 ns
138 ---------------------------
141 noise causes the major factor for the timer latency, because of preempt or
147 [root@f32 tracing]# tail -21 per_cpu/cpu7/trace
148 …insmod-1026 [007] dN.h1.. 200.201948: irq_noise: local_timer:236 start 200.201939376 duration…
149 … insmod-1026 [007] d..h1.. 200.202587: #29800 context irq timer_latency 1616 ns
150 …insmod-1026 [007] dN.h2.. 200.202598: irq_noise: local_timer:236 start 200.202586162 duration…
151 …insmod-1026 [007] dN.h3.. 200.202947: irq_noise: local_timer:236 start 200.202939174 duration…
152 …insmod-1026 [007] d...3.. 200.203444: thread_noise: insmod:1026 start 200.202586933 duratio…
153 … timerlat/7-1001 [007] ....... 200.203445: #29800 context thread timer_latency 859978 ns
154 timerlat/7-1001 [007] ....1.. 200.203446: <stack trace>
171 contribution to the *timer latency* and the stack trace, saved during
184 User-space interface
185 ---------------------------
187 Timerlat allows user-space threads to use timerlat infra-structure to
188 measure scheduling latency. This interface is accessible via a per-CPU
193 - timerlat tracer is enable
194 - osnoise workload option is set to NO_OSNOISE_WORKLOAD
195 - The user-space thread is affined to a single processor
196 - The thread opens the file associated with its single processor
197 - Only one thread can access the file at a time
206 IRQ latency and wake up the thread waiting in the read. The thread will be
207 scheduled and report the thread latency via tracer - as for the kernel
210 The difference from the in-kernel timerlat is that, instead of re-arming
215 will report the return from user-space latency, which is the total
216 latency. If this is the end of the work, it can be interpreted as the
219 After reporting the total latency, timerlat will restart the cycle, arm
224 signal will be sent to the user-space thread.
226 Here is an basic example of user-space code for timerlat::
239 if (sched_setaffinity(gettid(), sizeof(set), &set) == -1)