← Documents Documentation/arch/powerpc/vpa-dtl.rst GitHub 원문 ↗

Linux 6.18.37 · Architecture

DTL (Dispatch Trace Log)

VPA DTL을 hrtimer와 perf AUX trace로 수집해 sched event와 timestamp correlation하는 방법입니다.

Source pathDocumentation/arch/powerpc/vpa-dtl.rst
Source versionLinux v6.18.37
TranslationDUJINLABS 전문 번역 + 해설

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

1. 요약·해설

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

요약과 해설

vpa-dtl.rst:1-156

Interrupt 없는 VPA DTL PMU는 hrtimer로 raw buffer를 AUX area에 복사합니다. Userspace는 CPU별 auxtrace queue를 timestamp heap으로 merge하여 dispatch/preempt latency와 sched event를 같은 timeline에서 분석합니다.

2. 영어 원문 전체

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

원문 전체 펼치기
1 .. SPDX-License-Identifier: GPL-2.0
2 .. _vpa-dtl:
3
4 ===================================
5 DTL (Dispatch Trace Log)
6 ===================================
7
8 Athira Rajeev, 19 April 2025
9
10 .. contents::
11 :depth: 3
12
13
14 Basic overview
15 ==============
16
17 The pseries Shared Processor Logical Partition(SPLPAR) machines can
18 retrieve a log of dispatch and preempt events from the hypervisor
19 using data from Disptach Trace Log(DTL) buffer. With this information,
20 user can retrieve when and why each dispatch & preempt has occurred.
21 The vpa-dtl PMU exposes the Virtual Processor Area(VPA) DTL counters
22 via perf.
23
24 Infrastructure used
25 ===================
26
27 The VPA DTL PMU counters do not interrupt on overflow or generate any
28 PMI interrupts. Therefore, hrtimer is used to poll the DTL data. The timer
29 nterval can be provided by user via sample_period field in nano seconds.
30 vpa dtl pmu has one hrtimer added per vpa-dtl pmu thread. DTL (Dispatch
31 Trace Log) contains information about dispatch/preempt, enqueue time etc.
32 We directly copy the DTL buffer data as part of auxiliary buffer and it
33 will be processed later. This will avoid time taken to create samples
34 in the kernel space. The PMU driver collecting Dispatch Trace Log (DTL)
35 entries makes use of AUX support in perf infrastructure. On the tools side,
36 this data is made available as PERF_RECORD_AUXTRACE records.
37
38 To correlate each DTL entry with other events across CPU's, an auxtrace_queue
39 is created for each CPU. Each auxtrace queue has a array/list of auxtrace buffers.
40 All auxtrace queues is maintained in auxtrace heap. The queues are sorted
41 based on timestamp. When the different PERF_RECORD_XX records are processed,
42 compare the timestamp of perf record with timestamp of top element in the
43 auxtrace heap so that DTL events can be co-related with other events
44 Process the auxtrace queue if the timestamp of element from heap is
45 lower than timestamp from entry in perf record. Sometimes it could happen that
46 one buffer is only partially processed. if the timestamp of occurrence of
47 another event is more than currently processed element in the queue, it will
48 move on to next perf record. So keep track of position of buffer to continue
49 processing next time. Update the timestamp of the auxtrace heap with the timestamp
50 of last processed entry from the auxtrace buffer.
51
52 This infrastructure ensures dispatch trace log entries can be correlated
53 and presented along with other events like sched.
54
55 vpa-dtl PMU example usage
56 =========================
57
58 .. code-block:: sh
59
60 # ls /sys/devices/vpa_dtl/
61 events format perf_event_mux_interval_ms power subsystem type uevent
62
63
64 To capture the DTL data using perf record:
65 .. code-block:: sh
66
67 # ./perf record -a -e sched:\*,vpa_dtl/dtl_all/ -c 1000000000 sleep 1
68
69 The result can be interpreted using perf record. Snippet of perf report -D
70
71 .. code-block:: sh
72
73 # ./perf report -D
74
75 There are different PERF_RECORD_XX records. In that records corresponding to
76 auxtrace buffers includes:
77
78 1. PERF_RECORD_AUX
79 Conveys that new data is available in AUX area
80
81 2. PERF_RECORD_AUXTRACE_INFO
82 Describes offset and size of auxtrace data in the buffers
83
84 3. PERF_RECORD_AUXTRACE
85 This is the record that defines the auxtrace data which here in case of
86 vpa-dtl pmu is dispatch trace log data.
87
88 Snippet from perf report -D showing the PERF_RECORD_AUXTRACE dump
89
90 .. code-block:: sh
91
92 0 0 0x39b10 [0x30]: PERF_RECORD_AUXTRACE size: 0x690 offset: 0 ref: 0 idx: 0 tid: -1 cpu: 0
93 .
94 . ... VPA DTL PMU data: size 1680 bytes, entries is 35
95 . 00000000: boot_tb: 21349649546353231, tb_freq: 512000000
96 . 00000030: dispatch_reason:decrementer interrupt, preempt_reason:H_CEDE, enqueue_to_dispatch_time:7064, ready_to_enqueue_time:187, waiting_to_ready_time:6611773
97 . 00000060: dispatch_reason:priv doorbell, preempt_reason:H_CEDE, enqueue_to_dispatch_time:146, ready_to_enqueue_time:0, waiting_to_ready_time:15359437
98 . 00000090: dispatch_reason:decrementer interrupt, preempt_reason:H_CEDE, enqueue_to_dispatch_time:4868, ready_to_enqueue_time:232, waiting_to_ready_time:5100709
99 . 000000c0: dispatch_reason:priv doorbell, preempt_reason:H_CEDE, enqueue_to_dispatch_time:179, ready_to_enqueue_time:0, waiting_to_ready_time:30714243
100 . 000000f0: dispatch_reason:priv doorbell, preempt_reason:H_CEDE, enqueue_to_dispatch_time:197, ready_to_enqueue_time:0, waiting_to_ready_time:15350648
101 . 00000120: dispatch_reason:priv doorbell, preempt_reason:H_CEDE, enqueue_to_dispatch_time:213, ready_to_enqueue_time:0, waiting_to_ready_time:15353446
102 . 00000150: dispatch_reason:priv doorbell, preempt_reason:H_CEDE, enqueue_to_dispatch_time:212, ready_to_enqueue_time:0, waiting_to_ready_time:15355126
103 . 00000180: dispatch_reason:decrementer interrupt, preempt_reason:H_CEDE, enqueue_to_dispatch_time:6368, ready_to_enqueue_time:164, waiting_to_ready_time:5104665
104
105 Above is representation of dtl entry of below format:
106
107 struct dtl_entry {
108 u8 dispatch_reason;
109 u8 preempt_reason;
110 u16 processor_id;
111 u32 enqueue_to_dispatch_time;
112 u32 ready_to_enqueue_time;
113 u32 waiting_to_ready_time;
114 u64 timebase;
115 u64 fault_addr;
116 u64 srr0;
117 u64 srr1;
118
119 };
120
121 First two fields represent the dispatch reason and preempt reason. The post
122 processing of PERF_RECORD_AUXTRACE records will translate to meaningful data
123 for user to consume.
124
125 Visualize the dispatch trace log entries with perf report
126 =========================================================
127
128 .. code-block:: sh
129
130 # ./perf record -a -e sched:*,vpa_dtl/dtl_all/ -c 1000000000 sleep 1
131 [ perf record: Woken up 1 times to write data ]
132 [ perf record: Captured and wrote 0.300 MB perf.data ]
133
134 # ./perf report
135 # Samples: 321 of event 'vpa-dtl'
136 # Event count (approx.): 321
137 #
138 # Children Self Command Shared Object Symbol
139 # ........ ........ ....... ................. ..............................
140 #
141 100.00% 100.00% swapper [kernel.kallsyms] [k] plpar_hcall_norets_notrace
142
143 Visualize the dispatch trace log entries with perf script
144 =========================================================
145
146 .. code-block:: sh
147
148 # ./perf script
149 migration/9 67 [009] 105373.359903: sched:sched_waking: comm=perf pid=13418 prio=120 target_cpu=009
150 migration/9 67 [009] 105373.359904: sched:sched_migrate_task: comm=perf pid=13418 prio=120 orig_cpu=9 dest_cpu=10
151 migration/9 67 [009] 105373.359907: sched:sched_stat_runtime: comm=migration/9 pid=67 runtime=4050 [ns]
152 migration/9 67 [009] 105373.359908: sched:sched_switch: prev_comm=migration/9 prev_pid=67 prev_prio=0 prev_state=S ==> next_comm=swapper/9 next_pid=0 next_prio=120
153 :256 256 [016] 105373.359913: vpa-dtl: timebase: 21403600706628832 dispatch_reason:decrementer interrupt, preempt_reason:H_CEDE, enqueue_to_dispatch_time:4854, ready_to_enqueue_time:139, waiting_to_ready_time:511842115 c0000000000fcd28 plpar_hcall_norets_notrace+0x18 ([kernel.kallsyms])
154 :256 256 [017] 105373.360012: vpa-dtl: timebase: 21403600706679454 dispatch_reason:priv doorbell, preempt_reason:H_CEDE, enqueue_to_dispatch_time:236, ready_to_enqueue_time:0, waiting_to_ready_time:133864583 c0000000000fcd28 plpar_hcall_norets_notrace+0x18 ([kernel.kallsyms])
155 perf 13418 [010] 105373.360048: sched:sched_stat_runtime: comm=perf pid=13418 runtime=139748 [ns]
156 perf 13418 [010] 105373.360052: sched:sched_waking: comm=migration/10 pid=72 prio=0 target_cpu=010
157

