rtla-timerlat-top: 운영체제 타이머 지연 측정

요약 화면, 옵션과 자동 분석 전용 모드

`rtla timerlat top [OPTIONS]`는 `timerlat` 추적기의 주기 출력을 CPU별 요약으로 표시한다. `-T`를 사용하면 `osnoise:` tracepoint를 활성화하여 각각의 운영체제 간섭 정보도 함께 제공한다.

이 모드는 timerlat 설명·옵션, top 출력 옵션, RTLA 공통 옵션, timerlat 자동 분석 정의를 포함한다. `--aa-only us`는 통계 수집과 표시를 생략한 채 추적 중지 조건만 설정하고, 임계값을 넘었을 때 자동 분석을 출력한다. 따라서 통계 수집 비용 없이 원인 분석 기능을 켜고 싶을 때 유용하다.

.. |tool| replace:: timerlat top

====================
rtla-timerlat-top
====================
-------------------------------------------
Measures the operating system timer latency
-------------------------------------------

:Manual section: 1

SYNOPSIS
========
**rtla timerlat top** [*OPTIONS*] ...

DESCRIPTION
===========

.. include:: common_timerlat_description.txt

The **rtla timerlat top** displays a summary of the periodic output
from the *timerlat* tracer. It also provides information for each
operating system noise via the **osnoise:** tracepoints that can be
seem with the option **-T**.

OPTIONS
=======

.. include:: common_timerlat_options.txt

.. include:: common_top_options.txt

.. include:: common_options.txt

.. include:: common_timerlat_aa.txt

**--aa-only** *us*

        Set stop tracing conditions and run without collecting and displaying statistics.
        Print the auto-analysis if the system hits the stop tracing condition. This option
        is useful to reduce rtla timerlat CPU, enabling the debug without the overhead of
        collecting the statistics.

40us 중지 조건과 CPU 23 자동 분석

예제는 CPU 1-23에서 자동 추적 모드를 실행하고 40us 이상의 지연이 발견되면 추적을 멈춘다. `timerlat -a 40 -c 1-23 -q`의 `-q`는 실행 중 갱신 대신 최종 결과를 중심으로 보여 준다.

상단 표에서 `COUNT`는 CPU별 표본 수이고 IRQ와 Thread 영역의 `cur`, `min`, `avg`, `max`는 현재·최소·평균·최대 지연을 microsecond 단위로 나타낸다. CPU 23에서 IRQ 28us와 스레드 41us가 관찰되어 40us 중지 조건을 넘었고 자동 분석이 시작되었다.

자동 분석은 전체 41.96us 스레드 지연을 구성 요소별로 나눈다. IRQ handler delay가 27.49us로 65.52%를 차지하고, timerlat IRQ 자체 실행은 9.59us로 22.85%, 차단 스레드는 3.79us로 9.03%다. 따라서 이 사례의 주된 원인은 timerlat wakeup IRQ가 실행되기 전까지 인터럽트가 가려진 시간이다.

차단 스택은 `objtool:49256` 스레드가 btrfs 파일 시스템에서 write syscall을 수행하던 중 mem cgroup의 `raw spin lock` 경로를 지나며 인터럽트를 비활성화했음을 보여 준다. 스택의 함수명과 호출 순서는 원문 그대로 보존되며, idle 복귀 지연과 CPU 4의 idle 상태 최대 IRQ 지연 17.48us도 별도로 보고된다. 원시 추적은 `timerlat_trace.txt`에 저장된다.

EXAMPLE
=======

