Userspace에서 kernel debugging | Linux 6.18.37

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

1. 요약·해설

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

Dynamic debug control

userspace_debugging_guide.rst:4-62

CONFIG_DYNAMIC_DEBUG kernel은 /proc/dynamic_debug/control에서 pr_debug·dev_dbg callsite를 조회하고 file, module, function, line과 format query로 enable한다. 필요한 callsite만 +p하고 test 뒤 -p로 원복해 log 교란을 제한한다.

echo 'module my_driver +p' > /proc/dynamic_debug/control
echo 'func my_function +p' > /proc/dynamic_debug/control

Ftrace 수집과 log 읽기

userspace_debugging_guide.rst:63-114

Tracefs에서 current_tracer, set_ftrace_filter, events/*/enable과 trace buffer size를 설정한 뒤 tracing_on 구간만 수집한다. Function graph는 call duration을, event tracepoint는 구조화된 state를 보여 준다.

Trace line의 CPU, task·PID, timestamp, flags와 event payload를 함께 읽고 per-CPU ordering과 cross-CPU clock을 고려한다. trace-cmd record·report와 KernelShark는 긴 trace의 scheduling·IRQ 관계를 시각화한다.

perf로 hot path와 latency 분석

userspace_debugging_guide.rst:115-190

성능 문제는 먼저 throughput, tail latency, CPU utilization, cache miss 또는 sleep time 중 무엇이 나빠졌는지 metric을 정의한다. top, vmstat, iostat와 pidstat로 system 범위를 좁힌 뒤 perf stat으로 counter를 비교하고 perf record·report로 call graph를 수집한다.

Frequency, call graph mode와 sampling overhead를 기록하고 before·after를 같은 workload와 CPU placement에서 비교한다. Off-CPU 문제는 scheduler trace와 함께 보아 lock wait, I/O와 preemption을 구분한다.

Perfetto와 panic 분석

userspace_debugging_guide.rst:191-281

Perfetto는 userspace event, ftrace와 system metric을 하나의 timeline으로 합쳐 Android·embedded pipeline을 분석할 수 있다. Trace configuration에서 필요한 data source와 buffer를 제한한다.

Panic은 serial console, pstore, kdump·crash와 vmcore를 이용해 보존한다. Exact vmlinux와 module symbol을 확보하고 first oops, taint, CPU·PID, call trace와 fault address를 기준으로 분석한다. 후속 panic message는 첫 corruption의 결과일 수 있다.

2. 영어 원문 전체

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

원문 전체 펼치기

1 .. SPDX-License-Identifier: GPL-2.0

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

4 Userspace debugging advice

5 ==========================

7 This document provides a brief overview of common tools to debug the Linux

8 Kernel from userspace.

9 For debugging advice aimed at driver developers go :doc:`here

10 </process/debugging/driver_development_debugging_guide>`.

11 For general debugging advice, see :doc:`general advice document

12 </process/debugging/index>`.

14 .. contents::

15 :depth: 3

17 The following sections show you the available tools.

19 Dynamic debug

20 -------------

22 Mechanism to filter what ends up in the kernel log by dis-/en-abling log

23 messages.

25 Prerequisite: ``CONFIG_DYNAMIC_DEBUG``

27 Dynamic debug is only able to target:

29 - pr_debug()

30 - dev_dbg()

31 - print_hex_dump_debug()

32 - print_hex_dump_bytes()

34 Therefore the usability of this tool is, as of now, quite limited as there is

35 no uniform rule for adding debug prints to the codebase, resulting in a variety

36 of ways these prints are implemented.

38 Also, note that most debug statements are implemented as a variation of

39 dprintk(), which have to be activated via a parameter in respective module,

40 dynamic debug is unable to do that step for you.

42 Here is one example, that enables all available pr_debug()'s within the file::

44 $ alias ddcmd='echo $* > /proc/dynamic_debug/control'

45 $ ddcmd '-p; file v4l2-h264.c +p'

46 $ grep =p /proc/dynamic_debug/control

47 drivers/media/v4l2-core/v4l2-h264.c:372 [v4l2_h264]print_ref_list_b =p

48 "ref_pic_list_b%u (cur_poc %u%c) %s"

49 drivers/media/v4l2-core/v4l2-h264.c:333 [v4l2_h264]print_ref_list_p =p

50 "ref_pic_list_p (cur_poc %u%c) %s\n"

52 **When should you use this over Ftrace ?**

54 - When the code contains one of the valid print statements (see above) or when

55 you have added multiple pr_debug() statements during development

56 - When timing is not an issue, meaning if multiple pr_debug() statements in

57 the code won't cause delays

58 - When you care more about receiving specific log messages than tracing the

59 pattern of how a function is called

61 For the full documentation see :doc:`/admin-guide/dynamic-debug-howto`

63 Ftrace

64 ------

66 Prerequisite: ``CONFIG_DYNAMIC_FTRACE``

68 This tool uses the tracefs file system for the control files and output files.

69 That file system will be mounted as a ``tracing`` directory, which can be found

70 in either ``/sys/kernel/`` or ``/sys/debug/kernel/``.

72 Some of the most important operations for debugging are:

74 - You can perform a function trace by adding a function name to the

75 ``set_ftrace_filter`` file (which accepts any function name found within the

76 ``available_filter_functions`` file) or you can specifically disable certain

77 functions by adding their names to the ``set_ftrace_notrace`` file (more info

78 at: :ref:`trace/ftrace:dynamic ftrace`).

79 - In order to find out where calls originate from you can activate the

80 ``func_stack_trace`` option under ``options/func_stack_trace``.

81 - Tracing the children of a function call and showing the return values are

82 possible by adding the desired function in the ``set_graph_function`` file

83 (requires config ``FUNCTION_GRAPH_RETVAL``); more info at

84 :ref:`trace/ftrace:dynamic ftrace with the function graph tracer`.

86 For the full Ftrace documentation see :doc:`/trace/ftrace`

88 Or you could also trace for specific events by :ref:`using event tracing

89 <trace/events:2. using event tracing>`, which can be defined as described here:

90 :ref:`Creating a custom Ftrace tracepoint

91 <process/debugging/driver_development_debugging_guide:ftrace>`.

93 For the full Ftrace event tracing documentation see :doc:`/trace/events`

95 .. _read_ftrace_log:

97 Reading the ftrace log

98 ~~~~~~~~~~~~~~~~~~~~~~

100 The ``trace`` file can be read just like any other file (``cat``, ``tail``,

101 ``head``, ``vim``, etc.), the size of the file is limited by the

102 ``buffer_size_kb`` (``echo 1000 > buffer_size_kb``). The

103 :ref:`trace/ftrace:trace_pipe` will behave similarly to the ``trace`` file, but

104 whenever you read from the file the content is consumed.

105

106 Kernelshark

107 ~~~~~~~~~~~

108

109 A GUI interface to visualize the traces as a graph and list view from the

110 output of the `trace-cmd

111 <https://git.kernel.org/pub/scm/utils/trace-cmd/trace-cmd.git/>`__ application.

112

113 For the full documentation see `<https://kernelshark.org/Documentation.html>`__

114

115 Perf & alternatives

116 -------------------

117

118 The tools mentioned above provide ways to inspect kernel code, results,

119 variable values, etc. Sometimes you have to find out first where to look and

120 for those cases, a box of performance tracking tools can help you to frame the

121 issue.

122

123 Why should you do a performance analysis?

124 ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~

125

126 A performance analysis is a good first step when among other reasons:

127

128 - you cannot define the issue

129 - you do not know where it occurs

130 - the running system should not be interrupted or it is a remote system, where

131 you cannot install a new module/kernel

132

133 How to do a simple analysis with linux tools?

134 ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~

135

136 For the start of a performance analysis, you can start with the usual tools

137 like:

138

139 - ``top`` / ``htop`` / ``atop`` (*get an overview of the system load, see

140 spikes on specific processes*)

141 - ``mpstat -P ALL`` (*look at the load distribution among CPUs*)

142 - ``iostat -x`` (*observe input and output devices utilization and performance*)

143 - ``vmstat`` (*overview of memory usage on the system*)

144 - ``pidstat`` (*similar to* ``vmstat`` *but per process, to dial it down to the

145 target*)

146 - ``strace -tp $PID`` (*once you know the process, you can figure out how it

147 communicates with the Kernel*)

148

149 These should help to narrow down the areas to look at sufficiently.

150

151 Diving deeper with perf

152 ~~~~~~~~~~~~~~~~~~~~~~~

153

154 The **perf** tool provides a series of metrics and events to further dial down

155 on issues.

156

157 Prerequisite: build or install perf on your system

158

159 Gather statistics data for finding all files starting with ``gcc`` in ``/usr``::

160

161 # perf stat -d find /usr -name 'gcc*' | wc -l

162

163 Performance counter stats for 'find /usr -name gcc*':

164

165 1277.81 msec task-clock # 0.997 CPUs utilized

166 9 context-switches # 7.043 /sec

167 1 cpu-migrations # 0.783 /sec

168 704 page-faults # 550.943 /sec

169 766548897 cycles # 0.600 GHz (97.15%)

170 798285467 instructions # 1.04 insn per cycle (97.15%)

171 57582731 branches # 45.064 M/sec (2.85%)

172 3842573 branch-misses # 6.67% of all branches (97.15%)

173 281616097 L1-dcache-loads # 220.390 M/sec (97.15%)

174 4220975 L1-dcache-load-misses # 1.50% of all L1-dcache accesses (97.15%)

175 <not supported> LLC-loads

176 <not supported> LLC-load-misses

177

178 1.281746009 seconds time elapsed

179

180 0.508796000 seconds user

181 0.773209000 seconds sys

182

183

184 52

185

186 The availability of events and metrics depends on the system you are running.

187

188 For the full documentation see

189 `<https://perf.wiki.kernel.org/index.php/Main_Page>`__

190

191 Perfetto

192 ~~~~~~~~

193

194 A set of tools to measure and analyze how well applications and systems perform.

195 You can use it to:

196

197 * identify bottlenecks

198 * optimize code

199 * make software run faster and more efficiently.

200

201 **What is the difference between perfetto and perf?**

202

203 * perf is tool as part of and specialized for the Linux Kernel and has CLI user

204 interface.

205 * perfetto cross-platform performance analysis stack, has extended

206 functionality into userspace and provides a WEB user interface.

207

208 For the full documentation see `<https://perfetto.dev/docs/>`__

209

210 Kernel panic analysis tools

211 ---------------------------

212

213 To capture the crash dump please use ``Kdump`` & ``Kexec``. Below you can find

214 some advice for analysing the data.

215

216 For the full documentation see the :doc:`/admin-guide/kdump/kdump`

217

218 In order to find the corresponding line in the code you can use `faddr2line

219 <https://elixir.bootlin.com/linux/v6.11.6/source/scripts/faddr2line>`__; note

220 that you need to enable ``CONFIG_DEBUG_INFO`` for that to work.

221

222 An alternative to using ``faddr2line`` is the use of ``objdump`` (and its

223 derivatives for the different platforms like ``aarch64-linux-gnu-objdump``).

224 Take this line as an example:

225

226 ``[ +0.000240] rkvdec_device_run+0x50/0x138 [rockchip_vdec]``.

227

228 We can find the corresponding line of code by executing::

229

230 aarch64-linux-gnu-objdump -dS drivers/staging/media/rkvdec/rockchip-vdec.ko | grep rkvdec_device_run\>: -A 40

231 0000000000000ac8 <rkvdec_device_run>:

232 ac8: d503201f nop

233 acc: d503201f nop

234 {

235 ad0: d503233f paciasp

236 ad4: a9bd7bfd stp x29, x30, [sp, #-48]!

237 ad8: 910003fd mov x29, sp

238 adc: a90153f3 stp x19, x20, [sp, #16]

239 ae0: a9025bf5 stp x21, x22, [sp, #32]

240 const struct rkvdec_coded_fmt_desc *desc = ctx->coded_fmt_desc;

241 ae4: f9411814 ldr x20, [x0, #560]

242 struct rkvdec_dev *rkvdec = ctx->dev;

243 ae8: f9418015 ldr x21, [x0, #768]

244 if (WARN_ON(!desc))

245 aec: b4000654 cbz x20, bb4 <rkvdec_device_run+0xec>

246 ret = pm_runtime_resume_and_get(rkvdec->dev);

247 af0: f943d2b6 ldr x22, [x21, #1952]

248 ret = __pm_runtime_resume(dev, RPM_GET_PUT);

249 af4: aa0003f3 mov x19, x0

250 af8: 52800081 mov w1, #0x4 // #4

251 afc: aa1603e0 mov x0, x22

252 b00: 94000000 bl 0 <__pm_runtime_resume>

253 if (ret < 0) {

254 b04: 37f80340 tbnz w0, #31, b6c <rkvdec_device_run+0xa4>

255 dev_warn(rkvdec->dev, "Not good\n");

256 b08: f943d2a0 ldr x0, [x21, #1952]

257 b0c: 90000001 adrp x1, 0 <rkvdec_try_ctrl-0x8>

258 b10: 91000021 add x1, x1, #0x0

259 b14: 94000000 bl 0 <_dev_warn>

260 *bad = 1;

261 b18: d2800001 mov x1, #0x0 // #0

262 ...

263

264 Meaning, in this line from the crash dump::

265

266 [ +0.000240] rkvdec_device_run+0x50/0x138 [rockchip_vdec]

267

268 I can take the ``0x50`` as offset, which I have to add to the base address

269 of the corresponding function, which I find in this line::

270

271 0000000000000ac8 <rkvdec_device_run>:

272

273 The result of ``0xac8 + 0x50 = 0xb18``

274 And when I search for that address within the function I get the

275 following line::

276

277 *bad = 1;

278 b18: d2800001 mov x1, #0x0

279

281

3. 한국어 전문 번역

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

Userspace에서 kernel을 조사하는 도구

1-17

이 문서는 userspace에서 Linux kernel을 debugging할 때 흔히 사용하는 도구를 간략히 소개한다. Driver 개발자를 위한 조언은 Documentation/process/debugging/driver_development_debugging_guide.rst에 있고, 일반적인 debugging 조언은 Documentation/process/debugging/index.rst에 있다.

Dynamic debug

19-61

Dynamic debug는 log message를 enable 또는 disable하여 kernel log에 들어갈 내용을 거르는 mechanism이다. CONFIG_DYNAMIC_DEBUG가 필요하다.

pr_debug()
dev_dbg()
print_hex_dump_debug()
print_hex_dump_bytes()

현재 dynamic debug가 대상으로 삼을 수 있는 것은 위 네 종류뿐이다. Codebase에 debug print를 추가하는 통일된 규칙이 없어 서로 다른 방법으로 구현되어 있으므로 사용 범위가 제한된다. 많은 debug statement는 dprintk()의 변형이며 각 module parameter로 따로 활성화해야 한다. Dynamic debug가 그 단계까지 대신해 주지는 않는다.

다음 예는 v4l2-h264.c 안에서 사용할 수 있는 모든 pr_debug()를 enable한다.

$ alias ddcmd='echo $* > /proc/dynamic_debug/control'
$ ddcmd '-p; file v4l2-h264.c +p'
$ grep =p /proc/dynamic_debug/control
 drivers/media/v4l2-core/v4l2-h264.c:372 [v4l2_h264]print_ref_list_b =p
 "ref_pic_list_b%u (cur_poc %u%c) %s"
 drivers/media/v4l2-core/v4l2-h264.c:333 [v4l2_h264]print_ref_list_p =p
 "ref_pic_list_p (cur_poc %u%c) %s\n"

Ftrace보다 dynamic debug가 적합한 경우는 다음과 같다.

대상 code에 지원되는 print statement가 이미 있거나 개발 중 여러 pr_debug()를 추가한 경우
여러 pr_debug() 실행으로 생기는 지연이 문제가 되지 않는 경우
function 호출 pattern보다 특정 log message를 얻는 것이 더 중요한 경우

전체 설명은 Documentation/admin-guide/dynamic-debug-howto.rst를 참조한다.

Ftrace

63-104

Ftrace에는 CONFIG_DYNAMIC_FTRACE가 필요하다. Control file과 output file에는 tracefs를 사용하며 이 filesystem은 /sys/kernel/ 또는 /sys/debug/kernel/ 아래의 tracing directory로 mount된다.

set_ftrace_filter에 function 이름을 기록하면 function trace를 수행한다. available_filter_functions에 있는 이름을 사용할 수 있다. 반대로 set_ftrace_notrace에 이름을 기록하면 특정 function을 trace에서 제외한다.
호출이 어디에서 시작되었는지 확인하려면 options/func_stack_trace 아래의 func_stack_trace option을 활성화한다.
호출한 function의 child를 추적하고 return value를 표시하려면 set_graph_function에 원하는 function을 기록한다. FUNCTION_GRAPH_RETVAL 설정이 필요하다.

특정 event를 event tracing으로 추적할 수도 있고 custom Ftrace tracepoint를 정의할 수도 있다. 전체 function tracing 문서는 Documentation/trace/ftrace.rst에, event tracing 문서는 Documentation/trace/events.rst에 있다.

ftrace log 읽기

trace file은 cat, tail, head, vim 등으로 일반 file처럼 읽는다. 크기는 buffer_size_kb로 제한하며 예를 들어 echo 1000 > buffer_size_kb로 설정한다. trace_pipe도 trace와 비슷하지만 읽을 때마다 읽은 content가 소비된다는 차이가 있다.

KernelShark

106-113

KernelShark는 trace-cmd application의 output을 graph와 list view로 시각화하는 GUI다.

Performance 분석으로 조사 범위 좁히기

115-149

앞의 도구는 kernel code, 실행 결과, variable 값 등을 직접 조사한다. 그러나 먼저 어디를 봐야 할지 찾아야 하는 경우에는 performance 추적 도구 모음으로 문제 범위를 정할 수 있다.

문제를 명확히 정의할 수 없거나 발생 위치를 모르거나, 실행 중인 system을 중단하면 안 되거나, 새 module 또는 kernel을 설치할 수 없는 remote system이라면 performance 분석이 좋은 첫 단계다.

도구	확인 대상
top / htop / atop	system load 전체와 특정 process의 spike
mpstat -P ALL	CPU 사이의 load 분포
iostat -x	I/O device 활용률과 성능
vmstat	system memory 사용량 개요
pidstat	vmstat와 비슷한 정보를 process별로 확인하여 대상을 좁힘
strace -tp $PID	대상 process가 kernel과 어떻게 통신하는지 확인

이 도구들로 조사할 영역을 충분히 좁힐 수 있다.

perf로 더 깊게 분석하기

151-189

perf는 문제 범위를 더 좁히는 여러 metric과 event를 제공한다. System에 perf를 build하거나 설치해야 한다. 다음 예는 /usr에서 gcc로 시작하는 모든 file을 찾는 작업의 통계를 수집한다.

# perf stat -d find /usr -name 'gcc*' | wc -l

 Performance counter stats for 'find /usr -name gcc*':

   1277.81 msec    task-clock             #    0.997 CPUs utilized
   9               context-switches       #    7.043 /sec
   1               cpu-migrations         #    0.783 /sec
   704             page-faults            #  550.943 /sec
   766548897       cycles                 #    0.600 GHz                         (97.15%)
   798285467       instructions           #    1.04  insn per cycle              (97.15%)
   57582731        branches               #   45.064 M/sec                       (2.85%)
   3842573         branch-misses          #    6.67% of all branches             (97.15%)
   281616097       L1-dcache-loads        #  220.390 M/sec                       (97.15%)
   4220975         L1-dcache-load-misses  #    1.50% of all L1-dcache accesses   (97.15%)
   <not supported> LLC-loads
   <not supported> LLC-load-misses

 1.281746009 seconds time elapsed

 0.508796000 seconds user
 0.773209000 seconds sys

52

사용할 수 있는 event와 metric은 실행 중인 system에 따라 달라진다.

perf wikihttps://perf.wiki.kernel.org/index.php/Main_Page

Perfetto와 perf의 차이

191-208

Perfetto는 application과 system이 얼마나 잘 동작하는지 측정하고 분석하는 도구 모음이다. Bottleneck을 식별하고 code를 최적화하며 software를 더 빠르고 효율적으로 동작하게 할 수 있다.

perf는 Linux kernel의 일부이며 Linux kernel에 특화된 CLI tool이다. Perfetto는 cross-platform performance analysis stack으로 userspace까지 확장된 기능과 web user interface를 제공한다.

Perfetto documentationhttps://perfetto.dev/docs/

Kernel panic 분석과 symbol offset 계산

210-280

Crash dump를 수집하려면 Kdump와 Kexec를 사용한다. 전체 설명은 Documentation/admin-guide/kdump/kdump.rst에 있다. Dump의 주소에 대응하는 source line은 scripts/faddr2line로 찾을 수 있으며 CONFIG_DEBUG_INFO를 enable해야 한다.

faddr2line 대신 objdump 또는 aarch64-linux-gnu-objdump 같은 architecture별 변형을 사용할 수도 있다. 다음 crash line을 예로 든다.

[  +0.000240]  rkvdec_device_run+0x50/0x138 [rockchip_vdec]

다음 command로 module을 source와 함께 disassemble하고 rkvdec_device_run의 시작부터 40줄을 찾는다.

aarch64-linux-gnu-objdump -dS drivers/staging/media/rkvdec/rockchip-vdec.ko | grep rkvdec_device_run\>: -A 40
0000000000000ac8 <rkvdec_device_run>:
 ac8:	d503201f 	nop
 acc:	d503201f 	nop
{
 ad0:	d503233f 	paciasp
 ad4:	a9bd7bfd 	stp	x29, x30, [sp, #-48]!
 ad8:	910003fd 	mov	x29, sp
 adc:	a90153f3 	stp	x19, x20, [sp, #16]
 ae0:	a9025bf5 	stp	x21, x22, [sp, #32]
    const struct rkvdec_coded_fmt_desc *desc = ctx->coded_fmt_desc;
 ae4:	f9411814 	ldr	x20, [x0, #560]
    struct rkvdec_dev *rkvdec = ctx->dev;
 ae8:	f9418015 	ldr	x21, [x0, #768]
    if (WARN_ON(!desc))
 aec:	b4000654 	cbz	x20, bb4 <rkvdec_device_run+0xec>
    ret = pm_runtime_resume_and_get(rkvdec->dev);
 af0:	f943d2b6 	ldr	x22, [x21, #1952]
    ret = __pm_runtime_resume(dev, RPM_GET_PUT);
 af4:	aa0003f3 	mov	x19, x0
 af8:	52800081 	mov	w1, #0x4                    // #4
 afc:	aa1603e0 	mov	x0, x22
 b00:	94000000 	bl	0 <__pm_runtime_resume>
    if (ret < 0) {
 b04:	37f80340 	tbnz	w0, #31, b6c <rkvdec_device_run+0xa4>
    dev_warn(rkvdec->dev, "Not good\n");
 b08:	f943d2a0 	ldr	x0, [x21, #1952]
 b0c:	90000001 	adrp	x1, 0 <rkvdec_try_ctrl-0x8>
 b10:	91000021 	add	x1, x1, #0x0
 b14:	94000000 	bl	0 <_dev_warn>
    *bad = 1;
 b18:	d2800001 	mov	x1, #0x0                    // #0
...

Crash dump의 rkvdec_device_run+0x50에서 0x50은 function 시작점에 더할 offset이다. Disassembly에서 function base는 0xac8이므로 0xac8 + 0x50 = 0xb18이다. Function 안에서 0xb18을 찾으면 다음 source line과 instruction이 나온다.

*bad = 1;
b18:      d2800001        mov     x1, #0x0