3. 한국어 전문 번역

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

DTL (Dispatch Trace Log)

1-13

Athira Rajeev가 2025-04-19 작성한 이 문서는 pseries VPA Dispatch Trace Log를 perf AUX trace로 수집하고 해석하는 방법을 설명합니다.

기본 개요

14-23

Pseries Shared Processor Logical Partition(SPLPAR)은 VPA DTL buffer에서 Hypervisor의 dispatch/preempt event log를 가져와 각 event의 시점과 이유를 확인할 수 있습니다. `vpa-dtl` PMU가 VPA DTL counter를 perf에 노출합니다.

Perf AUX infrastructure

24-54

VPA DTL PMU counter는 overflow interrupt나 PMI를 만들지 않으므로 `hrtimer`로 DTL data를 polling합니다. User는 nanosecond 단위 `sample_period`로 interval을 지정하며 vpa-dtl PMU thread마다 hrtimer 하나가 있습니다.

DTL에는 dispatch/preempt, enqueue time 등이 있습니다. Driver는 kernel에서 sample을 다시 만들지 않고 DTL buffer를 AUX buffer에 직접 copy하여 overhead를 줄입니다. Tool에서는 `PERF_RECORD_AUXTRACE` record로 제공합니다.

CPU 사이 DTL entry와 다른 event를 correlate하기 위해 CPU마다 `auxtrace_queue`를 만들고 여러 auxtrace buffer를 둡니다. 모든 queue는 timestamp로 정렬된 auxtrace heap에서 관리합니다.

