디버깅과 코드 학습 능력
디버깅하면서 리눅스 커널 코드를 함께 분석하면 다음과 같은 정보를 더 얻을 수 있습니다.
분석 대상 코드가 동작하는 콜스택
함수가 실행될 때 변경되는 자료구조
함수가 실행되는 빈도와 실행 시각
분석 대상 코드를 실행하는 프로세스
대부분 리눅스 커널을 공부할 때는 커널 소스코드를 열어 봅니다. 코드를 이해하는 능력은 리눅스 개발자의 기본 소양이므로 소스를 이해하는 능력은 중요합니다. 하지만 소스코드를 분석하면 실행 흐름을 보는 시야가 좁아집니다. 그래서 코드 분석과 함께 함수 실행 흐름과 실행 빈도를 알 필요가 있습니다.
커널 소스코드만 분석한 분이 있다고 가정해 봅시다. 또 다른 분은 커널 디버깅과 함께 커널 코드를 함께 분석했습니다. 둘 중에서 누가 더 빨리 커널을 익힐 수 있을까요? 필자는 디버깅과 함께 커널 소스를 분석하면 소스만 분석할 때보다 5배 정도의 학습 효과가 있다고 생각합니다. 디버깅을 하면 5배 정도 많은 정보를 얻기 때문입니다. 그만큼 커널 디버깅이 중요합니다.
그런데 여러분은 필자의 의견을 읽고 조금 수긍이 가지만 조금은 막연한 느낌이 들 수 있습니다. 그렇다면 어떻게 커널 디버깅을 어떻게 해야 할까요? 사실, 필자는 '이 책에서 소개한 실습 과정을 확인해보세요.'라고 말씀드리고 싶습니다. 한 가지 쉬운 예시를 들면서 커널 디버깅 과정을 설명하겠습니다.
5장 '인터럽트'에서 다룬 내용을 읽으면서 커널이 인터럽트를 처리하는 과정을 배우고 있다고 가정하겠습니다. 여기서 한 가지 흥미로운 사실을 알게 됐습니다. 바로 "cat /proc/interrupts" 명령어를 입력하면 인터럽트 세부 속성을 알 수 있다는 것입니다.
그래서 라즈베리 파이에서 터미널에서 다음과 같은 명령어를 입력해서 인터럽트 속성을 알게 됐습니다.
root@raspberrypi:/home/pi# cat /proc/interrupts
CPU0 CPU1 CPU2 CPU3
17: 6624 0 0 0 ARMCTRL-level 1 Edge 3f00b880.mailbox
18: 34 0 0 0 ARMCTRL-level 2 Edge VCHIQ doorbell
...
IPI5: 8411 8223 5705 8429 IRQ work interrupts
IPI6: 0 0 0 0 completion interrupts
Err: 0
그런데 리눅스 터미널에서 인터럽트 속성 정보를 보고 나니 커널의 어느 코드에서 이를 출력하는지 궁금해졌습니다. 어렵게 코드를 검색하다 보니 show_interrupts() 함수가 이 정보를 터미널로 출력한다는 사실을 알게 됐습니다.
또한 분석을 하고 나니 다음과 같은 내용이 궁금해지기 시작했습니다.
인터럽트 디스크립터인 irq_desc 구조체의 action 필드에 저장된 인터럽트 속성 정보를 점검하고 싶다.
'cat /proc/interrupts' 명령어를 입력하면 show_interrupts() 함수가 호출되는지 확인하고 싶다.
show_interrupts() 함수를 호출할 때 프로세스 정보를 보고 싶다.
여기서 중요한 질문을 하나 하겠습니다. 이 정보를 파악하려면 어떻게 해야 할까요?
이를 위해서는 커널 코드를 수정할 필요가 있습니다. 2장에서 라즈비안 커널 소스를 빌드하는 방법을 알았으니 커널 코드를 수정해볼까요? 패치 코드의 내용을 먼저 소개합니다.
01 diff --git a/kernel/irq/proc.c b/kernel/irq/proc.c
02 --- a/kernel/irq/proc.c
03 +++ b/kernel/irq/proc.c
@@ -449,6 +449,21 @@ int __weak arch_show_interrupts(struct seq_file *p, int prec)
04 # define ACTUAL_NR_IRQS nr_irqs
05 #endif
06
07 +void rpi_get_interrupt_info(struct irqaction *action_p)
08 +{
09 + unsigned int irq_num = action_p->irq;
10 + void *irq_handler = NULL;
11 +
12 + if (action_p->handler) {
13 + irq_handler = (void*)action_p->handler;
14 + }
15 +
16 + if (irq_handler) {
17 + trace_printk("[%s] %d: %s, irq_handler: %pS \n",
18 + current->comm, irq_num, action_p->name, irq_handler);
19 + }
20 +}
21 +
22 int show_interrupts(struct seq_file *p, void *v)
23 {
24 static int prec;
@@ -514,6 +529,10 @@ int show_interrupts(struct seq_file *p, void *v)
25 seq_printf(p, "-%-8s", desc->name);
26
27 action = desc->action;
28 +
29 + if (action)
30 + rpi_get_interrupt_info(action);
31 +
32 if (action) {
33 seq_printf(p, " %s", action->name);
34 while ((action = action->next) != NULL)
먼저 패치 코드를 입력하는 방법을 설명하겠습니다.
다음 코드를 보면 커널의 원본 show_interrupts() 함수와 패치 코드를 입력할 위치를 알 수 있습니다.
int show_interrupts(struct seq_file *p, void *v)
{
static int prec;
unsigned long flags, any_count = 0;
...
if (desc->name)
seq_printf(p, "-%-8s", desc->name);
action = desc->action;
/* 이 부분에 1번째 패치 코드를 입력하세요 */
if (action) {
seq_printf(p, " %s", action->name);
while ((action = action->next) != NULL)
seq_printf(p, ", %s", action->name);
}
seq_putc(p, '\n');
“/* 이 부분에 1번째 패치 코드를 입력하세요 */”라는 주석으로 표시된 부분에 다음 코드를 입력합니다.
29 + if (action)
30 + rpi_get_interrupt_info(action);
irqaction 구조체 타입인 action 포인터형 변수가 NULL이 아닐 때 action 인자와 함께 rpi_get_interrupt_info() 함수를 호출하는 코드입니다.
이어서 show_interrupts() 함수의 윗부분에 다음 rpi_get_interrupt_info() 함수의 코드를 작성합니다.
07 +void rpi_get_interrupt_info(struct irqaction *action_p)
08 +{
09 + unsigned int irq_num = action_p->irq;
10 + void *irq_handler = NULL;
11 +
12 + if (action_p->handler) {
13 + irq_handler = (void*)action_p->handler;
14 + }
15 +
16 + if (irq_handler) {
17 + trace_printk("[%s] %d: %s, irq_handler: %pS \n",
18 + current->comm, irq_num, action_p->name, irq_handler);
19 + }
20 +}
rpi_get_interrupt_info() 함수는 ftrace로 다음 정보를 출력하는 기능입니다.
프로세스 이름
인터럽트 번호
인터럽트 이름
인터럽트 핸들러 함수 이름
여기서 한 가지 의문이 생깁니다. 위와 같은 패치 코드를 입력한 이유가 무엇일까요? 필자는 여러분이 인터럽트에 대해 공부하는 중이라고 가정했습니다.
인터럽트 속성 정보를 담고 있는 자료구조는 인터럽트 디스크립터를 나타내는 irq_desc 구조체입니다.
https://github.com/raspberrypi/linux/blob/rpi-4.19.y/include/linux/irqdesc.h
01 struct irq_desc {
02 struct irq_common_data irq_common_data;
03 struct irq_data irq_data;
04 unsigned int __percpu *kstat_irqs;
...
05 struct irqaction *action; /* IRQ action list */
그런데 코드를 읽다 보니 인터럽트 속성 정보는 위 05번째 줄과 같이 action 필드에 저장된다는 사실을 알게 됐습니다.
이어서 irqaction 구조체 내 필드를 보면서 인터럽트 속성 정보를 확인해봅시다.
https://github.com/raspberrypi/linux/blob/rpi-4.19.y/include/linux/interrupt.h
01 struct irqaction {
02 irq_handler_t handler; /* 인터럽트 핸들러 함수 */
03 void *dev_id;
...
04 unsigned int irq; /* 인터럽트 번호 */
05 unsigned int flags;
06 unsigned long thread_flags;
07 unsigned long thread_mask;
08 const char *name; /* 문자열 타입의 인터럽트 이름 */
09 struct proc_dir_entry *dir;
10 } ____cacheline_internodealigned_in_smp;
irqaction 구조체 오른쪽 부분에 표시된 주석이 인터럽트 속성 정보입니다. 이 정보를 라즈비안에서 확인하려고 패치 코드를 입력한 것입니다.
이제 코드를 입력하고 라즈비안 커널 빌드를 시작합시다. 커널 빌드가 끝난 후 커널 이미지를 라즈베리 파이에 설치합니다.
ftrace를 설정하기 위해 일일이 명령어를 입력할 수 있습니다만ftrace를 설정할 때마다 비슷한 패턴의 명령어를 입력하면 불편합니다. 다음에 소개할 내용은 ftrace를 설정하는 명령어로 작성한 셸 스크립트 코드입니다.
01 #!/bin/bash
02
03 echo 0 > /sys/kernel/debug/tracing/tracing_on
04 sleep 1
05 echo "tracing_off"
06
07 echo 0 > /sys/kernel/debug/tracing/events/enable
08 sleep 1
09 echo "events disabled"
10
11 echo secondary_start_kernel > /sys/kernel/debug/tracing/set_ftrace_filter
12 sleep 1
13 echo "set_ftrace_filter init"
14
15 echo function > /sys/kernel/debug/tracing/current_tracer
16 sleep 1
17 echo "function tracer enabled"
18
19 echo rpi_get_interrupt_info > /sys/kernel/debug/tracing/set_ftrace_filter
20 sleep 1
21 echo "set_ftrace_filter enabled"
22
23 echo 1 > /sys/kernel/debug/tracing/events/irq/irq_handler_entry/enable
24 echo 1 > /sys/kernel/debug/tracing/events/irq/irq_handler_exit/enable
25 echo "event enabled"
26
27 echo 1 > /sys/kernel/debug/tracing/options/func_stack_trace
28 echo "function stack trace enabled"
29
30 echo 1 > /sys/kernel/debug/tracing/options/func_stack_trace
31 echo 1 > /sys/kernel/debug/tracing/options/sym-offset
32 echo "function stack trace enabled"
33
34 echo 1 > /sys/kernel/debug/tracing/tracing_on
35 echo "tracing_on"
위 코드를 입력한 다음 irq_trace_ftrace.sh 파일로 저장해 실행하면 손쉽게 ftrace를 세팅할 수 있습니다.
위에서 소개한 ftrace 설정 명령어 중 가장 중요한 내용은 다음과 같습니다.
19 echo rpi_get_interrupt_info > /sys/kernel/debug/tracing/set_ftrace_filter
패치 코드에서 작성한 rpi_get_interrupt_info()라는 함수명을 /sys/kernel/debug/tracing/set_ftrace_filter 파일에 지정하는 명령어입니다.
이 같은 방식으로 함수 이름을 설정하면 rpi_get_interrupt_info() 함수를 누가 호출했는지 알 수 있습니다.
이번에는 다음 명령어를 입력해 irq_trace_ftrace.sh 셸 스크립트를 실행합니다.
root@raspberrypi:/home/pi# ./irq_trace_ftrace.sh
tracing_off
events disabled
set_ftrace_filter init
function tracer enabled
event enabled
set_ftrace_filter enabled
function stack trace enabled
tracing_on
이번에는 'cat /proc/interrupts' 명령어를 입력합니다.
root@raspberrypi:/home/pi# cat /proc/interrupts
CPU0 CPU1 CPU2 CPU3
17: 282 0 0 0 ARMCTRL-level 1 Edge 3f00b880.mailbox
18: 34 0 0 0 ARMCTRL-level 2 Edge VCHIQ doorbell
40: 36 0 0 0 ARMCTRL-level 48 Edge bcm2708_fb dma
42: 0 0 0 0 ARMCTRL-level 50 Edge DMA IRQ
...
IPI5: 806 522 230 775 IRQ work interrupts
IPI6: 0 0 0 0 completion interrupts
Err: 0
여기서 한 가지 의문이 생깁니다. 'cat /proc/interrupts' 명령어를 입력하는 이유는 무엇일까요? 이 질문에는 다음과 같이 답할 수 있습니다.
rpi_get_interrupt_info() 함수가 호출되도록 커널을 동작시킨다.
이미 우리는 'cat /proc/interrupts'를 입력하면 show_interrupts() 함수가 호출된다고 분석한 바 있습니다. 그런데 이번에 소개한 패치 코드는 show_interrupts() 함수 내에서 rpi_get_interrupt_info() 함수를 호출합니다. 따라서 rpi_get_interrupt_info() 함수가 호출되도록 'cat /proc/interrupts' 명령어를 입력하는 것입니다.
이어서 다음 명령어를 입력해 get_ftrace.sh 셸 스크립트를 실행합니다.
root@raspberrypi:/home/pi# ./get_ftrace.sh
ftrace off
이 셸 스크립트를 실행하면 ftrace 로그를 현재 디렉터리에 복사합니다.
이번에는 분석할 ftrace 로그를 소개합니다.
01 cat-884 [002] d... 333.875303: rpi_get_interrupt_info+0x14/0x6c <-show_interrupts+0x2dc/0x3e0
02 cat-884 [002] d... 333.875350: <stack trace>
03 => rpi_get_interrupt_info+0x18/0x6c
04 => show_interrupts+0x2dc/0x3e0
05 => seq_read+0x3d0/0x4b4
06 => proc_reg_read+0x70/0x98
07 => __vfs_read+0x48/0x168
08 => vfs_read+0x9c/0x164
09 => ksys_read+0x5c/0xbc
10 => sys_read+0x18/0x1c
11 => ret_fast_syscall+0x0/0x28
위와 같은 콜스택을 해석하는 방법을 알아봅시다. 위 로그에 나타난 함수의 흐름은 11번째 줄에서 03번째 줄 방향으로 이어집니다. 따라서 맨 먼저 실행된 함수는 ret_fast_syscall() 함수이고, 그다음은 sys_read() 함수입니다.
각 메시지에서 다음과 같은 정보를 알 수 있습니다.
01번째 줄: 'cat-884' 메시지로서 pid가 884인 cat 프로세스가 rpi_get_interrupt_info() 함수를 호출한다.
05번째 줄: seq_read() 함수에서 show_interrupts() 함수를 호출했다.
10번째 줄: sys_read() 함수가 호출됐으니 유저 공간에서 read 시스템 콜을 실행했다.
이번에는 rpi_get_interrupt_info() 함수에서 출력하는 인터럽트 속성 정보를 파악해보겠습니다. 이를 위해 다음과 같은 명령어를 입력합니다.
root@raspberrypi:/home/pi/# egrep -nr irq_handler *
cat-884 [002] d... 333.875361: rpi_get_interrupt_info+0x28/0x6c: [cat] 17: 3f00b880.mailbox, irq_handler: bcm2835_mbox_irq+0x0/0x94
cat-884 [002] d... 333.875397: rpi_get_interrupt_info+0x28/0x6c: [cat] 18: VCHIQ doorbell, irq_handler: vchiq_doorbell_irq+0x0/0x48
cat-884 [002] d... 333.875451: rpi_get_interrupt_info+0x28/0x6c: [cat] 40: bcm2708_fb dma, irq_handler: bcm2708_fb_dma_irq+0x0/0x44
cat-884 [002] d... 333.875487: rpi_get_interrupt_info+0x28/0x6c: [cat] 42: DMA IRQ, irq_handler: bcm2835_dma_callback+0x0/0x140
cat-884 [002] d... 333.875521: rpi_get_interrupt_info+0x28/0x6c: [cat] 44: DMA IRQ, irq_handler: bcm2835_dma_callback+0x0/0x140
cat-884 [002] d... 333.875555: rpi_get_interrupt_info+0x28/0x6c: [cat] 45: DMA IRQ, irq_handler: bcm2835_dma_callback+0x0/0x140
cat-884 [002] d... 333.875597: rpi_get_interrupt_info+0x28/0x6c: [cat] 56: dwc_otg, irq_handler: dwc_otg_common_irq+0x0/0x28
cat-884 [002] d... 333.875656: rpi_get_interrupt_info+0x28/0x6c: [cat] 80: mmc0, irq_handler: bcm2835_sdhost_irq+0x0/0x3e8
cat-884 [002] d... 333.875691: rpi_get_interrupt_info+0x28/0x6c: [cat] 81: uart-pl011, irq_handler: pl011_int+0x0/0x474
cat-884 [002] d... 333.875730: rpi_get_interrupt_info+0x28/0x6c: [cat] 86: mmc1, irq_handler: bcm2835_mmc_irq+0x0/0x754
cat-884 [002] d... 333.875815: rpi_get_interrupt_info+0x28/0x6c: [cat] 161: arch_timer, irq_handler: arch_timer_handler_phys+0x0/0x48
cat-884 [002] d... 333.875849: rpi_get_interrupt_info+0x28/0x6c: [cat] 162: arch_timer, irq_handler: arch_timer_handler_phys+0x0/0x48
cat-884 [002] d... 333.875887: rpi_get_interrupt_info+0x28/0x6c: [cat] 165: arm-pmu, irq_handler: armpmu_dispatch_irq+0x0/0x88
'egrep -nr irq_handler *' 명령어는 현재 디렉터리에 있는 파일에서 “irq_handler”라는 문자열을 검색한 결과를 출력합니다. 출력 결과의 각 라인에는 다음과 같은 정보가 출력됩니다.
인터럽트 번호
인터럽트 이름
인터럽트 핸들러 이름
예를 들어, 다음 로그를 해석해볼까요?
cat-884 [002] d... 333.875730: rpi_get_interrupt_info+0x28/0x6c: [cat] 86: mmc1, irq_handler: bcm2835_mmc_irq+0x0/0x754
위 로그를 읽으면 다음과 같은 내용을 알 수 있습니다.
인터럽트 번호: 86
인터럽트 이름: mmc1
인터럽트 핸들러 이름: bcm2835_mmc_irq
그런데 여기서 궁금증이 생깁니다. 86번 인터럽트 핸들러인 bcm2835_mmc_irq() 함수는 언제 어떻게 호출될까요?
이번 절에서 소개한 irq_trace_ftrace.sh 셸 스크립트의 23번째 줄을 다음과 같이 바꿔볼까요?
23 echo bcm2835_mmc_irq > /sys/kernel/debug/tracing/set_ftrace_filter
이것은 bcm2835_mmc_irq() 함수의 콜스택을 ftrace에 설정하는 명령어입니다. 코드를 이와 같이 코드를 고친 후 irq_trace_ftrace.sh 셸 스크립트를 실행합니다.
root@raspberrypi:/home/pi# ./irq_trace_ftrace.sh
tracing_off
events disabled
set_ftrace_filter init
function tracer enabled
event enabled
set_ftrace_filter enabled
function stack trace enabled
tracing_on
3초 후 get_ftrace.sh 스크립트를 실행해 ftrace 로그를 받습니다.
root@raspberrypi:/home/pi# ./get_ftrace.sh
ftrace off
이번에는 ftrace에서 bcm2835_mmc_irq() 함수의 콜스택을 볼 수 있습니다.
<idle>-0 [000] d.h. 826.627311: irq_handler_entry: irq=86 name=mmc1
<idle>-0 [000] d.h. 826.627313: bcm2835_mmc_irq+0x14/0x754 <-__handle_irq_event_percpu+0xbc/0x224
<idle>-0 [000] d.h. 826.627350: <stack trace>
=> bcm2835_mmc_irq+0x18/0x754
=> __handle_irq_event_percpu+0xbc/0x224
=> handle_irq_event_percpu+0x3c/0x8c
=> handle_irq_event+0x54/0x78
=> handle_level_irq+0xc0/0x16c
=> generic_handle_irq+0x34/0x44
=> bcm2836_chained_handle_irq+0x38/0x50
=> generic_handle_irq+0x34/0x44
=> __handle_domain_irq+0x6c/0xc4
=> bcm2836_arm_irqchip_handle_irq+0x60/0xa8
=> __irq_svc+0x5c/0x7c
=> finish_task_switch+0xa8/0x230
=> finish_task_switch+0xa8/0x230
=> __schedule+0x328/0x9b0
=> schedule_idle+0x44/0x84
=> do_idle+0x120/0x17c
=> cpu_startup_entry+0x28/0x2c
=> rest_init+0xc0/0xc4
=> start_kernel+0x490/0x4b8
<idle>-0 [000] d.h. 826.627355: irq_handler_exit: irq=86 ret=handled
ftrace 로그에 보이는 함수에 대해 더 자세히 설명하고 싶지만 이번 절은 커널을 디버깅하는 방법을 소개하는 절이므로 이 정도로 마무리하겠습니다.
지금까지 커널 코드를 수정해 ftrace 로그를 분석하는 커널 디버깅 방법을 알아봤는데, show_interrupts() 함수를 눈으로만 읽어 분석할 때보다 어떤 내용을 더 알게 됐나요? 함수 호출 흐름과 해당 코드를 실행하는 프로세스 이름, 자료구조까지 알게 됐습니다.
이처럼 코드를 분석하는 것보다 리눅스 시스템에서 디버깅하면 더 유익한 정보를 알 수 있습니다. 이 내용을 익힌 다음, 나중에 참고할 수 있게 차곡차곡 정리해서 블로그에 올려보면 어떨까요? 친구들에게 자랑도 하고 세미나로 배운 내용을 공유해도 좋습니다. 이러한 자료와 경험이 쌓여서 커널 디버깅 및 프로그래밍 실력을 높일 수 있습니다.
리눅스 개발자뿐만 아니라 다른 분야에 몸담고 있는 소프트웨어 개발자를 만나면 주로 이야기하는 주제가 디버깅입니다. 그중에서 게임계의 레전드 개발자이자 엔지니어인 김포프 님께서 언급하신 '디버깅에 대한 생각'을 공유합니다 (괄호 안의 내용은 발언 시점).
프로그래머의 자질은 코딩을 해서 제품을 만들 수 있는 능력이다(1:15).
프로그래머가 갖춰야 할 가장 중요한 능력은 디버깅 스킬이다(2:45).
디버깅을 잘한다는 것은 남의 코드를 잘 읽고 그 코드 속의 로직을 따질 수 있고 그 로직을 단계별로 나눌 수 있는 것이다(3:22).
디버깅을 잘하면 남의 코드를 보는 것이 두렵지 않고 이 과정으로 배우는 것이 정말 많다(4:52).
디버깅을 잘하는 프로그래머를 보면 엄청나게 성장할 것이란 것을 안다(5:01).
정말 코딩을 잘하는 사람 중에 디버깅을 못하는 사람을 본 적이 없다. 디버깅을 잘하는 사람 중에 코딩을 못하는 사람을 본 적이 없다. 디버깅을 못하는 사람 중에 코딩을 잘하는 사람은 (거의) 본 적이 없다. 디버깅을 못하는 사람 중에 설계를 잘하는 사람은 (거의) 본 적이 없다(7:35).
소프트웨어 개발자로서 너무 공감이 되고 깊이 새겨야 할 명언인 것 같습니다.
이번 절에서는 디버깅의 중요성과 코드 학습에 대해 살펴봤습니다. 다음 절에서 커널 디버깅 툴을 활용하는 방법을 소개합니다.
최근 덧글