ARM Linux Kernel Hacks

rousalome.egloos.com

포토로그 Kernel Crash


통계 위젯 (화이트)

191239
1625
172588


[리눅스커널] 프로세스: 유저 프로그램 실행 흐름 추적하기 4. 프로세스(Process) 관리

이번 장에서는 유저 공간에서 fork() 시스템 콜 함수를 호출하면 유저 프로세스가 실행된다고 설명한 바 있습니다. 그런데 유저 프로세스를 생성하는 목적은 크게 다음과 같은 두 가지로 분류할 수 있습니다.

fork() 시스템 콜 함수를 호출해 같은 미션의 프로그램을 여러 프로세스가 나눠서 실행
exev() 시스템 콜 함수로 아예 새로운 프로그램을 생성해서 실행

우리가 리눅스 시스템 프로그램으로 프로세스를 생성할 때는 대부분 첫 번째 방식을 사용합니다. 그래서 이번 장에서는 첫 번째 방법에 초점을 맞춰 유저 프로세스의 생성 과정을 설명한 것입니다. 하지만 두 번째 방식으로 유저 프로세스를 실행할 때가 있습니다. 이미 만들어 놓은 프로그램 파일을 실행하고 싶을 때입니다. 그래서 이번 절에서는 디버깅 실습으로 두 번째 방식으로 유저 프로세스가 실행되는 과정을 알아보겠습니다.

먼저 다음과 같은 질문을 드리겠습니다. 리눅스 터미널에서 명령어를 입력하면 커널에서 어떤 방식으로 관련 프로세스를 실행할까요? 

두 번째 방식으로 유저 프로세스가 실행을 시작합니다. 예를 들면 다음과 같습니다.

ls: 현재 파일 정보를 출력 
whoami: 사용자명을 출력
cat: 파일의 내용을 간단하게 출력

그런데 위와 같은 리눅스 명령어는 리눅스에서 제공하는 유틸리티 프로그램이 실행되는 것입니다. 각 프로그램은 아래 폴더에서 확인할 수 있습니다.

/usr/bin
/bin

하지만 리눅스에서 제공하는 유틸리티 프로그램은 우리가 실행만 하지 소스를 수정할 일이 거의 없습니다. 이번 절에는 whoami와 cat 명령어를 입력했을 때 커널에서 어떤 과정으로 프로세스를 생성하는지 살펴보겠습니다.

이번 실습에서는 코드를 입력할 필요가 없습니다. 다음 단계를 따라하면 됩니다.

1단계: ftrace 설정
2단계: 리눅스 터미널에서 whoami와 cat /proc/interrupts 명령어 입력
3간계: ftrace 로그 추출

ftrace 로그 설정

ftrace 로그를 설정하는 셸 스크립트 코드는 다음과 같습니다.

#!/bin/bash

echo 0 > /sys/kernel/debug/tracing/tracing_on
sleep 1
echo "tracing_off"

echo 0 > /sys/kernel/debug/tracing/events/enable
sleep 1
echo "events disabled"

echo  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.5 > /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_stack_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"

위 명령어에서 중요한 부분만 살펴보겠습니다.

1 "echo 1 > /sys/kernel/debug/tracing/events/sched/sched_process_exec/enable"
2 "echo 1 > /sys/kernel/debug/tracing/events/sched/sched_process_exit/enable"
3 "echo 1 > /sys/kernel/debug/tracing/events/sched/sched_process_fork/enable"
4 "echo 1 > /sys/kernel/debug/tracing/events/sched/sched_process_free/enable"
5
6 "echo  _do_fork sys_clone do_exit search_binary_handler copy_process* > /sys/kernel/debug/tracing/set_ftrace_filter"

ftrace 이벤트가 sched_xxxx로 시작하면 보통 프로세스 스케줄링 동작을 출력할 것이라 예상합니다. 그런데 프로세스 생성, 실행, 종료, 프로세스 자원 해제에 대한 동작을 추적할 수 있습니다. 각 이벤트가 어떤 커널 동작을 추적하는지 살펴보면 다음과 같습니다.

sched_process_fork: 프로세스 생성
sched_process_exec: 프로세스 실행
sched_process_exit: 프로세스 종료
sched_process_free: 프로세스 자원(메모리, 태스크 디스크립터) 해제

이번에는 함수의 콜스택을 지정하는 명령어를 보겠습니다.

