Linux Kernel(4.19) Hacks

rousalome.egloos.com

포토로그 Kernel Crash


통계 위젯 (화이트)

20113
1478
166890


[리눅스커널] 프로세스: 기본 유저 레벨 프로세스 실행 실습 및 ftrace 로그 분석 4. 프로세스(Process) 관리

ps 명령어를 이용한 프로세스 목록 확인

라즈베리 파이에서 터미널 프로그램을 열어 “ps -ely | grep bash” 명령어를 입력해 봅시다.

1 root@raspberrypi:/home/pi# ps -ely | grep bash
2 S   UID   PID  PPID  C PRI  NI   RSS    SZ WCHAN  TTY          TIME CMD
3 S  1000   541   443  0  80   0  4024  1645 poll_s tty1     00:00:00 bash
4 S  1000   880   878  0  80   0  4008  1628 wait   pts/0    00:00:00 bash
5 S     0   977   972  0  80   0  3284  1416 wait   pts/0    00:00:00 bash
6 S  1000   993   989  0  80   0  3960  1628 poll_s pts/1    00:00:00 bash

grep bash 명령어로 현재 실행 중인 프로세스 목록 중 bash라는 이름의 프로세스를 검색한 결과를 확인할 수 있습니다. 출력 결과, 4개의 bash 프로세스 목록을 볼 수 있습니다. 그런데 6번째 줄 메시지에서 보이는 “bash(pid:993)”가 현재 실행 중인 터미널 셸 프로세스입니다.

이번에는 터미널을 하나 더 열고 다음 명령어를 입력해서 bash 프로세스 목록을 확인합시다.

1 root@raspberrypi:/boot# ps -ely | grep bash
2 S   UID   PID  PPID  C PRI  NI   RSS    SZ WCHAN  TTY          TIME CMD
3 S  1000   541   443  0  80   0  4024  1645 poll_s tty1     00:00:00 bash
4 S  1000   880   878  0  80   0  4008  1628 wait   pts/0    00:00:00 bash
5 S     0   977   972  0  80   0  3284  1416 wait   pts/0    00:00:00 bash
6 S  1000   993   989  0  80   0  3960  1628 poll_s pts/1    00:00:00 bash
7 S  1000  1027   878  3  80   0  4036  1628 poll_s pts/2    00:00:00 bash

바로 이전에 출력한 결과와 비교해볼까요? 맨 마지막의 7 번째 줄 로그를 보면 pid가 1027인 bash 프로세스가 보입니다. 이렇게 터미널 셸을 하나 더 열고 “ps –ely” 명령어를 입력하니 이렇게 새로 생성된 프로세스를 볼 수 있습니다. 위 명령어의 출력 결과로 새로운 프로그램을 실행하면 이에 해당하는 프로세스가 생성된다는 사실을 알 수 있습니다.

그럼 터미널 셸 프로그램을 실행하면 bash 프로세스가 어떻게 실행되는지 알아봅시다. 이해를 돕기 위해 터미널 셸 프로그램의 아이콘이 바탕화면에 있다고 가정하고 터미널 프로그램을 실행하기 위해 터미널 셸의 프로그램 아이콘을 마우스로 더블클릭합니다.  

그럼 라즈베리 파이에서 배경 화면을 처리하는 프로세스가 이벤트를 받아서 bash라는 프로세스를 생성합니다. 이 과정에서 유저 공간에서 fork() 함수를 호출하게 됩니다. 대부분의 유저 레벨 프로세스는 셸이나 다른 프로세스를 통해 실행을 시작하고, 스스로 실행하지 못합니다. 

이번에는 라즈베리 파이에서 소스 에디터로 많이 쓰는 기니라는 프로그램을 열어 보겠습니다. 터미널을 열고 다음과 같이 “ps -ely | grep geany” 명령어를 입력해 봅시다.

1 root@raspberrypi:/home/pi# ps -ely | grep geany
2 S   UID   PID  PPID  C PRI  NI   RSS    SZ WCHAN  TTY          TIME CMD
3 S  1000   989   671  1  80   0 28276 25827 poll_s ?        00:00:06 geany

