NMI Trace Events | Linux 6.18.37

요약·해설과 원문, 전문 번역을 서로 분리했습니다. API 이름, symbol, source path는 원문 표기를 사용합니다.

1. 요약·해설

원문의 핵심 논리와 kernel programming 관점의 보충 설명입니다. 아래의 전문 번역과는 별도로 작성했습니다.

요약·해설

events-nmi.rst:1-45

오래 실행되는 NMI handler를 symbol address와 delta_ns 기준으로 좁혀 추적하는 방법입니다.

2. 영어 원문 전체

번역 기준이 된 Linux v6.18.37 원문입니다. 줄 번호는 이 버전의 파일 좌표입니다.

원문 전체 펼치기

1 ================

2 NMI Trace Events

3 ================

5 These events normally show up here:

7 /sys/kernel/tracing/events/nmi

10 nmi_handler

11 -----------

13 You might want to use this tracepoint if you suspect that your

14 NMI handlers are hogging large amounts of CPU time. The kernel

15 will warn if it sees long-running handlers::

17 INFO: NMI handler took too long to run: 9.207 msecs

19 and this tracepoint will allow you to drill down and get some

20 more details.

22 Let's say you suspect that perf_event_nmi_handler() is causing

23 you some problems and you only want to trace that handler

24 specifically. You need to find its address::

26 $ grep perf_event_nmi_handler /proc/kallsyms

27 ffffffff81625600 t perf_event_nmi_handler

29 Let's also say you are only interested in when that function is

30 really hogging a lot of CPU time, like a millisecond at a time.

31 Note that the kernel's output is in milliseconds, but the input

32 to the filter is in nanoseconds! You can filter on 'delta_ns'::

34 cd /sys/kernel/tracing/events/nmi/nmi_handler

35 echo 'handler==0xffffffff81625600 && delta_ns>1000000' > filter

36 echo 1 > enable

38 Your output would then look like::

40 $ cat /sys/kernel/tracing/trace_pipe

41 <idle>-0 [000] d.h3 505.397558: nmi_handler: perf_event_nmi_handler() delta_ns: 3236765 handled: 1

42 <idle>-0 [000] d.h3 505.805893: nmi_handler: perf_event_nmi_handler() delta_ns: 3174234 handled: 1

43 <idle>-0 [000] d.h3 506.158206: nmi_handler: perf_event_nmi_handler() delta_ns: 3084642 handled: 1

44 <idle>-0 [000] d.h3 506.334346: nmi_handler: perf_event_nmi_handler() delta_ns: 3080351 handled: 1

3. 한국어 전문 번역

영어 원문의 문단 순서와 의미를 유지한 전체 번역입니다. 코드, 함수명, symbol과 URL은 원문 표기를 유지합니다.

nmi_handler tracepoint의 목적

1-20

NMI event는 보통 `/sys/kernel/tracing/events/nmi` 아래에 나타난다.

`nmi_handler` tracepoint는 NMI handler가 CPU 시간을 지나치게 많이 쓰는 것으로 의심될 때 사용한다. kernel은 오래 실행되는 handler를 발견하면 `NMI handler took too long to run` 경고와 millisecond 시간을 출력한다.

이 tracepoint를 사용하면 경고만 보는 것보다 handler별 세부 시간을 더 깊게 조사할 수 있다.

NMI 지연 조사

Long-running NMI handlerKernel warning

Kernel warningEnable nmi_handler tracepoint

nmi_handler eventHandler address and delta_ns

kernel 경고에서 개별 handler trace로 범위를 좁힌다.

NMI trace 위치

항목값

Trace group/sys/kernel/tracing/events/nmi

Tracepointnmi_handler

목적오래 실행되는 NMI handler 식별

event group과 분석 대상이다.

================
NMI Trace Events
================

These events normally show up here:

	/sys/kernel/tracing/events/nmi


nmi_handler
-----------

You might want to use this tracepoint if you suspect that your
NMI handlers are hogging large amounts of CPU time.  The kernel
will warn if it sees long-running handlers::

	INFO: NMI handler took too long to run: 9.207 msecs

and this tracepoint will allow you to drill down and get some
more details.

Handler address와 delta_ns filter

21-37

예제는 `perf_event_nmi_handler()`만 추적한다. 먼저 `/proc/kallsyms`에서 symbol을 검색해 address `0xffffffff81625600`을 찾는다.

1 millisecond 이상 CPU를 점유할 때만 보고 싶다면 `delta_ns`로 filter한다. kernel 경고 출력 단위는 millisecond지만 filter 입력 단위는 nanosecond라는 점이 중요하다. 1 ms는 1,000,000 ns다.

`handler==0xffffffff81625600 && delta_ns>1000000` filter를 `nmi_handler` event에 쓰고 enable을 1로 설정한다.

NMI filter 조건

조건값

handler0xffffffff81625600

symbolperf_event_nmi_handler

delta_ns> 1000000

시간> 1 ms

handler identity와 실행 시간 조건을 함께 적용한다.

NMI handler 필터 구성

/proc/kallsymsHandler address

Handler addresshandler == address

1 msdelta_ns > 1000000

Combined expressionnmi_handler/filter

symbol address를 얻어 nanosecond threshold와 결합한다.


Let's say you suspect that perf_event_nmi_handler() is causing
you some problems and you only want to trace that handler
specifically.  You need to find its address::

	$ grep perf_event_nmi_handler /proc/kallsyms
	ffffffff81625600 t perf_event_nmi_handler

Let's also say you are only interested in when that function is
really hogging a lot of CPU time, like a millisecond at a time.
Note that the kernel's output is in milliseconds, but the input
to the filter is in nanoseconds!  You can filter on 'delta_ns'::

	cd /sys/kernel/tracing/events/nmi/nmi_handler
	echo 'handler==0xffffffff81625600 && delta_ns>1000000' > filter
	echo 1 > enable

trace_pipe 출력 해석

38-45

`trace_pipe` 출력은 idle task의 CPU 0에서 `perf_event_nmi_handler()`가 실행된 record를 보여 준다. 예시 `delta_ns`는 약 3.08~3.24 million ns로 모두 1 ms filter를 넘고 `handled: 1`이다.

예시 NMI 지연

delta_ns대략적인 시간handled

32367653.237 ms1

31742343.174 ms1

30846423.085 ms1

30803513.080 ms1

원문 trace의 네 delta_ns 값을 유지해 millisecond로 해석한다.

Your output would then look like::

	$ cat /sys/kernel/tracing/trace_pipe
	<idle>-0     [000] d.h3   505.397558: nmi_handler: perf_event_nmi_handler() delta_ns: 3236765 handled: 1
	<idle>-0     [000] d.h3   505.805893: nmi_handler: perf_event_nmi_handler() delta_ns: 3174234 handled: 1
	<idle>-0     [000] d.h3   506.158206: nmi_handler: perf_event_nmi_handler() delta_ns: 3084642 handled: 1
	<idle>-0     [000] d.h3   506.334346: nmi_handler: perf_event_nmi_handler() delta_ns: 3080351 handled: 1