Arm Linux Kernel Hacks

rousalome.egloos.com

포토로그 Kernel Crash


통계 위젯 (화이트)

71261
1501
219113


[리눅스커널] 커널 디버깅과 코드 학습: 디버깅과 코드 학습 능력 3. 커널 디버깅과 코드 학습

디버깅과 코드 학습 능력

디버깅하면서 리눅스 커널 코드를 함께 분석하면 다음과 같은 정보를 더 얻을 수 있습니다. 

분석 대상 코드가 동작하는 콜스택
함수가 실행될 때 변경되는 자료구조
함수가 실행되는 빈도와 실행 시각
분석 대상 코드를 실행하는 프로세스

대부분 리눅스 커널을 공부할 때는 커널 소스코드를 열어 봅니다. 코드를 이해하는 능력은 리눅스 개발자의 기본 소양이므로 소스를 이해하는 능력은 중요합니다. 하지만 소스코드를 분석하면 실행 흐름을 보는 시야가 좁아집니다. 그래서 코드 분석과 함께 함수 실행 흐름과 실행 빈도를 알 필요가 있습니다.

커널 소스코드만 분석한 분이 있다고 가정해 봅시다. 또 다른 분은 커널 디버깅과 함께 커널 코드를 함께 분석했습니다. 둘 중에서 누가 더 빨리 커널을 익힐 수 있을까요? 필자는 디버깅과 함께 커널 소스를 분석하면 소스만 분석할 때보다 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 1 > /sys/kernel/debug/tracing/options/sym-offset
29 echo "function stack trace enabled"
30
31 echo 1 > /sys/kernel/debug/tracing/tracing_on
32 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).

소프트웨어 개발자로서 너무 공감이 되고 깊이 새겨야 할 명언인 것 같습니다.

이번 절에서는 디버깅의 중요성과 코드 학습에 대해 살펴봤습니다. 다음 절에서 커널 디버깅 툴을 활용하는 방법을 소개합니다.

"혹시 궁금한 점이 있으면 댓글로 질문 남겨주세요. 아는 한 성실히 답변 올려드리겠습니다!" 

Thanks,
Austin Kim(austindh.kim@gmail.com)

동영상 강의 




커널 디버깅과 코드 학습


# Reference: For more information on 'Linux Kernel';

디버깅을 통해 배우는 리눅스 커널의 구조와 원리. 1

디버깅을 통해 배우는 리눅스 커널의 구조와 원리. 2


 






핑백

