[Linux Kernel] ftrace 를 통한 유저 레벨 프로세스 분석(Signal 종료 방식)

Embedded/Linux Kernel

[Linux Kernel] ftrace 를 통한 유저 레벨 프로세스 분석(Signal 종료 방식)

다크엔지니어 2022. 2. 7. 22:51

먼저 유저 프로세스 생성을 위한 raspbian_test.c 파일 이다.

#include <stdio.h>
#include <unistd.h>

#define PROC_TIMES 500
#define SLEEP_DURATION 3  // second unit

int main() 
{
	int proc_times = 0;

	for(proc_times = 0; proc_times < PROC_TIMES; proc_times++) {
		printf("raspbian tracing \n");
		sleep(SLEEP_DURATION);
	}

	return 0;	
}

위의 .c 파일을 빌드 하기 위한 Makefile 이며, make 를 통해 빌드 진행 하여 raspbian_proc 실행 파일 생성

raspbian_proc: raspbian_test.c
	gcc -o raspbian_proc raspbian_test.c

생성된 실행파일을 실행 한다. 소스 내용대로 500 카운팅까지 3초 sleep 후 카운팅

아래는 ftrace 설정 쉘 스크립트이다.

참고로 set_ftrace_filter 로 설정 가능한 함수 심볼은

/sys/kernel/debug/ftracing/available_filter_functions 에 존재해야 한다.

존재하지 않을 시 write error 발생 하게 된다.

필자의 경우 _do_fork 를 제외 시켰다.

#!/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 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

echo sys_clone do_exit > /sys/kernel/debug/tracing/set_ftrace_filter
echo copy_process* >> /sys/kernel/debug/tracing/set_ftrace_filter
sleep 1
echo "event enabled"

sleep 1
echo "set_ftrace_filter 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 를 설정하여

동작 시킨 후

.c 파일을 실행 시킨다.

./raspbian_proc

그 다음, 다른 터미널을 열어 ps 진행 raspbian_proc 프로세스 확인이 가능하다.

ps -ely

signal 을 통해 유저 프로세스를 소멸시킨다. 실제 __do_exit 함수 signal 9 매개변수가 들어간다.

프로세스가 없어진것을 확인 할 수 있고, ps -ely 로 확인 가능하다.

실제 원본 터미널에서 실행 중이던 raspbian_proc 프로세스가 소멸 되었다.

아래는 get_ftrace.sh 로 ftrace Log 추출 하기 위한 쉘 스크립트 이다.

#!/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

아래와 같이 실행하면 ftrace_log.c 가 생성 된것을 확인 할 수 있다.

vi 에디터를 통해 열었을때의 ftrace Log 이다.

눈여겨 볼 부분은

커널 5.10.y 버전에서는 _do_fork 함수에서 kernel_clone 함수로 변경이 되었다는 것이다.

또한, bash 930 프로세스로 부터 아래 로그가 만들어 지고 있다는 의미이다.

그 아래 ret_fast_syscall->sys_clone->kernel_clone 순으로 콜 스텍을 볼 수 있다.

유저 공간에서 fork 함수를 통해 시스템 콜 핸들러 함수인 sys_clone 함수가 호출 된다.

그 아래 sched_process_fork 함수 이벤트를 보면, pid 1440 인 자식 프로세스를 생성한다.

바로 raspbian_proc 1440 프로세스 생성인 것이다.

프로세스 생성

            bash-930     [001] ....  3209.082842: copy_process+0x14/0x1860 <-kernel_clone+0xb0/0x43c