Perf record timestamp와 heap top timestamp를 비교하여 heap entry가 더 이르면 해당 queue를 처리합니다. Buffer 일부만 처리한 경우 position을 보존해 다음번에 이어가고 마지막 처리 entry timestamp로 heap을 update합니다.

이 infrastructure로 DTL entry를 `sched` 같은 다른 event와 함께 시간순으로 제시할 수 있습니다.

VPA-DTL AUX collection
VPA DTL buffer`hrtimer` pollingPerf AUX buffer`PERF_RECORD_AUXTRACE`Userspace processing

Interrupt 없는 DTL buffer를 timer로 읽어 perf AUX record로 전달합니다.

Per-CPU auxtrace correlation
CPU0 queueAuxtrace heap
CPU1 queueAuxtrace heap
CPU N queueAuxtrace heap
Heap top timestampPerf record timestamp 비교Earlier DTL entries 처리Buffer position 보존

Timestamp heap이 CPU별 queue와 일반 perf record를 시간순으로 merge합니다.

VPA-DTL PMU sysfs

55-63

VPA-DTL PMU device의 sysfs entry 예입니다.

# ls /sys/devices/vpa_dtl/
events  format  perf_event_mux_interval_ms  power  subsystem  type  uevent

Perf record로 DTL capture

64-70