echo sys_clone do_exit search_binary_handler  copy_process.part.5 > /sys/kernel/debug/tracing/set_ftrace_filter

위 명령어는 다음 함수의 콜스택을 보기 위해 필터를 지정합니다.

sys_clone() 
do_exit() 
copy_process
search_binary_handler()  

모두 프로세스를 실행하고 종료할 때 호출되는 커널 함수입니다.

ftrace 로그를 설정하고 터미널에서 다음 명령어를 입력합시다.

whoami
cat /proc/interrupts

위 명령어를 라즈베리 파이 터미널에서 각각 입력하면 다음과 같은 출력 결과를 확인할 수 있습니다.

root@raspberrypi:/home/pi# whoami
root
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

위 명령어 입력이 끝난 후 4.4.1/4.4.2절에서 소개한 get_ftrace.sh 셸 스크립트를 실행해 ftrace 로그를 받습니다.

root@raspberrypi:/home/pi# ./get_ftrace.sh 
ftrace off

ftrace 로그 분석

ftrace 로그는 whoami와 cat 명령어를 입력했을 때의 프로세스 실행 정보를 담고 있습니다. 먼저 whoami 명령어를 입력했을 때의 커널 동작을 ftrace로 알아보겠습니다.

ftrace 로그 분석: whoami 명령어를 입력했을 때

whoami 명령어를 입력했을 때의 ftrace 메시지를 분석하겠습니다. 분석할 로그는 다음과 같습니다.

01 bash-2181 [001] .... 9537.645900: copy_process.part.5+0x14/0x1b08 <-_do_fork+0xd8/0x438
02 bash-2181 [001] .... 9537.645914: <stack trace>
03 => copy_process.part.5+0x18/0x1b08
04 => _do_fork+0xd8/0x438
05 => sys_clone+0x34/0x3c
06 => ret_fast_syscall+0x0/0x28
07 => 0x7ed03260
08 bash-2181 [001] .... 9537.646406: sched_process_fork: comm=bash pid=2181 child_comm=bash child_pid=30082
09 whoami-30082 [001] .... 9537.648249: search_binary_handler+0x10/0x24c <-__do_execve_file+0x530/0x7d4
10 whoami-30082 [001] .... 9537.648288: <stack trace>
11 => search_binary_handler+0x14/0x24c
12 => __do_execve_file+0x530/0x7d4
13 => do_execve+0x3c/0x44
14 => sys_execve+0x2c/0x30
15 => ret_fast_syscall+0x0/0x28
16 => 0x7ed03304
17 whoami-30082 [001] .... 9537.649127: sched_process_exec: filename=/usr/bin/whoami pid=30082 old_pid=30082
18 whoami-30082 [001] .... 9537.653404: do_exit+0x14/0xc18 <-do_group_exit+0x4c/0xe4
19 whoami-30082 [001] .... 9537.653452: <stack trace>
20 => do_exit+0x18/0xc18
21 => do_group_exit+0x4c/0xe4
22 => __wake_up_parent+0x0/0x30
23 => ret_fast_syscall+0x0/0x28
24 => 0x7ec605c8
 
먼저 whoami 프로세스를 생성하는 01~06번째 줄을 보겠습니다.

01 bash-2181 [001] .... 9537.645900: copy_process.part.5+0x14/0x1b08 <-_do_fork+0xd8/0x438
02 bash-2181 [001] .... 9537.645914: <stack trace>
03 => copy_process.part.5+0x18/0x1b08
04 => _do_fork+0xd8/0x438
05 => sys_clone+0x34/0x3c
06 => ret_fast_syscall+0x0/0x28

이번 장에서 많이 봤던 패턴의 로그입니다. 즉, _do_fork() 함수를 호출해 프로세스를 생성하는 동작입니다.

다음으로 08번째 줄을 보겠습니다.

08 bash-2181 [001] .... 9537.646406: sched_process_fork: comm=bash pid=2181 child_comm=bash child_pid=30082

ftrace의 sched_process_fork 이벤트 메시지로 프로세스가 생성하는 세부 정보를 알 수 있습니다. 위 로그는 pid가 2181인 bash 프로세스가 pid가 30082인 프로세스를 생성한다는 의미입니다.

여기서 child_comm과 child_pid가 생성되는 프로세스 정보입니다. 그런데 한 가지 의문이 생깁니다. 생성하는 프로세스의 이름이 부모 프로세스의 이름과 같다는 것입니다.