위 결과는 프로세스 목록에서 geany란 프로세스를 검색해서 출력한 결과입니다. 맨 마지막 줄에서 PID가 989인 geany 프로세스를 확인할 수 있습니다.

이번에는 기니 프로그램을 하나 더 열고 다음 명령어를 다시 입력합시다.

1 root@raspberrypi:/home/pi# ps -ely | grep geany
2 S   UID   PID  PPID  C PRI  NI   RSS    SZ WCHAN  TTY          TIME CMD
3 S  1000   989   671  1  80   0 28276 25827 poll_s ?        00:00:06 geany
4 S  1000  1297   671 38  80   0 25204 13533 poll_s ?        00:00:01 geany

4 번째 줄의 출력 결과를 보면 PID가 1297인 geany 프로세스가 생성됐음을 알 수 있습니다. 처음 실행한 기니 프로그램에 대한 프로세스는 3번째 줄과 같은 Geany(PID:989) 프로세스입니다. 두 번째로 실행한 기니 프로그램에 대응하는 프로세스는 4번째 줄과 같이 PID가 1297인 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("rasbian 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 }

소스코드를 잠깐 볼까요? 11~14번째 줄 코드는 for 루프입니다. proc_times 지역변수가 500보다 작을 때까지 +1만큼 증가하니 for 루프는 500번 실행합니다.

이번에는 for 루프 안의 코드를 살펴봅시다. 12번째 줄 코드는 “raspbian tracing”이란 메시지를 셸로 출력합니다. 다음 13번째 줄 코드를 실행하면 sleep() 함수를 호출해서 3초 동안 휴면 상태로 진입합니다. sleep() 함수는 인자로 전달된 정숫값(초 단위)만큼 휴면 상태로 진입하는 기능입니다. 3초 동안 휴면하고 난 후 깨어나 다시 12번째 줄 코드를 실행합니다.

정리하면 위 코드는 다음 동작을 500번 반복합니다.

"raspbian tracing" 문자열을 printf() 함수를 통해 출력한다.
3초 동안 휴면 상태로 진입한다.

위 코드를 입력한 다음 raspbian_test.c라는 이름으로 저장합시다.

컴파일을 쉽게 하기 위해 다음과 같이 코드를 작성하고 파일명을 Makefile로 저장합니다.

raspbian_proc: raspbian_test.c
gcc -o raspbian_proc raspbian_test.c

make 명령어로 위와 같은 Makefile을 실행하면 raspbian_proc이라는 실행 파일이 만들어집니다.

---
Makefile은 여러 개의 모듈을 빌드(컴파일)하기 위해 일일이 컴파일 명령어를 입력하기 번거롭기 때문에 컴파일 설정을 효율적으로 만들기 위해 쓰는 것입니다. 실전 프로젝트에서도 Makefile을 자주 쓰는데, 소스코드를 새롭게 추가하거나 컴파일 옵션을 수정할 때 Makefile을 수정합니다.
---

ftrace 설정 방법 따라해보기

이번에는 ftrace 로그를 설정하는 방법을 소개합니다. raspbian_proc 프로세스가 어떻게 생성되고 실행되는지 파악하려면 다음과 같은 명령어로 ftrace를 설정할 필요가 있습니다.  

1  #!/bin/bash
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 설정을 위한 명령어 중 핵심 코드를 소개합니다.

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

위 명령어를 실행하면 콜스택을 출력할 함수를 set_ftrace_filter라는 파일로 지정합니다.

sys_clone()
do_exit()
_do_fork()
copy_process()

다음 명령어는 sched_process_fork와 sched_process_exit 이벤트를 활성화하는 동작입니다. sched_process_fork와 sched_process_exit 이벤트를 통해 프로세스가 종료하고 생성하는 동작을 추적할 수 있습니다. 

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

raspbian_proc 프로세스와 ftrace를 실행해 프로세스 실행와 종료 로그 확보하기
앞에서와 같이 코드를 작성한 후 clone_process_debug.sh라는 이름으로 저장한 후 다음과 같이 이 셸 스크립트를 실행합니다.
root@raspberrypi:/home/pi#./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프로그램을 실행했으니 이에 해당하는 프로세스가 생성됐을 것이라 예상할 수 있습니다. 

이번에는 터미널을 하나 열겠습니다. 기존 터미널에서는 이미 raspbian_proc 프로그램을 실행 중이라 명령어를 입력할 수 없습니다. 새로 연 두 번째 터미널에서 “ps -ely” 명령어를 입력해서 프로세스 목록을 확인합니다.

root@raspberrypi:/home/pi# ps -ely
01 S   UID   PID  PPID  C PRI  NI   RSS    SZ WCHAN  TTY          TIME CMD
02 S     0     1     0  0  80   0  5956  6991 SyS_ep ?        00:00:02 systemd
03 S     0     2     0  0  80   0     0     0 kthrea ?        00:00:00 kthreadd
...
04
05 S     0   895   890  0  80   0  3420  1448 wait   pts/0    00:00:00 bash
06 S  1000   991   685  0  80   0  7500  7842 poll_s ?        00:00:00 ibus-engine-han
...
07 S     0   937   849  0  80   0  2940  1905 poll_s pts/0    00:00:00 sudo
08 S     0   941   937  0  80   0  2680  1810 wait   pts/0    00:00:00 su
09 S     0   946   941  0  80   0  2872  1399 wait   pts/0    00:00:00 bash
...
10 I     0  1338     2  0  60 -20     0     0 worker ?        00:00:00 kworker/2:1H
11 I     0  1340     2  0  80   0     0     0 worker ?        00:00:00 kworker/u8:1-ev
12 S     0  1360   946  0  80   0   320   450 hrtime pts/0    00:00:00 raspbian_proc
13 R     0  1361  1320  0  80   0  1160  1911 -      pts/2    00:00:00 ps 

프로세스 목록의 12번째 항목을 보면 pid가 1360인 raspbian_proc 프로세스가 보입니다. 리눅스 시스템에서 raspbian_proc 프로세스가 READY 상태란 의미입니다. 

1 S   UID   PID  PPID  C PRI  NI   RSS    SZ WCHAN  TTY          TIME CMD
...
11 I     0  1340     2  0  80   0     0     0 worker ?        00:00:00 kworker/u8:1-ev
12 S     0  1360   946  0  80   0   320   450 hrtime pts/0    00:00:00 raspbian_proc

그런데 1번 줄 로그에서 PPID가 보입니다. PPID는 무엇일까요? 바로 부모 프로세스의 pid를 의미합니다. 12번째 줄에서는 PID인 1360 오른쪽에 있는 숫자가 PPID입니다. 즉,  raspbian_proc 프로세스의 부모 프로세스는 pid가 946인 것입니다. 

이번에는 pid가 946인 프로세스를 확인하니 09번째 항목과 같이 bash 프로세스입니다. 따라서 raspbian_proc 프로세스의 부모 프로세스는 bash임을 알 수 있습니다. 이는 raspbian_proc 프로세스를 실행할 때 터미널 셸에서 다음 명령어로 실행했기 때문입니다.

root@raspberrypi:/home/pi# ./raspbian_proc 

이 방식으로 첫 번째 터미널에서 raspbian_proc 프로세스를 이렇게 15초 동안 실행합니다. 이후 두 번째 터미널에서 다음 명령어로 raspbian_proc 프로세스를 강제 종료해봅시다.

root@raspberrypi:/home/pi# kill -9  1360

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/bash

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 로그가 담긴 ftrace.c라는 파일이 생성됐음을 확인할 수 있습니다.

지금까지 ftrace 로그를 추출하기 위해 진행한 과정을 정리해볼까요?  

1 단계: [첫 번째 터미널] ftrace 로그 설정 
2 단계: [첫 번째 터미널] 다음 명령어로 raspbian_proc 프로세스를 실행
root@raspberrypi:/home/pi# ./raspbian_proc 
3 단계: [두 번째 터미널] “ps –ely” 명령어로 프로세스의 동작을 확인
4 단계: [두 번째 터미널]raspbian_proc 프로세스 종료
root@raspberrypi:/home/pi# kill -9  1360
5 단계: [두 번째 터미널] ftrace 로그 추출

ftrace 메시지로 프로세스 생성과 종료 과정 분석하기

raspbian_proc 프로세스를 실행하고 강제로 종료된 동작이 포함된 ftrace 로그를 확보했습니다. 이제 커널 공간에서 raspbian_proc 프로세스가 어떤 코드 흐름으로 생성되고 종료되는지 살펴봅시다. 분석할 전체 ftrace 로그는 다음과 같습니다.

1 bash-946 [003] .... 676.984916: copy_process.part.5+0x14/0x1acc <-_do_fork+0xc0/0x41c
2 bash-946 [003] .... 676.984929: <stack trace>
3  => copy_process.part.5+0x18/0x1acc
4  => _do_fork+0xc0/0x41c
5  => sys_clone+0x30/0x38
6  => ret_fast_syscall+0x0/0x28
7  => 0x7ef11270
8 ...
9 bash-946 [003] .... 676.985385: sched_process_fork: comm=bash pid=946 child_comm=bash child_pid=1360
...
10 raspbian_proc-1360 [001] d.h. 676.989734: sched_wakeup: comm=lxterminal pid=847 prio=120 target_cpu=001
11 raspbian_proc-1360 [001] d... 676.989763: sched_switch: prev_comm=raspbian_proc prev_pid=1360 prev_prio=120 prev_state=S
...   
12 <idle>-0 [001] dnh. 679.989823: sched_wakeup: comm=raspbian_proc pid=1360 prio=120 target_cpu=001
13 raspbian_proc-1360 [001] d... 679.989938: sched_switch: prev_comm=raspbian_proc prev_pid=1360 prev_prio=120 prev_state=S ==> next_comm=kworker/1:3 next_pid=431 next_prio=120   
...
14 <idle>-0 [001] dnh. 682.990027: sched_wakeup: comm=raspbian_proc pid=1360 prio=120 target_cpu=001
15 raspbian_proc-1360  [001] d... 682.990149: sched_switch: prev_comm=raspbian_proc prev_pid=1360 prev_prio=120 prev_state=S ==> next_comm=swapper/1 next_pid=0 next_prio=120 
...
16 <idle>-0 [001] dnh. 685.990214: sched_wakeup: comm=raspbian_proc pid=1360 prio=120 target_cpu=001
17 raspbian_proc-1360 [001] d... 685.990325: sched_switch: prev_comm=raspbian_proc prev_pid=1360 prev_prio=120 prev_state=S ==> next_comm=kworker/1:3 next_pid=431 next_prio=120  
...
18 bash-1320 [003] d... 701.305400: signal_generate: sig=9 errno=0 code=0 comm=raspbian_proc pid=1360 grp=1 res=0
...
19 raspbian_proc-1360 [001] .... 701.305489: do_exit+0x14/0xbe0 <-do_group_exit+0x50/0xe8
20 raspbian_proc-1360 [001] .... 701.305528: <stack trace>
21 => do_exit+0x18/0xbe0
22 => do_group_exit+0x50/0xe8
23 => get_signal+0x160/0x7dc
24 => do_signal+0x38c/0x468
25 => do_work_pending+0xd4/0xec
26 => slow_work_pending+0xc/0x20
27 => 0x76e10008
...
28 raspbian_proc-1360 [001] .... 701.305911: sched_process_exit: comm=raspbian_proc pid=1360 prio=120
29 raspbian_proc-1360 [001] d... 701.306010: signal_generate: sig=17 errno=0 code=2 comm=bash pid=946 grp=1 res=0

복잡해 보이는 이 ftrace 로그의 실행 흐름은 4단계로 나눌 수 있습니다. 

1단계: 프로세스 생성
첫 번째 단계로 raspbian_proc 프로세스가 생성되며, 부모 프로세스는 pid가 946인 bash 프로세스입니다.

2단계: raspbian_proc 프로세스 실행
raspbian_proc 프로세스는 3초 간격으로 실행과 휴면을 반복합니다. 유저 애플리케이션에서 작성한 코드대로 동작합니다.

3단계: 프로세스 종료
2번째 터미널에서 “kill [pid]” 형식의 명령어로 raspbian_proc 프로세스를 종료시켰습니다. raspbian_proc 프로세스가 종료되는 동작입니다.

4단계: 부모 프로세스에게 시그널 전달
종료하는 raspbian_proc 프로세스는 부모 프로세스인 bash에게 시그널을 전달합니다.

실행 흐름을 알아봤으니 각 단계별로 ftrace 로그를 상세히 분석하겠습니다.

1단계: 프로세스 생성 단계의 ftrace 메시지 분석

먼저 유저 공간에서 _do_fork() 함수가 호출되면 다음과 같은 흐름으로 프로세스를 생성합니다. 

            
그림 4.4 유저 공간에서 fork() 함수 호출 시 프로세스 생성 흐름도 

보다시피 유저 공간에서 리눅스 시스템 저수준 함수로 fork() 함수를 호출하면 fork 시스템 콜이 발생해 커널 모드로 실행 흐름이 변경됩니다. 이후 커널 모드에서 시스템 콜 번호에 해당하는 시스템 콜 핸들러 함수가 호출됩니다. 이 함수가 sys_clone()입니다.

이 처리 과정을 ftrace 로그에서 확인해보겠습니다. 먼저 01~09번째 줄 로그를 분석하겠습니다.

01 bash-946 [003] .... 676.984916: copy_process.part.5+0x14/0x1acc <-_do_fork+0xc0/0x41c
02 bash-946 [003] .... 676.984929: <stack trace>
03  => copy_process.part.5+0x18/0x1acc
04  => _do_fork+0xc0/0x41c
05  => sys_clone+0x30/0x38
06  => ret_fast_syscall+0x0/0x28
07  => 0x7ef11270
08 ...
09 bash-946 [003] .... 676.985385: sched_process_fork: comm=bash pid=946 child_comm=bash child_pid=1360

01번째 줄 로그의 맨 왼쪽에 “bash-946”이라는 메시지가 보입니다. 이는 01번째 로그를 출력하는 주인공이 pid가 946인 bash 프로세스이라는 의미입니다. 

01~08번째 줄은 “bash-946” 프로세스가 다음 콜스택으로 실행 중인 것을 나타냅니다.

03  => copy_process.part.5+0x18/0x1acc
04  => _do_fork+0xc0/0x41c
05  => sys_clone+0x30/0x38
06  => ret_fast_syscall+0x0/0x28

함수 호출 방향은 06번째 줄에서 03번째 줄 방향입니다. 유저 공간에서 fork() 함수를 호출해 해당 시스템 콜 핸들러 함수인 sys_clone() 함수가 호출됩니다. 이는 프로세스를 생성하는 동작입니다. 

그럼 이 과정에서 어떤 프로세스를 생성할까요? 다음 09번째 줄 로그를 보면 알 수 있습니다.

09 bash-946 [003] .... 676.985385: sched_process_fork: comm=bash pid=946 child_comm=bash child_pid=1360

pid가 1360인 프로세스를 생성합니다. 그런데 “child_comm=bash” 메시지로 자식 프로세스 이름도 bash인 것 같습니다. 사실 부모 프로세스가 자식 프로세스를 생성하는 첫 과정에서 프로세스 이름도 자식 프로세스에 복제됩니다. 하지만 프로세스가 생성되는 마지막 단계에서 프로세스 이름을 자식 프로세스 이름으로 바꿉니다. 

이 동작을 확인하려면 task_rename이라는 ftrace 이벤트를 활성화해야 다음과 같은 로그를 볼 수 있습니다.

raspbian_proc-1360 [003] .... 676.985982 task_rename: pid=1360 oldcomm=bash newcomm=raspbian_proc oom_score_adj=0

2단계: raspbian_proc 프로세스 실행에 대한 ftrace 메시지 분석

10~17번째 줄 로그는 raspbian_proc(pid:1360) 프로세스가 실행되는 것을 나타내는 로그입니다.

10 raspbian_proc-1360 [001] d.h. 676.989734: sched_wakeup: comm=lxterminal pid=847 prio=120 target_cpu=001
11 raspbian_proc-1360 [001] d... 676.989763: sched_switch: prev_comm=raspbian_proc prev_pid=1360 prev_prio=120 prev_state=S
...   
12 <idle>-0 [001] dnh. 679.989823: sched_wakeup: comm=raspbian_proc pid=1360 prio=120 target_cpu=001
13 raspbian_proc-1360 [001] d... 679.989938: sched_switch: prev_comm=raspbian_proc prev_pid=1360 prev_prio=120 prev_state=S ==> next_comm=kworker/1:3 next_pid=431 next_prio=120   
...
14 <idle>-0 [001] dnh. 682.990027: sched_wakeup: comm=raspbian_proc pid=1360 prio=120 target_cpu=001
15 raspbian_proc-1360  [001] d... 682.990149: sched_switch: prev_comm=raspbian_proc prev_pid=1360 prev_prio=120 prev_state=S ==> next_comm=swapper/1 next_pid=0 next_prio=120 
...
16 <idle>-0 [001] dnh. 685.990214: sched_wakeup: comm=raspbian_proc pid=1360 prio=120 target_cpu=001
17 raspbian_proc-1360 [001] d... 685.990325: sched_switch: prev_comm=raspbian_proc prev_pid=1360 prev_prio=120 prev_state=S ==> next_comm=kworker/1:3 next_pid=431 next_prio=120

11, 13, 15, 17번째 줄을 보면 raspbian_proc 프로세스가 다음 시간에 스케줄링으로 실행을 시작한다는 사실을 알 수 있습니다.

676.989763 -> 679.989938 -> 682.990149 ->685.990325 

각 메시지 맨 왼쪽 부분에 보이는 "raspbian_proc-1360"은 pid가 1360인 raspbian_proc 프로세스라는 의미입니다. 실행 시간을 보면 3초 간격으로 휴면 상태로 진입했다가 실행을 반복합니다. 그런데 여기서 한 가지 의문이 생깁니다. 3초 간격으로 raspbian_proc 프로세스가 실행되는 이유는 무엇일까요?

이번 절에서 소개한 raspbian_proc_test.c 소스코드에서 구현한 대로 실행되기 때문입니다.

5 #define SLEEP_DURATION 3  // second unit
...
11 for(proc_times = 0; proc_times < PROC_TIMES; proc_times++) {
12 printf("rasbian tracing \n");
13 sleep(SLEEP_DURATION);
14 }

즉, 앞서 코드를 작성한대로 3초 간격으로 sleep() 함수를 호출하고 “raspbian tracing”이란 메시지를 출력합니다.

3단계: 프로세스 종료에 대한 ftrace 메시지 분석

이번에는 raspbian_proc 프로세스가 종료되는 3단계 로그를 분석할 차례입니다.

 
 그림 4.5 프로세스가 종료될 때의 실행 흐름도 

실습 과정에서 raspbian_proc 프로세스를 종료할 때 kill 명령어를 썼습니다. kill 명령어는 프로세스를 종료시키는 시그널을 전달하는 명령어입니다. 위 그림에서 볼 수 있듯이 터미널에서 kill 명령어를 입력하면 해당 프로세스는 '종료 시그널'을 받아 소멸됩니다.

---
kill 명령어를 입력한 후 프로세스에게 어떤 방식으로 시그널을 전달하고 시그널 핸들러를 실행하는지는 12장 ‘시그널’에서 자세히 다룹니다.
---

kill 명령어로 프로세스가 종료되는 흐름을 알아봤습니다. 다음은 raspbian_proc-1360 프로세스가 종료할 때 출력되는 로그입니다.

18 bash-1320 [003] d... 701.305400: signal_generate: sig=9 errno=0 code=0 comm=raspbian_proc pid=1360 grp=1 res=0
...
19 raspbian_proc-1360 [001] .... 701.305489: do_exit+0x14/0xbe0 <-do_group_exit+0x50/0xe8
20 raspbian_proc-1360 [001] .... 701.305528: <stack trace>
21 => do_exit+0x18/0xbe0
22 => do_group_exit+0x50/0xe8
23 => get_signal+0x160/0x7dc
24 => do_signal+0x38c/0x468
25 => do_work_pending+0xd4/0xec
26 => slow_work_pending+0xc/0x20
27 => 0x76e10008
...
28 raspbian_proc-1360 [001] .... 701.305911: sched_process_exit: comm=raspbian_proc pid=1360 prio=120

18번째 줄 메시지를 보겠습니다. 

18 bash-1320 [003] d... 701.305400: signal_generate: sig=9 errno=0 code=0 comm=raspbian_proc pid=1360 grp=1 res=0

이 로그는 두 번째 터미널에서 다음 명령어로 raspbian_proc(pid: 1360) 프로세스를 종료했을 때 출력됩니다.

root@raspberrypi:/home/pi# kill -9  1360

터미널에서 ‘kill -9 1360’ 명령어를 입력하면 pid가 1360인 raspbian_proc 프로세스에게 “sig=9” 시그널을 전달합니다. 그렇다면 ‘sig=9’ 시그널의 의미는 무엇일까요?
 
시그널 타입은 정수로 선언돼 있으며, 9번은 프로세스 종료를 요청하는 SIGKILL 시그널입니다.

[https://elixir.bootlin.com/linux/v4.19.30/source/arch/arm/include/uapi/asm/signal.h]
#define SIGKILL 9

19~27번째 줄 메시지를 보겠습니다.

19 raspbian_proc-1360 [001] .... 701.305489: do_exit+0x14/0xbe0 <-do_group_exit+0x50/0xe8
20 raspbian_proc-1360 [001] .... 701.305528: <stack trace>
21 => do_exit+0x18/0xbe0
22 => do_group_exit+0x50/0xe8
23 => get_signal+0x160/0x7dc
24 => do_signal+0x38c/0x468
25 => do_work_pending+0xd4/0xec
26 => slow_work_pending+0xc/0x20
27 => 0x76e10008

raspbian_proc-1360 프로세스가 종료될 때의 콜스택입니다. 즉, raspbian_proc 프로세스가 시그널을 받아 종료될 때의 함수 흐름입니다.

다음은 28번째 줄의 메시지입니다.

28 raspbian_proc-1360 [001] .... 701.305911: sched_process_exit: comm=raspbian_proc pid=1360 prio=120

pid가 1360인 raspbian_proc 프로세스가 종료하는 동작을 보여줍니다.


4단계: 부모 프로세스에게 시그널을 전달하는 과정에 대한 ftrace 메시지 분석

프로세스는 종료할 때 부모 프로세스에게 SIGCHIL 시그널을 전달합니다. 이 규칙에 따라 종료된는 raspbian_proc 프로세스는 부모 프로세스인 bash(pid:946)에게 시그널을 전달합니다. 29번째 줄 메시지를 보겠습니다.

29 raspbian_proc-1360 [001] d... 701.306010: signal_generate: sig=17 errno=0 code=2 comm=bash pid=946 grp=1 res=0

pid가1360인 raspbian_proc 프로세스는 자신이 소멸될 것이란 사실을 부모 프로세스인 bash(pid: 946)에 시그널로 통지합니다. 이처럼 프로세스는 종료될 때 부모 프로세스에게 자신이 종료할 것이란 정보를 전달합니다. 위 메시지에서는 “sig=17”이 여기에 해당하고,  시그널 번호는 17입니다. 다음과 같은 매크로 선언과 같이 17은 SIGCHLD 시그널을 나타낸다는 사실을 알 수 있습니다.

https://elixir.bootlin.com/linux/v4.19.30/source/arch/arm/include/uapi/asm/signal.h
#define SIGCHLD 17

이번 절에서는 ftrace 로그 분석을 통해 구체적으로 어떤 흐름으로 프로세스가 생성되고 종료되는지 알아봤습니다. 

이어서 프로세스가 생성되고 종료되는 흐름별로 실행되는 함수 목록을 정리해보겠습니다.

프로세스 생성 단계의 함수 흐름

copy_process.part.5+0x18/0x1acc
_do_fork+0xc0/0x41c
sys_clone+0x30/0x38
ret_fast_syscall+0x0/0x28

프로세스 종료 단계의 함수 흐름

do_exit+0x18/0xbe0
do_group_exit+0x50/0xe8
get_signal+0x160/0x7dc
do_signal+0x38c/0x468
do_work_pending+0xd4/0xec
slow_work_pending+0xc/0x20

유저 프로세스가 생성되고 종료될 때 커널 내부에서 위와 같은 함수가 실행한다는 사실을 기억해 둡시다.

다음 절에서는 다른 리눅스 시스템 프로그램을 작성해서 유저 공간에서 생성된 프로세스가 어떤 과정으로 생성되고 소멸되는지 확인해 보겠습니다.


#프로세스

프로세스 소개 
프로세스 확인하기  
프로세스는 어떻게 생성할까?  
유저 레벨 프로세스 실행 실습  
커널 스레드  
커널 내부 프로세스의 생성 과정   
프로세스의 종료 과정 분석  
태스크 디스크립터(task_struct 구조체)  
스레드 정보: thread_info 구조체  
프로세스의 태스크 디스크립터에 접근하는 매크로 함수  
프로세스 디버깅  
   * glibc의 fork() 함수를 gdb로 디버깅하기  


"혹시 궁금한 점이 있으면 댓글로 질문 남겨주세요. 아는 한 성실히 답변 올려드리겠습니다!" 

Thanks,
Austin Kim(austindh.kim@gmail.com)


# Reference: For more information on 'Linux Kernel';

디버깅을 통해 배우는 리눅스 커널의 구조와 원리. 1

디버깅을 통해 배우는 리눅스 커널의 구조와 원리. 2









핑백

덧글

  • 45645 2020/06/17 02:09 # 삭제 답글

    원래 크롬창 띄우고 ftrace sh 실행하면 로그에 chromium도 같이 찍히나요...? 죄다 크롬로그가 찍혀서 로그 파악이 안되네요 ㅠㅠ
  • AustinKim 2020/06/17 13:38 #

    사실, ftrace 메시지는 CPU 코어별로 동시다발적으로 출력되기 때문에 보고 싶은 로그를 확인하기 어려운 부분이 있습니다.
    그래서 책에 소개된 ftrace 메시지는 독자 분들이 보기 편하기 잘 정돈해서 표기했습니다.

    아래는 ftrace 메시지의 한 예시입니다.

    <idle>-0 [001] dnh. 5977.725501: irq_handler_exit: irq=17 ret=handled
    chromium-browse-12120 [002] d.h. 5977.727383: irq_handler_entry: irq=17 name=arch_timer
    <...>-30832 [003] d.h. 5977.727383: irq_handler_entry: irq=17 name=arch_timer
    Chrome_IOThread-4443 [001] d.h. 5977.727388: irq_handler_entry: irq=17 name=arch_timer
    Chrome_IOThread-4443 [001] d.h. 5977.727393: arch_timer_handler_phys <-handle_percpu_devid_irq
    <...>-30832 [003] d.h. 5977.727393: arch_timer_handler_phys <-handle_percpu_devid_irq
    chromium-browse-12120 [002] d.h. 5977.727394: arch_timer_handler_phys <-handle_percpu_devid_irq

    위 메시지는 CPU 코어별로 해석하면 조금 더 편하게 볼 수 있습니다.
    아래 메시지에서 CPU 코어 001에 해당하는 부분은 화살표로 표시된 로그를 참고하세요.

    <idle>-0 [001] dnh. 5977.725501: irq_handler_exit: irq=17 ret=handled <<<
    chromium-browse-12120 [002] d.h. 5977.727383: irq_handler_entry: irq=17 name=arch_timer
    <...>-30832 [003] d.h. 5977.727383: irq_handler_entry: irq=17 name=arch_timer
    Chrome_IOThread-4443 [001] d.h. 5977.727388: irq_handler_entry: irq=17 name=arch_timer <<<
    Chrome_IOThread-4443 [001] d.h. 5977.727393: arch_timer_handler_phys <-handle_percpu_devid_irq <<<
    <...>-30832 [003] d.h. 5977.727393: arch_timer_handler_phys <-handle_percpu_devid_irq
    chromium-browse-12120 [002] d.h. 5977.727394: arch_timer_handler_phys <-handle_percpu_devid_irq
  • 2020/06/17 13:38 # 답글 비공개

    비공개 덧글입니다.
댓글 입력 영역