덧글

  • sh 2020/07/10 01:57 # 삭제 답글

    안녕하세요. 집필하신 도서 아주 잘 읽고 있습니다. 그런데 위 내용 중 ftrace를 설정하는 명령어로 작성한 셸 스크립트 코드를 보면 28번 라인, 32번 라인이 같아서 실행 시 같은 문구가 출력돼야 하는데, 아래 실행 화면에는 다른 문구가 출력되네요. set_ftrace_filter enabled 의 순서도 달라지는 것으로 보입니다. 책으로 읽다가 발견해서 블로그로 와봤는데 아직 수정이 되지 않아 덧글 남깁니다. 혹시 셸 스크립트를 어떻게 수정되어야 하는지 올려주실 수 있나요?
  • AustinKim 2020/07/10 07:14 #

    먼저 책을 구입해주셔서 정말 감사합니다.
    책을 정말 꼼꼼이 읽으신 것 같은데요. (:

    지적하신대로, 27~28번째 줄은 중복되는 명령어니 삭제되는 것이 맞습니다.

    27 echo 1 > /sys/kernel/debug/tracing/options/func_stack_trace
    28 echo "function stack trace enabled"

    이 내용은 방금 위 블로그 포스팅에도 수정했고 2판이나 이북 출간 시 반영하도록 하겠습니다.

    책을 읽다가 궁금한 점이 있으면 언제든 댓글로 질문주세요.

    감사합니다.
  • 2020/07/10 07:12 # 답글 비공개

    비공개 덧글입니다.
  • ㅇㅇ 2020/09/10 11:06 # 삭제 답글

    커널 전체를 빌드 및 설치하려면 시간이 꽤 소요되는데, 저 proc.c 패치 내용만 부분 컴파일하여 적용하는 방법은 없나요? 수정 부분만 추가로 커널 이미지에 포함시켜 적용하려면 전체 make과정을 거쳐야만 하는지가 궁금합니다.
  • AustinKim 2020/09/10 20:13 #

    일단 한번은 커널을 전체 빌드해야 합니다.
    이후 proc.c 패치 내용만 수정하면 proc.c 파일만 컴파일돼 커널 이미지에 반영됩니다.
  • 조용한 에스키모 2020/10/20 15:34 # 답글

    커널빌드하고 설치한후 irq_trace_ftrace.sh를 실행하면 line 19: echo: write error: Invalid argument라는 에러가 뜹니다. 오타가 있었나 찾아보기도 하고 proc.c 함수명이 틀렸나하고 봐도 이상한게 없는데 뭐가 문제일지 알수 있을까요? 제가 쓴 스크립트 아래와 같이 올려봅니다.

    echo rpi_get_interrupt_info bcm2835_mmc_irq > /sys/kernel/debug/tracing/set_ftrace_filter

  • AustinKim 2020/10/20 17:22 #

    주신 질문에 답을 적다보니 내용이 길어져, 아예 새로운 글을 올렸습니다.
    아래 블로그 글을 참고하시고, 추가로 궁금한 점이 있으면 댓글로 문의주세요.

    [공유][문의] line 19: echo: write error: Invalid argument라는 에러가 뜹니다
    http://rousalome.egloos.com/10020085

    감사합니다.
  • 2020/10/20 17:23 # 답글 비공개

    비공개 덧글입니다.
  • HokiMin 2020/12/26 18:12 # 답글

    안녕하세요 어스틴님.
    실습 도중 질문이 있습니다.
    cat /proc/interrupts를 하였을 때 아래와 같은 ftrace 로그를 얻는데에는 성공하였습니다.

    cat-726 [002] d... 65.749611: rpi_get_interrupt_info+0x28/0x6c: [cat] 86: mmc1, irq_handler: bcm2835_mmc_irq+0x0/0x71c
    cat-726 [002] d... 65.749679: rpi_get_interrupt_info+0x14/0x6c <-show_interrupts+0x24c/0x370
    cat-726 [002] d... 65.749699: <stack trace>
    => rpi_get_interrupt_info+0x18/0x6c
    => show_interrupts+0x24c/0x370
    => seq_read+0x30c/0x484
    => proc_reg_read+0x70/0x9c
    => __vfs_read+0x38/0x14c
    => vfs_read+0x98/0x168
    => ksys_read+0x5c/0xd0
    => sys_read+0x18/0x1c
    => ret_fast_syscall+0x0/0x28
    => 0x7ed783f0

    그러나 bcm2835_mmc_irq을 호출하는 콜 스텍은 볼 수가 없었습니다.
    제 생각에는, rpi_get_interrupt_info에서
    irq_handler = (void*)action_p->handler; 를 통해
    각 interrupt 핸들러의 자료구조에 접근을 하여 정보를 출력해주지만
    실제로 인터럽트 핸들러를 호출하는 것은 아니기 때문에
    bcm2835_mmc_irq를 호출하는 콜 스텍을 볼 수 없었다고 생각합니다.

    어떻게하면 bcm2835_mmc_irq 인터럽트 핸들러를 호출시켜서 콜스텍을 볼 수 있을까요?
    (어떤 경우에 bcm2835_mmc_irq 인터럽트 핸들러가 불리는지 몰라서 해매고 있습니다.)


  • AustinKim 2020/12/26 19:05 #

    연휴에도 열심히 리눅스를 공부하시는 것 같습니다.

    ftrace를 설정하실 때, bcm2835_mmc_irq() 함수를 다음과 같이 지정하셨는지 궁금합니다.
    echo rpi_get_interrupt_info bcm2835_mmc_irq > /sys/kernel/debug/tracing/set_ftrace_filter

    위와 같은 코드를 추가하신 후 irq_trace_ftrace.sh 셸 스크립트를 실행해 ftrace를 설정하시고요.
    한 10초 정도 기다린 다음에 ftrace 로그를 추출하시면, bcm2835_mmc_irq() 함수의 콜 스택이 담겨 있는 ftrace 로그를 확인하실 수 있습니다.

    혹시 잘 안되시면 댓글로 남겨주세요.
    즐거운 주말 보내세요.

    PS) 유튜브 동영상에 블로그 링크를 댓글로 남기시는데요. 블로그와 링크만 남기시면, 유튜브가 자동으로 댓글을 삭제합니다. (제가 삭제한 거 아닙니다.)

    조금 더 문장을 추가하신 후 블로그 링크를 남기시면 아마 삭제가 안 될 꺼에요.
  • 2020/12/26 19:05 # 답글 비공개

    비공개 덧글입니다.
  • HokiMin 2020/12/26 20:16 # 답글

    어스틴님 답변 감사합니다 ㅎ.ㅎ
    유투브 댓글도 차차 수정해야겠네요.

    연휴 잘 보내고 계신가요?
    연휴이지만, 저에게는 일상이랑 다를게 없네요 (앗...)

    말씀하신대로 bcm2835_mmc_irq가 set_ftrace_filter에 넣어져 있는 것을 확인하였습니다.

    root@raspberrypi:/home/pi# cat /sys/kernel/debug/tracing/set_ftrace_filter
    __handle_irq_event_percpu
    rpi_get_interrupt_info
    bcm2835_mmc_irq

    System.map파일에
    25018번째 줄: 8069ead4 t bcm2835_mmc_irq
    이라는 심볼도 잘 들어가 있습니다.

    그런데...
    cat /proc/interrupts
    ...
    CPU0 CPU1 CPU2 CPU3
    86: 456 0 0 0 ARMCTRL-level 94 Edge mmc1
    ...

    86번 인터럽트 mmc1이 CPU0에서 456번 불린걸로 보이는데요,
    10분, 20분이 넘게 지나도 저 456이란 숫자가 늘지가 않습니다.
    mmc1인터럽트가 왜인지 불리지 않는 것 같습니다 (mmc0도 마찬가지).
    물론 get_ftrace.sh를 실행시켜도 콜스텍이 보이지 않습니다.

    갑자기 든 생각으로
    make menuconfig를 열고 MMC_BCM2835를 검색해보았는데요,

    Symbol: MMC_BCM2835 [=n]
    Prompt: Broadcom BCM2835 SDHOST MMC Controller support

    Symbol: MMC_BCM2835_DMA [=n]
    Prompt: DMA support on BCM2835 Arasan controller

    Symbol: MMC_BCM2835_MMC [=n]
    Prompt: MMC support on BCM2835

    Symbol: MMC_BCM2835_PIO_DMA_BARRIER [=]
    Prompt: Block count limit for PIO transfers

    Symbol: MMC_BCM2835_SDHOST [=n]
    Prompt: Support for the SDHost controller on BCM2708/9

    위의 결과를 볼 수 있었습니다.
    Y가 아니라 N라서그런걸까요? (시도해 보고 답글을 다시 달겠습니다.)

    out/drivers/mmc/host 디렉토리에 가보니
    bcm2835-mmc.o는 잘 생성되어있습니다.

    원인을 모르겠습니다 ㅜ.ㅜ

    참고로 실습은 github에 있는 스크립트를 이용하여 진행하고 있습니다.
    (https://github.com/wikibook/linux-kernel)

    라즈베리파이 버전: 라즈베리파이 3B
  • HokiMin 2020/12/26 20:35 #

    make menuconfig에서
    ARCH_BCM2835 심볼이 =y로 나와야하는데 uknown으로 나와서
    곰곰히 생각해보니
    제가 ARCH=arm 옵션을 안주고 make menuconfig를 했다는 것을 깨달았습니다.

    지금 make bcm2835_defconfig를 하고 다시 빌드 중에 있습니다.
    make bcm2835_defconfig를 하니 MMC_BCM2835 심볼이 [=y]가 뜨네요!

    라즈베리파이에서 빌드가 너무 느려서 크로스 컴파일러를 이용해서 하고 있는데요,
    그러다 보니까 ARCH 같은 타겟 옵션같은거 주는거에 소흘했던 것 같습니다.

    다시 한 번 시도해 보고 댓글 남기겠습니다.
  • AustinKim 2020/12/26 21:46 #

    라즈베리 커뮤니티 사이트에 가시면요,
    https://www.raspberrypi.org/documentation/linux/kernel/building.md

    라즈베리 파이 3B인 경우 라즈비안 커널의 빌드 명령어는 아래와 같습니다.

    cd linux
    KERNEL=kernel7
    make bcm2709_defconfig

    따라서 아래 링크에 있는,
    http://rousalome.egloos.com/10011640

    다음과 같은 빌드 스크립트로 라즈비안을 컴파일해보시길 권장드립니다.

    01 #!/bin/bash
    02
    03 echo "configure build output path"
    04
    05 KERNEL_TOP_PATH="$( cd "$(dirname "$0")" ; pwd -P )"
    06 OUTPUT="$KERNEL_TOP_PATH/out"
    07 echo "$OUTPUT"
    08
    09 KERNEL=kernel7
    10 BUILD_LOG="$KERNEL_TOP_PATH/rpi_build_log.txt"
    11
    12 echo "move kernel source"
    13 cd linux
    14
    15 echo "make defconfig"
    16 make O=$OUTPUT bcm2709_defconfig
    17
    18 echo "kernel build"
    19 make O=$OUTPUT zImage modules dtbs -j4 2>&1 | tee $BUILD_LOG
  • AustinKim 2020/12/26 21:58 #

    라즈비안 커널을 빌드하면 out 디렉터리에 .config 파일이 생성됩니다.
    이 .config 파일에서 커널 컨피그를 확인할 수 있는데요.

    아래는 .config 파일에서 확인된 MMC_BCM2835 관련 컨피그 설정 내용입니다.

    #
    # MMC/SD/SDIO Host Controller Drivers
    #
    CONFIG_MMC_BCM2835_MMC=y
    CONFIG_MMC_BCM2835_DMA=y
    CONFIG_MMC_BCM2835_PIO_DMA_BARRIER=2
    CONFIG_MMC_BCM2835_SDHOST=y
    # CONFIG_MMC_DEBUG is not set
    # CONFIG_MMC_ARMMMCI is not set
    CONFIG_MMC_SDHCI=y
    CONFIG_MMC_SDHCI_PLTFM=y

    위에 선언된 컨피그가 보이는 지 확인하셔도 좋을 것 같습니다.

    'make bcm2835_defconfig'로 빌드하신 후 라즈비안 이미지를 설치하시면, 라즈베리 파이가 아예 부팅을 못할 수도 있으니 참고하세요.
  • HokiMin 2020/12/27 14:28 # 답글

    bcm2709_defconfig로 했어야 했는데
    bcm2835_defconfig로 해서 부팅이 안되는 일이 벌어졌었는데
    날카로우십니다 ㅎ.ㅎ
    bcm2709_defconfig를 하면 위에서 어스틴님이 말씀하신 CONFIG_MMC_X와 동일한 결과를 얻을 수 있었습니다.

    여러가지 실험을 한 결과를 말씀드리면, (모든 실험은 크로스컴파일 환경에서 시행되었습니다)

    1. 책에서 소개한 2019-07-10-raspbian-buster.img (커널 버전 4.19.57-v7)
    을 다운받아서 micro SD카드에 넣어서 부팅하면
    mmc1 인터럽트 count가 지속적으로 늘어나는 것을 확인하였습니다. (정상동작)
    # cat /proc/interrupts

    2. rpi-4.19.y 브랜치 (최신 버전 4.19.127) 를 다운받아 make bcm2709_defconfig 수행 후 빌드하여
    생성 된 내용물들을 라즈베리파이에 install하여 reboot하면 mmc1의 인터럽트 횟수가
    456에서 변하지 않는 현상 발생. (컴퓨터 켜놓고 잤는데, 아침에 일어나서 확인해도 동일하네요)
    # cat /proc/interrupts
    86: 456 0 0 0 ARMCTRL-level 94 Edge mmc1

    3. 최신 버전이 아닌 다운받은 이미지와 동일한 버전인
    4.19.57-v7 커널 버전을 다운받아서 2의 내용을 반복해도
    동일한 결과 확인
    (소스: https://github.com/raspberrypi/linux/releases/tag/raspberrypi-kernel_1.20190709-1)
    책에서는 4.19.60으로 확인 되었다고 해서 4.19.60을 다운받아서 해봐야하는데
    아직 4.19.60은 시도해보지 못했습니다.

    4. 크로스 컴파일러 버전에 문제가 있는건가 싶어서 아래의 크로스컴파일러를 실험해보았습니다.
    gcc-linaro-arm-linux-gnueabihf-raspbian-x64 (4.8.3)
    arm-rpi-4.9.3-linux-gnueabihf
    결과는 2와 동일
    (툴체인 소스: https://github.com/raspberrypi/tools)
    (제 host 우분투는 18.04 64bit버전입니다.)

    5. mmc1이 아닌 mmc0 인터럽트는 이따금씩 발생하는것을 확인하였기에
    mmc0의 콜스텍을 확인해 보기 위해 ftrace filter에 bcm2835_sdhost_irq를 등록하였고
    정상적으로 콜스텍을 확인할 수 있었습니다.

    6. 기타 커맨드 실행 결과
    # ps -ely | grep mmc1
    S 0 84 2 0 9 - 0 0 irq_th ? 00:00:00 irq/86-mmc1
    # dmesg | grep mmc1
    [ 0.811974] mmc1: queuing unknown CIS tuple 0x80 (2 bytes)
    [ 0.813560] mmc1: queuing unknown CIS tuple 0x80 (3 bytes)
    [ 0.815142] mmc1: queuing unknown CIS tuple 0x80 (3 bytes)
    [ 0.817985] mmc1: queuing unknown CIS tuple 0x80 (7 bytes)
    [ 0.935493] mmc1: new high speed SDIO card at address 0001

    mmc1 인터럽트가 유일하게 IRQ 쓰레드로 처리되다 보니
    책에서 여러번 소개가 되어서 문제를 해결해 보고 싶었으나,
    너무 많은 시간을 할애할 수 없어서 우선 다음 4장 실습을 진행하고자 합니다.

    실습은, 기본적으로 github에서 받은 소스를 이용하고 있고
    스크립트에 크로스컴파일러를 위한 환경변수설정 및
    제 편의에 맞게 수정하여 진행하고 있는데요,

    후에 책에서 "하라는 대로" 해보아야겠습니다 ㅜ.ㅜ

    답변 감사합니다 어스틴님.
  • AustinKim 2020/12/27 15:28 #

    아이고, 글을 보니 시행착오로 고생이 많으셨을 것 같습니다.

    언급하신대로 4장으로 진행하시고, 혹시 실습하시다가 막히는 부분이 있으면 언제든 댓글로 알려주세요. 최대한 자세히 답을 드릴께요.
    그럼, 남은 연휴 잘 보내세요.
  • HokiMin 2021/01/03 00:03 # 답글

    안녕하세요 어스틴님.
    우연히도 mmc1 인터럽트가 발생하지 않았던 문제를 해결하게 되었습니다!!
    혹시 저와 같은 현상을 겪었을 분들을 위해서 포스팅을 남깁니다.

    결론부터 얘기하면 bcm2709_defconfig 옵션으로 크로스컴파일 한 후,
    module들을 라즈베리파이에 install하지 않았기 때문입니다.

    라즈베리파이에서 네이티브 컴파일을 했을 경우 make -O=$OUPTUT modules_install을 하게 되면
    라즈베리파이 /lib/modules안에 module들을 설치하게 되는데요,
    크로스 컴파일을 하는 경우에 똑같은 커멘드를 실행하면
    host의 /lib/modules안에 module들을 설치하게 됩니다.

    라즈베리파이 /lib/modules안에 설치하기 위해서 다음과 같은 방법을 찾았습니다.

    1. host에서 라즈베리파이 /home/pi를 mount 한 후 (sshfs 사용), 마운트한 디렉토리($MODULES)에 modules_install합니다.
    sshfs pi@169.254.43.140:/home/pi/ $MODULES
    cd $OUTPUT
    make O=$OUTPUT modules_install INSTALL_MOD_PATH=$MODULES
    (크로스컴파일을 위한 환경변수 export 설정은 생략합니다.)

    2. 마운트를 해제합니다.
    umount $MODULES

    3. 라즈베리파이 /home/pi에 가보면 lib폴더가 생성되어 있는 것을 확인할 수 있습니다. 이를 /에 덮어씁니다.
    cp -r /home/pi/lib /

    재부팅한 후 cat /proc/interrupts를 확인해 보면 mmc1 인터럽트 횟수가 쭉쭉 늘어나는 것을 확인할 수 있습니다 ㅎ.ㅎ

    예상한대로 bcm2835_mmc_irq가 ftrace로그에 보입니다!

    <idle>-0 [000] d.h. 194.423085: bcm2835_mmc_irq+0x14/0x71c <-__handle_irq_event_percpu+0x4c/0x218
    <idle>-0 [000] d.h. 194.423147: <stack trace>
    => bcm2835_mmc_irq+0x18/0x71c
    => __handle_irq_event_percpu+0x4c/0x218
    => handle_irq_event_percpu+0x2c/0x68
    => handle_irq_event+0x50/0x74
    => handle_level_irq+0xbc/0x14c
    => generic_handle_irq+0x30/0x44
    => bcm2836_chained_handle_irq+0x38/0x4c
    => generic_handle_irq+0x30/0x44
    => __handle_domain_irq+0x60/0xc4
    => bcm2836_arm_irqchip_handle_irq+0x5c/0xa4
    => __irq_svc+0x5c/0x7c
    => arch_cpu_idle+0x30/0x4c
    => arch_cpu_idle+0x30/0x4c
    => default_idle_call+0x34/0x48
    => do_idle+0xe0/0x16c
    => cpu_startup_entry+0x28/0x2c
    => rest_init+0xa0/0xc0
    => start_kernel+0x400/0x494
  • AustinKim 2021/01/02 23:04 #


    고생이 많으셨고, 시행착오로 겪은 내용을 잘 공유해주셔서 감사합니다.
    즐거운 주말 보내세요.
  • park 2021/01/21 12:27 # 삭제 답글

    cat /proc/interrupts 명령어를 수행하면 show_interrupt 함수가 실행이 되는데 이 함수가 현재 커널에 구현되어 있는 전체 interrupt에 대한 정보를 보여주는 게 맞는건가요? 어떤 인터럽트의 정보들을 보여주는건지 궁급합니다ㅎㅎ
  • AustinKim 2021/01/22 11:14 #

    show_interrupt() 함수는 해당 시스템에서 설정된 인터럽트의 정보를 출력하는 기능입니다.

    아래는 라즈베리 파이에 설정된 인터럽트의 정보를 나타내며, 시스템마다 출력되는 정보는 다릅니다.

    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
댓글 입력 영역