Lines Matching +full:clock +full:- +full:latency +full:- +full:ns
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
101 thread took 7597 ns, and the qxl:21 device IRQ took 7139 ns. Finally,
102 the cc1 thread noise took 9909 ns of time before the context switch.
109 by the IRQ execution (which indeed accounted for 12736 ns). But
114 observes it at the top and the osnoise: events at the bottom. Each "-"
118 clock latency latency
119 event 13585 ns 39960 ns
122 |-------------| |
123 |-------------+-------------------------|
127 [another thread...^ v..^ v.......][timerlat/ thread] <-- CPU timeline
129 |-------| |-------|
130 |--^ v-------|
132 | | + thread_noise: 9909 ns
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