프로세스 생성과 종료 과정 메시지가 포함된 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() 함수에 대한 내용을 읽을 수 있습니다.
[http://man7.org/linux/man-pages/man3/exit.3.html]
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(프로세스)
Reference(워크큐)
워크큐(Workqueue) Overview
최근 덧글