Linux Kernel(4.19) Hacks

rousalome.egloos.com

포토로그 Kernel Crash


통계 위젯 (화이트)

75235
1036
103645


[리눅스커널] 시스템 콜/디버깅: ftrace 시스템 콜 이벤트 소개하기 11장. 시스템 콜

시스템 콜 관련 코드를 분석하다 보면 다음과 같은 의문이 생길 수 있습니다. 
평소 시스템 콜은 얼마나 자주 발생할까?
시스템 콜 번호는 어떻게 확인할 수 있을까?

ftrace 메시지를 보면 이런 궁금증을 해소할 수 있습니다. ftrace에서는 시스템 콜 동작을 트레이싱하는 다음과 같은 이벤트를 제공합니다.
sys_enter
sys_exit

먼저 위 ftrace 이벤트를 키는 방법부터 배워볼까요?

ftrace: sys_enter와 sys_exit 이벤트 켜보기

ftrace sys_enter와 sys_exit 이벤트를 키려면 다음 명령어를 입력해야 합니다. enable 파일을 1로 써 주면 됩니다.
echo 1 > /sys/kernel/debug/tracing/events/raw_syscalls/sys_enter/enable
echo 1 > /sys/kernel/debug/tracing/events/raw_syscalls/sys_exit/enable

부팅할 때 위 경로에 위치한 enable 파일은 기본으로 0으로 설정돼 있습니다.

시스템 콜 ftrace 이벤트를 설정하는 전체 명령어는 다음과 같습니다.
#!/bin/bash

echo  > /sys/kernel/debug/tracing/set_event
sleep 1

echo 0 > /sys/kernel/debug/tracing/tracing_on
sleep 1

echo nop > /sys/kernel/debug/tracing/current_tracer
sleep 1"

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 1 > /sys/kernel/debug/tracing/tracing_on
sleep 1

위 명령어에서 가장 중요한 부분은 다음과 같습니다.
echo 1 > /sys/kernel/debug/tracing/events/raw_syscalls/sys_enter/enable
echo 1 > /sys/kernel/debug/tracing/events/raw_syscalls/sys_exit/enable

sys_enter와 sys_exit ftrace 이벤트를 키는 명령어입니다.

코드를 다음과 같이 syscall_ftrace.sh 셸 스크립트 파일로 저장해서 실행하면 효율적으로 ftrace 설정을 할 수 있습니다.
root@raspberrypi:/home/pi# ./syscall_ftrace.sh

위 셸 스크립트 파일을 실행해서 시스템 콜 이벤트를 설정합니다. 라즈베리파이에서 터미널만 연 상태로 있다가 10초 후에 ftrace 로그를 받습니다. 

ftrace: sys_enter/sys_exit 이벤트 메시지 분석해보기

이어서 sys_enter/sys_exit ftrace 이벤트 메시지를 보는 방법을 배워봅시다.
먼저 sys_enter 이벤트 메시지를 배워 볼까요?

sys_enter 이벤트

ftrace에서 sys_enter 이벤트가 출력하는 세부 정보는 다음과 같습니다.
 
[그림 11.10] ftrace sys_enter 이벤트 메시지 포멧 

sys_enter 메시지에서 특히 눈여겨봐야 할 부분은 다음과 같습니다.
시스템 콜 번호
시스템 콜 실행 시각
시스템 콜 핸들러 함수로 전달된 인자

위 sys_enter 메시지에서 보이는 정보를 모으면 다음과 같이 해석할 수 있습니다. 

    pid가 887인 bash 프로세스가 11824.891592 초에 120번 시스템 콜 실행을 
     시작했다.
 
sys_exit 이벤트
이어서 sys_exit 이벤트는 어떤 정보를 출력하는지 확인해 보겠습니다.
 
[그림 11.11] ftrace sys_exit 이벤트 메시지 포멧 

sys_exit 메시지에서 특히 눈여겨봐야 할 정보는 다음과 같습니다.
시스템 콜 실행 종료 실행 시각
시스템 콜 반환 값

위 sys_exit 메시지 정보로 다음 사실을 알 수 있습니다. 

    "pid가 887인 bash 프로세스가 120번 시스템 콜을 11824.893365 초에 마무리 
    했습니다. 유저 공간으로 복귀 하기 직전 시점입니다."

여기까지 시스템 콜 이벤트 메시지 정보를 해석하는 방법을 알아봤습니다. 이어서 실제 ftrace 로그를 보면서 시스템 콜 메시지를 해석하는 방법을 배워 봅시다. 
1 bash-887  [000] 11824.891592: sys_enter: NR 120 (1200011, 0, 0, 0, 76f88068, 0)
2 bash-887  [000] 11824.893365: sys_exit: NR 120 = 894
3 bash-887  [000] 11824.893835: sys_enter: NR 3 (3, 7ec6b0f0, 200, 0, 76f71000, 0)
4 bash-887  [000] 11824.893852: sys_exit: NR 3 = 512

