ARM Linux Kernel Hacks

rousalome.egloos.com

포토로그 Kernel Crash


통계 위젯 (화이트)

194239
1625
172591


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

이번 소절에서는 유저 어플리케이션 코드를 작성하면서 시그널 핸들러를 커널에서 어떤 방식으로 호출하는지 살펴보겠습니다. 이번 챕터에서 배운 내용을 총정리하는 실습이니 꼭 따라서 해보시길 바랍니다.

유저 어플리케이션 시그널 핸들러 설정 코드 입력하기

다음은 유저 어플리케이션에서 시그널 핸들러를 지정하는 실습 코드입니다.
1 #include <unistd.h>
2 #include <signal.h>
3 #include <stdio.h>
4 #include <stdlib.h>
5
6 void sig_handler(int signum) {
7 switch(signum) {
8 case SIGINT:
9 printf("sig num [%d] \n", signum);
10 break;
11
12 case SIGALRM:
13 printf("sig num [%d] \n", signum);
14 break;
15
16 case SIGKILL:
17 printf("sig num [%d] \n", signum);
18 break;
19
20 default:
21 printf(" default sig num [%d] \n", signum);
22 }
23 }
24
25 int main() 
26 {
27 struct sigaction act;
28 sigset_t set;
29
30 void *func_ptr;
31   
32      func_ptr = sig_handler;
33      printf(" signal_handler = 0x%x \n", (unsigned int)func_ptr);
34
35 sigemptyset(&(act.sa_mask));
36
37 sigaddset(&(act.sa_mask), SIGALRM);
38 sigaddset(&(act.sa_mask), SIGINT);
39 sigaddset(&(act.sa_mask), SIGKILL);
40
41 act.sa_handler = sig_handler;
42
43 sigaction(SIGALRM, &act, NULL);
44 sigaction(SIGINT, &act, NULL);
45 sigaction(SIGUSR1, &act, NULL);
46
47 for(;;)
48 pause();
49 }

위 코드의 핵심은 SIGALRM, SIGINT, SIGUSR1 시그널이 발생했을 때 sig_handler() 함수가 호출되는 동작입니다. 

대부분 코드는 이번 챕터에서 다룬 내용이니 넘어가고 가장 중요한 30번째 줄 코드를 보겠습니다.
30 void *func_ptr;
31   
32      func_ptr = sig_handler;
33      printf(" signal_handler = 0x%x \n", (unsigned int)func_ptr);

32번째 줄 코드에서 시그널 핸들러 함수인 sig_handler를 void 타입 func_ptr 포인터에 저장합니다. 다음 33번째 줄 코드에서 시그널 핸들러 함수 sig_handler() 주소를 출력합니다.

위와 같이 코드를 작성한 후 RPi_signal.c 파일로 저장합시다. Makefile을 아래와 같이 작성한 다음에 라즈베리파이에서 컴파일을 합시다.
RPi_signal: RPi_signal.c
gcc -o RPi_signal RPi_signal.c

컴파일이 제대로 완료되면 RPi_signal 파일이 생성됩니다.

시그널 디버깅을 위해 커널 소스 코드 수정해보기

이번에는 시그널 관련 커널 소스 코드를 수정해 보겠습니다.

