[리눅스] insmod 명령어로 드라이버 설치 시 커널 내부 동작 디버깅해보기(ftrace) - (Aarch32, v5.4)

이전에 다음 글에서 insmod 명령어를 통해 모듈 타입 디바이스 드라이버가 설치될 때,
커널 내부 함수가 어떤 흐름으로 작동하는지 코드를 리뷰했습니다.

유저 공간에서 insmod가 실행되면 시스템 콜이 발생합니다. 커널 내부에서 다음과 같은 함수들이 호출됩니다.

    ● sys_finit_module() 함수
    ● load_module() 함수
    ● do_init_module() 함수
    ● do_one_initcall() 함수

위 함수 흐름을 보면 do_one_initcall() 함수에서 다음과 같이 module_init 키워드로 정의한 hello_module_init() 함수를 호출한다는 사실을 알 수 있습니다.

static int hello_module_init(void)
{
printk("Hello Module! \n");
return 0;
}
module_init(hello_module_init);

전체 흐름은 다음과 같이 정리할 수 있습니다.

    ● 'insmod' 명령어를 사용해 모듈식 디바이스 드라이버를 설치하면 된다. 
    ● 커널의 모듈 서스 시스템을 구성하는 do_one_initcall() 함수에서 hello_module_init() 함수를 호출한다.

모듈식 디바이스 드라이버를 설치하면 커널에서 어떤 흐름으로 함수가 호출되는지 알아봤으니, 
이어서 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 1 > /sys/kernel/debug/tracing/events/sched/sched_process_fork/enable
20 echo 1 > /sys/kernel/debug/tracing/events/sched/sched_process_exec/enable
21 echo 1 > /sys/kernel/debug/tracing/events/sched/sched_process_exit/enable
22 echo 1 > /sys/kernel/debug/tracing/events/raw_syscalls/enable
23
24 echo 1 > /sys/kernel/debug/tracing/events/signal/enable
25
26 echo printk > /sys/kernel/debug/tracing/set_ftrace_filter
27 sleep 1
28 echo "event enabled"
29
30 sleep 1
31 echo "set_ftrace_filter enabled"
32
33 echo 1 > /sys/kernel/debug/tracing/options/func_stack_trace
34 echo 1 > /sys/kernel/debug/tracing/options/sym-offset
35 echo "function stack trace enabled"
36
37 echo 1 > /sys/kernel/debug/tracing/tracing_on
38 echo "tracing_on"

위 명령어를 trace_module_init.sh 이름으로 저장합시다.

이제 명령어에서 중요한 부분을 소개합니다.
먼저 19~21번째 줄입니다.

19 echo 1 > /sys/kernel/debug/tracing/events/sched/sched_process_fork/enable
20 echo 1 > /sys/kernel/debug/tracing/events/sched/sched_process_exec/enable
21 echo 1 > /sys/kernel/debug/tracing/events/sched/sched_process_exit/enable

프로세스가 생성/실행/소멸되는 동작을 추적(트레이싱)하기 위한 ftrace 이벤트를 활성화하는 명령어입니다.

이어서 22번째 줄을 보겠습니다.

22 echo 1 > /sys/kernel/debug/tracing/events/raw_syscalls/enable

시스템 콜의 세부 동작을 추적하는 이벤트를 활성화하는 명령어입니다.

마지막으로, 26번째 줄을 보겠습니다.

26 echo printk > /sys/kernel/debug/tracing/set_ftrace_filter

set_ftrace_filter에 printk() 함수를 지정하는 명령어입니다.
갑자기 set_ftrace_filter에 printk() 함수를 지정하는 이유는 무엇일까요?

다음과 같이 디바이스 드라이버가 설치되는 과정에서 호출되는 hello_module_init() 함수를 보면 이유를 알 수 있습니다.

static int hello_module_init(void)
{
printk("Hello Module! \n");
return 0;
}

보시다시피 hello_module_init() 함수에서 printk() 함수를 호출해 커널 로그를 출력합니다.
set_ftrace_filter에 printk() 함수를 지정하면 hello_module_init() 함수의 콜 스택을 함께 볼 수 있습니다.

전체 실습 과정 소개

이제 전체 실습 과정을 소개합니다.
라즈베리 파이에서 터미널을 먼저 열겠습니다.

1> 가장 먼저 다음 명령어를 입력해 이번 포스팅에서 소개한 trace_module_init.sh 셸 스크립트를 실행합시다.
 
root@raspberrypi:/home/pi/work_0614# ./trace_module_init.sh

2> 이어서 'insmod hello_module.ko' 명령어를 입력해 모듈을 설치합시다.

root@raspberrypi:/home/pi/work_0614# insmod hello_module.ko

3> 마지막으로 터미널에서 다음 명령어를 입력해 ftrace 로그를 추출합니다.

echo 0 > /sys/kernel/debug/tracing/tracing_on
cp /sys/kernel/debug/tracing/trace . 
mv trace ftrace_log.c

이제 ftrace를 설정한 후 ftrace 로그를 추출했습니다.
이어서 ftrace 로그를 분석하겠습니다.

ftrace 메시지 분석하기

다음은 분석할 ftrace 메시지입니다.

