부모 자식 프로세스 생성 실습 및 ftrace 로그 분석 


이번에 리눅스 시스템 프로그래밍으로 프로세스를 생성해 봅시다. 소스 코드는 다음과 같으니 같이 입력해 봅시다.
1  #include <stdio.h>
2  #include <unistd.h>
3  #include <sys/types.h>
4
5  #define PROC_TIMES  7
6  #define SLEEP_DURATION  2
7  #define FORK_MAX_TIMES  3
8
9  void raspbian_proc_process(void);
10
11 void raspbian_proc_process(void) 
12 {
13 int proc_times = 0;
14
15 for(proc_times = 0; proc_times < PROC_TIMES; proc_times++) {
16 printf("raspbian tracing ppid:%d pid:%d \n", getppid(), getpid());
17 sleep(SLEEP_DURATION);
18 }
19
20  exit(EXIT_SUCCESS);
21 }

22 int main() 
23 {
24 pid_t pid;
25 int fork_times = 0;
26
27 printf("About to fork process \n");
28
29 pid = fork();
30
31 if ( pid == 0 )  {
32 printf("start execution of child process\n");
33 raspbian_proc_process();
34 }
35
36 else if ( pid > 0 ) {
37 printf("start execution of parent process\n");
38 raspbian_proc_process();
39 }
40
41 return 0;
42 }

이전 절에 작성한 코드에서 다음 동작이 추가됐습니다. 29번째 줄 코드부터 분석을 시작합니다.
29 pid = fork();
30
31 if ( pid == 0 )  {
32 printf("start execution of child process\n");
33 raspbian_proc_process();
34 }
35
36 else if ( pid > 0 ) {
37 printf("start execution of parent process\n");
38 raspbian_proc_process();
39 }

fork() 함수를 호출해서 자식 프로세스를 생성합니다. fork() 함수는 실행 후 pid란 지역변수로 반환값을 저장합니다. pid가 0이면 자식 프로세스 혹은 pid가 0보다 크면 부모 프로세스가 생성된 겁니다. 만약 fork() 함수 실행 도중 오류가 발생하면 자식 프로세스가 생성되지 않고 -1를 반환합니다.

위 코드를 입력한 다음 raspbian_test_fork.c 란 이름으로 저장합시다.
raspbian_fork: raspbian_test_fork.c
gcc -o raspbian_fork raspbian_test_fork.c

이전 시간에 작성한 ftrace 로그 설정 셸 스크립트인 ./clone_process_debug.sh를 실행합니다.

다음 명령어로 raspbian_fork 프로세스를 실행합시다.
root@raspberrypi:/home/pi # ./raspbian_fork 
About to fork process 
start execution of parent process
raspbian tracing ppid:895 pid:17120 
start execution of child process
raspbian tracing ppid:17120 pid:17121 
raspbian tracing ppid:895 pid:17120 
raspbian tracing ppid:17120 pid:17121

화면에 출력되는 메시지는 raspbian_test_fork.c 파일에서 작성한 코드가 실행하면서 출력합니다. pid가 17120/17121인 프로세스가 실행하는 것으로 보입니다.

다음 명령어로 실행 중인 프로세스를 확인합시다.
root@raspberrypi:/home/pi # ps -ely | grep raspbian_fork
S   UID   PID  PPID  C PRI  NI   RSS    SZ WCHAN  TTY          TIME CMD
S  1000 17120   895  0  80   0   320   453 hrtime pts/0    00:00:00 raspbian_fork
S  1000 17121 17120  0  80   0    96   453 hrtime pts/0    00:00:00 raspbian_fork

위 메시지로 보아 pid가 17121인 raspbian_fork 프로세스의 부모 프로세스의 pid는 17120임을 알 수 있습니다. 마찬가지로 pid가 17120인 raspbian_fork 프로세스 부모 프로세스 pid는 895입니다. 

이렇게 raspbian_fork 프로세스를 실행하면 14초 정도 구동하다가 프로세스가 종료합니다. 그 이유는 14초 정도 raspbian_proc_process() 함수 실행 후 다음 20번째 줄 코드와 같이 exit() 함수를 실행해서 프로세스를 종료하기 때문입니다.
11 void raspbian_proc_process(void) 
12 {
13 int proc_times = 0;
14
15 for(proc_times = 0; proc_times < PROC_TIMES; proc_times++) {
16 printf("raspbian tracing ppid:%d pid:%d \n", getppid(), getpid());
17 sleep(SLEEP_DURATION);
18 }
19
20  exit(EXIT_SUCCESS);
21 }

