ARM Linux Kernel Hacks

rousalome.egloos.com

포토로그 Kernel Crash


통계 위젯 (화이트)

203239
1625
172600


[리눅스커널] 시그널: ftrace로 시그널 기본 동작 라즈베리파이에서 확인해보기 12. 시그널

이번 시간에는 라즈베리파이에서 ftrace를 설정하고 로그를 받아 분석하는 실습을 해 보겠습니다.  

ftrace 설정하기

먼저 ftrace 설정 방법을 소개합니다.
#!/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_start_kernel  > /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  do_exit dequeue_signal ttwu_do_wakeup > /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_process_exit/enable

echo 1 > /sys/kernel/debug/tracing/events/signal/signal_generate/enable
echo 1 > /sys/kernel/debug/tracing/events/signal/signal_deliver/enable

echo 1 > /sys/kernel/debug/tracing/events/raw_syscalls/sys_enter/enable
echo 1 > /sys/kernel/debug/tracing/events/raw_syscalls/sys_exit/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"
위에서 소개한 ftrace 명령어를 signal_debug.sh 셸 스크립트로 저장한 다음 실행하면 효율적으로 ftrace를 설정할 수 있습니다.

ftrace 설정 명령어의 주요 내용은 다음과 같습니다.
enable 하는 ftrace 이벤트 목록 
signal_generate
signal_deliver
sched_switch
sched_process_exit
sys_enter
sys_exit

set_ftrace_filter 필터로 지정하는 함수 목록 
ttwu_do_wakeup
dequeue_signal
do_exit

프로세스 SIGKILL 시그널 전달을 위한 과정 소개하기

라즈베리파이에서 터미널을 하나 실행합시다. 처음 실행한 터미널을 첫 번째 터미널이라고 부르 겠습니다. 이어서 터미널을 하나 더 실행합시다. 이를 두 번째 터미널로 부르겠습니다.

첫 번째 터미널에서 다음 명령어를 입력합시다.
01 root@raspberrypi:/usr/include # ps -ely | grep bash
02 S 1000 500 432 0 80 0 4096 1645 poll_s tty1 00:00:00 bash
03 S 1000 750 1146 0 80 0 4192 1628 wait pts / 0 00:00:00 bash
04 S 0 833 1350 0 80 0 3376 1433 wait pts / 0 00:00:00 bash
05 S 1000 1240 1146 0 80 0 3964 1628 poll_s pts / 1 00:00:00 bash

05번째 줄에서 보이는 프로세스가 2번째 터미널에서 실행하는 bash 셸입니다. PID가 1240입니다.

그러면 첫 번째 터미널에서 다음 명령어를 입력해 2 번째 터미널에서 실행하는 bash 셸을 종료시킵시다.
root@raspberrypi:# kill -SIGKILL 1240

이후 ftrace 로그를 받습니다.

ftrace 로그 분석하기

분석할 ftrace 로그는 다음과 같습니다
1  bash-833 [003] .... 3742.555094: sys_enter: NR 37 (4d8, 9, 0, 5a7cf300, 4d8, f9ef8)
2  bash-833 [003] d... 3742.555125: ttwu_do_wakeup+0x10/0x1a4 <-ttwu_do_activate+0x80/0x84
3  bash-833 [003] d... 3742.555151: <stack trace>
4  => wake_up_state+0x1c/0x20
5  => signal_wake_up_state+0x34/0x48
6  => complete_signal+0x204/0x248
7  => __send_signal+0x160/0x420
8  => send_signal+0x48/0x98
9  => do_send_sig_info+0x50/0x7c
10 => group_send_sig_info+0x50/0x54
11 => kill_pid_info+0x40/0x54
12 => sys_kill+0x11c/0x1c4
13 => __sys_trace_return+0x0/0x10
14 bash-833 [003] d... 3742.555155: sched_wakeup: comm=bash pid=1240 prio=120 target_cpu=003
15 bash-833 [003] d... 3742.555159: signal_generate: sig=9 errno=0 code=0 comm=bash pid=1240 grp=1 res=0
16 bash-833 [003] .... 3742.555161: sys_exit: NR 37 = 0
...
17 bash-833 [003] d...  3742.557372: sched_switch: prev_comm=bash prev_pid=833 prev_prio=120 prev_state=D ==> next_comm=bash next_pid=1240 next_prio=120
18 bash-1240 [003] ....  3742.557387: sys_exit: NR 335 = -514
19 bash-1240 [003] d... 3742.557391: dequeue_signal+0x14/0x19c <-get_signal+0x104/0x72c
20 bash-1240 [003] d...  3742.557406: <stack trace>
21 => do_work_pending+0xb4/0xcc
22 => slow_work_pending+0xc/0x20
23 bash-1240 [003] d...  3742.557411: signal_deliver: sig=9 errno=0 code=0 sa_handler=0 sa_flags=0
24 bash-1240 [003] ....  3742.557425: do_exit+0x14/0xb60 <-do_group_exit+0x50/0xe4
25 bash-1240  [003] ....  3742.557440: <stack trace>
26 => do_signal+0x78/0x4dc
27 => do_work_pending+0xb4/0xcc
28 => slow_work_pending+0xc/0x20
29 bash-1240  [003] ....  3742.558690: sched_process_exit: comm=bash pid=1240 prio=120

