커널 공간에서 raspbian_proc 이란 프로세스가 어떤 코드 흐름으로 생성하고 종료했는지 ftrace 로그로 알아봅시다.
분석할 전체 ftrace 로그는 다음과 같습니다.
1 bash-895 [003] .... 909.253260: SyS_clone+0x14/0x38 <-ret_fast_syscall+0x0/0x28
2 bash-895 [003] .... 909.253295: <stack trace>
3 bash-895 [003] .... 909.253298: _do_fork+0x14/0x3ec <-SyS_clone+0x30/0x38
4 bash-895 [003] .... 909.253310: <stack trace>
5 lxpanel-730 [002] d.h. 909.253310: sched_wakeup: comm=ibus-x11 pid=717 prio=120 target_cpu=002
6 bash-895 [003] .... 909.253312: copy_process.part.5+0x14/0x17d8 <-_do_fork+0xb0/0x3ec
7 bash-895 [003] .... 909.253324: <stack trace>
8 => ret_fast_syscall+0x0/0x28
...
9 bash-895 [003] .... 909.253776: sched_process_fork: comm=bash pid=895 child_comm=bash child_pid=17082
10 <idle>-0 [002] d... 909.253809: sched_switch: prev_comm=swapper/2 prev_pid=0 prev_prio=120 prev_state=R ==> next_comm=bash next_pid=17082 next_prio=120
11 bash-895 [003] d... 909.254159: sched_switch: prev_comm=bash prev_pid=895 prev_prio=120 prev_state=S ==> next_comm=kworker/u8:0 next_pid=1047 next_prio=120
12 <idle>-0 [000] dnh. 909.254206: sched_wakeup: comm=lxterminal pid=876 prio=120 target_cpu=000
13 <idle>-0 [000] d... 909.254215: sched_switch: prev_comm=swapper/0 prev_pid=0 prev_prio=120 prev_state=R ==> next_comm=lxterminal next_pid=876 next_prio=120
14 kworker/u8:0-1047 [003] d... 909.254221: sched_switch: prev_comm=kworker/u8:0 prev_pid=1047 prev_prio=120 prev_state=t ==> next_comm=swapper/3 next_pid=0 next_prio=120
15 raspbian_proc-17082 [002] d.s. 909.254409: sched_wakeup: comm=rcu_sched pid=8 prio=120 target_cpu=002
16 raspbian_proc-17082 [002] d... 909.257817: sched_switch: prev_comm=raspbian_proc prev_pid=17082 prev_prio=120 prev_state=S ==> next_comm=swapper/2 next_pid=0 next_prio=120
...
17 <idle>-0 [002] dnh. 912.257874: sched_wakeup: comm=raspbian_proc pid=17082 prio=120 target_cpu=002
18 raspbian_proc-17082 [002] d... 912.257957: sched_switch: prev_comm=raspbian_proc prev_pid=17082 prev_prio=120 prev_state=S ==> next_comm=swapper/2 next_pid=0 next_prio=120
...
19 <idle>-0 [002] dnh. 915.258028: sched_wakeup: comm=raspbian_proc pid=17082 prio=120 target_cpu=002
20 <idle>-0 [002] d... 915.258044: sched_switch: prev_comm=swapper/2 prev_pid=0 prev_prio=120 prev_state=R ==> next_comm=raspbian_proc next_pid=17082 next_prio=120
21 <idle>-0 [003] dnh. 915.258098: sched_wakeup: comm=kworker/u8:1 pid=17084 prio=120 target_cpu=003
22 raspbian_proc-17082 [002] d... 915.258110: sched_switch: prev_comm=raspbian_proc prev_pid=17082 prev_prio=120 prev_state=S ==> next_comm=swapper/2 next_pid=0 next_prio=120
...
23 raspbian_proc-17082 [002] d... 933.741224: signal_deliver: sig=9 errno=0 code=0 sa_handler=0 sa_flags=0
24 kworker/u8:2-137 [001] d... 933.741230: sched_switch: prev_comm=kworker/u8:2 prev_pid=137 prev_prio=120 prev_state=t ==> next_comm=swapper/1 next_pid=0 next_prio=120
25 raspbian_proc-17082 [002] .... 933.741230: do_exit+0x14/0xc18 <-do_group_exit+0x50/0xe4
26 raspbian_proc-17082 [002] .... 933.741270: <stack trace>
27 => do_signal+0x300/0x3d4
28 => do_work_pending+0xb4/0xcc
29 => slow_work_pending+0xc/0x20
30 lxpanel-730 [000] d... 933.741295: sched_switch: prev_comm=lxpanel prev_pid=730 prev_prio=120 prev_state=S ==> next_comm=Xorg next_pid=454 next_prio=120
31 Xorg-454 [000] dn.. 933.741333: sched_wakeup: comm=openbox pid=723 prio=120 target_cpu=000
32 Xorg-454 [000] d... 933.741346: sched_switch: prev_comm=Xorg prev_pid=454 prev_prio=120 prev_state=R ==> next_comm=openbox next_pid=723 next_prio=120
33 raspbian_proc-17082 [002] .... 933.741609: sched_process_exit: comm=raspbian_proc pid=17082 prio=120
34 ibus-x11-717 [001] d... 933.741639: sched_switch: prev_comm=ibus-x11 prev_pid=717 prev_prio=120 prev_state=S ==> next_comm=swapper/1 next_pid=0 next_prio=120
35 openbox-723 [000] d... 933.741673: sched_switch: prev_comm=openbox prev_pid=723 prev_prio=120 prev_state=S ==> next_comm=Xorg next_pid=454 next_prio=120
36 raspbian_proc-17082 [002] d... 933.741693: signal_generate: sig=17 errno=0 code=2 comm=bash pid=895 grp=1 res=0
먼저 유저 공간에서 프로세스가 생성하면 다음 그림과 같은 흐름으로 _do_fork() 함수가 실행합니다.
리눅스에서 실행 공간은 메모리 접근과 실행 권한 기준으로 유저 공간과 커널 공간으로 구분할 수 있습니다. 유저 공간은 유저 모드, 커널 공간은 커널 모드에서 각각 에서 실행하는 메모리 공간입니다. 유저 공간과 유저 모드는 거의 비슷한 의미로 씁니다.
리눅스 시스템 저수준 함수로 fork() 함수를 호출하면 유저 공간에서 코드 공간으로 실행 흐름 공간을 이동하는 시스템 콜이 발생하고 커널 모드로 실행 흐름이 변경됩니다. 이후 커널 모드에서 시스템 콜 번호에 해당하는 핸들러 함수가 호출됩니다. 이 함수가 sys_clone()입니다.
위 그림이 실제 ftrace 로그로 어떻게 출력하는지 확인합시다.
먼저 1~8번째 줄 로그를 분석하겠습니다.
1 bash-895 [003] .... 909.253260: SyS_clone+0x14/0x38 <-ret_fast_syscall+0x0/0x28
2 bash-895 [003] .... 909.253295: <stack trace>
3 bash-895 [003] .... 909.253298: _do_fork+0x14/0x3ec <-SyS_clone+0x30/0x38
4 bash-895 [003] .... 909.253310: <stack trace>
5 lxpanel-730 [002] d.h. 909.253310: sched_wakeup: comm=ibus-x11 pid=717 prio=120 target_cpu=002
6 bash-895 [003] .... 909.253312: copy_process.part.5+0x14/0x17d8 <-_do_fork+0xb0/0x3ec
7 bash-895 [003] .... 909.253324: <stack trace>
8 => ret_fast_syscall+0x0/0x28
조금 더 알아보기: ftrace 로그 한줄 한줄을 실행하는 주체는 프로세스입니다. 모든 ftrace 가장 왼쪽에서 프로세스 이름과 pid를 볼 수 있습니다.
위 ftrace 로그에서는 가장 왼쪽에 “bash-895” 메시지가 보이는데 이 정보를 어떻게 해석해야 할까요? 이 정보는 pid가 895인 bash 프로세스를 의미합니다. 5번째 줄 로그 가장 왼쪽에서도 “lxpanel-730”이란 메시지를 볼 수 있습니다. 역시 pid가 730인 lxpanel이란 프로세스를 의미합니다.
로그들이 어지럽게 섞여 있는데 위 로그는 “bash-895”이란 프로세스가 다음 함수 흐름(콜스택)으로 실행 중인 상태입니다.
1 => copy_process.part.5+0x14/0x17d8
2 => _do_fork+0x14/0x3ec
3 => SyS_clone+0x14/0x38
4 => ret_fast_syscall+0x0/0x28
함수 호출 방향은 4에서 1번 로그 방향입니다. 시스템 콜 함수인 SyS_clone() 함수에서 _do_fork() 함수를 호출합니다.
다음 9번째 줄 로그를 봅시다.
9 bash-895 [003] .... 909.253776: sched_process_fork: comm=bash pid=895 child_comm=bash child_pid=17082
sched_process_fork이란 ftrace 이벤트 메시지와 함께 디버깅 정보를 출력합니다. pid가 895인 bash 프로세스가 pid가 17082인 자식 프로세스를 생성한다는 의미입니다. 부모 프로세스가 자식 프로세스를 생성할 때는 프로세스 이름은 그대로 가져갑니다. 이후 프로세스 이름을 자식 프로세스 이름으로 변경합니다.
task_rename 이란 ftrace 이벤트를 키면 다음과 같은 정보를 볼 수 있습니다.
raspbian_proc-17083 [003] .... 909.253836 task_rename: pid=17082 oldcomm=bash newcomm=raspbian_proc oom_score_adj=0
15~23번째 줄 로그는 raspbian_proc(pid:17083) 프로세스가 실행하는 정보입니다.
15 raspbian_proc-17082 [002] d.s. 909.254409: sched_wakeup: comm=rcu_sched pid=8 prio=120 target_cpu=002
16 raspbian_proc-17082 [002] d... 909.257817: sched_switch: prev_comm=raspbian_proc prev_pid=17082 prev_prio=120 prev_state=S ==> next_comm=swapper/2 next_pid=0 next_prio=120
...
17 <idle>-0 [002] dnh. 912.257874: sched_wakeup: comm=raspbian_proc pid=17082 prio=120 target_cpu=002
18 raspbian_proc-17082 [002] d... 912.257957: sched_switch: prev_comm=raspbian_proc prev_pid=17082 prev_prio=120 prev_state=S ==> next_comm=swapper/2 next_pid=0 next_prio=120
...
19 <idle>-0 [002] dnh. 918.258177: sched_wakeup: comm=raspbian_proc pid=17082 prio=120 target_cpu=002
20 <idle>-0 [002] d... 918.258193: sched_switch: prev_comm=swapper/2 prev_pid=0 prev_prio=120 prev_state=R ==> next_comm=raspbian_proc next_pid=17082 next_prio=120
21 raspbian_proc-17082 [002] d... 918.258250: sched_wakeup: comm=kworker/u8:1 pid=17084 prio=120 target_cpu=002
22 raspbian_proc-17082 [002] d... 918.258277: sched_switch: prev_comm=raspbian_proc prev_pid=17082 prev_prio=120 prev_state=S ==> next_comm=kworker/u8:1 next_pid=17084 next_prio=120
15번째 줄 로그를 보면 909.254409초에 raspbian_proc(pid: 17082) 프로세스가 "rcu_sched" 프로세스를 깨웁니다. 이후 909.257817초에 16번째 줄 로그와 같이 "swapper/2" 프로세스로 스케줄링됩니다.
17번째 로그를 보면, 약 3초 후인 912.257874 초에 idle-0이란 프로세스가 raspbian_proc(pid: 17082) 프로세스를 깨우고, 18번째 로그와 같이 912.257957 초에 "swapper/2" 프로세스로 스케줄링됩니다.
sched_wakeup 이란 ftrace 이벤트는 프로세스를 깨우는 동작을 표현합니다. 정확히 설명을 드리면 스케줄러에게 해당 프로세스 실행 요청을 하는 것입니다.
같은 패턴으로 19~22번째 줄 로그를 보면 915.258028 초에 raspbian_proc(pid: 17082) 프로세스가 깨어나 실행합니다.
raspbian_proc_test.c 파일에서 3초 간격으로 sleep() 함수를 호출하고 raspbian tracing 이란 메시지를 출력하는 코드가 동작하는 것입니다. 구현된 코드와 같이 다음 시간 간격으로 3초 주기로 raspbian_proc 프로세스가 실행합니다.
909.254409 -> 912.257874 -> 915.258028
프로세스가 생성하는 1단계부터 raspbian_proc 프로세스가 3초 간격으로 실행하는 로그를 분석했습니다.
정리하면 유저 모드에서 fork() 이란 리눅스 시스템 저수준 함수를 호출하면 커널 공간에서 fork() 에 대응하는 시스템 콜 핸들러인 sys_clone() 함수를 호출하는 것입니다. 이 후 sys_clone() 함수에서 _do_fork() 함수 호출로 프로세스를 생성(복제)합니다.
프로세스는 생성 후 바로 실행을 시작하는데 3초 주기로 실행합니다.
이번에는 raspbian_proc 프로세스가 종료하는 2단계 로그를 분석할 차례입니다. 이 과정은 다음 그림에서 확인할 수 있습니다.
우리는 다음 명령어로 raspbian_proc(pid:17082) 프로세스를 강제 종료시켰습니다.
root@raspberrypi:/home/pi# kill -9 17082
유저 레벨 프로세스가 유저 모드에서 명시적으로 exit() 함수를 호출해 종료하지 않고 kill 당한 것입니다.
다음과 같은 형식으로 kill 명령어를 입력하면 유저 레벨 프로세스를 강제 종료시킬 수 있습니다. 여기서 PID는 프로세스 아이디로 정수형 숫자를 의미합니다.
kill -9 [PID]
조금 더 알아보기
위 명령어를 입력하면 리눅스 커널에서는 다음과 같은 동작을 수행합니다.
1. 유저 모드에서 kill() 함수를 호출해서 커널 모드에서 sys_kill() 함수를 실행합니다.
2. “kill -9 [PID]” 명령어에서 PID에 해당하는 프로세스를 스케줄러에게 깨워 달라고 요청합니다.
3. 스케줄러가 PID에 해당하는 프로세스를 컨택스트 스위칭하면 해당 프로세스는 유저 공간으로 복귀 직전 slow_work_pending 이란 레이블을 실행합니다.
4. 위 그림 화살표 방향에서 보이는 함수 흐름으로 do_exit() 함수를 실행해 프로세스를 종료합니다.
kill 명령어는 프로세스를 종료시키는 시그널을 전달하는 명령어입니다.
kill이란 명령어는 유저 레벨에서 시그널로 전달하고 있고 커널에서 kill 명령어 실행에 할 수 있습니다. 조금 어렵게 설명을 드리면 커널에서 kill 명령어에 대응하는 함수 조합으로 kill 명령어 실행과 같은 동작을 할 수 있다는 것입니다.
유저 프로세스가 종료하려면 exit() 이란 함수를 실행하면 됩니다. 이 함수를 호출하면 시스템 콜이 실행되어 커널 공간에서 do_exit() 이란 함수가 실행합니다. 이번 소절에서는 kill 이란 명령어를 입력해서 프로세스를 강제 종료했습니다. exit() 저수준 함수를 호출해서 프로세스를 종료할 때와 실행 흐름이 다릅니다.
다음은 raspbian_proc-17082 프로세스가 종료할 때 로그입니다.
25 raspbian_proc-17082 [002] .... 933.741230: do_exit+0x14/0xc18 <-do_group_exit+0x50/0xe4
26 raspbian_proc-17082 [002] .... 933.741270: <stack trace>
27 => do_signal+0x300/0x3d4
28 => do_work_pending+0xb4/0xcc
29 => slow_work_pending+0xc/0x20
30 lxpanel-730 [000] d... 933.741295: sched_switch: prev_comm=lxpanel prev_pid=730 prev_prio=120 prev_state=S ==> next_comm=Xorg next_pid=454 next_prio=120
31 Xorg-454 [000] dn.. 933.741333: sched_wakeup: comm=openbox pid=723 prio=120 target_cpu=000
32 Xorg-454 [000] d... 933.741346: sched_switch: prev_comm=Xorg prev_pid=454 prev_prio=120 prev_state=R ==> next_comm=openbox next_pid=723 next_prio=120
33 raspbian_proc-17082 [002] .... 933.741609: sched_process_exit: comm=raspbian_proc pid=17082 prio=120
34 ibus-x11-717 [001] d... 933.741639: sched_switch: prev_comm=ibus-x11 prev_pid=717 prev_prio=120 prev_state=S ==> next_comm=swapper/1 next_pid=0 next_prio=120
35 openbox-723 [000] d... 933.741673: sched_switch: prev_comm=openbox prev_pid=723 prev_prio=120 prev_state=S ==> next_comm=Xorg next_pid=454 next_prio=120
36 raspbian_proc-17082 [002] d... 933.741693: signal_generate: sig=17 errno=0 code=2 comm=bash pid=895 grp=1 res=0
위 로그는 다음 명령어로 강제로 raspbian_proc(pid: 17082) 프로세스를 종료했을 때 출력합니다.
root@raspberrypi:/home/pi# kill -9 17082
25~29번째 줄 로그를 보면 raspbian_proc(pid: 17082)가 어떤 콜스택으로 종료하는지 알 수 있습니다.
25 raspbian_proc-17082 [002] .... 933.741230: do_exit+0x14/0xc18 <-do_group_exit+0x50/0xe4
26 raspbian_proc-17082 [002] .... 933.741270: <stack trace>
27 => do_signal+0x300/0x3d4
28 => do_work_pending+0xb4/0xcc
29 => slow_work_pending+0xc/0x20
raspbian_proc(pid:17082) 프로세스가 do_signal() 함수에서 do_exit() 함수를 호출해서 raspbian_proc(pid: 17082) 프로세스를 종료하는 동작입니다.
이번에 36번째 줄 로그를 보겠습니다.
36 raspbian_proc-17082 [002] d... 933.741693: signal_generate: sig=17 errno=0 code=2 comm=bash pid=895 grp=1 res=0
raspbian_proc(pid: 17082)가 자신이 종료한다는 정보를 시그널로 전달합니다.
프로세스는 종료 과정에서 자신의 부모 프로세스에게 자신이 종료하고 있다는 시그널을 전달합니다.
프로세스가 생성할 때 SyS_clone() 이란 커널 함수가 호출되고 종료될 때 do_exit() 커널 함수가 호출된다는 점을 확인했습니다.
다음에 다른 리눅스 시스템 프로그램을 작성해서 유저 공간에서 생성된 프로세스가 어떤 과정으로 생성되고 소멸되는지 확인합시다.
Reference(프로세스)
Reference(워크큐)
워크큐(Workqueue) Overview
.
최근 덧글