15195             bash-930     [001] ....  3209.082844: <stack trace>
15196  => kernel_clone+0xb0/0x43c
15197  => sys_clone+0x78/0xa0
15198  => ret_fast_syscall+0x0/0x28
15199  => 0xbe917260
15200             sshd-906     [002] d...  3209.082944: sched_wakeup: comm=kworker/u8:0 pid=1147 prio=120 target_cpu=002
15201             sshd-906     [002] d...  3209.083106: sched_switch: prev_comm=sshd prev_pid=906 prev_prio=120 prev_state=S ==> next_comm=kworker/u8:0 next_pid=1147 next_prio=120
15202            <...>-1147    [002] d...  3209.083181: sched_switch: prev_comm=kworker/u8:0 prev_pid=1147 prev_prio=120 prev_state=D ==> next_comm=swapper/2 next_pid=0 next_prio=120
15203           <idle>-0       [002] dnh.  3209.083225: sched_wakeup: comm=kworker/u8:0 pid=1147 prio=120 target_cpu=002
15204           <idle>-0       [002] d...  3209.083243: sched_switch: prev_comm=swapper/2 prev_pid=0 prev_prio=120 prev_state=R ==> next_comm=kworker/u8:0 next_pid=1147 next_prio=120
15205            <...>-1147    [002] dn..  3209.083266: sched_wakeup: comm=ksoftirqd/2 pid=22 prio=120 target_cpu=002
15206            <...>-1147    [002] dns.  3209.083331: sched_wakeup: comm=kworker/u8:1 pid=1148 prio=120 target_cpu=002
15207            <...>-1147    [002] d...  3209.083383: sched_switch: prev_comm=kworker/u8:0 prev_pid=1147 prev_prio=120 prev_state=R+ ==> next_comm=ksoftirqd/2 next_pid=22 next_prio=120
15208      ksoftirqd/2-22      [002] d...  3209.083394: sched_switch: prev_comm=ksoftirqd/2 prev_pid=22 prev_prio=120 prev_state=S ==> next_comm=kworker/u8:1 next_pid=1148 next_prio=120
15209     kworker/u8:1-1148    [002] d...  3209.083405: sched_switch: prev_comm=kworker/u8:1 prev_pid=1148 prev_prio=120 prev_state=I ==> next_comm=kworker/u8:0 next_pid=1147 next_prio=120
15210            <...>-1147    [002] d...  3209.083445: sched_switch: prev_comm=kworker/u8:0 prev_pid=1147 prev_prio=120 prev_state=D ==> next_comm=swapper/2 next_pid=0 next_prio=120
15211           <idle>-0       [002] dnh.  3209.083487: sched_wakeup: comm=kworker/u8:0 pid=1147 prio=120 target_cpu=002
15212             bash-930     [001] ....  3209.083500: sched_process_fork: comm=bash pid=930 child_comm=bash child_pid=1440
15213           <idle>-0       [002] d...  3209.083504: sched_switch: prev_comm=swapper/2 prev_pid=0 prev_prio=120 prev_state=R ==> next_comm=kworker/u8:0 next_pid=1147 next_prio=120
15214           <idle>-0       [003] d...  3209.083536: sched_switch: prev_comm=swapper/3 prev_pid=0 prev_prio=120 prev_state=R ==> next_comm=bash next_pid=1440 next_prio=120
15215            <...>-1147    [002] d...  3209.083552: sched_switch: prev_comm=kworker/u8:0 prev_pid=1147 prev_prio=120 prev_state=I ==> next_comm=swapper/2 next_pid=0 next_prio=120
15216             bash-930     [001] d...  3209.084127: sched_switch: prev_comm=bash prev_pid=930 prev_prio=120 prev_state=S ==> next_comm=swapper/1 next_pid=0 next_prio=120
15217           <idle>-0       [002] dnh.  3209.088393: sched_wakeup: comm=kworker/u8:0 pid=1147 prio=120 target_cpu=002
15218           <idle>-0       [002] d...  3209.088426: sched_switch: prev_comm=swapper/2 prev_pid=0 prev_prio=120 prev_state=R ==> next_comm=kworker/u8:0 next_pid=1147 next_prio=120
15219            <...>-1147    [002] d...  3209.088451: sched_wakeup: comm=sshd pid=906 prio=120 target_cpu=002
15220            <...>-1147    [002] d...  3209.088466: sched_switch: prev_comm=kworker/u8:0 prev_pid=1147 prev_prio=120 prev_state=I ==> next_comm=sshd next_pid=906 next_prio=120
15221    raspbian_proc-1440    [003] d...  3209.088470: sched_switch: prev_comm=raspbian_proc prev_pid=1440 prev_prio=120 prev_state=S ==> next_comm=swapper/3 next_pid=0 next_prio=120
15222             sshd-906     [002] d...  3209.088738: sched_wakeup: comm=kworker/u8:0 pid=1147 prio=120 target_cpu=002
15223             sshd-906     [002] d...  3209.088804: sched_switch: prev_comm=sshd prev_pid=906 prev_prio=120 prev_state=S ==> next_comm=kworker/u8:0 next_pid=1147 next_prio=120
15224            <...>-1147    [002] d...  3209.088886: sched_switch: prev_comm=kworker/u8:0 prev_pid=1147 prev_prio=120 prev_state=D ==> next_comm=swapper/2 next_pid=0 next_prio=120
15225           <idle>-0       [002] dnh.  3209.088924: sched_wakeup: comm=kworker/u8:0 pid=1147 prio=120 target_cpu=002
15226           <idle>-0       [002] d...  3209.088942: sched_switch: prev_comm=swapper/2 prev_pid=0 prev_prio=120 prev_state=R ==> next_comm=kworker/u8:0 next_pid=1147 next_prio=120
15227            <...>-1147    [002] d...  3209.088969: sched_switch: prev_comm=kworker/u8:0 prev_pid=1147 prev_prio=120 prev_state=I ==> next_comm=swapper/2 next_pid=0 next_prio=120
15228           <idle>-0       [000] dnh.  3209.089116: sched_wakeup: comm=kworker/0:2 pid=1225 prio=120 target_cpu=000
15229           <idle>-0       [000] d...  3209.089135: sched_switch: prev_comm=swapper/0 prev_pid=0 prev_prio=120 prev_state=R ==> next_comm=kworker/0:2 next_pid=1225 next_prio=120
15230      kworker/0:2-1225    [000] d.s.  3209.089186: sched_wakeup: comm=kworker/0:2 pid=1225 prio=120 target_cpu=000
15231      kworker/0:2-1225    [000] d.s.  3209.089240: sched_wakeup: comm=kworker/0:2 pid=1225 prio=120 target_cpu=000
15232           <idle>-0       [002] dnh.  3209.089308: sched_wakeup: comm=kworker/u8:0 pid=1147 prio=120 target_cpu=002
15233      kworker/0:2-1225    [000] d...  3209.089321: sched_switch: prev_comm=kworker/0:2 prev_pid=1225 prev_prio=120 prev_state=I ==> next_comm=swapper/0 next_pid=0 next_prio=120
15234           <idle>-0       [002] d...  3209.089325: sched_switch: prev_comm=swapper/2 prev_pid=0 prev_prio=120 prev_state=R ==> next_comm=kworker/u8:0 next_pid=1147 next_prio=120
15235            <...>-1147    [002] d...  3209.089387: sched_switch: prev_comm=kworker/u8:0 prev_pid=1147 prev_prio=120 prev_state=D ==> next_comm=swapper/2 next_pid=0 next_prio=120
15236           <idle>-0       [002] dnh.  3209.089414: sched_wakeup: comm=kworker/u8:0 pid=1147 prio=120 target_cpu=002
15237           <idle>-0       [002] d...  3209.089430: sched_switch: prev_comm=swapper/2 prev_pid=0 prev_prio=120 prev_state=R ==> next_comm=kworker/u8:0 next_pid=1147 next_prio=120
15238            <...>-1147    [002] d...  3209.089466: sched_switch: prev_comm=kworker/u8:0 prev_pid=1147 prev_prio=120 prev_state=D ==> next_comm=swapper/2 next_pid=0 next_prio=120
15239           <idle>-0       [002] dnh.  3209.089488: sched_wakeup: comm=kworker/u8:0 pid=1147 prio=120 target_cpu=002