복잡해 보이는 ftrace 로그는 실행 흐름에 따라 2단계로 분류할 수 있습니다.
 
[그림 12.14] ftrace: 시그널 생성과 시그널 처리 단계 실행 흐름도

위 그림에서 왼쪽 박스에 ① 시그널 생성과 오른쪽 박스에 ② 시그널 처리 박스를 눈으로 따라가 봅시다. 각 단계별로 호출되는 주요 커널 함수는 다음과 같습니다. 

① 단계: 시그널 생성  
__send_signal(): 펜딩 시그널 정보를 써줌
ttwu_do_wakeup(): 시그널을 받을 프로세스를 깨움
 
② 단계: 시그널 처리
do_signal(): 펜딩 시그널을 받음
do_exit(): 프로세스 종료

이어서 단계별로 ftrace 로그를 분석합니다.

① 단계: 시그널 생성 로그 분석
먼저 시그널 생성 단계 로그를 분석하겠습니다.

다음은 "kill -9 [pid]" 명령어를 입력했을 때 로그입니다.
1  bash-833 [003] .... 3742.555094: sys_enter: NR 37 (4d8, 9, 0, 5a7cf300, 4d8, f9ef8)
2  bash-833 [003] d... 3742.555125: ttwu_do_wakeup+0x10/0x1a4 <-ttwu_do_activate+0x80/0x84
3  bash-833 [003] d... 3742.555151: <stack trace>
4  => wake_up_state+0x1c/0x20
5  => signal_wake_up_state+0x34/0x48
6  => complete_signal+0x204/0x248
7  => __send_signal+0x160/0x420
8  => send_signal+0x48/0x98
9  => do_send_sig_info+0x50/0x7c
10 => group_send_sig_info+0x50/0x54
11 => kill_pid_info+0x40/0x54
12 => sys_kill+0x11c/0x1c4
13 => __sys_trace_return+0x0/0x10
14 bash-833 [003] d... 3742.555155: sched_wakeup: comm=bash pid=1240 prio=120 target_cpu=003
15 bash-833 [003] d... 3742.555159: signal_generate: sig=9 errno=0 code=0 comm=bash pid=1240 grp=1 res=0
7~13번째 줄 로그를 보면 다음 사실을 알 수 있습니다. 
유저 공간에서 kill() 함수를 호출하면 해당 시스템 콜 핸들러인 sys_kill() 함수가 호출된다.
커널 내부 __send_signal() 함수가 호출된다. 

요약하면 시그널을 받을 프로세스 태스크 디스크립터에 접근해서 펜딩 시그널(처리되야 할) 시그널 정보를 써주는 동작입니다.  

다음 2~6번째 줄 로그를 보면 시그널을 받을 bash 프로세스(pid:1240)을 깨워 스케줄링 요청을 하는 함수 목록을 볼 수 있습니다. 


프로세스를 깨우면 resched_curr() 함수를 호출하며 스케줄러에게 깨우려는 프로세스를 실행시켜 달라고 요청합니다. 스케줄러는 이 요청을 받은 후 런큐에 대기 중인 프로세스와 우선 순위를 비교한 후 요청한 프로세스를 실행합니다. 

런큐에 실행을 기다리는 프로세스가 없으면 resched_curr() 함수 호출 이후 대부분 프로세스는 스케줄링으로 실행을 시작합니다.   


다음 14번째 줄 로그를 보겠습니다.
14 bash-833 [003] d... 3742.555155: sched_wakeup: comm=bash pid=1240 prio=120 target_cpu=003

bash 프로세스를 깨우는 동작입니다. sched_wakeup는 프로세스를 깨우는 동작을 표현하는 ftrace 이벤트 입니다.

이어서 15번째 줄 로그를 분석하겠습니다. 
15 bash-833 [003] d... 3742.555159: signal_generate: sig=9 errno=0 code=0 comm=bash pid=1240 grp=1 res=0

