Linux Kernel(4.14) Hacks

rousalome.egloos.com

포토로그 Kernel Crash




[리눅스커널] 프로세스 - 기본 유저레벨 프로세스 생성 실습 및 ftrace 로그 분석(1/2) [라즈베리파이] 커널 프로세스

다시 라즈베리파이에서 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
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 로그 추출

다음 시간에서는 프로세스 생성과 종료 흐름이 저장된 ftrace 로그를 심층 분석하는 시간을 갖겠습니다.


Reference(워크큐)
워크큐(Workqueue) Overview




핑백

덧글

댓글 입력 영역