프로세스를 생성할 때는 부모 프로세스의 리소스를 복제합니다. 자식 프로세스가 복제되는 단계에서 부모 프로세스 이름은 그대로 물려 봤습니다. 하지만 프로세스 생성이 끝난 시점에는 자신만의 이름을 갖게 됩니다.

다음으로 09~15번째 줄을 보겠습니다.

09 whoami-30082 [001] .... 9537.648249: search_binary_handler+0x10/0x24c <-__do_execve_file+0x530/0x7d4
10 whoami-30082 [001] .... 9537.648288: <stack trace>
11 => search_binary_handler+0x14/0x24c
12 => __do_execve_file+0x530/0x7d4
13 => do_execve+0x3c/0x44
14 => sys_execve+0x2c/0x30
15 => ret_fast_syscall+0x0/0x28

함수의 호출 방향은 15~09번째 줄입니다. 이 중에서 가장 먼저 눈여겨볼 함수의 이름은 14번째 줄의 sys_execve()입니다. sys_execve() 함수는 execve 시스템 콜 핸들러 함수이므로 유저 공간에서 execve POSIX 시스템 콜을 발생했다는 사실을 알 수 있습니다. 이 정보를 토대로 fork() 시스템 콜 이후에 execve() 시스템 콜을 유저 공간에서 실행했다는 사실을 알 수 있습니다.

이처럼 리눅스에 내장된 유틸리티 프로그램을 실행해서 생성되는 프로세스의 동작은 2단계로 나눌 수 있습니다.

다음으로 17번째 줄을 보겠습니다.

17 whoami-30082 [001] .... 9537.649127: sched_process_exec: filename=/usr/bin/whoami pid=30082 old_pid=30082

위 메시지는 ftrace의 sched_process_exec 이벤트를 통해 프로세스 실행 정보를 출력한 것입니다. 이것은 실행을 시작하는, pid가 30082인 whoami 프로세스의 정체는 /usr/bin/whoami라고 해석할 수 있습니다. 즉, whoami 명령어를 입력하면 실행되는 파일의 정체는 /usr/bin/whoami인 것입니다. 

그렇다면 위와 같은 메시지는 어느 함수에서 출력하는 것일까요? 시스템 콜 핸들러인 sys_execve() 함수가 호출된 후 다음 함수 흐름으로 exec_binprm() 함수가 실행됩니다.

do_execveat_common() 
exec_binprm()

exec_binprm() 함수를 보면서 세부 동작을 파악해 봅시다.