위 메시지는 다음 사실을 말해줍니다. 

    시그널을 생성했으며 SIGKILL 시그널을 bash 프로세스에 전달했다.

② 단계: 시그널 처리 로그 분석
2 단계 시그널 처리 로그를 분석합니다. 시그널을 받아 후속 처리를 하는 실행 흐름입니다. 
17 bash-833 [003] d...  3742.557372: sched_switch: prev_comm=bash prev_pid=833 prev_prio=120 prev_state=D ==> next_comm=bash next_pid=1240 next_prio=120
18 bash-1240 [003] ....  3742.557387: sys_exit: NR 3 = -514
19 bash-1240 [003] d... 3742.557391: dequeue_signal+0x14/0x19c <-get_signal+0x104/0x72c
20 bash-1240 [003] d...  3742.557406: <stack trace>
21 => do_work_pending+0xb4/0xcc
22 => slow_work_pending+0xc/0x20
23 bash-1240 [003] d...  3742.557411: signal_deliver: sig=9 errno=0 code=0 sa_handler=0 sa_flags=0
24 bash-1240 [003] ....  3742.557425: do_exit+0x14/0xb60 <-do_group_exit+0x50/0xe4
25 bash-1240  [003] ....  3742.557440: <stack trace>
26 => do_signal+0x78/0x4dc
27 => do_work_pending+0xb4/0xcc
28 => slow_work_pending+0xc/0x20
29 bash-1240  [003] ....  3742.558690: sched_process_exit: comm=bash pid=1240 prio=120 

17번째 줄 ftrace 이전에 bash-1240 프로세스는 어떤 상태였을까요? 다음과 같은 콜스택으로 잠들어 있었습니다.
-000|context_switch(inline)
-000|__schedule()
-001|schedule()
-002|schedule_timeout()
-003|n_tty_read()
-004|tty_read()
-005|vfs_read()
-006|SYSC_read(inline)
-006|sys_read()
-007|ret_fast_syscall(asm)

잠들어 있던 bash-1240 프로세스는 깨어나 실행을 재개합니다. 

    그렇다면 bash-1240 프로세스는 어떻게 깨어날까요?

이전 2단계 동작에서 resched_curr() 함수를 호출해서 bash(pid:1240) 프로세스 실행을 요청했습니다. 그렇다면 스케줄러가 bash(pid:1240) 프로세스를 실행시키면 어떻게 동작할까요? 

    콜스택 정보와 같이context_switch() 함수부터 sys_read() 함수로 다시 돌아와 
   ret_fast_syscall 레이블을 실행합니다.

그렇다면 이와 같은 동작을 했다는 흔적은 ftrace로그에서 확인할 수 있을까요?

    33번째 줄 로그로 이 정보를 알 수 있습니다. 

다음과 같이 3번 read 시스템 콜 처리가 끝났다는 내용입니다.
18 bash-1240 [003] ....  3742.557387: sys_exit: NR 3 = -514

다음 34번째 줄 로그를 보겠습니다.
34 sh-17015 [002] d..2 11842.282522: dequeue_signal+0x24/0x1b0 <-get_signal+0xc0/0x588

dequeue_signal() 함수를 호출해서 시그널을 처리할 프로세스의 태스크 디스크립터에 접근하여 펜딩된 시그널을 가져옵니다.  

이어서 39번째 줄 로그를 보겠습니다.
39 sh-17015 [002] d..1 11842.282543: signal_deliver: sig=9 errno=0 code=0 sa_handler=0 sa_flags=0

이번 소절에서 가장 로그로 다음과 같이 해석할 수 있습니다.  

    9번 SIGKILL 시그널을 bash(pid:17015) 프로세스가 제대로 처리했다. 

마지막으로 40~45번째 줄 로그를 보겠습니다.
40 sh-17015 [002] ...1 11842.282553: do_exit+0x28/0xa70 <-do_group_exit+0x40/0xa0
41 sh-17015 [002] ...1 11842.282557: <stack trace>
42 => get_signal+0x2bc/0x588
43 => do_signal+0x15c/0x544
44 => do_notify_resume+0xa0/0xa8
45 => work_pending+0x8/0x14

do_group_exit() 함수를 호출해서 스레드 그룹에 있는 스레드를 종료합니다.

#Referene 시그널
시그널이란
시그널 설정은 어떻게 할까
시그널 생성 과정 함수 분석
프로세스는 언제 시그널을 받을까
시그널 전달과 처리는 어떻게 할까?
시그널 제어 suspend() 함수 분석 
시그널 ftrace 디버깅

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



핑백

덧글

댓글 입력 영역