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

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

[리눅스] 드라이버: module_init 키워드로 지정한 함수가 호출되는 원리 - sys_finit_module()

이어서 이번 시간에는 ftrace를 통해 hello_module_init() 함수가 어떻게 호출되는지 살펴보겠습니다.


insmod 명령어로 디바이스 드라이버를 설치할 때의 전체 흐름

먼저 다음 그림은 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진수가 보이는 것입니다.