Lines Matching +full:wakeup +full:- +full:latency +full:- +full:us
6 find souces 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
63 ---------------------
69 - cpus: CPUs at which a timerlat thread will execute.
70 - timerlat_period_us: the period of the timerlat thread.
71 - osnoise/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 higher than the configured
77 - print_stack: save the stack of the IRQ ocurrence, and print
81 ----------------------------
90 [root@f32 tracing]# tail -10 trace
91 … cc1-87882 [005] d..h... 548.771078: #402268 context irq timer_latency 13585 ns
92 …cc1-87882 [005] dNLh1.. 548.771082: irq_noise: local_timer:236 start 548.771077442 duration 75…
93 … cc1-87882 [005] dNLh2.. 548.771099: irq_noise: qxl:21 start 548.771085017 duration 7139 ns
94 …cc1-87882 [005] d...3.. 548.771102: thread_noise: cc1:87882 start 548.771078243 duration …
95 … timerlat/5-1035 [005] ....... 548.771104: #402268 context thread timer_latency 39960 ns
97 In this case, the root cause of the timer latency does not point to a
99 for 13 us, which may point to a long IRQ disabled section (see IRQ
114 observes it at the top and the osnoise: events at the bottom. Each "-"
115 in the timelines means circa 1 us, and the time moves ==>::
118 clock latency latency
122 |-------------| |
123 |-------------+-------------------------|
127 [another thread...^ v..^ v.......][timerlat/ thread] <-- CPU timeline
129 |-------| |-------|
130 |--^ v-------|
133 | +-> irq_noise: 6139 ns
134 +-> irq_noise: 7597 ns
137 ---------------------------
140 noise causes the major factor for the timer latency, because of preempt or
146 [root@f32 tracing]# tail -21 per_cpu/cpu7/trace
147 …insmod-1026 [007] dN.h1.. 200.201948: irq_noise: local_timer:236 start 200.201939376 duration…
148 … insmod-1026 [007] d..h1.. 200.202587: #29800 context irq timer_latency 1616 ns
149 …insmod-1026 [007] dN.h2.. 200.202598: irq_noise: local_timer:236 start 200.202586162 duration…
150 …insmod-1026 [007] dN.h3.. 200.202947: irq_noise: local_timer:236 start 200.202939174 duration…
151 …insmod-1026 [007] d...3.. 200.203444: thread_noise: insmod:1026 start 200.202586933 duratio…
152 … timerlat/7-1001 [007] ....... 200.203445: #29800 context thread timer_latency 859978 ns
153 timerlat/7-1001 [007] ....1.. 200.203446: <stack trace>
170 contribution to the *timer latency* and the stack trace, saved during