다음 command는 system-wide sched event와 `vpa_dtl/dtl_all/`을 1초 동안 함께 기록하며 sample period는 1,000,000,000입니다.

# ./perf record -a -e sched:\*,vpa_dtl/dtl_all/ -c 1000000000 sleep 1

Perf AUX record 종류

71-87

Raw record는 `perf report -D`로 확인합니다.

# ./perf report -D
Record역할
`PERF_RECORD_AUX`AUX area에 새 data가 있음을 알림
`PERF_RECORD_AUXTRACE_INFO`Buffer의 auxtrace data offset과 size 설명
`PERF_RECORD_AUXTRACE`VPA-DTL PMU의 실제 Dispatch Trace Log auxtrace data

PERF_RECORD_AUXTRACE dump

88-104

Dump에는 AUXTRACE size/offset, boot timebase와 frequency, 각 DTL entry의 dispatch/preempt reason 및 세 단계 latency가 표시됩니다.

0 0 0x39b10 [0x30]: PERF_RECORD_AUXTRACE size: 0x690  offset: 0  ref: 0  idx: 0  tid: -1  cpu: 0
.
. ... VPA DTL PMU data: size 1680 bytes, entries is 35
.  00000000: boot_tb: 21349649546353231, tb_freq: 512000000
.  00000030: dispatch_reason:decrementer interrupt, preempt_reason:H_CEDE, enqueue_to_dispatch_time:7064, ready_to_enqueue_time:187, waiting_to_ready_time:6611773
.  00000060: dispatch_reason:priv doorbell, preempt_reason:H_CEDE, enqueue_to_dispatch_time:146, ready_to_enqueue_time:0, waiting_to_ready_time:15359437
.  00000090: dispatch_reason:decrementer interrupt, preempt_reason:H_CEDE, enqueue_to_dispatch_time:4868, ready_to_enqueue_time:232, waiting_to_ready_time:5100709
.  000000c0: dispatch_reason:priv doorbell, preempt_reason:H_CEDE, enqueue_to_dispatch_time:179, ready_to_enqueue_time:0, waiting_to_ready_time:30714243
.  000000f0: dispatch_reason:priv doorbell, preempt_reason:H_CEDE, enqueue_to_dispatch_time:197, ready_to_enqueue_time:0, waiting_to_ready_time:15350648
.  00000120: dispatch_reason:priv doorbell, preempt_reason:H_CEDE, enqueue_to_dispatch_time:213, ready_to_enqueue_time:0, waiting_to_ready_time:15353446
.  00000150: dispatch_reason:priv doorbell, preempt_reason:H_CEDE, enqueue_to_dispatch_time:212, ready_to_enqueue_time:0, waiting_to_ready_time:15355126
.  00000180: dispatch_reason:decrementer interrupt, preempt_reason:H_CEDE, enqueue_to_dispatch_time:6368, ready_to_enqueue_time:164, waiting_to_ready_time:5104665

struct dtl_entry

105-124

