Timerlat tracer¶
The timerlat tracer aims to help the preemptive kernel developers tofind sources of wakeup latencies of real-time threads. Like cyclictest,the tracer sets a periodic timer that wakes up a thread. The thread thencomputes awakeup latency value as the difference between thecurrenttime and theabsolute time that the timer was set to expire. The maingoal of timerlat is tracing in such a way to help kernel developers.
Usage¶
Write the ASCII text “timerlat” into the current_tracer file of thetracing system (generally mounted at /sys/kernel/tracing).
For example:
[root@f32 ~]# cd /sys/kernel/tracing/[root@f32 tracing]# echo timerlat > current_tracer
It is possible to follow the trace by reading the trace file:
[root@f32 tracing]# cat trace# tracer: timerlat## _-----=> irqs-off# / _----=> need-resched# | / _---=> hardirq/softirq# || / _--=> preempt-depth# || /# |||| ACTIVATION# TASK-PID CPU# |||| TIMESTAMP ID CONTEXT LATENCY# | | | |||| | | | | <idle>-0 [000] d.h1 54.029328: #1 context irq timer_latency 932 ns <...>-867 [000] .... 54.029339: #1 context thread timer_latency 11700 ns <idle>-0 [001] dNh1 54.029346: #1 context irq timer_latency 2833 ns <...>-868 [001] .... 54.029353: #1 context thread timer_latency 9820 ns <idle>-0 [000] d.h1 54.030328: #2 context irq timer_latency 769 ns <...>-867 [000] .... 54.030330: #2 context thread timer_latency 3070 ns <idle>-0 [001] d.h1 54.030344: #2 context irq timer_latency 935 ns <...>-868 [001] .... 54.030347: #2 context thread timer_latency 4351 ns
The tracer creates a per-cpu kernel thread with real-time prioritySCHED_FIFO:95 that prints two lines at every activation. The first isthetimer latency observed at thehardirq context before the activationof the thread. The second is thetimer latency observed by the thread.The ACTIVATION ID field serves to relate theirq execution to itsrespectivethread execution.
Theirq/thread splitting is important to clarify in which contextthe unexpected high value is coming from. Theirq context can bedelayed by hardware-related actions, such as SMIs, NMIs, IRQs,or by thread masking interrupts. Once the timer happens, the delaycan also be influenced by blocking caused by threads. For example, bypostponing the scheduler execution viapreempt_disable(), schedulerexecution, or masking interrupts. Threads can also be delayed by theinterference from other threads and IRQs.
Tracer options¶
The timerlat tracer is built on top of osnoise tracer.So its configuration is also done in the osnoise/ configdirectory. The timerlat configs are:
cpus: CPUs at which a timerlat thread will execute.
timerlat_period_us: the period of the timerlat thread.
stop_tracing_us: stop the system tracing if atimer latency at theirq context higher than the configuredvalue happens. Writing 0 disables this option.
stop_tracing_total_us: stop the system tracing if atimer latency at thethread context is higher than the configuredvalue happens. Writing 0 disables this option.
print_stack: save the stack of the IRQ occurrence. The stack is printedafter thethread context event, or at the IRQ handler ifstop_tracing_usis hit.
timerlat and osnoise¶
The timerlat can also take advantage of the osnoise: traceevents.For example:
[root@f32 ~]# cd /sys/kernel/tracing/ [root@f32 tracing]# echo timerlat > current_tracer [root@f32 tracing]# echo 1 > events/osnoise/enable [root@f32 tracing]# echo 25 > osnoise/stop_tracing_total_us [root@f32 tracing]# tail -10 trace cc1-87882 [005] d..h... 548.771078: #402268 context irq timer_latency 13585 ns cc1-87882 [005] dNLh1.. 548.771082: irq_noise: local_timer:236 start 548.771077442 duration 7597 ns cc1-87882 [005] dNLh2.. 548.771099: irq_noise: qxl:21 start 548.771085017 duration 7139 ns cc1-87882 [005] d...3.. 548.771102: thread_noise: cc1:87882 start 548.771078243 duration 9909 nstimerlat/5-1035 [005] ....... 548.771104: #402268 context thread timer_latency 39960 ns
In this case, the root cause of the timer latency does not point to asingle cause but to multiple ones. Firstly, the timer IRQ was delayedfor 13 us, which may point to a long IRQ disabled section (see IRQstacktrace section). Then the timer interrupt that wakes up the timerlatthread took 7597 ns, and the qxl:21 device IRQ took 7139 ns. Finally,the cc1 thread noise took 9909 ns of time before the context switch.Such pieces of evidence are useful for the developer to use othertracing methods to figure out how to debug and optimize the system.
It is worth mentioning that theduration values reportedby the osnoise: events arenet values. For example, thethread_noise does not include the duration of the overhead causedby the IRQ execution (which indeed accounted for 12736 ns). Butthe values reported by the timerlat tracer (timerlat_latency)aregross values.
The art below illustrates a CPU timeline and how the timerlat tracerobserves it at the top and the osnoise: events at the bottom. Each “-”in the timelines means circa 1 us, and the time moves ==>:
External timer irq thread clock latency latency event 13585 ns 39960 ns | ^ ^ v | | |-------------| | |-------------+-------------------------| ^ ^======================================================================== [tmr irq] [dev irq][another thread...^ v..^ v.......][timerlat/ thread] <-- CPU timeline========================================================================= |-------| |-------| |--^ v-------| | | | | | + thread_noise: 9909 ns | +-> irq_noise: 6139 ns +-> irq_noise: 7597 ns
IRQ stacktrace¶
The osnoise/print_stack option is helpful for the cases in which a threadnoise causes the major factor for the timer latency, because of preempt orirq disabled. For example:
[root@f32 tracing]# echo 500 > osnoise/stop_tracing_total_us [root@f32 tracing]# echo 500 > osnoise/print_stack [root@f32 tracing]# echo timerlat > current_tracer [root@f32 tracing]# tail -21 per_cpu/cpu7/trace insmod-1026 [007] dN.h1.. 200.201948: irq_noise: local_timer:236 start 200.201939376 duration 7872 ns insmod-1026 [007] d..h1.. 200.202587: #29800 context irq timer_latency 1616 ns insmod-1026 [007] dN.h2.. 200.202598: irq_noise: local_timer:236 start 200.202586162 duration 11855 ns insmod-1026 [007] dN.h3.. 200.202947: irq_noise: local_timer:236 start 200.202939174 duration 7318 ns insmod-1026 [007] d...3.. 200.203444: thread_noise: insmod:1026 start 200.202586933 duration 838681 ns timerlat/7-1001 [007] ....... 200.203445: #29800 context thread timer_latency 859978 ns timerlat/7-1001 [007] ....1.. 200.203446: <stack trace>=> timerlat_irq=> __hrtimer_run_queues=> hrtimer_interrupt=> __sysvec_apic_timer_interrupt=> asm_call_irq_on_stack=> sysvec_apic_timer_interrupt=> asm_sysvec_apic_timer_interrupt=> delay_tsc=> dummy_load_1ms_pd_init=> do_one_initcall=> do_init_module=> __do_sys_finit_module=> do_syscall_64=> entry_SYSCALL_64_after_hwframe
In this case, it is possible to see that the thread added the highestcontribution to thetimer latency and the stack trace, saved duringthe timerlat IRQ handler, points to a function nameddummy_load_1ms_pd_init, which had the following code (on purpose):
static int __init dummy_load_1ms_pd_init(void){ preempt_disable(); mdelay(1); preempt_enable(); return 0;}User-space interface¶
Timerlat allows user-space threads to use timerlat infra-structure tomeasure scheduling latency. This interface is accessible via a per-CPUfile descriptor inside $tracing_dir/osnoise/per_cpu/cpu$ID/timerlat_fd.
This interface is accessible under the following conditions:
timerlat tracer is enable
osnoise workload option is set to NO_OSNOISE_WORKLOAD
The user-space thread is affined to a single processor
The thread opens the file associated with its single processor
Only one thread can access the file at a time
The open() syscall will fail if any of these conditions are not met.After opening the file descriptor, the user space can read from it.
The read() system call will run a timerlat code that will arm thetimer in the future and wait for it as the regular kernel thread does.
When the timer IRQ fires, the timerlat IRQ will execute, report theIRQ latency and wake up the thread waiting in the read. The thread will bescheduled and report the thread latency via tracer - as for the kernelthread.
The difference from the in-kernel timerlat is that, instead of re-armingthe timer, timerlat will return to the read() system call. At this point,the user can run any code.
If the application rereads the file timerlat file descriptor, the tracerwill report the return from user-space latency, which is the totallatency. If this is the end of the work, it can be interpreted as theresponse time for the request.
After reporting the total latency, timerlat will restart the cycle, arma timer, and go to sleep for the following activation.
If at any time one of the conditions is broken, e.g., the thread migrateswhile in user space, or the timerlat tracer is disabled, the SIG_KILLsignal will be sent to the user-space thread.
Here is an basic example of user-space code for timerlat:
int main(void){ char buffer[1024]; int timerlat_fd; int retval; long cpu = 0; /* place in CPU 0 */ cpu_set_t set; CPU_ZERO(&set); CPU_SET(cpu, &set); if (sched_setaffinity(gettid(), sizeof(set), &set) == -1) return 1; snprintf(buffer, sizeof(buffer), "/sys/kernel/tracing/osnoise/per_cpu/cpu%ld/timerlat_fd", cpu); timerlat_fd = open(buffer, O_RDONLY); if (timerlat_fd < 0) { printf("error opening %s: %s\n", buffer, strerror(errno)); exit(1); } for (;;) { retval = read(timerlat_fd, buffer, 1024); if (retval < 0) break; } close(timerlat_fd); exit(0);}