Linux Kernel(4.19) Hacks

rousalome.egloos.com

포토로그 Kernel Crash


통계 위젯 (화이트)

0112
737
82110


[라즈베리파이] 프로세스 - 자식 프로세스 생성 실습 및 ftrace 로그 분석(2/2) 4장. 프로세스 관리



프로세스 생성과 종료 과정 메시지가 포함된 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(워크큐)
워크큐(Workqueue) Overview



핑백

덧글

댓글 입력 영역