In the example below, the timerlat tracer is dispatched in cpus *1-23* in the
automatic trace mode, instructing the tracer to stop if a *40 us* latency or
higher is found::

  # timerlat -a 40 -c 1-23 -q
                                     Timer Latency
    0 00:00:12   |          IRQ Timer Latency (us)        |         Thread Timer Latency (us)
  CPU COUNT      |      cur       min       avg       max |      cur       min       avg       max
    1 #12322     |        0         0         1        15 |       10         3         9        31
    2 #12322     |        3         0         1        12 |       10         3         9        23
    3 #12322     |        1         0         1        21 |        8         2         8        34
    4 #12322     |        1         0         1        17 |       10         2        11        33
    5 #12322     |        0         0         1        12 |        8         3         8        25
    6 #12322     |        1         0         1        14 |       16         3        11        35
    7 #12322     |        0         0         1        14 |        9         2         8        29
    8 #12322     |        1         0         1        22 |        9         3         9        34
    9 #12322     |        0         0         1        14 |        8         2         8        24
   10 #12322     |        1         0         0        12 |        9         3         8        24
   11 #12322     |        0         0         0        15 |        6         2         7        29
   12 #12321     |        1         0         0        13 |        5         3         8        23
   13 #12319     |        0         0         1        14 |        9         3         9        26
   14 #12321     |        1         0         0        13 |        6         2         8        24
   15 #12321     |        1         0         1        15 |       12         3        11        27
   16 #12318     |        0         0         1        13 |        7         3        10        24
   17 #12319     |        0         0         1        13 |       11         3         9        25
   18 #12318     |        0         0         0        12 |        8         2         8        20
   19 #12319     |        0         0         1        18 |       10         2         9        28
   20 #12317     |        0         0         0        20 |        9         3         8        34
   21 #12318     |        0         0         0        13 |        8         3         8        28
   22 #12319     |        0         0         1        11 |        8         3        10        22
   23 #12320     |       28         0         1        28 |       41         3        11        41
  rtla timerlat hit stop tracing
  ## CPU 23 hit stop tracing, analyzing it ##
  IRQ handler delay:                                        27.49 us (65.52 %)
  IRQ latency:                                              28.13 us
  Timerlat IRQ duration:                                     9.59 us (22.85 %)
  Blocking thread:                                           3.79 us (9.03 %)
                         objtool:49256                       3.79 us
    Blocking thread stacktrace
                -> timerlat_irq
                -> __hrtimer_run_queues
                -> hrtimer_interrupt
                -> __sysvec_apic_timer_interrupt
                -> sysvec_apic_timer_interrupt
                -> asm_sysvec_apic_timer_interrupt
                -> _raw_spin_unlock_irqrestore
                -> cgroup_rstat_flush_locked
                -> cgroup_rstat_flush_irqsafe
                -> mem_cgroup_flush_stats
                -> mem_cgroup_wb_stats
                -> balance_dirty_pages
                -> balance_dirty_pages_ratelimited_flags
                -> btrfs_buffered_write
                -> btrfs_do_write_iter
                -> vfs_write
                -> __x64_sys_pwrite64
                -> do_syscall_64
                -> entry_SYSCALL_64_after_hwframe
  ------------------------------------------------------------------------
    Thread latency:                                          41.96 us (100%)

  The system has exit from idle latency!
    Max timerlat IRQ latency from idle: 17.48 us in cpu 4
  Saving trace to timerlat_trace.txt

원인 결론과 기본 우선순위

이 사례에서 가장 큰 요인은 timerlat wakeup을 담당하는 IRQ handler가 겪은 65.52%의 지연이다. 현재 스레드 `objtool:49256`이 btrfs 파일 시스템의 write syscall을 수행하면서 mem cgroup 내부의 raw spin lock 연산으로 인터럽트를 가렸다는 사실을 차단 스택에서 확인할 수 있다.

추가 분석을 위해 원시 추적은 `timerlat_trace.txt`에 저장된다. 이 실행에서는 timerlat 추적기 스레드의 우선순위를 따로 바꾸지 않았다. 기본값이 실시간 커널 개발자가 스케줄링 지연을 분석할 때 흔히 쓰는 `FIFO:95`이므로 일반적으로 별도 변경이 필요하지 않다.

In this case, the major factor was the delay suffered by the *IRQ handler*
that handles **timerlat** wakeup: *65.52%*. This can be caused by the
current thread masking interrupts, which can be seen in the blocking
thread stacktrace: the current thread (*objtool:49256*) disabled interrupts
via *raw spin lock* operations inside mem cgroup, while doing write
syscall in a btrfs file system.

The raw trace is saved in the **timerlat_trace.txt** file for further analysis.

Note that **rtla timerlat** was dispatched without changing *timerlat* tracer
threads' priority. That is generally not needed because these threads have
priority *FIFO:95* by default, which is a common priority used by real-time
kernel developers to analyze scheduling delays.

관련 문서와 작성 정보

관련 매뉴얼은 `rtla-timerlat(1)`과 `rtla-timerlat-hist(1)`이며, 커널 추적기 세부 사항은 timerlat tracer 문서에서 확인한다.

이 문서는 Daniel Bristot de Oliveira가 작성했다. 마지막 `common_appendix.txt`는 RTLA 공통 부록을 포함한다.

SEE ALSO
--------
**rtla-timerlat**\(1), **rtla-timerlat-hist**\(1)

*timerlat* tracer documentation: <https://www.kernel.org/doc/html/latest/trace/timerlat-tracer.html>

AUTHOR
------
Written by Daniel Bristot de Oliveira <bristot@kernel.org>

.. include:: common_appendix.txt