Linux Kernel(4.19) Hacks

rousalome.egloos.com

포토로그 Kernel Crash


통계 위젯 (화이트)

229224
1178
109351


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

이번 챕터에서 유저 공간에서 fork() 시스템 콜 함수를 호출하면 유저 프로세스가 실행된다고 설명을 드렸습니다. 그런데 유저 프로세스를 생성하는 목적은 크게 2가지로 분류할 수 있습니다.
 - fork() 시스템 콜 함수를 호출해 같은 미션의 프로그램을 여러 프로세스가 나눠서 실행
 - exev() 시스템 콜 함수로 아예 새로운 프로그램을 생성해서 실행

우리가 리눅스 시스템 프로그램으로 대부분 프로세스를 생성할 때 1번째 방식을 사용합니다. 그래서 이번 챕터에서는 1번째 방법에 초점을 맞춰서 유저 프로세스 생성 과정을 설명을 드린 것입니다. 하지만 2번째 방식으로 유저 프로세스를 실행할 때가 있습니다. 

   "이미 만들어 놓은 프로그램 파일을 실행하고 싶을 때"

이번 소절에서는 디버깅 실습으로 2번째 방식으로 유저 프로세스가 실행하는 과정을 알아보겠습니다.

먼저 다음 질문을 먼저 드리겠습니다.

   "리눅스 터미널에서 명령어를 입력하면 커널에서 어떤 방식으로 관련 프로세스를 
    실행할까요?"  

2번째 방식으로 유저 프로세스는 실행을 시작합니다. 예를 잠깐 들어볼까요?
 - 'ls': 현재 파일 정보를 출력 
 - 'whoami': 사용자명을 출력
 - 'cat': 파일의 내용을 간단하게 출력

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

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

이번 실습에서는 코드를 입력할 필요는 없습니다. 다음 단계를 따라하면 됩니다.
1단계: ftrace 설정하기
2단계: 리눅스 터미널에서 'whoami'와 'cat /proc/interrupts' 명령어 입력하기
3간계: ftrace 로그 추출하기

ftrace 로그 설정하기
ftrace 로그 설정 코드는 다음과 같습니다.
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: 프로세스 정보(메모리, 태스크 디스크립터) 해제

지정한 함수 콜스택을 확인하려면 다음과 같이 set_ftrace_filter 노드를 지정해야 합니다.
6 "echo  _do_fork sys_clone do_exit copy_process* > /sys/kernel/debug/tracing/set_ftrace_filter"

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://github.com/raspberrypi/linux/blob/rpi-4.19.y/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() 함수를 호출하면 실행하는 코드 흐름입니다."

위 콜스택에서 __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() 시스템 콜 함수를 호출한다.

이번 소절에서 소개한 내용을 참고해 다른 리눅스 명령어도 어떤 방식으로 실행하는지 확인하는 것은 어떨까요? 이 과정에서 리눅스에 대한 재미를 느낄 수 있습니다. 


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

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

#Reference(프로세스 관리)
프로세스 디버깅
   glibc fork 함수 gdb 디버깅





핑백

덧글

댓글 입력 영역