https://elixir.bootlin.com/linux/v4.19.30/source/fs/exec.c
1 static int exec_binprm(struct linux_binprm *bprm)
2 {
3 pid_t old_pid, old_vpid;
4 int ret;
5
6 /* Need to fetch pid before load_binary changes it */
7 old_pid = current->pid;
8 rcu_read_lock();
9 old_vpid = task_pid_nr_ns(current, task_active_pid_ns(current->parent));
10 rcu_read_unlock();
11
12 ret = search_binary_handler(bprm);
13 if (ret >= 0) {
14 audit_bprm(bprm);
15 trace_sched_process_exec(current, old_pid, bprm);

15번째 줄에서 whoami 프로세스가 실행을 시작하는 동작을 ftrace 이벤트로 출력합니다.

디렉터리를 포함한 파일 이름은 /usr/bin/whoami이고 pid는 30082입니다. /usr/bin/whoami는 리눅스 시스템에 파일 형태로 존재합니다. 그런데 이 파일 자체가 프로세스는 아닙니다. 커널이 이 파일을 메모리에 적재해서 실행할 때가 프로세스인 것입니다.

이 프로세스가 실행을 시작하는 동작은 17번째 줄로 알 수 있습니다. 

17 whoami-30082 [001] .... 9537.649127: sched_process_exec: filename=/usr/bin/whoami pid=30082 old_pid=30082

다음으로 18~23번째 줄을 보겠습니다.

18 whoami-30082 [001] .... 9537.653404: do_exit+0x14/0xc18 <-do_group_exit+0x4c/0xe4
19 whoami-30082 [001] .... 9537.653452: <stack trace>
20 => do_exit+0x18/0xc18
21 => do_group_exit+0x4c/0xe4
22 => __wake_up_parent+0x0/0x30
23 => ret_fast_syscall+0x0/0x28

whoami 프로세스가 종료되는 로그입니다. whoami 명령어를 입력하고 root란 결과를 출력했으니 프로세스를 바로 종료하는 것입니다. 이것은 유저 공간에서 exit() 함수를 호출하면 실행되는 코드의 흐름입니다.

위 콜스택의 22번째 줄에서 __wake_up_parent+0x0이라는 정보를 볼 수 있습니다. 하지만 정확한 디버깅 정보는 다음과 같이 sys_exit_group+0xc 입니다.

18 whoami-30082 [001] .... 9537.653404: do_exit+0x14/0xc18 <-do_group_exit+0x4c/0xe4
19 whoami-30082 [001] .... 9537.653452: <stack trace>
20 => do_exit+0x18/0xc18
21 => do_group_exit+0x4c/0xe4
22 => sys_exit_group+0xc/0x3c
23 => ret_fast_syscall+0x0/0x28

여기서 다시 의문이 생깁니다. __wake_up_parent+0x0 심벌 정보가 sys_exit_group+0xc인 이유는 무엇일까요?

이 내용은 4.4.2절에서 이미 다뤘는데 복습하는 차원에서 중요 내용만 설명하겠습니다.

ARM 아키텍처에서는 파이프라인을 적용합니다. 그래서 실제로 실행된 코드 주소에서 +0x4만큼 떨어진 주소를 프로그램 카운터로 저장합니다. 그래서 ftrace 콜스택 정보에서 함수 이름 오른쪽에 실행 주소의 오프셋이 0x0이면 실제 함수 이름이 아닐 가능성이 높습니다.

실제 어셈블리 코드를 보면 실제로 sys_exit_group() 함수의 마지막 코드에서 do_group_exit() 함수를 호출합니다.

01 801213c4 <sys_exit_group>:
02 801213c4: e1a0c00d mov ip, sp
03 801213c8: e92dd800 push {fp, ip, lr, pc}
...
04 801213dc: e2000cff and r0, r0, #65280 ; 0xff00
05 801213e0: ebffffbe bl 801212e0 <do_group_exit>
06
07 801213e4 <__wake_up_parent>:

ftrace 콜스택 정보에서 함수 이름 오른쪽에 있는 실행 주소 오프셋이 0x0이면 함수 이름이 맞는지 의심해봅시다.

ftrace 로그 분석: cat 명령어를 입력했을 때

이어서 cat 명령어를 입력했을 때의 ftrace 메시지를 분석하겠습니다.

01 bash-2181 [001] .... 9541.693910: copy_process.part.5+0x14/0x1b08 <-_do_fork+0xd8/0x438
02 bash-2181 [001] .... 9541.693925: <stack trace>
03 => copy_process.part.5+0x18/0x1b08
04 => _do_fork+0xd8/0x438
05 => sys_clone+0x34/0x3c
06 => ret_fast_syscall+0x0/0x28
07 => 0x7ed03260
08 bash-2181  [001] .... 9541.694405: sched_process_fork: comm=bash pid=2181 child_comm=bash child_pid=30083
09 cat-30083 [000] .... 9541.696001: search_binary_handler+0x10/0x24c <-__do_execve_file+0x530/0x7d4
10 cat-30083 [000] .... 9541.696041: <stack trace>
11 => search_binary_handler+0x14/0x24c
12 => __do_execve_file+0x530/0x7d4
13 => do_execve+0x3c/0x44
14 => sys_execve+0x2c/0x30
15 => ret_fast_syscall+0x0/0x28
16 => 0x7ed03304
17 cat-30083 [000] .... 9541.697012: sched_process_exec: filename=/bin/cat pid=30083 old_pid=30083
18 cat-30083 [000] .... 9541.700627: do_exit+0x14/0xc18 <-do_group_exit+0x4c/0xe4
19 cat-30083 [000] .... 9541.700661: <stack trace>
20 => do_exit+0x18/0xc18
21 => do_group_exit+0x4c/0xe4
22 => __wake_up_parent+0x0/0x30
23 => ret_fast_syscall+0x0/0x28
24 => 0x7ebba5c8

먼저 cat 프로세스를 생성하는 01~06번째 줄을 보겠습니다.

01 bash-2181 [001] .... 9541.693910: copy_process.part.5+0x14/0x1b08 <-_do_fork+0xd8/0x438
02 bash-2181 [001] .... 9541.693925: <stack trace>
03 => copy_process.part.5+0x18/0x1b08
04 => _do_fork+0xd8/0x438
05 => sys_clone+0x34/0x3c
06 => ret_fast_syscall+0x0/0x28

_do_fork() 함수를 호출해 cat 프로세스를 생성하는 동작입니다.

다음으로 08번째 줄을 보겠습니다.

08 bash-2181  [001] .... 9541.694405: sched_process_fork: comm=bash pid=2181 child_comm=bash child_pid=30083

08번째 줄은 ftrace의 sched_process_fork 이벤트 메시지로서 프로세스가 생성하는 세부 정보를 출력합니다. 위 로그는 pid가 2181인 bash 프로세스가 pid가 30083인 프로세스를 생성한다는 의미입니다. 여기서 child_comm과 child_pid이 생성되는 프로세스 정보입니다. 

다음으로 09~15번째 줄을 보겠습니다.

09 cat-30083 [000] .... 9541.696001: search_binary_handler+0x10/0x24c <-__do_execve_file+0x530/0x7d4
10 cat-30083 [000] .... 9541.696041: <stack trace>
11 => search_binary_handler+0x14/0x24c
12 => __do_execve_file+0x530/0x7d4
13 => do_execve+0x3c/0x44
14 => sys_execve+0x2c/0x30
15 => ret_fast_syscall+0x0/0x28

이번에도 먼저 눈여겨볼 함수의 이름은 14번째 줄의 sys_execve() 함수입니다. sys_execve() 함수는 execve 시스템 콜 핸들러 함수이므로 유저 공간에서 execve POSIX 시스템 콜을 발생시켰다는 사실을 알 수 있습니다.

다음으로 17번째 줄을 보겠습니다.

17 cat-30083 [000] .... 9541.697012: sched_process_exec: filename=/bin/cat pid=30083 old_pid=30083

위 메시지는 ftrace의 sched_process_exec 이벤트를 통해 프로세스 실행 정보를 출력한 것입니다. 이는 실행을 시작하는, pid가 30083인 cat 프로세스의 정체는 /bin/cat이라는 것을 의미합니다.

이처럼 whoami 명령어를 입력하면 실행되는 파일의 정체는 /bin/cat인 것입니다. 즉, 디렉터리를 포함한 파일명은 /bin/cat이고 pid는 30083입니다.

다음으로 18~23번째 줄을 보겠습니다.

18 cat-30083 [000] .... 9541.700627: do_exit+0x14/0xc18 <-do_group_exit+0x4c/0xe4
19 cat-30083 [000] .... 9541.700661: <stack trace>
20 => do_exit+0x18/0xc18
21 => do_group_exit+0x4c/0xe4
22 => __wake_up_parent+0x0/0x30
23 => ret_fast_syscall+0x0/0x28

cat 프로세스가 종료되는 로그입니다. cat 명령어를 입력하고 터미널로 파일 내용을 출력했으니 프로세스는 바로 종료됩니다.

ftrace 로그 분석 내용 정리

이번 절에서는 ftrace 분석으로 다음과 같은 내용을 알게 됐습니다.

리눅스 유틸리티 프로그램을 실행할 때 프로세스는 fork()와 execve() 시스템 콜 함수가 호출된다.
ftrace의 sched_process_exec 이벤트로 리눅스 유틸리티 프로그램의 파일 위치를 알 수 있다.
리눅스 유틸리티 프로그램을 종료할 때의 프로세스는 exit() 시스템 콜 함수를 호출한다.

이번 절에서 배운 내용을 참고해서 다른 리눅스 명령어도 어떤 방식으로 실행되는지 확인해 보면 어떨까요? 이 과정에서 리눅스의 또 다른 재미를 느낄 수 있습니다. 


#프로세스

프로세스 소개 
프로세스 확인하기  
프로세스는 어떻게 생성할까?  
유저 레벨 프로세스 실행 실습  
커널 스레드  
커널 내부 프로세스의 생성 과정   
프로세스의 종료 과정 분석  
태스크 디스크립터(task_struct 구조체)  
스레드 정보: thread_info 구조체  
프로세스의 태스크 디스크립터에 접근하는 매크로 함수  
프로세스 디버깅  
   * glibc의 fork() 함수를 gdb로 디버깅하기  


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

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


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

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

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


 

핑백

덧글

댓글 입력 영역