1번째와 3번째 줄 로그에서 보이는 sys_enter란 메시지로 시스템 콜이 실행을 시작한다는 사실을 알 수 있습니다. 다음 2번째와 4번째 줄 로그에서 출력하는 sys_exit 메시지는 시스템 콜 실행을 마무리하는 동작을 출력합니다. 

유저 공간에서 시스템 콜을 발생하면 커널 공간에서 시스템 콜 핸들러에서 커널 함수를 호출합니다. 다음 시스템 콜 종류에 따라 커널 내부 함수를 호출합니다. 이 처리를 마친 후 ret_fast_syscall 레이블을 실행해 유저 공간으로 다시 복귀합니다.  sys_exit 메시지는 이 시점에서 ftrace 로그를 출력합니다.

다음 시스템 콜 번호를 확인해 보겠습니다.
1번째 줄 로그에서 보이는 "NR 120" 메시지는 시스템 콜 번호를 의미합니다. 또한 3번째 줄 로그 “NR 3” 메시지로 3번 시스템 콜이 실행했음을 알 수 있습니다.

120번과 3번에 대응하는 시스템 콜 핸들러 함수 이름은 무엇일까요?
POSIX에서 정의한 시스템 콜 번호는 다음 경로 해더 파일에서 확인할 수 있습니다.
[usr/include/arm-linux-gnueabihf/asm/unistd-common.h]
#define __NR_read (__NR_SYSCALL_BASE+  3)
...
#define __NR_clone (__NR_SYSCALL_BASE+120)

시스템 콜 번호 3번에 대한 시스템 콜 핸들러는 sys_read() 함수 그리고 120번 시스템 콜 핸들러는 sys_clone() 함수임을 알 수 있습니다.

ftrace: sys_enter 이벤트 인자 값 확인해보기

ftrace 시스템 콜 sys_enter 이벤트는 시스템 콜 핸들러에 전달하는 인자를 함께 출력합니다.
이번에는 시스템 콜 핸들러에 전달한 인자의 의미를 살펴보겠습니다.

먼저 다음 로그에 전달된 인자를 살펴봅시다.
sys_enter: NR 120 (1200011, 0, 0, 0, 76f88068, 0)

위 ftrace 메시지는 6개의 인자가 전달됐으며 각 인자는 시스템 콜 핸들러 함수로 전달됩니다.

참고로 clone 시스템 콜에 대한 시스템 콜 핸들러는 sys_clone() 함수이며 선언부는 다음과 같습니다.
[https://elixir.bootlin.com/linux/v4.19.30/source/kernel/fork.c]
1 SYSCALL_DEFINE5(clone, unsigned long, clone_flags, unsigned long, newsp,
2 int __user *, parent_tidptr,
3 unsigned long, tls,
4 int __user *, child_tidptr)
5
6 long sys_clone(unsigned long clone_flags, unsigned long newsp, int * parent_tidptr, unsigned long tls, int * child_tidptr)

다음 ftrace 메시지와 함수 선언부에서 보이는 인자를 같이 확인해볼까요?
sys_enter: NR 120 (1200011, 0, 0, 0, 76f88068, 0)

ftrace 이벤트 메시지와 함수 인자를 함께 나열하면 다음과 같습니다.
unsigned long clone_flags = 1200011;
unsigned long newsp = 0x0;
int * parent_tidptr = 0x0;
unsigned long tls = 0x0;
int * child_tidptr = 0x76f88068;

다음은 3번 read 시스템 콜 메시지 인자를 분석하겠습니다. 
sys_enter: NR 3 (3, 7ec6b0f0, 200, 0, 76f71000, 0)

먼저 sys_read() 함수 구현부를 볼까요?
[https://elixir.bootlin.com/linux/v4.19.30/source/fs/read_write.c]
SYSCALL_DEFINE3(read, unsigned int, fd, char __user *, buf, size_t, count)
{
return ksys_read(fd, buf, count);
}

ftrace 메시지 정보를 함수 인자와 함께 보면 다음과 같습니다.
unsigned int fd = 3;
const char __user * buf = 7ec6b0f0;
size_t count = 300;

이 방식으로 시스템 콜 동작을 시스템 콜 핸들러 함수를 함께 보면서 디버깅하면 더 많은 정보를 얻을 수 있습니다.

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

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


#Reference: 시스템 콜
시스템 콜 주요 개념 소개
유저 공간에서 시스템 콜은 어떻게 발생할까
시스템 콜 핸들러는 어떤 동작을 할까? 
시스템 콜 실행 완료 후 무슨 일을 할까?
시스템 콜 관련 함수  
시스템 콜 디버깅  



핑백

덧글

댓글 입력 영역