sched_wakeup, sched_switch 이벤트 분석을 통해 3초 간격 휴면 상태 진입 후 실행을 반복한다.

정확시 주기를 알고 싶다면, 타임스탬프를 보면 된다.

프로세스 소멸

그리고 kill -9 시그널을 보냈을 때, signal_generate 이벤트 분석을 통해 종료 됨을 알 수 있다.

아래는 siganl define 이며 유저레벨에서 kill -9 등을 통해 이루어 질 수 있다.

17의 경우 프로세스 소멸 시 부모 프로세스에게 알리기 위함이다.

arch/arm/include/uapi/asm/signal.h

종료 시 call stack 은 아래 부분 Log 부분을 통해 분석 가능하다.

그리고 아래 signal 17 을 통해 부모 프로세스에게 종료 시그널을 전달 한다.

            kill-1473    [003] dn..  3299.693228: sched_wakeup: comm=raspbian_proc pid=1440 prio=120 target_cpu=003
45888             kill-1473    [003] dn..  3299.693230: signal_generate: sig=9 errno=0 code=0 comm=raspbian_proc pid=1440 grp=1 res=0
45889             kill-1473    [003] d...  3299.693235: sched_switch: prev_comm=kill prev_pid=1473 prev_prio=120 prev_state=R ==> next_comm=raspbian_proc next_pid=1440 next_prio=120
45890    raspbian_proc-1440    [003] d...  3299.693244: signal_deliver: sig=9 errno=0 code=0 sa_handler=0 sa_flags=0
45891    raspbian_proc-1440    [003] ....  3299.693247: do_exit+0x14/0xa90 <-do_group_exit+0x50/0xe0
45892    raspbian_proc-1440    [003] ....  3299.693248: <stack trace>
45893  => do_group_exit+0x50/0xe0
45894  => get_signal+0x17c/0xa34
45895  => do_work_pending+0x460/0x57c
45896  => slow_work_pending+0xc/0x20
45897  => 0xb6e58eac
45898    raspbian_proc-1440    [003] ....  3299.693430: sched_process_exit: comm=raspbian_proc pid=1440 prio=120
45899    raspbian_proc-1440    [003] dn..  3299.693467: signal_generate: sig=17 errno=0 code=2 comm=bash pid=930 grp=1 res=0
45900    raspbian_proc-1440    [003] d...  3299.693477: sched_switch: prev_comm=raspbian_proc prev_pid=1440 prev_prio=120 prev_state=Z ==> next_comm=kill next_pid=1473 next_prio=120
45901           <idle>-0       [001] dnh.  3299.693480: sched_wakeup: comm=bash pid=930 prio=120 target_cpu=001
45902           <idle>-0       [001] d...  3299.693492: sched_switch: prev_comm=swapper/1 prev_pid=0 prev_prio=120 prev_state=R ==> next_comm=bash next_pid=930 next_prio=120
45903             kill-1473    [003] ....  3299.693612: do_exit+0x14/0xa90 <-do_group_exit+0x50/0xe0
45904             kill-1473    [003] ....  3299.693613: <stack trace>
45905  => do_group_exit+0x50/0xe0
45906  => __wake_up_parent+0x0/0x30
45907  => ret_fast_syscall+0x0/0x28
45908  => 0xbe8b3560
45909           <idle>-0       [000] dnh.  3299.693965: sched_wakeup: comm=kworker/u8:3 pid=1427 prio=120 target_cpu=000
45910             bash-930     [001] d...  3299.693972: signal_deliver: sig=17 errno=0 code=2 sa_handler=57bc0 sa_flags=14000000
45911           <idle>-0       [000] d...  3299.693973: sched_switch: prev_comm=swapper/0 prev_pid=0 prev_prio=120 prev_state=R ==> next_comm=kworker/u8:3 next_pid=1427 next_prio=120
45912     kworker/u8:3-1427    [000] d...  3299.693992: sched_wakeup: comm=sshd pid=906 prio=120 target_cpu=000
45913     kworker/u8:3-1427    [000] d...  3299.693999: sched_switch: prev_comm=kworker/u8:3 prev_pid=1427 prev_prio=120 prev_state=I ==> next_comm=sshd next_pid=906 next_prio=120
45914             kill-1473    [003] ....  3299.694072: sched_process_exit: comm=ki  pid=1473 prio=120
45915             kill-1473    [003] dn..  3299.694127: signal_generate: sig=17 errno=0 code=1 comm=sudo pid=1471 grp=1 res=0
45916           <idle>-0       [002] dnh.  3299.694133: sched_wakeup: comm=sudo pid=1471 prio=120 target_cpu=002
45917           <idle>-0       [002] d...  3299.694140: sched_switch: prev_comm=swapper/2 prev_pid=0 prev_prio=120 prev_state=R ==> next_comm=sudo next_pid=1471 next_prio=120
45918             kill-1473    [003] d...  3299.694147: sched_switch: prev_comm=kill prev_pid=1473 prev_prio=120 prev_state=Z ==> next_comm=swapper/3 next_pid=0 next_prio=120
45919             sudo-1471    [002] d...  3299.694148: signal_deliver: sig=17 errno=0 code=1 sa_handler=b6eee640 sa_flags=14000004
45920             sshd-906     [000] d.h.  3299.694171: sched_wakeup: comm=kworker/u8:3 pid=1427 prio=120 target_cpu=000
45921             sshd-906     [000] d...  3299.694231: sched_switch: prev_comm=sshd prev_pid=906 prev_prio=120 prev_state=D ==> next_comm=kworker/u8:3 next_pid=1427 next_prio=120
45922           <idle>-0       [003] dnh.  3299.694242: sched_wakeup: comm=kworker/u8:1 pid=1148 prio=120 target_cpu=003
45923             bash-930     [001] d...  3299.694244: sched_switch: prev_comm=bash prev_pid=930 prev_prio=120 prev_state=S ==> next_comm=swapper/1 next_pid=0 next_prio=120
45924     kworker/u8:3-1427    [000] d...  3299.694245: sched_wakeup: comm=sshd pid=906 prio=120 target_cpu=000
45925           <idle>-0       [003] d...  3299.694249: sched_switch: prev_comm=swapper/3 prev_pid=0 prev_prio=120 prev_state=R ==> next_comm=kworker/u8:1 next_pid=1148 next_prio=120
45926     kworker/u8:1-1148    [003] d...  3299.694258: sched_switch: prev_comm=kworker/u8:1 prev_pid=1148 prev_prio=120 prev_state=I ==> next_comm=swapper/3 next_pid=0 next_prio=120
45927     kworker/u8:3-1427    [000] d.s.  3299.694277: sched_wakeup: comm=kworker/u8:3 pid=1427 prio=120 target_cpu=000
45928     kworker/u8:3-1427    [000] d...  3299.694282: sched_switch: prev_comm=kworker/u8:3 prev_pid=1427 prev_prio=120 prev_state=R ==> next_

