Linux는 리누스 토르발즈가 만들어 오픈소스로 배포한 UNIX 계열 운영체제입니다.
현재 수 대부분의 프로그램이 Linux 환경에서 실행되고 있다고 할 수 있을 정도로 Linux는 현대 IT 생태계에서 중요한 위치를 차지하고 있는데요.
하지만 정작 Linux의 동작 원리에 대해서는 모르고 사용하는 경우가 많은 것 같습니다.
Linux를 잘 사용하고 다루기 위해서는 Linux의 핵심인 커널에 대해서 파악하고 있어야 합니다.
특히 네트워크 인프라를 다뤄야 하는 엔지니어는 Linux 커널을 모르고서는 트러블슈팅이나 디버깅에 큰 제약이 있을 수 밖에 없을 것 입니다.
그렇다면 Linux 커널의 동작은 어떻게 파악할 수 있을까요?
그 시작은 Linux 프로세스가 실행될때 커널에서 어떤 일이 일어나는지 확인하는 것입니다.
본 포스팅에서는 ftrace를 사용해서 유저 프로세스가 실행될때 커널에서 어떤 일이 일어나는지 추적하는 과정을 담아 보겠습니다.
포스팅에 사용된 환경은 다음과 같습니다.
- OS : Rasbian Linux rpi-6.1y
- Linux Kernel version : 6.1
1. ftrace란?
ftrace는 Linux 커널에서 일어나는 일들을 파악할 수 있는 Tracer 도구입니다.
Tracer 도구란 수 많은 함수들의 실행으로 이루어진 일련의 흐름을 보기 쉽게 출력해주는 도구를 말합니다.
ftrace는 아래와 같은 기능을 수행할 수 있습니다.
- 프로세스 디버깅 : 함수의 콜스택을 출력해 어떤 부분에서 문제가 발생했는지 추적할 수 있습니다.
- 퍼포먼스 테스트 : 함수가 실행된 시간 정보를 출력해 프로세스의 퍼포먼스를 측정할 수 있습니다.
- 이벤트 트레이싱 : Linux에서 일어나는 수 많은 Event 중, 원하는 event만을 추적할 수 있습니다.
Linux 커널의 디버깅을 위해서는 직접 패치 코드를 작성하거나, Trace32를 사용할 수도 있지만 가장 간편하고 레퍼런스가 많은 도구가 ftrace이기 때문에 ftrace는 현재도 Linux 커널 분석에 널리 사용되고 있습니다.
본 포스팅에서도 ftrace를 이용해 프로세스가 실행될때 커널에서 일어나는 Event들을 추적해볼 예정입니다.
2. ftrace로 로그 추출하기
Linux에서 프로세스가 실행될때 어떤 일이 일어나는지 분석하려면, 프로세스가 실행되는 시점에 어떤 함수들이 실행되는지를 파악해야 합니다.
ftrace를 이용해 함수 실행과 관련한 로그들을 추출하면 이같은 정보들을 얻을 수 있습니다.
그래서 이번 장에서는 ftrace로 함수 로그를 추출하기 전에 먼저 해야 할 세팅을 알아보고, 로그를 추출해보겠습니다.
2-1. ftrace 사용을 위한 세팅
ftrace 설정 파일은 ftrace가 포함된 Linux에서 "/sys/kernel/debug/tracing" 디렉토리에 존재합니다.
위 디렉토리에 포함된 파일들을 원하는 값으로 변경하는 것으로 ftrace를 설정할 수 있습니다.
예를 들어 ftrace를 활성화하고자 한다면, "tracing_on" 파일의 값을 1로 변경하는 것으로 설정할 수 있습니다.
ftrace는 상황별로 사용할 수 있는 다양한 tracer 옵션을 제공합니다.
아래와 같이 "current_tracer" 파일에 tracer 이름 값을 넣으면 특정한 tracer를 사용해 함수를 추적하도록 설정할 수 있습니다.
특정한 함수만 추적하고 싶다면, "set_ftrace_filter" 파일에 추적하고자 하는 함수 명을 지정하는 것으로 설정할 수 있습니다. 이는 "function"과 "function_graph" Tracer를 사용했을 때에만 설정할 수 있습니다.
여기서 주의해야 할 것은, Linux는 짧은 시간에도 수없이 많은 함수가 실행되는 시스템이기 때문에 특정 함수만 추적하도록 필터를 걸어놓지 않으면 시스템이 락업 상태가 된다는 것입니다.
그러므로 꼭 tfrace를 활성화하기 전에 "set_ftrace_filter" 파일을 통해 추적하고자 하는 함수를 지정해놓아야 합니다. 아무 함수도 지정하지 않으면 모든 함수를 추적하기 때문에 락업 상태로 진입하게 됩니다.
ftrace가 모든 함수들을 추적할 수 있는 것은 아닙니다. 추적할 수 있는 함수들의 목록은 "available_filter_functions"에서 확인할 수 있습니다.
ftrace는 Event별로 추적할 수 있는 기능을 포함하고 있습니다. 이를 통해 특정 Event가 활성화되었을때의 로그를 추출할 수 있습니다.
예를 들어 인터럽트 핸들링의 종료 Event를 추적하고자 한다면 아래와 "events/irq/irq_handler_exit/enable" 파일의 값을 1로 변경합니다.
2-2. ftrace로 로그 추출
이제 본격적으로 Linux에서 프로세스가 실행됐을때 일어나는 로그들을 추출해보겠습니다.
먼저 ftrace 세팅부터 시작하겠습니다. 세팅에 어떤 스크립트가 필요한지 순차적으로 알아보도록 하겠습니다.
이전 장에서 말씀드렸다시피 "set_ftrace_filter"에 아무 함수도 지정하지 않으면 시스템이 락업 상태에 진입하게 됩니다
그래서 아래와 같이 더미 함수를 "set_ftrace_filter"에 넣어 락업 상태를 방지하는 것으로 스크립트를 시작합니다.
|
1
2
3
|
echo 0 > secondary_start_kernel > /sys/kernel/debug/tracing/set_ftrace_filter
sleep 1
echo "set_ftrace_filter init"
|
cs |
다음으로 ftrace가 사용할 Tracer를 지정합니다. 이번 포스팅에서 사용할 tracer는 "function" Tracer로 실행된 함수를 기준으로 로그를 출력하는 기능을 가지고 있습니다.
아래와 같은 스크립트를 추가하여 "function" Tracer를 지정할 수 있습니다.
|
1
2
3
|
echo function > /sys/kernel/debug/tracing/current_tracer
sleep 1
echo "function tracer enabled"
|
cs |
그리고 특정 함수의 실행을 추적하기 위해 "set_ftrace_filter" 파일을 설정합니다.
우리는 프로세스가 실행될시 일어나는 프로세스 생성, 종료, 복제 행위를 보고 싶으므로 아래와 같이 설정합니다.
|
1
2
3
|
echo sys_clone do_exit search_binary_handler copy_process.part* > /sys/kernel/debug/tracing/set_ftrace_filter
sleep 1
echo "set_ftrace_filter enabled"
|
cs |
다음으로 Event별로 추적할 로그를 남기기 위해 Event를 설정합니다. 프로세스의 생성부터 종료까지 Lifecycle에 관여하는 Event를 지정합니다.
아래와 같은 스크립트를 추가해 프로세스 생성, 실행, 종료, 자원 해제에 해당하는 Event를 추적하도록 설정합니다.
|
1
2
3
4
5
6
|
echo 1 > /sys/kernel/debug/tracing/events/sched/sched_process_exit/enable
echo 1 > /sys/kernel/debug/tracing/events/sched/sched_process_fork/enable
echo 1 > /sys/kernel/debug/tracing/events/sched/sched_process_free/enable
echo 1 > /sys/kernel/debug/tracing/events/sched/sched_process_exec/enable
sleep 1
echo "event enabled"
|
cs |
다음으로 분석을 편리하게 할 수 있도록 출력되는 로그가 함수의 콜 스택 및 주소의 오프셋을 포함하도록 설정합니다.
아래와 같은 스크립트를 추가합니다.
|
1
2
3
|
echo 1 > /sys/kernel/debug/tracing/options/func_stact_trace
echo 1 > /sys/kernel/debug/tracing/options/sym-offset
echo "function stack trace enabled"
|
cs |
마지막으로 ftrace를 활성화하는 스크립트를 추가해 설정을 마칩니다.
|
1
2
|
echo 1 > /sys/kernel/debug/tracing/tracing_on
echo "tracing on"
|
cs |
위에서 작성한 스크립트를 종합하면 아래와 같습니다.
|
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
|
#!/bin/bash
echo 0 > secondary_start_kernel > /sys/kernel/debug/tracing/set_ftrace_filter
sleep 1
echo "set_ftrace_filter init"
echo function > /sys/kernel/debug/tracing/current_tracer
sleep 1
echo "function tracer enabled"
echo sys_clone do_exit search_binary_handler copy_process.part* > /sys/kernel/debug/tracing/set_ftrace_filter
sleep 1
echo "set_ftrace_filter enabled"
echo 1 > /sys/kernel/debug/tracing/events/sched/sched_process_exit/enable
echo 1 > /sys/kernel/debug/tracing/events/sched/sched_process_fork/enable
echo 1 > /sys/kernel/debug/tracing/events/sched/sched_process_free/enable
echo 1 > /sys/kernel/debug/tracing/events/sched/sched_process_exec/enable
sleep 1
echo "event enabled"
echo 1 > /sys/kernel/debug/tracing/options/func_stact_trace
echo 1 > /sys/kernel/debug/tracing/options/sym-offset
echo "function stack trace enabled"
echo 1 > /sys/kernel/debug/tracing/tracing_on
echo "tracing on"
|
cs |
위 스크립트를 sh 파일로 저장한 뒤 실행하면, "/sys/kernel/debug/tracing/trace" 경로에 추적한 함수들을 담은 로그 파일이 생성됩니다.
그럼 이제 Linux 프로세스가 실행되는 과정을 알아보기 위해서 간단한 Linux 프로그램인 "ls"를 실행한 결과를 로그로 받아보겠습니다.
아래와 같이 작성한 스크립트 파일을 실행한 뒤, 명령어 ls를 입력합니다.
3. 로그 분석
이전 장에서 ftrace를 세팅하고 프로세스가 실행될때의 함수를 추적하기 위해 Linux 프로그램 "ls"를 실행한 결과를 로그로 남겼습니다.
말씀드렸다시피 로그 파일은 "/sys/kernel/debug/tracing/trace" 경로에 남게 되는데요.
이 로그 파일을 현재 경로로 가져오고 ftrace를 비활성화하는 스크립트를 작성해 로그 분석을 위한 준비를 마쳐보겠습니다.
아래 스크립트를 저장 후 실행합니다.
|
1
2
3
4
5
6
7
8
|
#!/bin/bash
echo 0 > /sys/kernel/debug/tracing/tracing_on
sleep 3
echo "ftrace off"
cp /sys/kernel/debug/tracing/trace .
mv trace ftrace_log.c
|
cs |
작성한 스크립트를 실행하면 아래와 같이 ftrace가 비활성화되고 로그 파일이 현재 디렉토리에 생성됩니다.
생성된 로그 파일을 열면 아래와 같이 ftrace로 생성한 로그가 존재하는 것을 확인할 수 있습니다.
로그 내용 중, 이번 포스팅에서 알아볼 Linux 프로세스의 생애주기와 관련된 내용은 아래와 같습니다.
|
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
|
bash-32291 [003] .... 1854854.212525: sched_process_fork: comm=bash pid=32291 child_comm=bash child_pid=32326
bash-32291 [003] .... 1854854.212542: <stack trace>
=> _do_fork+0x1e4/0x404
=> sys_clone+0x34/0x3c
=> ret_fast_syscall+0x0/0x28
=> 0x7ef3f270
ls-32326 [000] .... 1854854.214519: sched_process_exec: filename=/usr/bin/ls pid=32326 old_pid=32326
ls-32326 [000] .... 1854854.214543: <stack trace>
=> __do_execve_file+0x7a8/0x804
=> sys_execve+0x44/0x4c
=> ret_fast_syscall+0x0/0x28
=> 0x7ef927b0
ls-32326 [000] .... 1854854.226876: sched_process_exit: comm=ls pid=32326 prio=120
ls-32326 [000] .... 1854854.226891: <stack trace>
=> do_exit+0x5a4/0xb28
=> do_group_exit+0x50/0xe8
=> __wake_up_parent+0x0/0x34
=> ret_fast_syscall+0x0/0x28
=> 0x7ef92630
|
cs |
위 로그 내용을 하나씩 분석해보도록 하겠습니다.
3-1. 프로세스 생성
이전 장에서 프로세스가 실행될때 Linux 커널에서는 어떤 일이 일어나는지 파악하기 위해 ftrace를 활성화하고 Linux 프로그램인 "ls"를 실행한 결과를 로그 파일로 남겼습니다.
이제 생성된 로그 파일을 기반으로 프로세스의 실행 시 커널에서 어떤 프로세스가 생성되고, 어떤 함수가 호출되는지 알아보도록 하겠습니다.
가장 먼저 출력된 로그는 프로세스의 생성과 관련된 로그입니다. 해당 로그는 아래와 같습니다.
|
1
2
3
4
5
6
|
bash-32291 [003] .... 1854854.212525: sched_process_fork: comm=bash pid=32291 child_comm=bash child_pid=32326
bash-32291 [003] .... 1854854.212542: <stack trace>
=> _do_fork+0x1e4/0x404
=> sys_clone+0x34/0x3c
=> ret_fast_syscall+0x0/0x28
=> 0x7ef3f270
|
cs |
이벤트 로그는 다음과 같습니다.
sched_process_fork: comm=bash pid=32291 child_comm=bash child_pid=32326
이를 해석하면 "1854854.212525" 시간에 "sched_process_fork" 이벤트가 발생했으며, 이를 통해 pid가 32291인 bash 프로세스가 pid 32326인 자식 프로세스를 생성했다는 뜻입니다.
그런데 생성되는 자식 프로세스의 이름이 bash인 것을 볼 수 있습니다.
왜 실행한 프로그램은 ls인데 bash 프로세스가 생성되는 걸까요?
이는 프로세스가 생성될 때에는 부모 프로세스를 fork, 즉 복제해서 만들어지는데, 이 과정의 처음에는 부모 프로세스의 이름을 그대로 가져오기 때문입니다.
이어서 함수의 콜스택을 보면 ret_fast_syscall -> sys_clone -> _do_fork 순으로 실행된 것을 확인할 수 있습니다.
ret_fast_syscall 함수는 시스템 콜 실행을 종료하고 User space로 진입하는 역할을 합니다. 이 함수를 통해 유저 프로그램을 실행할 수 있습니다.
sys_clone 함수는 프로세스를 복제하는 fork() 함수의 핸들러입니다. 유저 프로그램은 fork() 함수를 호출함으로써 Linux 프로세스를 생성할 수 있는데, 이 과정에서 호출되는 함수입니다.
_do_fork 함수는 부모 프로세스를 복제해 자식 프로세스를 생성하는 역할을 합니다. 가장 핵심적인 함수로 이 함수를 통해 pid 32326의 새 프로세스가 생성된 것을 확인할 수 있습니다.
3-2. 프로세스 실행
프로세스를 생성하는데 성공했으니 이제 Linux 커널에서는 생성한 프로세스를 실행하는 단계를 시작합니다.
해당 로그는 아래와 같습니다.
|
1
2
3
4
5
6
|
ls-32326 [000] .... 1854854.214519: sched_process_exec: filename=/usr/bin/ls pid=32326 old_pid=32326
ls-32326 [000] .... 1854854.214543: <stack trace>
=> __do_execve_file+0x7a8/0x804
=> sys_execve+0x44/0x4c
=> ret_fast_syscall+0x0/0x28
=> 0x7ef927b0
|
cs |
이벤트 로그는 다음과 같습니다.
sched_process_exec: filename=/usr/bin/ls pid=32326 old_pid=32326
이를 해석하면 "sched_process_exec" 이벤트가 발생했으며, 이를통해 pid가 32326인 "/usr/bin/ls" 파일이 실행되었다는 뜻입니다.
여기서 우리가 실행해왔던 ls 프로그램은 /usr/bin/ls 디렉토리에 존재한다는 것을 알 수 있습니다.
함수의 콜스택을 보면 ret_fast_syscall -> sys_execve -> __do_execve_file 순으로 실행된 것을 확인할 수 있습니다.
sys_execve 함수는 프로그램을 실행하는 함수인 execve()의 핸들러입니다. 이를 통해 executable file을 기존의 프로세스와 교체하여 적재할 수 있습니다. 이 상황에서는 ls 파일을 기존의 bash 프로세스 대신 프로세스에 적재하는 역할을 합니다.
__do_execve_file 함수는 본격적으로 프로그램을 실행하는 역할을 합니다. 이를 통해 ls 명령어가 실행되어 ls 프로그램의 함수가 실행되는 절차로 이어지게 됩니다.
3-3. 프로세스 종료
프로세스를 실행하는데까지 진행되었다면 이제 생성된 프로세스를 종료하고 메모리를 반환하는 단계를 시작합니다.
해당 로그 내역은 아래와 같습니다.
|
1
2
3
4
5
6
7
|
ls-32326 [000] .... 1854854.226876: sched_process_exit: comm=ls pid=32326 prio=120
ls-32326 [000] .... 1854854.226891: <stack trace>
=> do_exit+0x5a4/0xb28
=> do_group_exit+0x50/0xe8
=> __wake_up_parent+0x0/0x34
=> ret_fast_syscall+0x0/0x28
=> 0x7ef92630
|
cs |
이벤트 로그는 다음과 같습니다.
sched_process_exit: comm=ls pid=32326 prio=120
이를 해석하면 "sched_process_exit" 이벤트가 발생했으며, 이를 통해 pid 32326의 "ls" 프로세스가 종료되었다는 뜻입니다.
이제는 부모 프로세스에게서 물려받은 "bash" 이름 대신 원래 이름인 "ls" 로 대체되어 있는 것을 확인할 수 있습니다.
함수 콜스택을 보면 ret_fast_syscall -> __wake_up_parent -> do_group_exit -> do_exit 순으로 실행되었다는 것을 확인할 수 있습니다.
__wake_up_parent 함수는 부모 프로세스에게 종료할 자식 프로세스를 알려주는 역할을 합니다. 부모 프로세스가 자식 프로세스를 종료시킬 준비가 되면 종료 단계로 넘어갑니다.
do_exit 함수는 실제로 프로세스를 종료시키는 역할을 합니다. 이 과정은 프로세스 리소스를 해제시키고 부모 프로세스에게 이를 알리며 점유하고 있던 태스크 디스크립터와 스택 메모리를 반환하는 순서로 진행됩니다.
4. 결론
지금까지 프로세스를 실행했을때 Linux 커널에서 일어나는 일들에 대해서 알아봤습니다.
Linux 커널에서 어떤 일이 일어나는지 확인하기 위해 Trace 도구인 ftrace를 사용했으며, 이를 적절히 세팅하는 것으로 원하는 이벤트를 추적할 수 있었습니다.
이를 통해 프로세스의 생성, 실행 및 종료에 관한 로그를 얻을 수 있었으며 이를 분석해 그 과정에서 어떤 함수들이 호출되는지 확인할 수 있었습니다.
이번 포스팅에서는 간단한 Linux 프로그램인 "ls"를 실행했을때의 로그를 분석했지만, ftrace는 광범위하게 사용되는 tracing 도구이기 때문에 Linux 디버깅에 유용하게 사용할 수 있습니다.
5. 마무리
Linux는 서버 및 네트워크를 다루는 엔지니어라면 필수적으로 다루게 되는 운영체제입니다.
물론 Linux의 커널 단까지 몰라도 이용하는데에는 전혀 무리가 없겠지만, Linux를 advanced하게 다룰 수 있기 위해서는 Linux의 코어에 해당하는 커널이 어떻게 돌아가는지 알고 있어야 한다고 생각합니다.
저는 이번 포스팅을 작성하며 Linux 커널과 조금 친해졌다는 생각이 드는데요.
기존에는 검은 안개처럼 어두웠던 Linux 커널이라는 영역이 이제 조금 밝혀지면서 Linux의 동작 방식을 더 잘 이해할 수 있게 되었습니다.
앞으로도 가지고 있는 지식 중에서 검은 안개와도 같던 영역을 없애나가는 것을 목표로 해야겠습니다.
이 포스팅을 읽는 여러분들도 각자의 검은 안개들을 밝혀나갈 수 있기를 바랍니다.
