Lines Matching +full:duration +full:- +full:us
6 find sources of wakeup latencies of real-time threads. Like cyclictest,
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
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
74 - stop_tracing_total_us: stop the system tracing if a
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
100 for 13 us, which may point to a long IRQ disabled section (see IRQ
107 It is worth mentioning that the *duration* values reported
109 thread_noise does not include the duration of the overhead caused
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 ==>::
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 ---------------------------
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>
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
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
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)