이 후 이전에 썼던 방식으로 다음 스크립트를 실행해서 ftrace 로그를 라즈베리파이에서 추출합시다.
root@raspberrypi:/home/pi#./get_ftrace.sh

프로세스 생성과 종료 과정 메시지가 포함된 ftrace 전체 로그는 다음과 같습니다. 각 단계 별로 ftrace 로그를 분석하겠습니다.
1 raspbian_fork-17120 [003] ....1318.513909: copy_process+0x14/0x17d8 <-_do_fork+0xb0/0x3ec
2  raspbian_fork-17120 [003] ....1318.513921: <stack trace>
3 => _do_fork+0xb0
4 => SyS_clone+0x30
5 => ret_fast_syscall+0x0
...
6 raspbian_fork-17120 [003] d...1318.514446: sched_switch: prev_comm=raspbian_fork prev_pid=17120 prev_prio=120 prev_state=S ==> next_comm=swapper/3 next_pid=0 next_prio=120
7 raspbian_fork-17121 [002] d...1318.514869: sched_switch: prev_comm=raspbian_fork prev_pid=17121 prev_prio=120 prev_state=S ==> next_comm=swapper/2 next_pid=0 next_prio=120
...
8 raspbian_fork-17120 [003] d...1320.514615: sched_switch: prev_comm=raspbian_fork prev_pid=17120 prev_prio=120 prev_state=S ==> next_comm=swapper/3 next_pid=0 next_prio=120
9 raspbian_fork-17121 [002] d...1320.515011: sched_switch: prev_comm=raspbian_fork prev_pid=17121 prev_prio=120 prev_state=S ==> next_comm=kworker/u8:0 next_pid=17108 next_prio=120
...
10 raspbian_fork-17120 [003] d...1322.514829: sched_switch: prev_comm=raspbian_fork prev_pid=17120 prev_prio=120 prev_state=S ==> next_comm=kworker/u8:0 next_pid=17108 next_prio=120
11 raspbian_fork-17121 [002] d...1322.515192: sched_switch: prev_comm=raspbian_fork prev_pid=17121 prev_prio=120 prev_state=S ==> next_comm=kworker/u8:0 next_pid=17108 next_prio=120
...
12 raspbian_fork-17121 [002] ....  1343.333582: do_exit+0x14/0xc18 <-do_group_exit+0x50/0xe4
13 raspbian_fork-17120 [003] ....  1343.333583: do_exit+0x14/0xc18 <-do_group_exit+0x50/0xe4
14 raspbian_fork-17121 [002] ....  1343.333621: <stack trace>
15 => SyS_exit_group+0x24/SyS_exit_group+0x24
16 => ret_fast_syscall+0x0/0x28
17   raspbian_fork-17120 [003] ....  1343.333621: <stack trace>
18 => SyS_exit_group+0x24/SyS_exit_group+0x24
19 => ret_fast_syscall+0x0/0x28
20 lxterminal-876   [000] d...  1343.333844: sched_switch: prev_comm=lxterminal prev_pid=876 prev_prio=120 prev_state=S ==> next_comm=Xorg next_pid=454 next_prio=120
21 Xorg-454   [000] dn..  1343.333946: sched_wakeup: comm=lxterminal pid=876 prio=120 target_cpu=000
22 Xorg-454   [000] d...  1343.333957: sched_switch: prev_comm=Xorg prev_pid=454 prev_prio=120 prev_state=R ==> next_comm=lxterminal next_pid=876 next_prio=120
23 raspbian_fork-17120 [003] ....  1343.333959: sched_process_exit: comm=raspbian_fork pid=17120 prio=120
24 raspbian_fork-17121 [002] ....  1343.333980: sched_process_exit: comm=raspbian_fork pid=17121 prio=120
25 raspbian_fork-17120 [003] d...  1343.334028: signal_generate: sig=17 errno=0 code=2 comm=bash pid=895 grp=1 res=0
26 lxterminal-876   [000] dnh.  1343.334048: sched_wakeup: comm=bash pid=895 prio=120 target_cpu=000
27 raspbian_fork-17121 [002] d...  1343.334049: signal_generate: sig=17 errno=0 code=2 comm=systemd pid=1 grp=1 res=0

1번째 로그부터 분석을 시작합니다.
1 raspbian_fork-17120 [003] ....1318.513909: copy_process+0x14/0x17d8 <-_do_fork+0xb0/0x3ec
2 raspbian_fork-17120 [003] ....1318.513921: <stack trace>
3 => _do_fork+0xb0
4 => SyS_clone+0x30
5 => ret_fast_syscall+0x0

