261 lines · plain
1###############2Timerlat tracer3###############4 5The timerlat tracer aims to help the preemptive kernel developers to6find sources of wakeup latencies of real-time threads. Like cyclictest,7the tracer sets a periodic timer that wakes up a thread. The thread then8computes a *wakeup latency* value as the difference between the *current9time* and the *absolute time* that the timer was set to expire. The main10goal of timerlat is tracing in such a way to help kernel developers.11 12Usage13-----14 15Write the ASCII text "timerlat" into the current_tracer file of the16tracing system (generally mounted at /sys/kernel/tracing).17 18For example::19 20 [root@f32 ~]# cd /sys/kernel/tracing/21 [root@f32 tracing]# echo timerlat > current_tracer22 23It is possible to follow the trace by reading the trace file::24 25 [root@f32 tracing]# cat trace26 # tracer: timerlat27 #28 # _-----=> irqs-off29 # / _----=> need-resched30 # | / _---=> hardirq/softirq31 # || / _--=> preempt-depth32 # || /33 # |||| ACTIVATION34 # TASK-PID CPU# |||| TIMESTAMP ID CONTEXT LATENCY35 # | | | |||| | | | |36 <idle>-0 [000] d.h1 54.029328: #1 context irq timer_latency 932 ns37 <...>-867 [000] .... 54.029339: #1 context thread timer_latency 11700 ns38 <idle>-0 [001] dNh1 54.029346: #1 context irq timer_latency 2833 ns39 <...>-868 [001] .... 54.029353: #1 context thread timer_latency 9820 ns40 <idle>-0 [000] d.h1 54.030328: #2 context irq timer_latency 769 ns41 <...>-867 [000] .... 54.030330: #2 context thread timer_latency 3070 ns42 <idle>-0 [001] d.h1 54.030344: #2 context irq timer_latency 935 ns43 <...>-868 [001] .... 54.030347: #2 context thread timer_latency 4351 ns44 45 46The tracer creates a per-cpu kernel thread with real-time priority that47prints two lines at every activation. The first is the *timer latency*48observed at the *hardirq* context before the activation of the thread.49The second is the *timer latency* observed by the thread. The ACTIVATION50ID field serves to relate the *irq* execution to its respective *thread*51execution.52 53The *irq*/*thread* splitting is important to clarify in which context54the unexpected high value is coming from. The *irq* context can be55delayed by hardware-related actions, such as SMIs, NMIs, IRQs,56or by thread masking interrupts. Once the timer happens, the delay57can also be influenced by blocking caused by threads. For example, by58postponing the scheduler execution via preempt_disable(), scheduler59execution, or masking interrupts. Threads can also be delayed by the60interference from other threads and IRQs.61 62Tracer options63---------------------64 65The timerlat tracer is built on top of osnoise tracer.66So its configuration is also done in the osnoise/ config67directory. The timerlat configs are:68 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 a72 timer latency at the *irq* context higher than the configured73 value happens. Writing 0 disables this option.74 - stop_tracing_total_us: stop the system tracing if a75 timer latency at the *thread* context is higher than the configured76 value happens. Writing 0 disables this option.77 - print_stack: save the stack of the IRQ occurrence. The stack is printed78 after the *thread context* event, or at the IRQ handler if *stop_tracing_us*79 is hit.80 81timerlat and osnoise82----------------------------83 84The timerlat can also take advantage of the osnoise: traceevents.85For example::86 87 [root@f32 ~]# cd /sys/kernel/tracing/88 [root@f32 tracing]# echo timerlat > current_tracer89 [root@f32 tracing]# echo 1 > events/osnoise/enable90 [root@f32 tracing]# echo 25 > osnoise/stop_tracing_total_us91 [root@f32 tracing]# tail -10 trace92 cc1-87882 [005] d..h... 548.771078: #402268 context irq timer_latency 13585 ns93 cc1-87882 [005] dNLh1.. 548.771082: irq_noise: local_timer:236 start 548.771077442 duration 7597 ns94 cc1-87882 [005] dNLh2.. 548.771099: irq_noise: qxl:21 start 548.771085017 duration 7139 ns95 cc1-87882 [005] d...3.. 548.771102: thread_noise: cc1:87882 start 548.771078243 duration 9909 ns96 timerlat/5-1035 [005] ....... 548.771104: #402268 context thread timer_latency 39960 ns97 98In this case, the root cause of the timer latency does not point to a99single cause but to multiple ones. Firstly, the timer IRQ was delayed100for 13 us, which may point to a long IRQ disabled section (see IRQ101stacktrace section). Then the timer interrupt that wakes up the timerlat102thread took 7597 ns, and the qxl:21 device IRQ took 7139 ns. Finally,103the cc1 thread noise took 9909 ns of time before the context switch.104Such pieces of evidence are useful for the developer to use other105tracing methods to figure out how to debug and optimize the system.106 107It is worth mentioning that the *duration* values reported108by the osnoise: events are *net* values. For example, the109thread_noise does not include the duration of the overhead caused110by the IRQ execution (which indeed accounted for 12736 ns). But111the values reported by the timerlat tracer (timerlat_latency)112are *gross* values.113 114The art below illustrates a CPU timeline and how the timerlat tracer115observes it at the top and the osnoise: events at the bottom. Each "-"116in the timelines means circa 1 us, and the time moves ==>::117 118 External timer irq thread119 clock latency latency120 event 13585 ns 39960 ns121 | ^ ^122 v | |123 |-------------| |124 |-------------+-------------------------|125 ^ ^126 ========================================================================127 [tmr irq] [dev irq]128 [another thread...^ v..^ v.......][timerlat/ thread] <-- CPU timeline129 =========================================================================130 |-------| |-------|131 |--^ v-------|132 | | |133 | | + thread_noise: 9909 ns134 | +-> irq_noise: 6139 ns135 +-> irq_noise: 7597 ns136 137IRQ stacktrace138---------------------------139 140The osnoise/print_stack option is helpful for the cases in which a thread141noise causes the major factor for the timer latency, because of preempt or142irq disabled. For example::143 144 [root@f32 tracing]# echo 500 > osnoise/stop_tracing_total_us145 [root@f32 tracing]# echo 500 > osnoise/print_stack146 [root@f32 tracing]# echo timerlat > current_tracer147 [root@f32 tracing]# tail -21 per_cpu/cpu7/trace148 insmod-1026 [007] dN.h1.. 200.201948: irq_noise: local_timer:236 start 200.201939376 duration 7872 ns149 insmod-1026 [007] d..h1.. 200.202587: #29800 context irq timer_latency 1616 ns150 insmod-1026 [007] dN.h2.. 200.202598: irq_noise: local_timer:236 start 200.202586162 duration 11855 ns151 insmod-1026 [007] dN.h3.. 200.202947: irq_noise: local_timer:236 start 200.202939174 duration 7318 ns152 insmod-1026 [007] d...3.. 200.203444: thread_noise: insmod:1026 start 200.202586933 duration 838681 ns153 timerlat/7-1001 [007] ....... 200.203445: #29800 context thread timer_latency 859978 ns154 timerlat/7-1001 [007] ....1.. 200.203446: <stack trace>155 => timerlat_irq156 => __hrtimer_run_queues157 => hrtimer_interrupt158 => __sysvec_apic_timer_interrupt159 => asm_call_irq_on_stack160 => sysvec_apic_timer_interrupt161 => asm_sysvec_apic_timer_interrupt162 => delay_tsc163 => dummy_load_1ms_pd_init164 => do_one_initcall165 => do_init_module166 => __do_sys_finit_module167 => do_syscall_64168 => entry_SYSCALL_64_after_hwframe169 170In this case, it is possible to see that the thread added the highest171contribution to the *timer latency* and the stack trace, saved during172the timerlat IRQ handler, points to a function named173dummy_load_1ms_pd_init, which had the following code (on purpose)::174 175 static int __init dummy_load_1ms_pd_init(void)176 {177 preempt_disable();178 mdelay(1);179 preempt_enable();180 return 0;181 182 }183 184User-space interface185---------------------------186 187Timerlat allows user-space threads to use timerlat infra-structure to188measure scheduling latency. This interface is accessible via a per-CPU189file descriptor inside $tracing_dir/osnoise/per_cpu/cpu$ID/timerlat_fd.190 191This interface is accessible under the following conditions:192 193 - timerlat tracer is enable194 - osnoise workload option is set to NO_OSNOISE_WORKLOAD195 - The user-space thread is affined to a single processor196 - The thread opens the file associated with its single processor197 - Only one thread can access the file at a time198 199The open() syscall will fail if any of these conditions are not met.200After opening the file descriptor, the user space can read from it.201 202The read() system call will run a timerlat code that will arm the203timer in the future and wait for it as the regular kernel thread does.204 205When the timer IRQ fires, the timerlat IRQ will execute, report the206IRQ latency and wake up the thread waiting in the read. The thread will be207scheduled and report the thread latency via tracer - as for the kernel208thread.209 210The difference from the in-kernel timerlat is that, instead of re-arming211the timer, timerlat will return to the read() system call. At this point,212the user can run any code.213 214If the application rereads the file timerlat file descriptor, the tracer215will report the return from user-space latency, which is the total216latency. If this is the end of the work, it can be interpreted as the217response time for the request.218 219After reporting the total latency, timerlat will restart the cycle, arm220a timer, and go to sleep for the following activation.221 222If at any time one of the conditions is broken, e.g., the thread migrates223while in user space, or the timerlat tracer is disabled, the SIG_KILL224signal will be sent to the user-space thread.225 226Here is an basic example of user-space code for timerlat::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(set), &set) == -1)240 return 1;241 242 snprintf(buffer, sizeof(buffer),243 "/sys/kernel/tracing/osnoise/per_cpu/cpu%ld/timerlat_fd",244 cpu);245 246 timerlat_fd = open(buffer, O_RDONLY);247 if (timerlat_fd < 0) {248 printf("error opening %s: %s\n", buffer, strerror(errno));249 exit(1);250 }251 252 for (;;) {253 retval = read(timerlat_fd, buffer, 1024);254 if (retval < 0)255 break;256 }257 258 close(timerlat_fd);259 exit(0);260 }261