기본 유저 레벨 프로세스 실행 실습 및 ftrace 로그 분석
라즈베리파이에서 X-terminal 프로그램을 실행해서 셸을 엽시다.
root@raspberrypi:/boot# ps -ely | grep bash
S UID PID PPID C PRI NI RSS SZ WCHAN TTY TIME CMD
S 1000 541 443 0 80 0 4024 1645 poll_s tty1 00:00:00 bash
S 1000 880 878 0 80 0 4008 1628 wait pts/0 00:00:00 bash
S 0 977 972 0 80 0 3284 1416 wait pts/0 00:00:00 bash
S 1000 993 989 0 80 0 3960 1628 poll_s pts/1 00:00:00 bash
grep bash 명령어로 현재 실행 중인 프로세스 중에 bash 프로세스를 출력합니다. 출력 결과 4개 bash 프로세스 목록을 볼 수 있습니다.
이 상태에서 X-terminal 셸을 하나 더 실행하고 다음 명령어를 입력해서 bash 프로세스 목록을 확인합시다.
root@raspberrypi:/boot# ps -ely | grep bash
S UID PID PPID C PRI NI RSS SZ WCHAN TTY TIME CMD
S 1000 541 443 0 80 0 4024 1645 poll_s tty1 00:00:00 bash
S 1000 880 878 0 80 0 4008 1628 wait pts/0 00:00:00 bash
S 0 977 972 0 80 0 3284 1416 wait pts/0 00:00:00 bash
S 1000 993 989 0 80 0 3960 1628 poll_s pts/1 00:00:00 bash
S 1000 1027 878 3 80 0 4036 1628 poll_s pts/2 00:00:00 bash
이전에 출력한 결과와 비교해봅시다. 맨 마지막 줄 로그를 보면 pid가 1027인 bash 프로세스가 보입니다. 셸을 하나 더 열고 “ps –ely” 명령어를 입력하니 bash(pid:1027)과 같이 새로 생성된 프로세스를 볼 수 있습니다. 이렇게 새로운 프로그램을 실행하면 이에 해당하는 프로세스가 생성됩니다.
라즈베리파이 X-Terminal 셸 화면을 마우스로 더블 클릭하는 순간 라즈베리파이 배경 화면을 처리하는 프로세스가 이벤트를 받아서 bash라는 프로세스를 생성합니다. 이 때 리눅스 저수준 함수인 fork()를 호출합니다. 이렇게 유저 레벨 프로세스는 셸이나 다른 프로세스를 통해서 실행을 시작합니다. 유저 레벨 프로세스는 혼자서 실행할 수 없습니다.
이번에는 라즈베리파이에서 소스 에디터로 많이 쓰는 Geany란 프로그램을 열겠습니다.
root@raspberrypi:/boot# ps -ely | grep geany
S UID PID PPID C PRI NI RSS SZ WCHAN TTY TIME CMD
S 1000 989 671 1 80 0 28276 25827 poll_s ? 00:00:06 geany
Geany 프로그램을 하나 더 열고 다음 명령어를 입력합시다.
root@raspberrypi:/boot# ps -ely | grep geany
S UID PID PPID C PRI NI RSS SZ WCHAN TTY TIME CMD
S 1000 989 671 1 80 0 28276 25827 poll_s ? 00:00:06 geany
S 1000 1297 671 38 80 0 25204 13533 poll_s ? 00:00:01 geany
PID가 1297인 geany 프로세스가 생성됐습니다.
프로세스를 어렵게 생각할 필요가 없습니다. 셸이나 geany이란 프로그램을 실행하면 메모리에서 실행하는 것이 프로세스입니다. 유저 레벨에서 실행하는 프로세스는 이렇게 유저 동작으로 생성됩니다.
이번에 리눅스 시스템 프로그래밍으로 프로세스를 생성해 봅시다. 소스 코드는 다음과 같으니 같이 입력해 봅시다.
1 #include <stdio.h>
2 #include <unistd.h>
3
4 #define PROC_TIMES 500
5 #define SLEEP_DURATION 3 // second unit
6
7 int main()
8 {
9 int proc_times = 0;
10
11 for(proc_times = 0; proc_times < PROC_TIMES; proc_times++) {
12 printf("raspbian tracing \n");
13 sleep(SLEEP_DURATION);
14 }
15
16 return 0;
17 }
위와 같은 프로그램을 리눅스 시스템 프로그램이라고 합니다. 리눅스 시스템을 관리하는 sleep()이나 fork() 함수를 직접 호출하기 때문에 응용 프로그램 입장에서 저수준 프로그래밍이라고도 합니다. 위 함수를 리눅스 시스템 저수준 함수(API)라고 부르겠습니다.
위 코드는 다음 코드 이외에 다른 동작을 하지 않습니다.
11 for(proc_times = 0; proc_times < PROC_TIMES; proc_times++) {
12 printf("raspbian tracing \n");
13 sleep(SLEEP_DURATION);
14 }
소스 코드를 잠깐 봅시다.
12번째 줄 코드와 같이 “raspbian tracing”이란 메시지를 셸로 출력하고 13번째 줄 코드와 같이 3초 동안 휴면에 들어갈 뿐입니다.
위 코드를 입력한 다음 raspbian_test.c 란 이름으로 저장합시다. 컴파일을 쉽게 하기 위해 다음과 같이 코드를 작성하고 파일 이름을 Makefile으로 저장합시다.
raspbian_proc: raspbian_test.c
gcc -o raspbian_proc raspbian_test.c
“make” 명령어로 위와 같은 메이크 파일을 실행하면 raspbian_proc이란 실행 파일이 생성됩니다.
메이크 파일은 여러 모듈을 일일이 컴파일 명령어를 입력하기 어려우니 컴파일 설정 속도를 빠르게 하기 위해 고안된 겁니다. 실전 프로젝트에서 메이크 파일은 자주 쓰니 잘 알아둡시다.
make란 명령어를 입력해서 raspbian_test.c 파일을 컴파일하면 raspbian_proc이란 프로그램을 생성할 수 있습니다.
raspbian_proc 이란 프로세스가 어떻게 생성되고 실행되는지 파악하려면 다음과 같이 ftrace 로그를 설정할 필요가 있습니다. 코드를 봅시다.
1 #!/bin/sh
2
3 echo 0 > /sys/kernel/debug/tracing/tracing_on
4 sleep 1
5 echo "tracing_off"
6
7 echo 0 > /sys/kernel/debug/tracing/events/enable
8 sleep 1
9 echo "events disabled"
10
11 echo secondary_start_kernel > /sys/kernel/debug/tracing/set_ftrace_filter
12 sleep 1
13 echo "set_ftrace_filter init"
14
15 echo function > /sys/kernel/debug/tracing/current_tracer
16 sleep 1
17 echo "function tracer enabled"
18
19 echo SyS_clone do_exit > /sys/kernel/debug/tracing/set_ftrace_filter
20 echo _do_fork copy_process* >> /sys/kernel/debug/tracing/set_ftrace_filter
21
22 sleep 1
23 echo "set_ftrace_filter enabled"
24
25 echo 1 > /sys/kernel/debug/tracing/events/sched/sched_switch/enable
26 echo 1 > /sys/kernel/debug/tracing/events/sched/sched_wakeup/enable
27 echo 1 > /sys/kernel/debug/tracing/events/sched/sched_process_fork/enable
28 echo 1 > /sys/kernel/debug/tracing/events/sched/sched_process_exit/enable
29
30 echo 1 > /sys/kernel/debug/tracing/events/signal/enable
31
32 sleep 1
33 echo "event enabled"
34
35 echo 1 > /sys/kernel/debug/tracing/options/func_stack_trace
36 echo 1 > /sys/kernel/debug/tracing/options/sym-offset
37 echo "function stack trace enabled"
38
39 echo 1 > /sys/kernel/debug/tracing/tracing_on
40 echo "tracing_on"
조금 더 알아보기
ftrace 에서 시스템 콜 핸들러 함수 심볼(이름)을 Alias 심볼로 씁니다.
예를 들어 sys_write() 함수에 대한 alias 심볼은 SyS_write와 같습니다.
다음 전처리 코드는 fs/read_write.c 파일에 위치한 write 시스템 콜 핸들러 함수 선언부입니다.
[out/fs/.tmp_read_write.i]
1 long sys_write(unsigned int fd, const char * buf, size_t count) __attribute__((alias("SyS_write")));
2
3 [https://elixir.bootlin.com/linux/v4.14.70/source/fs/read_write.c]
4 SYSCALL_DEFINE3(write, unsigned int, fd, const char __user *, buf,
5 size_t, count)
6 {
7 struct fd f = fdget_pos(fd);
8 ssize_t ret = -EBADF;
1번째 줄 코드를 보면 함수 인자 오른쪽에 다음과 같은 코드를 볼 수 있습니다.
__attribute__((alias("SyS_write")));
GCC 컴파일러가 함수 컴파일시 alias 심볼을 적용한 것인데 sys_write() 함수에 대한 alias 심볼이 SyS_write입니다.
ftrace 로그에서 SyS_xxx 로 어떤 함수를 표현하면 실제 함수 이름은 sys_xxx() 이라고 생각해도 좋습니다.
따라서 ftrace 로그 설정 시 set_ftrace_filter로 SyS_clone 함수로 지정한 겁니다.
19 echo SyS_clone do_exit > /sys/kernel/debug/tracing/set_ftrace_filter
이렇게 지정하면 ftrace는 실제 리눅스 커널 코드에서 sys_clone 함수를 추적(트레이싱)합니다.
위와 같이 코드를 작성한 후 clone_process_debug.sh 와 같은 이름을 저장한 후 다음과 같이 이 셸 스크립트를 실행합시다.
./clone_process_debug.sh
위 셸 스크립트를 실행하면 5~6초 내 ftrace 로그 설정이 끝납니다. 이후 raspbian_test.c 파일을 컴파일하면 생성되는 raspbian_proc이란 프로그램을 다음 명령어로 실행합시다.
root@raspberrypi:/home/pi# ./raspbian_proc
raspbian tracing
raspbian tracing
raspbian tracing
raspbian tracing
raspbian tracing
raspbian tracing
raspbian_proc 이란 프로그램을 실행하니 3초 간격으로 “raspbian tracing”이란 메시지를 출력합니다. 소스 코드에서 구현한 대로 실행합니다.
raspbian_proc 프로그램을 실행했으니 이에 해당하는 프로세스가 생성됐을 것이라 예상할 수 있습니다. 이번에는 “ps -ely” 명령어를 입력해서 프로세스 목록을 확인합시다.
root@raspberrypi:/home/pi# ps -ely
1 S UID PID PPID C PRI NI RSS SZ WCHAN TTY TIME CMD
2 S 0 1 0 0 80 0 5956 6991 SyS_ep ? 00:00:02 systemd
3 S 0 2 0 0 80 0 0 0 kthrea ? 00:00:00 kthreadd
...
4
5 S 0 895 890 0 80 0 3420 1448 wait pts/0 00:00:00 bash
6 S 1000 991 685 0 80 0 7500 7842 poll_s ? 00:00:00 ibus-engine-han
...
7 S 0 1078 1073 0 80 0 3244 1416 wait pts/2 00:00:00 bash
8 I 0 1079 2 0 80 0 0 0 worker ? 00:00:00 kworker/3:2
9 I 0 2302 2 0 80 0 0 0 worker ? 00:00:00 kworker/0:1
10 S 0 17082 895 0 80 0 344 453 hrtime pts/0 00:00:00 raspbian_proc
11 I 0 17084 2 0 80 0 0 0 worker ? 00:00:00 kworker/u8:1
12 I 0 17085 2 0 80 0 0 0 worker ? 00:00:00 kworker/1:0
13 R 0 17086 1078 0 80 0 1156 1918 - pts/2 00:00:00 ps
프로세스 목록 10번째 항목을 보면 pid가 17082인 raspbian_proc 프로세스가 보입니다. 리눅스 시스템에서 raspbian_proc 프로세스가 READY 상태이란 의미입니다.
1 S UID PID PPID C PRI NI RSS SZ WCHAN TTY TIME CMD
5 S 0 895 890 0 80 0 3420 1448 wait pts/0 00:00:00 bash
...
10 S 0 17082 895 0 80 0 344 453 hrtime pts/0 00:00:00 raspbian_proc
1번째 줄 로그에서 PPID가 보입니다. 이 정보는 부모 프로세스의 pid를 의미합니다. raspbian_proc 프로세스의 부모 프로세스는 pid가 895입니다. pid가 895인 프로세스를 확인하니 프로세스 목록 5번째 항목과 같이 bash 프로세스입니다. raspbian_proc 프로세스의 부모 프로세스는 bash임을 알 수 있습니다.
raspbian_proc 프로세스의 부모 프로세스는 왜 bash(pid:895) 일까요? raspbian_proc 프로세스를 실행할 때 X-Terminal bash 셸에서 다음 명령어로 실행했기 때문입니다.
root@raspberrypi:/home/pi# ./raspbian_proc
이렇게 유저 레벨 프로세스는 셸이나 다른 프로세스를 통해서 실행을 시작합니다. 만약 라즈베리파이 바탕 화면에 있는 아이콘을 클릭해서 프로그램을 시작해서 유저 레벨 프로세스를 실행했다고 가정합시다. 이 경우 바탕화면을 제어하는 프로세스가 부모 프로세스가 됩니다.
raspbian_proc 프로세스를 이렇게 15초 동안 실행시킨 다음에 다른 x-terminal 셸을 실행을 실행해서 다음과 같이 raspbian_proc 프로세스를 강제 종료해봅시다.
root@raspberrypi:/home/pi# kill -9 17082
kill 명령어로 pid를 지정하면 강제로 지정한 프로세스를 종료합니다. -9는 강제로 프로세스를 종료시키는 옵션입니다.
다음 명령어를 입력해서 kill이란 명령어가 어떤 의미인지 확인합시다.
root@raspberrypi:/home/pi# info kill
24.1 ‘kill’: Send a signal to processes
=======================================
The ‘kill’ command sends a signal to processes, causing them to
terminate or otherwise act upon receiving the signal in some way.
Alternatively, it lists information about signals. Synopses:
kill [-s SIGNAL | --signal SIGNAL | -SIGNAL] PID...
kill [-l | --list | -t | --table] [SIGNAL]...
Due to shell aliases and built-in ‘kill’ functions, using an
unadorned ‘kill’ interactively or in a script may get you different
functionality than that described here. Invoke it via ‘env’ (i.e., ‘env
kill ...’) to avoid interference from the shell.
매뉴얼 내용과 같이 kill 명령어는 프로세스를 종료하는 역할을 수행합니다.
이번에는 다음과 같은 셸 스크립트를 실행해서 ftrace 로그를 추출합시다.
#!/bin/sh
echo 0 > /sys/kernel/debug/tracing/tracing_on
echo "ftrace off"
sleep 3
cp /sys/kernel/debug/tracing/trace .
mv trace ftrace_log.c
위 코드를 get_ftrace.sh 이름으로 저장해놓고 ftrace 로그를 받을 때 다음 명령어를 실행합니다.
root@raspberrypi:/home/pi#./get_ftrace.sh
그러면 같은 폴더에 ftrace.c이란 파일이 생성됐음을 확인할 수 있습니다.
이제까지 프로세스 생성과 종료 과정을 저장한 ftrace 로그를 추출하기 위해 진행한 과정을 정리하면 다음과 같습니다.
1. 다음 명령어로 프로세스 실행
root@raspberrypi:/home/pi# ./raspbian_proc
2. ftrace 로그 설정 및 시작
3. ps 명령어로 프로세스 동작 확인
4. raspbian_proc 프로세스 종료
root@raspberrypi:/home/pi# kill -9 17082
5. ftrace 로그 추출
커널 공간에서 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() 커널 함수가 호출된다는 점을 확인했습니다.
다음에 다른 리눅스 시스템 프로그램을 작성해서 유저 공간에서 생성된 프로세스가 어떤 과정으로 생성되고 소멸되는지 확인합시다.
'리눅스 커널의 구조와 원리 > 4. 프로세스(Process) 관리' 카테고리의 다른 글
| [리눅스커널] 커널 스레드란 무엇인가 (0) | 2019.03.10 |
|---|---|
| [리눅스커널] 부모 프로세스가 자식 프로세스를 생성하는 과정 ftrace 로그로 분석해보기 (0) | 2019.03.10 |
| [리눅스커널][프로세스] 프로세스는 어떻게 생성하나? (0) | 2019.02.11 |
| [리눅스커널][프로세스] ps 명령어로 프로세스 확인하기 (0) | 2019.02.11 |
| [리눅스커널[프로세스] 프로세스, 태스크란 무엇일까? (0) | 2019.02.11 |