pid가 17120인 raspbian_fork 프로세스가 pid가 17121인 raspbian_fork 프로세스를 생성하는 동작입니다.
raspbian_test_fork.c 파일에서 유저 공간에서 프로세스를 생성하는 코드는 29번째 줄과 같았습니다. 
22 int main() 
23 {
24 pid_t pid;
25 int fork_times = 0;
26
27 printf("About to fork process \n");
28
29 pid = fork();

유저 공간에서 fork() 함수를 호출하면 시스템 콜이 실행해서 커널 공간에서 SyS_clone() 이란 함수를 호출하는 겁니다.

다음 6~11번째 줄 로그를 분석해봅시다.
6 raspbian_fork-17120 [003] d...1318.514446: sched_switch: prev_comm=raspbian_fork prev_pid=17120 prev_prio=120 prev_state=S ==> next_comm=swapper/3 next_pid=0 next_prio=120
7 raspbian_fork-17121 [002] d...1318.514869: sched_switch: prev_comm=raspbian_fork prev_pid=17121 prev_prio=120 prev_state=S ==> next_comm=swapper/2 next_pid=0 next_prio=120
...
8 raspbian_fork-17120 [003] d...1320.514615: sched_switch: prev_comm=raspbian_fork prev_pid=17120 prev_prio=120 prev_state=S ==> next_comm=swapper/3 next_pid=0 next_prio=120
9 raspbian_fork-17121 [002] d...1320.515011: sched_switch: prev_comm=raspbian_fork prev_pid=17121 prev_prio=120 prev_state=S ==> next_comm=kworker/u8:0 next_pid=17108 next_prio=120
...
10 raspbian_fork-17120 [003] d...1322.514829: sched_switch: prev_comm=raspbian_fork prev_pid=17120 prev_prio=120 prev_state=S ==> next_comm=kworker/u8:0 next_pid=17108 next_prio=120
11 raspbian_fork-17121 [002] d...1322.515192: sched_switch: prev_comm=raspbian_fork prev_pid=17121 prev_prio=120 prev_state=S ==> next_comm=kworker/u8:0 next_pid=17108 next_prio=120

raspbian_fork-17120와 raspbian_fork-17121 프로세스가 2초 간격으로 스케줄링되어 실행합니다. 
raspbian_test_fork.c 파일에서 다음과 같이 두 개 프로세스가 2초 주기로 휴면되도록 구현한 코드가 실행하는 겁니다.
11 void raspbian_proc_process(void) 
12 {
13 int proc_times = 0;
14
15 for(proc_times = 0; proc_times < PROC_TIMES; proc_times++) {
16 printf("raspbian tracing ppid:%d pid:%d \n", getppid(), getpid());
17 sleep(SLEEP_DURATION);
18 }
19
20  exit(EXIT_SUCCESS);
21 }

다음은 유저 레벨 프로세스에서 위에서 보이는 20번째 줄 exit(EXIT_SUCCESS); 함수를 실행하면 커널에서 어떤 동작을 하는지 살펴볼 차례입니다. 

exit() 리눅스 저수준 표준 함수 중 하나이며 리눅스 시스템 프로그램에서 많이 쓰는 함수입니다. 
다음 리눅스 메뉴얼 페이지에서 exit() 함수에 대한 내용을 읽을 수 있습니다.
EXIT(3)                   Linux Programmer's Manual                  EXIT(3)
NAME         top
       exit - cause normal process termination
SYNOPSIS         top
       #include <stdlib.h>

       void exit(int status);
DESCRIPTION         top
       The exit() function causes normal process termination and the value
       of status & 0377 is returned to the parent (see wait(2)).

명시적으로 프로세스를 종료시키는 동작입니다.
로그 분석으로 돌아가겠습니다.
12 raspbian_fork-17121 [002] ....  1343.333582: do_exit+0x14/0xc18 <-do_group_exit+0x50/0xe4
13 raspbian_fork-17120 [003] ....  1343.333583: do_exit+0x14/0xc18 <-do_group_exit+0x50/0xe4
14 raspbian_fork-17121 [002] ....  1343.333621: <stack trace>
15 => SyS_exit_group+0x24/SyS_exit_group+0x24
16 => ret_fast_syscall+0x0/0x28
17   raspbian_fork-17120 [003] ....  1343.333621: <stack trace>
18 => SyS_exit_group+0x24/SyS_exit_group+0x24
19 => ret_fast_syscall+0x0/0x28

raspbian_fork-17120와 raspbian_fork-17121 프로세스가 종료하는 동작입니다.
이 로그에서 프로세스가 종료하는 흐름은 다음 그림과 같습니다.

리눅스 저수준 exit() 함수를 유저 프로세스에서 실행하니 해당 함수에 대한 시스템 콜 핸들러인 sys_exit_group() 함수에서 do_group_exit() -> do_exit() 순서로 함수를 호출해서 두 프로세스를 종료합니다.

마지막으로 27~31번째 줄 로그를 봅시다.
27 raspbian_fork-17120 [003] ....  1343.333959: sched_process_exit: comm=raspbian_fork pid=17120 prio=120
28 raspbian_fork-17121 [002] ....  1343.333980: sched_process_exit: comm=raspbian_fork pid=17121 prio=120
29 raspbian_fork-17120 [003] d...  1343.334028: signal_generate: sig=17 errno=0 code=2 comm=bash pid=895 grp=1 res=0
30 lxterminal-876   [000] dnh.  1343.334048: sched_wakeup: comm=bash pid=895 prio=120 target_cpu=000
31 raspbian_fork-17121 [002] d...  1343.334049: signal_generate: sig=17 errno=0 code=2 comm=systemd pid=1 grp=1 res=0

sched_process_exit 이란 ftrace 이벤트로 pid 17120, 17121 인 raspbian_fork 프로세스가 종료하고, 각각 부모 프로세스에 시그널을 전달합니다.

raspbian_fork-17120 프로세스는 bash란 부모 프로세스에 시그널을 전달하고, raspbian_fork-17121 프로세스는 부모 프로세스인 raspbian_fork-17120가 종료됐으니 pid가 1인 systemd 프로세스에 시그널을 전달합니다.
29 raspbian_fork-17120 [003] d...  1343.334028: signal_generate: sig=17 errno=0 code=2 comm=bash pid=895 grp=1 res=0
30 lxterminal-876   [000] dnh.  1343.334048: sched_wakeup: comm=bash pid=895 prio=120 target_cpu=000
31 raspbian_fork-17121 [002] d...  1343.334049: signal_generate: sig=17 errno=0 code=2 comm=systemd pid=1 grp=1 res=0

유저 공간에서 fork() 이란 함수를 호출하면 리눅스 커널에서 어떤 과정으로 프로세스를 생성하는지 확인했습니다. 이번에 다룬 내용을 정리합시다.
1. 유저 공간에서 fork() 함수를 호출하면 시스템 콜이 실행되어 커널 공간에 있는 SyS_clone()이란 함수를 호출하고 _do_fork() 이란 프로세스를 생성하는 함수를 호출합니다.

2. 유저 레벨 프로세스는 스스로 프로세스를 생성하지 못합니다. 시스템 라이브러리 도움을 받아서 커널 공간에 프로세스 생성 요청을 합니다.

3. 프로세스를 종료할 때 do_exit() 함수를 호출합니다.

4. 프로세스가 종료할 때 부모 프로세스에게 자신이 종료됐다는 사실을 시그널로 알립니다.

유저 공간에서 어떤 함수를 호출하면 리눅스 커널에서 어떤 함수 흐름으로 코드가 실행되는지 전체 그림을 그리면서 파악하는 것이 중요합니다.

Reference(프로세스 관리)
4.9 프로세스 컨택스트 정보는 어떻게 저장할까?
 4.9.1 컨택스트 소개
 4.9.2 인터럽트 컨택스트 정보 확인하기
 4.9.3 Soft IRQ 컨택스트 정보 확인하기
 4.9.4 선점 스케줄링 여부 정보 저장
4.10 프로세스 디스크립터 접근 매크로 함수
 4.10.1 current_thread_info()
 4.10.2 current 매크로란
4.11 프로세스 디버깅
 4.11.1 glibc fork 함수 gdb 디버깅
 4.11.2 유저 프로그램 실행 추적 



저작자표시

'리눅스 커널의 구조와 원리 > 4. 프로세스(Process) 관리' 카테고리의 다른 글

[리눅스커널] 프로세스를 생성 세부 함수 분석: do_fork() copy_process()  (0) 2019.03.10
[리눅스커널] 커널 스레드란 무엇인가  (0) 2019.03.10
[리눅스커널][프로세스] 기본 유저 레벨 프로세스 실행 실습 및 ftrace 로그 분석  (0) 2019.02.11
[리눅스커널][프로세스] 프로세스는 어떻게 생성하나?  (0) 2019.02.11
[리눅스커널][프로세스] ps 명령어로 프로세스 확인하기  (0) 2019.02.11

+ Recent posts

티스토리툴바