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

이전에 다음 글에서 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-2244 [003] .....   944.807148: sched_process_exec: filename=/usr/sbin/insmod pid=2244 old_pid=2244
02 insmod-2244 [003] .....   944.809356: _printk+0x4/0x98 <ffffd00084105ef4> <-hello_module_init+0x20/0x38 [hello_module] <ffffd00017f8c028>
03 insmod-2244 [003] .....   944.809357: <stack trace>
04 => _printk+0x8/0x98 <ffffd00084105ef8>
05 => hello_module_init+0x20/0x38 [hello_module] <ffffd00017f8c028>
06 => do_one_initcall+0x60/0x2c0 <ffffd00084014f40>
07 => do_init_module+0x60/0x218 <ffffd0008413e9a8>
08 => load_module+0x1de0/0x2090 <ffffd00084140cb0>
09 => init_module_from_file+0x8c/0xd8 <ffffd000841411cc>
10 => __arm64_sys_finit_module+0x150/0x330 <ffffd000841413d8>
11 => invoke_syscall+0x50/0x128 <ffffd00084029d20>
12 => el0_svc_common.constprop.0+0x48/0xf0 <ffffd00084029e40>
13 => do_el0_svc+0x24/0x38 <ffffd00084029f0c>
14 => el0_svc+0x40/0xe8 <ffffd00084cffa70>
15 => el0t_64_sync_handler+0x100/0x130 <ffffd00084cffed8>
16 => el0t_64_sync+0x190/0x198 <ffffd00084011550>
17 insmod-2244 [003] .....   944.809522: sched_process_exit: comm=insmod pid=2244 prio=120

먼저 01번째 줄입니다.

01 insmod-2244 [003] .....   944.807148: sched_process_exec: filename=/usr/sbin/insmod pid=2244 old_pid=2244

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

02 insmod-2244 [003] .....   944.809356: _printk+0x4/0x98  <-hello_module_init+0x20/0x38 [hello_module] 
03 insmod-2244 [003] .....   944.809357: </stack trace>
04 => _printk+0x8/0x98 
05 => hello_module_init+0x20/0x38 [hello_module] 
06 => do_one_initcall+0x60/0x2c0 
07 => do_init_module+0x60/0x218 
08 => load_module+0x1de0/0x2090 
09 => init_module_from_file+0x8c/0xd8 
10 => __arm64_sys_finit_module+0x150/0x330 
11 => invoke_syscall+0x50/0x128 
12 => el0_svc_common.constprop.0+0x48/0xf0 
13 => do_el0_svc+0x24/0x38 
14 => el0_svc+0x40/0xe8 
15 => el0t_64_sync_handler+0x100/0x130 
16 => el0t_64_sync+0x190/0x198 

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

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