Dump의 각 entry는 다음 원문 structure에 대응합니다.

struct dtl_entry {
        u8      dispatch_reason;
        u8      preempt_reason;
        u16     processor_id;
        u32     enqueue_to_dispatch_time;
        u32     ready_to_enqueue_time;
        u32     waiting_to_ready_time;
        u64     timebase;
        u64     fault_addr;
        u64     srr0;
        u64     srr1;

};
FieldType의미
`dispatch_reason``u8`Dispatch 이유
`preempt_reason``u8`Preempt 이유
`processor_id``u16`Processor identifier
`enqueue_to_dispatch_time``u32`Enqueue에서 dispatch까지 시간
`ready_to_enqueue_time``u32`Ready에서 enqueue까지 시간
`waiting_to_ready_time``u32`Waiting에서 ready까지 시간
`timebase``u64`DTL timestamp
`fault_addr``u64`Fault address
`srr0`, `srr1``u64` 각각Saved instruction/MSR state

첫 두 field는 dispatch reason과 preempt reason입니다. `PERF_RECORD_AUXTRACE` post-processing이 raw value를 사용자가 읽을 수 있는 의미로 변환합니다.

Perf report와 script 시각화

125-156

`perf report`는 vpa-dtl sample을 symbol별로 집계하고, `perf script`는 sched event와 vpa-dtl event를 timestamp 순서로 함께 출력합니다.

# ./perf record -a -e sched:*,vpa_dtl/dtl_all/ -c 1000000000 sleep 1
[ perf record: Woken up 1 times to write data ]
[ perf record: Captured and wrote 0.300 MB perf.data ]

# ./perf report
# Samples: 321  of event 'vpa-dtl'
# Event count (approx.): 321
#
# Children      Self  Command  Shared Object      Symbol
# ........  ........  .......  .................  ..............................
#
   100.00%   100.00%  swapper  [kernel.kallsyms]  [k] plpar_hcall_norets_notrace
# ./perf script
  migration/9      67 [009] 105373.359903:                     sched:sched_waking: comm=perf pid=13418 prio=120 target_cpu=009
  migration/9      67 [009] 105373.359904:               sched:sched_migrate_task: comm=perf pid=13418 prio=120 orig_cpu=9 dest_cpu=10
  migration/9      67 [009] 105373.359907:               sched:sched_stat_runtime: comm=migration/9 pid=67 runtime=4050 [ns]
  migration/9      67 [009] 105373.359908:                     sched:sched_switch: prev_comm=migration/9 prev_pid=67 prev_prio=0 prev_state=S ==> next_comm=swapper/9 next_pid=0 next_prio=120
         :256     256 [016] 105373.359913:                                vpa-dtl: timebase: 21403600706628832 dispatch_reason:decrementer interrupt, preempt_reason:H_CEDE, enqueue_to_dispatch_time:4854,                        ready_to_enqueue_time:139, waiting_to_ready_time:511842115 c0000000000fcd28 plpar_hcall_norets_notrace+0x18 ([kernel.kallsyms])
         :256     256 [017] 105373.360012:                                vpa-dtl: timebase: 21403600706679454 dispatch_reason:priv doorbell, preempt_reason:H_CEDE, enqueue_to_dispatch_time:236,                         ready_to_enqueue_time:0, waiting_to_ready_time:133864583 c0000000000fcd28 plpar_hcall_norets_notrace+0x18 ([kernel.kallsyms])
         perf   13418 [010] 105373.360048:               sched:sched_stat_runtime: comm=perf pid=13418 runtime=139748 [ns]
         perf   13418 [010] 105373.360052:                     sched:sched_waking: comm=migration/10 pid=72 prio=0 target_cpu=010
DTL 분석 출력
`perf.data``perf report`Aggregated vpa-dtl samples
`perf.data``perf script`sched + vpa-dtl timeline

같은 perf.data에서 summary와 timestamp timeline을 선택할 수 있습니다.