Timerlat tracer

목적, 사용법과 IRQ·thread 지연

timerlat tracer는 preemptive kernel 개발자가 real-time thread의 wakeup latency 원인을 찾도록 돕습니다. cyclictest처럼 주기 timer를 설정해 thread를 깨우고, timer가 만료하도록 설정된 absolute time과 current time의 차이로 wakeup latency를 계산합니다. timerlat의 주된 목적은 kernel 개발에 도움이 되는 trace를 함께 제공하는 것입니다.

tracing system이 일반적으로 mount되는 `/sys/kernel/tracing`의 `current_tracer` file에 ASCII text `timerlat`을 쓰면 tracer가 활성화됩니다.

[root@f32 ~]# cd /sys/kernel/tracing/
[root@f32 tracing]# echo timerlat > current_tracer

`trace` file을 읽으면 실시간 출력을 볼 수 있습니다. 각 CPU activation마다 irq context와 thread context의 두 행이 같은 ACTIVATION ID로 연결됩니다.

  [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

tracer는 CPU마다 real-time priority kernel thread를 만들고 activation마다 두 행을 출력합니다. 첫 행은 thread가 활성화되기 전 hardirq context에서 관찰한 timer latency이고, 둘째 행은 깨어난 thread가 관찰한 timer latency입니다. ACTIVATION ID는 해당 irq 실행과 thread 실행을 짝지어 줍니다.

irq와 thread를 나누는 이유는 예기치 않게 큰 값이 어느 context에서 생겼는지 밝히기 위해서입니다. irq context는 SMI, NMI, IRQ 같은 hardware 관련 동작이나 thread의 interrupt masking 때문에 늦어질 수 있습니다.

timer가 발생한 뒤에는 `preempt_disable()`로 scheduler 실행을 미루거나 scheduler 자체가 지연되거나 interrupt를 가리는 thread 때문에 추가로 block될 수 있습니다. 다른 thread와 IRQ의 간섭도 timerlat thread 실행을 늦출 수 있습니다.

###############
Timerlat tracer
###############

The timerlat tracer aims to help the preemptive kernel developers to
find sources of wakeup latencies of real-time threads. Like cyclictest,
the tracer sets a periodic timer that wakes up a thread. The thread then
computes a *wakeup latency* value as the difference between the *current
time* and the *absolute time* that the timer was set to expire. The main
goal of timerlat is tracing in such a way to help kernel developers.

Usage
-----

Write the ASCII text "timerlat" into the current_tracer file of the
tracing 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 priority that
prints two lines at every activation. The first is the *timer latency*
observed at the *hardirq* context before the activation of the thread.
The second is the *timer latency* observed by the thread. The ACTIVATION
ID field serves to relate the *irq* execution to its respective *thread*
execution.

The *irq*/*thread* splitting is important to clarify in which context
the unexpected high value is coming from. The *irq* context can be
delayed by hardware-related actions, such as SMIs, NMIs, IRQs,
or by thread masking interrupts. Once the timer happens, the delay
can also be influenced by blocking caused by threads. For example, by
postponing the scheduler execution via preempt_disable(), scheduler
execution, or masking interrupts. Threads can also be delayed by the
interference from other threads and IRQs.

osnoise 기반 tracer 옵션

timerlat tracer는 osnoise tracer 위에 구현되므로 `osnoise/` config directory에서 설정합니다.

`cpus`는 timerlat thread를 실행할 CPU를, `timerlat_period_us`는 thread 주기를 정합니다. `stop_tracing_us`는 irq context latency가 설정값보다 클 때 tracing을 멈추며, `stop_tracing_total_us`는 thread context latency가 설정값보다 클 때 멈춥니다. 두 값 모두 0을 쓰면 기능이 꺼집니다.

`print_stack`은 IRQ 발생 시점의 stack을 저장합니다. stack은 thread context event 뒤에 출력되거나, `stop_tracing_us` 임계값에 걸린 경우 IRQ handler에서 출력됩니다.

Tracer options
---------------------

The timerlat tracer is built on top of osnoise tracer.
So its configuration is also done in the osnoise/ config
directory. 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 a
   timer latency at the *irq* context higher than the configured
   value happens. Writing 0 disables this option.
 - stop_tracing_total_us: stop the system tracing if a
   timer latency at the *thread* context is higher than the configured
   value happens. Writing 0 disables this option.
 - print_stack: save the stack of the IRQ occurrence. The stack is printed
   after the *thread context* event, or at the IRQ handler if *stop_tracing_us*
   is hit.

osnoise event를 이용한 복합 원인 분석

timerlat은 `osnoise:` trace event도 함께 활용할 수 있습니다. 다음 예는 event를 켜고 thread context latency가 25us를 넘으면 tracing을 멈춘 뒤 마지막 열 행을 확인합니다.

        [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 ns
      timerlat/5-1035    [005] .......   548.771104: #402268 context thread timer_latency     39960 ns

이 사례의 timer latency는 단일 원인이 아니라 여러 원인이 합쳐진 결과입니다. timer IRQ가 먼저 13us 지연되어 긴 IRQ-disabled section 가능성을 보이고, timerlat thread를 깨우는 local timer interrupt가 7,597ns, `qxl:21` device IRQ가 7,139ns를 사용했습니다. context switch 전 `cc1` thread noise는 9,909ns였습니다.

이 증거를 바탕으로 개발자는 다른 tracing 기법을 선택해 system을 debug하고 최적화할 수 있습니다.

osnoise event의 `duration`은 net 값입니다. 예를 들어 `thread_noise`에는 IRQ 실행 overhead 12,736ns가 포함되지 않습니다. 반면 timerlat tracer의 `timerlat_latency`는 모든 간섭을 포함한 gross 값입니다.

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 ns
      timerlat/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 a
single cause but to multiple ones. Firstly, the timer IRQ was delayed
for 13 us, which may point to a long IRQ disabled section (see IRQ
stacktrace section). Then the timer interrupt that wakes up the timerlat
thread 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 other
tracing methods to figure out how to debug and optimize the system.

It is worth mentioning that the *duration* values reported
by the osnoise: events are *net* values. For example, the
thread_noise does not include the duration of the overhead caused
by the IRQ execution (which indeed accounted for 12736 ns). But
the values reported by the timerlat tracer (timerlat_latency)
are *gross* values.

CPU timeline과 net·gross 관찰 범위

원문의 ASCII 도식은 CPU timeline 위쪽에 timerlat tracer가 보는 external clock event, irq latency 13,585ns, thread latency 39,960ns를 놓고, 아래쪽에 osnoise event가 보는 개별 실행 구간을 배치합니다. `-` 하나는 약 1us이고 시간은 오른쪽으로 흐릅니다.

timerlat은 시작점부터 irq 또는 thread 관찰점까지의 누적 시간을 보고하고, osnoise는 그 사이의 timer IRQ, device IRQ, thread noise 각 구간을 서로 겹치지 않는 net duration으로 보고합니다.

The art below illustrates a CPU timeline and how the timerlat tracer
observes 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로 긴 thread noise 추적

`osnoise/print_stack` option은 preemption 또는 interrupt disabled 상태의 thread noise가 timer latency의 주된 요인일 때 유용합니다.

        [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

예제에서는 thread가 859,978ns의 가장 큰 timer latency를 만들었습니다. timerlat IRQ handler에서 저장한 stack은 `dummy_load_1ms_pd_init` 함수로 이어집니다.

해당 함수는 의도적으로 preemption을 끄고 1ms 동안 busy delay를 수행한 뒤 다시 켭니다. 함수명, 호출 순서와 코드는 원문 그대로 보존합니다.

	static int __init dummy_load_1ms_pd_init(void)
	{
		preempt_disable();
		mdelay(1);
		preempt_enable();
		return 0;

	}

IRQ stacktrace
---------------------------

The osnoise/print_stack option is helpful for the cases in which a thread
noise causes the major factor for the timer latency, because of preempt or
irq 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 highest
contribution to the *timer latency* and the stack trace, saved during
the timerlat IRQ handler, points to a function named
dummy_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 timerlat interface

timerlat은 user-space thread가 같은 infrastructure로 scheduling latency를 측정하도록 합니다. interface는 CPU별 file descriptor인 `$tracing_dir/osnoise/per_cpu/cpu$ID/timerlat_fd`로 제공됩니다.

접근 조건은 timerlat tracer가 활성화되어 있고, osnoise workload option이 `NO_OSNOISE_WORKLOAD`이며, user-space thread가 CPU 하나에 affinity로 고정되고, 그 CPU의 file을 열며, 동시에 한 thread만 file에 접근하는 것입니다.

조건이 하나라도 맞지 않으면 `open()` syscall이 실패합니다. file descriptor를 연 뒤 user space는 이를 `read()`할 수 있습니다.

`read()`는 kernel timerlat thread와 마찬가지로 미래 시점에 timer를 arm하고 기다리는 timerlat code를 실행합니다.

timer IRQ가 발생하면 timerlat IRQ가 실행되어 IRQ latency를 보고하고 `read()`에서 기다리는 thread를 깨웁니다. thread가 schedule되면 kernel thread 방식과 동일하게 tracer를 통해 thread latency를 보고합니다.

in-kernel timerlat과 다른 점은 timer를 즉시 다시 arm하지 않고 `read()` syscall로 돌아간다는 것입니다. 이 시점에 user application은 원하는 code를 실행할 수 있습니다.

application이 timerlat file descriptor를 다시 읽으면 tracer는 user space에서 돌아온 시점까지의 total latency를 보고합니다. 작업 끝에 다시 읽었다면 이 값은 request response time으로 해석할 수 있습니다.

total latency를 보고한 뒤 timerlat은 다음 activation을 위해 timer를 arm하고 sleep하면서 cycle을 다시 시작합니다.

user space 실행 중 thread가 migration되거나 timerlat tracer가 꺼지는 등 조건이 깨지면 user-space thread에 `SIG_KILL`이 전달됩니다.

User-space interface
---------------------------

Timerlat allows user-space threads to use timerlat infra-structure to
measure scheduling latency. This interface is accessible via a per-CPU
file 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 the
timer in the future and wait for it as the regular kernel thread does.

When the timer IRQ fires, the timerlat IRQ will execute, report the
IRQ latency and wake up the thread waiting in the read. The thread will be
scheduled and report the thread latency via tracer - as for the kernel
thread.

The difference from the in-kernel timerlat is that, instead of re-arming
the 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 tracer
will report the return from user-space latency, which is the total
latency. If this is the end of the work, it can be interpreted as the
response time for the request.

After reporting the total latency, timerlat will restart the cycle, arm
a timer, and go to sleep for the following activation.

If at any time one of the conditions is broken, e.g., the thread migrates
while in user space, or the timerlat tracer is disabled, the SIG_KILL
signal will be sent to the user-space thread.

CPU 0 user-space 측정 예제

예제 program은 thread affinity를 CPU 0으로 고정하고 해당 CPU의 `timerlat_fd` 경로를 구성한 뒤 read-only로 엽니다.

무한 loop에서 `read(timerlat_fd, buffer, 1024)`를 반복할 때마다 timerlat cycle이 실행됩니다. 오류가 발생하면 loop를 빠져나와 descriptor를 닫고 종료합니다.

 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);
 }

예제에서 `retval < 0`은 측정 조건이 더 이상 유지되지 않거나 read가 실패했음을 뜻합니다. 정상적인 read가 이어지는 동안에는 같은 CPU에서 activation과 user-space 복귀 지연을 계속 기록합니다.

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);
 }