01 insmod-2337 [001] .... 3058.441009: sched_process_exec: filename=/sbin/insmod pid=2337 old_pid=2337
02 ...
03 insmod-2337 [001] .... 3058.442694: sys_enter: NR 379 (3, 2cd30, 0, 0, d138b300, 2)
04 insmod-2337 [001] .... 3058.443179: printk+0x18/0x5c <-0x7f679020
05 insmod-2337 [001] .... 3058.443230: <stack trace>
06 => printk+0x1c/0x5c
07 => 0x7f679020
08 => do_one_initcall+0x50/0x214
09 => do_init_module+0x74/0x224
10 => load_module+0x1ee4/0x2610
11 => sys_finit_module+0xd8/0xe8
12 => __sys_trace_return+0x0/0x10
13 => 0x7ed70580
14 ...
15 insmod-2337  [001] ....  3058.443274: sys_exit: NR 379 = 0

먼저 01번째 줄입니다.

01 insmod-2337 [001] .... 3058.441009: sched_process_exec: filename=/sbin/insmod pid=2337 old_pid=2337

라즈베리 파이의 '/sbin/insmod' 파일이 실행되면서 insmod 프로세스가 실행되는 동작을 나타냅니다.
  
이어서 03번째 줄을 보겠습니다.

03 insmod-2337 [001] .... 3058.442694: sys_enter: NR 379 (3, 2cd30, 0, 0, d138b300, 2)

PID가 2337인 insmod 프로세스에서 379번 시스템 콜이 발생했다는 정보입니다.
여기서 379번 시스템 콜의 정체는 무엇일까요? 
라즈베리 파이에서 /usr/include/arm-linux-gnueabihf/asm/unistd.h 파일을 열어보면 그 정체를 알 수 있습니다.

/usr/include/arm-linux-gnueabihf/asm/unistd.h
# define __NR_timerfd_create(__NR_SYSCALL_BASE+350)
#define __NR_finit_module(__NR_SYSCALL_BASE+379)

379번 시스템 콜의 이름은 finit_module 이라는 사실을 알 수 있습니다.

이어서 04~13번째 줄을 분석하겠습니다.

04 insmod-2337 [001] .... 3058.443179: printk+0x18/0x5c <-0x7f679020
05 insmod-2337 [001] .... 3058.443230: <stack trace>
06 => printk+0x1c/0x5c
07 => 0x7f679020
08 => do_one_initcall+0x50/0x214
09 => do_init_module+0x74/0x224
10 => load_module+0x1ee4/0x2610
11 => sys_finit_module+0xd8/0xe8
12 => __sys_trace_return+0x0/0x10
13 => 0x7ed70580

finit_module 시스템 콜에 대한 시스템 콜 핸들러인 sys_finit_module() 함수가 호출된 후,
다음 목록의 커널 함수들이 호출된다는 정보를 확인할 수 있습니다.

    ● load_module()   
    ● do_init_module() 
    ● do_one_initcall()

07번째 줄에 0x7f679020이란 16진수가 보입니다.
07 => 0x7f679020

이는 이미 작성한 hello_module_init() 함수의 주소를 나타냅니다.

static int hello_module_init(void)
{
printk("Hello Module! \n");
return 0;
}

0x7f679020 주소의 정체 파악하기

자 그렇다면 0x7f679020 주소가 hello_module_init() 함수라는 사실은 어떻게 알 수 있을까요?
'cat /proc/kallsyms | grep hello' 명령어를 입력하면 심벌의 주소를 알 수 있습니다.

다음은 'cat /proc/kallsyms | grep hello' 명령어를 입력한 결과입니다.

root@raspberrypi:/home/pi/work_0614# cat /proc/kallsyms | grep hello
7f66b000 t $a[hello_module]
7f66b000 t hello_module_init[hello_module]

hello_module_init() 함수의 시작 주소가 7f66b000 임을 알 수 있습니다.
함수의 시작 주소가 7f66b000이고 hello_module_init() 함수에서 스택을 푸시하는 명령어를 빼면,
+0x20 오프셋 주소에서 printk() 함수를 호출할 것이라고 예측할 수 있습니다.

조금 더 명확히 이 정보를 확인하려면 objdump라는 바이너리 유틸리티를 사용해 hello_module.ko 파일에 포함된 hello_module_init() 함수를 확인 할 수 있습니다.
 
root@raspberrypi:/home/pi/work_0614# objdump -d hello_module.ko
hello_module.ko:     file format elf32-littlearm


Disassembly of section .text:

00000000 <hello_module_init>:
   0:e1a0c00d movip, sp
   4:e92dd800 push{fp, ip, lr, pc}
   8:e24cb004 subfp, ip, #4
   c:e52de004 push{lr}; (str lr, [sp, #-4]!)
  10:ebfffffe bl0 <__gnu_mcount_nc>
  14:e3000000 movwr0, #0
  18:e3400000 movtr0, #0
  1c:ebfffffe bl0 <printk>
  20:e3a00000 movr0, #0

hello_module.ko 파일은 demangle 하기 전의 상태이므로 hello_module_init() 함수의 시작 주소는 00000000으로 표기됩니다.
그런데 printk를 호출하는 부분의 주소는 0x1c입니다. ARM 아키텍처는 파이프라인을 적용했으므로 실제 실행되는 주소보다 +0x4 바이트를 더해서 표기됩니다.

그래서 ftrace 메시지의 07번째 줄에 0x7f679020이란 16진수가 보이는 것입니다.