리눅스 커널 빌드 스크립트와 ftrace 로그로 살펴본 프로세스 처리 콜스택
디버깅을 통해 배우는 리눅스 커널의 구조와 원리에서 다루지 않는 최신 커널 빌드 방법에 대해 소개하고 ftrace 로그를 통해 프로세스가 커널에서 어떻게 처리 되는지 분석한다
리눅스 커널 빌드 스크립트와 ftrace 로그로 살펴본 프로세스 처리 콜스택
디버깅을 통해 배우는 리눅스 커널의 구조와 원리라는 책의 학습 과정은 라즈베리 파이4와 리눅스 커널 4.19 버전을 기반으로 되어 있기 때문에
라즈베리 파이5와 리눅스 커널 6.6 버전을 사용하여 책 내용을 그대로 쫓아 갈 수가 없다.
학습의 큰 줄기는 책 내용을 따르되 커널 4.19에서 6.6 간 변경 사항들을 따로 적용하고 비교하면서 공부 해야 한다.
build_rpi_kernel.sh
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
#!/bin/bash
echo "configure build output path"
KERNEL_TOP_PATH="$( cd "$(dirname "$0")" ; pwd -P )"
OUTPUT="$KERNEL_TOP_PATH/out"
echo "$OUTPUT"
KERNEL=kernel_2712
BUILD_LOG="$KERNEL_TOP_PATH/rpi_build_log.txt"
echo "move kernel source"
cd linux
echo "make defconfig"
make O=$OUTPUT bcm2712_defconfig
echo "kernel build"
make O=$OUTPUT Image.gz modules dtbs -j6 2>&1 | tee $BUILD_LOG
1. 라즈베리 파이5에서 사용하기 위한 리눅스 커널 6.6 빌드 스크립트
책에서 다루는 라즈베리 파이3에는 CPU의 base 칩셋으로 BCM 2709 칩셋이 사용된다.
그러나 라즈베리 파이5에는 BCM 2712 칩셋이 사용된다.
따라서 책에 서술된 커널 빌드 스크립트 build_rpi_kernel.sh를 다음과 같이 수정해야 한다.
2. 프로세스 파트 공부 시, 변경 내역과 ftrace 로깅 스크립트
2.1. 함수 변경 내역
| Kernel 4.19 | Kernel 6.6 |
|---|---|
| _do_fork | kernel_clone |
2.2. ftrace 함수 필터 변경 내역
| Kernel 4.19 | Kernel 6.6 |
|---|---|
| sys_clone | __arm64_sys_clone |
2.2.1. 함수 필터 찾는 방법
커널 버전이 변경 되면서 4.19 버전의 함수 필터를 6.6 버전에서 그대로 사용하지 못하는 경우가 있다.
이때는 다음 경로에서 함수 필터가 존재하는지 확인해 봐야 한다.
/sys/kernel/debug/tracing/available_filter_functions
예를 들어, 현재 설치된 커널에서 함수 필터 rpi_get_interrupt_info를 지원하고 있는지 찾기 위해서는 다음과 같이 검색을 시도해 본다.
1
cat /sys/kernel/debug/tracing/available_filter_functions | grep rpi_get_interrupt_info
2.3. 스크립트
마찬가지로 clone process 내역을 ftrace로 로깅 하기 위한 스크립트 clone_process_debug.sh도 다음과 같이 수정해야 한다.
clone_process_debug.sh
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
59
60
61
62
63
64
65
66
67
68
69
70
71
72
73
#!/bin/bash
echo 0 > /sys/kernel/debug/tracing/tracing_on
sleep 1
echo "tracing_off"
echo 0 > /sys/kernel/debug/tracing/events/enable
sleep 1
echo "events disabled"
#echo secondary_startup > /sys/kernel/debug/tracing/set_ftrace_filter
#sleep 1
#echo "set_ftrace_filter init"
echo function > /sys/kernel/debug/tracing/current_tracer
sleep 1
echo "function tracer enabled"
echo __arm64_sys_clone do_exit > /sys/kernel/debug/tracing/set_ftrace_filter
echo kernel_clone copy_process* >> /sys/kernel/debug/tracing/set_ftrace_filter
sleep 1
echo "set_ftrace_filter enabled"
echo 1 > /sys/kernel/debug/tracing/events/sched/sched_switch/enable
echo 1 > /sys/kernel/debug/tracing/events/sched/sched_wakeup/enable
echo 1 > /sys/kernel/debug/tracing/events/sched/sched_process_fork/enable
echo 1 > /sys/kernel/debug/tracing/events/sched/sched_process_exit/enable
echo 1 > /sys/kernel/debug/tracing/events/signal/enable
sleep 1
echo "event enabled"
echo 1 > /sys/kernel/debug/tracing/options/func_stack_trace
echo 1 > /sys/kernel/debug/tracing/options/sym-offset
echo "function stack trace enabled"
echo 1 > /sys/kernel/debug/tracing/tracing_on
echo "tracing_on"
3. 프로세스
3.1. 유저 프로세스 생성 및 종료 콜스택
3.1.1. 생성
프로세스 생성
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
bash-2124 [002] ..... 6400.733066: copy_process+0x4/0x1610 <-kernel_clone+0x9c/0x448
bash-2124 [002] ..... 6400.733067: <stack trace>
=> copy_process+0x8/0x1610
=> kernel_clone+0x9c/0x448
=> __do_sys_clone+0x70/0xa8
=> __arm64_sys_clone+0x28/0x40
=> invoke_syscall+0x50/0x128
=> el0_svc_common.constprop.0+0x48/0xf0
=> do_el0_svc+0x24/0x38
=> el0_svc+0x40/0xe8
=> el0t_64_sync_handler+0x100/0x130
=> el0t_64_sync+0x190/0x198
bash-2124 [002] ..... 6400.733176: sched_process_fork: comm=bash pid=2124 child_comm=bash child_pid=2466
<idle>-0 [003] d..2. 6400.733185: sched_switch: prev_comm=swapper/3 prev_pid=0 prev_prio=120 prev_state=R ==> next_comm=bash next_pid=2466 next_prio=120
raspbian_proc-2466 [003] d..2. 6400.733311: sched_switch: prev_comm=bash prev_pid=2466 prev_prio=120 prev_state=S ==> next_comm=kworker/u11:2 next_pid=208 next_prio=120
raspbian_proc-2466 [003] d..4. 6400.733856: sched_wakeup: comm=kworker/u12:1 pid=219 prio=120 target_cpu=003
raspbian_proc-2466 [003] d..2. 6400.733867: sched_switch: prev_comm=raspbian_proc prev_pid=2466 prev_prio=120 prev_state=S ==> next_comm=kworker/u12:1 next_pid=219 next_prio=12
3.1.2. 종료
3.1.2.1. 코드 내 return 명령으로 정상 종료 시
프로그램 내 return 명령에 의한 종료
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
raspbian_proc-2466 [003] ..... 6403.733965: do_exit+0x4/0x990 <-do_group_exit+0x3c/0xa0
raspbian_proc-2466 [003] ..... 6403.733967: <stack trace>
=> do_exit+0x8/0x990
=> do_group_exit+0x3c/0xa0
=> __arm64_sys_exit_group+0x20/0x28
=> invoke_syscall+0x50/0x128
=> el0_svc_common.constprop.0+0x48/0xf0 // 트랩 핸들러
=> do_el0_svc+0x24/0x38 // 트랩 핸들러
=> el0_svc+0x40/0xe8 // 트랩 핸들러
=> el0t_64_sync_handler+0x100/0x130 // 트랩 핸들러
=> el0t_64_sync+0x190/0x198 // 트랩 핸들러
// 64비트에서는 사용자 공간 실행 주소이자 복귀 주소가 명확히 기록되지 않고 대신 트랩 핸들러를 통해 묵시적으로 처리 됨
raspbian_proc-2466 [003] ..... 6403.734019: sched_process_exit: comm=raspbian_proc pid=2466 prio=120
raspbian_proc-2466 [003] d..2. 6403.734033: signal_generate: sig=17 errno=0 code=1 comm=bash pid=2124 grp=1 res=0
<idle>-0 [002] dNh2. 6403.734038: sched_wakeup: comm=bash pid=2124 prio=120 target_cpu=002
raspbian_proc-2466 [003] d..2. 6403.734039: sched_switch: prev_comm=raspbian_proc prev_pid=2466 prev_prio=120 prev_state=Z ==> next_comm=swapper/3 next_pid=0 next_prio=120
<idle>-0 [002] d..2. 6403.734039: sched_switch: prev_comm=swapper/2 prev_pid=0 prev_prio=120 prev_state=R ==> next_comm=bash next_pid=2124 next_prio=120
bash-2124 [002] d..1. 6403.734085: signal_deliver: sig=17 errno=0 code=1 sa_handler=5555c7f650f4 sa_flags=10000000
3.1.2.2. bash 에서 kill 시그널 수신하여 종료 시
1) bash에서 kill 수행 시, kii 될 process로 sig_generate 함수를 통해 SIGKILL(9) 전달
2) kill 수신 받은 process : get_signal 통해 시그널을 받은 뒤에 sched_process_exit 수행
3) 부모 프로세스인 bash에게 sig_generate 함수 통해 SIGCHLD(17) 전달
4) 부모 프로세스인 bash는 signal_deliver 함수 통해 SIGCHLD(17) 수신
kill(SIGKILL(9)) 수신으로 인한 종료
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
bash-2061 [001] d..1. 8123.263608: signal_generate: sig=9 errno=0 code=0 comm=raspbian_proc pid=3682 grp=1 res=0
<idle>-0 [003] dNh2. 8123.263610: sched_wakeup: comm=raspbian_proc pid=3682 prio=120 target_cpu=003
<idle>-0 [003] d..2. 8123.263612: sched_switch: prev_comm=swapper/3 prev_pid=0 prev_prio=120 prev_state=R ==> next_comm=raspbian_proc next_pid=3682 next_prio=120
raspbian_proc-3682 [003] d..1. 8123.263615: signal_deliver: sig=9 errno=0 code=0 sa_handler=0 sa_flags=0
raspbian_proc-3682 [003] ..... 8123.263616: do_exit+0x4/0x990 <-do_group_exit+0x3c/0xa0
raspbian_proc-3682 [003] ..... 8123.263618: <stack trace>
=> do_exit+0x8/0x990
=> do_group_exit+0x3c/0xa0
=> get_signal+0x9e4/0x9f0
=> do_notify_resume+0x15c/0x1370
=> el0_svc+0xd8/0xe8
=> el0t_64_sync_handler+0x100/0x130
=> el0t_64_sync+0x190/0x198
raspbian_proc-3682 [003] ..... 8123.263674: sched_process_exit: comm=raspbian_proc pid=3682 prio=120
raspbian_proc-3682 [003] d..2. 8123.263686: signal_generate: sig=17 errno=0 code=2 comm=bash pid=2260 grp=1 res=0
<idle>-0 [002] dNh2. 8123.263690: sched_wakeup: comm=bash pid=2260 prio=120 target_cpu=002
<idle>-0 [002] d..2. 8123.263692: sched_switch: prev_comm=swapper/2 prev_pid=0 prev_prio=120 prev_state=R ==> next_comm=bash next_pid=2260 next_prio=120
raspbian_proc-3682 [003] d..2. 8123.263696: sched_switch: prev_comm=raspbian_proc prev_pid=3682 prev_prio=120 prev_state=X ==> next_comm=kworker/u10:0 next_pid=2462 next_prio=120
bash-2260 [002] d..1. 8123.263971: signal_deliver: sig=17 errno=0 code=2 sa_handler=5555b70e50f4 sa_flags=10000000
이 기사는 저작권자의 CC BY 4.0 라이센스를 따릅니다.