패치 코드 입력 방법을 소개하기 위해 커널 오리지널 setup_return() 함수 코드를 소개합니다.
[https://github.com/raspberrypi/linux/blob/rpi-4.19.y/arch/arm/kernel/signal.c]
static int
setup_return(struct pt_regs *regs, struct ksignal *ksig,
     unsigned long __user *rc, void __user *frame)
{
unsigned long handler = (unsigned long)ksig->ka.sa.sa_handler;
unsigned long handler_fdpic_GOT = 0;
...
{
/*
 * Ensure that the instruction cache sees
 * the return code written onto the stack.
 */
flush_icache_range((unsigned long)rc,
   (unsigned long)(rc + 3));

retcode = ((unsigned long)rc) + thumb;
}
}

/* 패치 코드를 입력하세요 */
regs->ARM_r0 = ksig->sig;
regs->ARM_sp = (unsigned long)frame;
regs->ARM_lr = retcode;
regs->ARM_pc = handler;

위 소스 코드에서 /* 패치 코드를 입력하세요 */ 이라고 표시된 부분에 
다음 코드를 작성합시다. 
trace_printk("[+] handler:0x%lx, sig:%d \n", 
(unsigned long)handler, ksig->sig);

ftrace로 유저 공간에서 지정한 시그널 핸들러 주소와 시그널 종류를 ftrace로 출력하는 패치 코드 입니다.

위와 같이 소스 코드를 입력하고 커널 빌드를 합시다. 에러 없이 커널 빌드가 끝나면 커널 이미지를 라즈베리파이에 설치 후 리부팅합시다.

ftrace 설정 방법 소개

다음은 ftrace를 설정하는 코드입니다.
1 #!/bin/bash
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  do_exit __set_current_blocked > /sys/kernel/debug/tracing/set_ftrace_filter
20 echo  sys_pause dequeue_signal signal_setup_done sys_sigreturn >> /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_wait_task/enable
26 echo 1 > /sys/kernel/debug/tracing/events/sched/sched_switch/enable
27
28 echo 1 > /sys/kernel/debug/tracing/events/signal/signal_generate/enable
29 echo 1 > /sys/kernel/debug/tracing/events/signal/signal_deliver/enable
30
31 echo 1 > /sys/kernel/debug/tracing/events/raw_syscalls/enable
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"

위 코드에서 눈여겨볼 부분은 28~29번째 줄 코드와 같이 signal_generate와 signal_deliver 이벤트를 설정하는 코드입니다.
28 echo 1 > /sys/kernel/debug/tracing/events/signal/signal_generate/enable
29 echo 1 > /sys/kernel/debug/tracing/events/signal/signal_deliver/enable

또한 다음 이벤트를 설정해서 시스템 콜 이벤트도 켜줍니다.
31 echo 1 > /sys/kernel/debug/tracing/events/raw_syscalls/enable

위 코드를 셸 스크립트 파일(RPi_signal_trace.sh)로 저장하면 쉽게 ftrace 설정을 할 수 있습니다. 

이제 유저 어플리케이션 실행 코드와 ftrace 설정 준비가 끝났으니 ftrace 로그를 받는 과정을 설명드리겠습니다.

시그널을 발생시킨 후 ftrace 로그를 받는 과정 소개

1. 먼저 ftrace를 설정합니다. 
root@raspberrypi:/home/pi # ./RPi_signal_trace.sh

2. 다음 명령어로 RPi_signal 어플리케이션을 실행한 다음 ‘Ctl+C 키’를 터미널로 입력합시다.
root@raspberrypi:/home/pi # ./RPi_signal
 signal_handler = 0x10510 
^Csig num [2] 
^Csig num [2] 
^Csig num [2] 
^Csig num [2] 

터미널로 sig_handler() 함수 주소가 0x10510임을 알 수 있습니다.

3. 다음 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_trace.sh  셸 스크립트 파일로 저장해서 실행하면 바로 ftrace 로그를 ftrace_log.c 파일로 추출할 수 있습니다.

ftrace 로그 분석하기

이제 ftrace 로그를 분석할 차례입니다. 전체 로그는 다음과 같습니다. 
1 kworker/u8:0-1119  [001] d...  2772.154341: ttwu_do_wakeup+0x10/0x1a4 <-ttwu_do_activate+0x80/0x84
2 kworker/u8:0-1119  [001] d...  2772.154378: <stack trace>
3  => wake_up_state+0x1c/0x20
4  => signal_wake_up_state+0x34/0x48
5  => complete_signal+0x114/0x248
6  => __send_signal+0x160/0x420
7  => send_signal+0x48/0x98
8  => do_send_sig_info+0x50/0x7c
9  => group_send_sig_info+0x50/0x54
10 => __kill_pgrp_info+0x4c/0x7c
11 => kill_pgrp+0x44/0x74
12 => __isig+0x34/0x40
13 => isig+0x54/0x104
14 => n_tty_receive_signal_char+0x28/0x70
15 => n_tty_receive_char_special+0xa10/0xb78
16 => n_tty_receive_buf_common+0x610/0xc04
17 => n_tty_receive_buf2+0x24/0x2c
18 => tty_ldisc_receive_buf+0x30/0x6c
19 => tty_port_default_receive_buf+0x48/0x68
20 => flush_to_ldisc+0xb4/0xcc
21 => process_one_work+0x224/0x518
22 => worker_thread+0x60/0x5f0
23 => kthread+0x144/0x174
24 => ret_from_fork+0x14/0x28
25    kworker/u8:0-1119  [001] d...  2772.154381: sched_wakeup: comm=RPi_signal pid=1127 prio=120 target_cpu=001
26    kworker/u8:0-1119  [001] d...  2772.154384: signal_generate: sig=2 errno=0 code=128 comm=RPi_signal pid=1127 grp=1 res=0
...
27 kworker/u8:0-1119  [001] d...  2772.154422: sched_switch: prev_comm=kworker/u8:0 prev_pid=1119 prev_prio=120 prev_state=R+ ==> next_comm=RPi_signal next_pid=1127 next_prio=120
28 RPi_signal-1127  [001] ....  2772.154427: sys_exit: NR 29 = -514
29 RPi_signal-1127  [001] d...  2772.154432: dequeue_signal+0x14/0x19c <-get_signal+0x104/0x72c
30 RPi_signal-1127  [001] d...  2772.154447: <stack trace>
31 => do_work_pending+0xb4/0xcc
32 => slow_work_pending+0xc/0x20
33 RPi_signal-1127  [001] d...  2772.154457: signal_deliver: sig=2 errno=0 code=128 sa_handler=10510 sa_flags=4000000
34 RPi_signal-1127  [001] ....  2772.154500: setup_return+0x160/0x264: [+] handler:0x10510 , sig:2 
...
35 RPi_signal-1127  [001] ....  2772.154684: sys_enter: NR 119 (d, 0, 1, 0, 10714, 0)
36 RPi_signal-1127  [001] ....  2772.154688: sys_sigreturn+0x14/0xdc <-__sys_trace_return+0x0/0x10

복잡해 보이는ftrace 로그를 시그널 처리 과정 단계별로 정리하면 다음과 같습니다.

 
[그림 12.15] ftrace: 시그널 핸들러 실행 전체 흐름도

각 단계 별 동작을 확인합시다.

[1] 단계
시그널을 생성하는 과정에서 시그널을 정보를 시그널을 받을 프로세스 태스크 디스크립터에 써주는 동작입니다.

[2] 단계
시그널을 받을 프로세스를 깨웁니다.

[3] 단계
sys_pause() 시스템 콜 함수에서 schedule() 함수로 진입해서 RPi_handle 프로세스는 다시 깨어나 실행을 실행합니다. ret_fast_syscall 레이블로 복귀해서 시그널 처리를 시작합니다.

[4] 단계
시그널 핸들러를 유저 프로세스 PC 레지스터에 저장하고 시그널 핸들러 실행 후 커널로 복귀할 코드를 r14 레지스터에 저장합니다.

[5] 단계
시그널 핸들러인 sig_handler() 함수가 실행합니다. printf() 함수를 호출해서 로그를 출력합니다.

[6] 단계
시그널 핸들러 실행이 끝나면 POSIX 117번 sigreturn 시스템 콜을 발생합니다.

[7] 단계
커널 공간에서 sigreturn 시스템 콜 핸들러인 sys_sigreturn() 함수가 실행합니다. 이 함수에서 유저 스택 공간에 저장한 유저 프로세스 레지스터 정보를 다시 커널 스택 공간으로 백업합니다

[8] 단계
시그널 발생 전 sys_pause() 함수과 schedule() 함수 콜스택으로 다시 복귀한 후 시그널 전달을 기다립니다.

ftrace 로그 분석: 시그널 생성 단계

1번째 줄 로그부터 분석을 시작하겠습니다.
1 kworker/u8:0-1119  [001] d...  2772.154341: ttwu_do_wakeup+0x10/0x1a4 <-ttwu_do_activate+0x80/0x84
2 kworker/u8:0-1119  [001] d...  2772.154378: <stack trace>
3  => wake_up_state+0x1c/0x20
4  => signal_wake_up_state+0x34/0x48
5  => complete_signal+0x114/0x248
6  => __send_signal+0x160/0x420
7  => send_signal+0x48/0x98
8  => do_send_sig_info+0x50/0x7c
9  => group_send_sig_info+0x50/0x54
10 => __kill_pgrp_info+0x4c/0x7c
11 => kill_pgrp+0x44/0x74
12 => __isig+0x34/0x40
13 => isig+0x54/0x104
14 => n_tty_receive_signal_char+0x28/0x70
15 => n_tty_receive_char_special+0xa10/0xb78
16 => n_tty_receive_buf_common+0x610/0xc04
17 => n_tty_receive_buf2+0x24/0x2c
18 => tty_ldisc_receive_buf+0x30/0x6c
19 => tty_port_default_receive_buf+0x48/0x68
20 => flush_to_ldisc+0xb4/0xcc
21 => process_one_work+0x224/0x518
22 => worker_thread+0x60/0x5f0
23 => kthread+0x144/0x174
24 => ret_from_fork+0x14/0x28

함수 흐름 방향이 24~1번째 줄 로그이라는 점 주의합시다.

17~12번째 줄 로그는 TTY 리시브 버퍼에서 "Ctl+C" 키 입력을 인지하는 함수 흐름입니다.
12 => __isig+0x34/0x40
13 => isig+0x54/0x104
14 => n_tty_receive_signal_char+0x28/0x70
15 => n_tty_receive_char_special+0xa10/0xb78
16 => n_tty_receive_buf_common+0x610/0xc04
17 => n_tty_receive_buf2+0x24/0x2c

n_tty_receive_char_special() 함수에서 "Ctl+C" 키 입력을 감지하고 시그널 전달 인터페이스 함수로 접근합니다.

11~6번째 줄 로그는 시그널 인터페이스 함수에 접근해서 시그널에 대한 전처리를 수행합니다.
7  => send_signal+0x48/0x98
8  => do_send_sig_info+0x50/0x7c
9  => group_send_sig_info+0x50/0x54
10 => __kill_pgrp_info+0x4c/0x7c
11 => kill_pgrp+0x44/0x74

다음 5~1번째 줄 로그는 시그널을 받을 프로세스를 깨우는 함수 흐름입니다.
1 kworker/u8:0-1119  [001] d...  2772.154341: ttwu_do_wakeup+0x10/0x1a4 <-ttwu_do_activate+0x80/0x84
2 kworker/u8:0-1119  [001] d...  2772.154378: <stack trace>
3  => wake_up_state+0x1c/0x20
4  => signal_wake_up_state+0x34/0x48
5  => complete_signal+0x114/0x248

다음 25번째 줄 로그를 보겠습니다.
25    kworker/u8:0-1119  [001] d...  2772.154381: sched_wakeup: comm=RPi_signal pid=1127 prio=120 target_cpu=001

25번째 줄 로그는 ftrace에서 sched_wakeup이란 이벤트를 켰을 때 출력하는 메시지입니다.
RPi_signal(pid: 1127) 프로세스를 깨우는 동작입니다.

스케줄러에게 RPi_signal(pid: 1127) 프로세스 실행을 요쳥하는데, 스케줄러는 런큐에 대기 중인 다른 프로세스들과 우선 순위를 고려한 후 RPi_signal(pid: 1127) 프로세스를 실행합니다.

다음 26번째 줄 로그는 시그널을 생성했다는 ftrace 메시지입니다.
26    kworker/u8:0-1119  [001] d...  2772.154384: signal_generate: sig=2 errno=0 code=128 comm=RPi_signal pid=1127 grp=1 res=0

signal_generate 이벤트 메세지로 다음 내용을 알 수 있습니다.
시그널 번호가 2인 SIGINT 시그널을 생성했다.
시그널을 받을 프로세스는 RPi_signal(pid: 1127) 이다.

여기까지 시그널 생성 과정을 ftrace 로그로 확인했습니다.
1. 시그널을 받을 프로세스 태스크 디스크립터에 접근해서 시그널 정보를 써줌
2. 해당 프로세스를 깨워줌

이어서 시그널을 받아 처리하는 ftrace 로그를 분석해봅시다.

ftrace 로그 분석: 시그널을 받아 처리하는 단계

다음에 분석할 로그는 시그널을 받아 처리하는 3단계 동작입니다.
27 kworker/u8:0-1119  [001] d...  2772.154422: sched_switch: prev_comm=kworker/u8:0 prev_pid=1119 prev_prio=120 prev_state=R+ ==> next_comm=RPi_signal next_pid=1127 next_prio=120
28 RPi_signal-1127  [001] ....  2772.154427: sys_exit: NR 29 = -514
29 RPi_signal-1127  [001] d...  2772.154432: dequeue_signal+0x14/0x19c <-get_signal+0x104/0x72c
30 RPi_signal-1127  [001] d...  2772.154447: <stack trace>
31 => do_work_pending+0xb4/0xcc
32 => slow_work_pending+0xc/0x20

27번째 줄 로그는 kworker/u8:0(pid: 1119) 프로세스에서 RPi_signal(pid: 1127)로 스케줄링 되는 동작입니다.
27 kworker/u8:0-1119  [001] d...  2772.154422: sched_switch: prev_comm=kworker/u8:0 prev_pid=1119 prev_prio=120 prev_state=R+ ==> next_comm=RPi_signal next_pid=1127 next_prio=120

다음 28번째 줄 로그를 보겠습니다.
28 RPi_signal-1127  [001] ....  2772.154427: sys_exit: NR 29 = -514
29 RPi_signal-1127  [001] d...  2772.154432: dequeue_signal+0x14/0x19c <-get_signal+0x104/0x72c
30 RPi_signal-1127  [001] d...  2772.154447: <stack trace>
31 => do_work_pending+0xb4/0xcc
32 => slow_work_pending+0xc/0x20

스케줄러에 의해 다시 실행을 시작한 RPi_signal 프로세스는 29번 시스템 콜 핸들러 서브 루틴에서 ret_fast_syscall 레이블로 복귀합니다. 이어서 slow_work_pending 레이블을 실행합니다. 이후 시그널을 처리하는 get_signal() 함수와 dequeue_signal() 함수 순서로 실행하여 자신에게 전달된 시그널 정보를 읽습니다.

다음 33번째 줄 로그를 보겠습니다. 
33 RPi_signal-1127  [001] d...  2772.154457: signal_deliver: sig=2 errno=0 code=128 sa_handler=10510 sa_flags=4000000

signal_deliver 이벤트 메세지로 다음 내용을 알 수 있습니다.
2번 SIGINT 시그널을 제대로 받았다.
시그널 핸들러 주소가 0x10510이다.

유저 공간에서 SIGINT, SIGALAM, SIGUSR1 시그널에 대한 시그널 핸들러를 sig_handler() 함수로 지정했습니다. 위 ftrace 메시지는 이 정보를 출력합니다.

ftrace 로그 분석: 시그널 핸들러를 호출하는 단계

다음 34번째 줄 로그를 보겠습니다.
34 RPi_signal-1127  [001] ....  2772.154500: setup_return+0x160/0x264: [+] handler:0x10510 , sig:2

조금 더 상세한 코드 실행 흐름을 점검하기 위해 추가한 ftrace 로그 코드가 실행할 때 출력하는 메시지입니다.

34번째 줄 로그를 보면 setup_return() 함수에서 유저 공간에서 실행할 레지스터 프로그램 카운터에 시그널 핸들러인 0x10510 주소를 저장한다는 사실을 알 수 있습니다.

우리는 시그널 핸들러를 시그널 종류에 맞게 등록하면 시그널 핸들러가 실행한다고 알고 있습니다. 이렇게 리눅스 커널은 시그널 처리를 위해 프로그램 카운터 레지스터에 시그널 핸들러 주소를 저장합니다.

ftrace 로그 분석: 시그널 핸들러를 호출하고 커널 공간으로 복귀하는 단계

34번째 줄 로그에서 보이는 2772.154500 초 이후 다음 동작을 처리합니다.
유저 공간으로 실행 흐름을 복귀한 후 지정한 시그널 핸들러를 실행한다
다시 커널 공간으로 진입한다.

35~37번째 줄 로그를 보면서 이 내용을 확인해볼까요?
35 RPi_signal-1127  [001] ....  2772.154684: sys_enter: NR 119 (d, 0, 1, 0, 10714, 0)
36 RPi_signal-1127  [001] ....  2772.154688: sys_sigreturn+0x14/0xdc <-__sys_trace_return+0x0/0x10

119 시스템 콜을 발생하여 헤당 시스템 콜 핸들러인 sys_sigreturn() 함수를 실행합니다. 


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

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


핑백

덧글

댓글 입력 영역