이를 통해 생성되는 콜스텍 소멸되는 콜스텍, 그리고 함수 이벤트 들을 확인해 보았다.

위 ftrace Log 포멧은 아래 게시글을 참고하길 바란다.

2022.02.01 - [Embedded/Linux Kernel] - [Linux Kernel] ftrace Log 포맷 해석 및 발생 경로 확인

[Linux Kernel] ftrace Log 포맷 해석 및 발생 경로 확인

ftrace 에는 크게 4가지 이벤트가 존재한다. sched_switch sched_wakeup irq_handler_entry irq_handler_exit 각 ftrace 이벤트 별로 당연히 발생되는 경로와 이유가 존재한다. 이번 글을 통해 어떻게 해석하고 어..

darkengineer.tistory.com

저작자표시 비영리 변경금지 (새창열림)

'Embedded > Linux Kernel' 카테고리의 다른 글

[Linux Kernel] ftrace 를 통한 유저 레벨 프로세스 분석(POSIX exit 종료 방식) (0)	2022.02.16
[Linux Kernel] 프로세스 소멸 과정 소스 분석 (0)	2022.02.16
[Linux Kernel] 커널 스레드(프로세스) 생성 과정 소스 분석 (0)	2022.02.07
[Linux Kernel] 커널에서의 프로세스 테스크 스레드 이해 (0)	2022.02.06
[Linux Kernel] 커널 디버깅용 Debugfs 드라이버 코드 (0)	2022.02.06

현재글[Linux Kernel] ftrace 를 통한 유저 레벨 프로세스 분석(Signal 종료 방식)

다크 엔지니어