Embedded/Linux Kernel
[Linux Kernel] ftrace 를 통한 유저 레벨 프로세스 분석(POSIX exit 종료 방식)
다크엔지니어
2022. 2. 16. 01:05
반응형
프로세스 종료 방식
프로세스 종료 방식은 크게 두 가지로 나뉜다.
1, 유저 레벨에서의 Signal 종료
아래 경로 글에서 Signal 방식의 종료에 대하여 ftrace 를 통해 분석하였다.
2022.02.07 - [Embedded/Linux Kernel] - [Linux Kernel] ftrace 를 통한 유저 프로세스 분석
[Linux Kernel] ftrace 를 통한 유저 레벨 프로세스 분석
먼저 유저 프로세스 생성을 위한 raspbian_test.c 파일 이다. #include #include #define PROC_TIMES 500 #define SLEEP_DURATION 3 // second unit int main() { int proc_times = 0; for(proc_times = 0; proc_t..
darkengineer.tistory.com
2. POSIX exit 시스템 콜을 통한 스스로 종료
이 글에서는 유저 프로세스가 POSIX exit 시스템 콜을 발생하였을 때, 커널 내부의 흐름을 알아 볼 것 이다.
아래 rpi_process_exit.c 라는 .c 파일을 실행 해볼 것 이다.
3sec 간격으로 3번 실행 후 exit 를 통해 유저 레벨에서 프로세서 스스로 소멸 시키는 로직이다.
#include <stdio.h>
#include <unistd.h>
#include <stdlib.h>
#define PROC_TIMES 3
#define SLEEP_DURATION 3 // second unit
int main()
{
int proc_times = 0;
for(proc_times = 0; proc_times < PROC_TIMES; proc_times++) {
printf("rpi tracing \n");
sleep(SLEEP_DURATION);
}
exit(EXIT_SUCCESS);
return 0;
}
아래는 쉽게 빌드하기 위한 Makefile 이다. make 를 통해 실행 파일을 생성한다.
rpi_proc_exit:rpi_process_exit.c
gcc -o rpi_proc_exit rpi_process_exit.c
shell script 로 ftrace 설정을 위한 script 이다.
set ftrace filter 로 프로세스 관련 함수들을 볼 것 이다.
#!/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 kernel_clone 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 파일로 Log 추출을 위한 shell script 이다.
#!/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
위의 .c 파일 및 script 를 진행하는 과정은 아래와 같다.
위 결과를 통해 ftrace_log.c log 로 분석이 가능하다.
그리고 rpi tracing 인 메세지로 동작 확인이 가능하다.
ftrace_log.c 인 ftrace 로그를 열어보면
프로세스 생성
pid가 979 인 bash 프로세스를 통해 1494 인 rpi_proc_exit 프로세스를 생성하게 되는 것을 알 수 있다.
그리고 콜스택을 통해 함수 호출 과정을 볼 수 있다.
콜스텍 에서 주소에 대하여 잠시 얘기하자면, ARMv7 의 경우 파이프라인을 적용한 아키텍처라서
실제로 호출되는 코드의 주소보다 0x4 바이트 offset 을 출력 한다는 점이다.
그럼 아래 kernel_clone 의 경우 0xb0 이지만 실제로는 0xb0 - 0x04 = 0xac 가 되는 것이다.
프로세스 소멸
1494 인 rpi_proc_exit 프로세스가 종료되며 signal 17 로 부모 프로세스에게 전달 하는 것을 볼 수 있다.
즉, 프로세스가 스스로 exit POSIX 시스템 콜을 호출하면 스스로 소멸 가능하다는 것이다.
exit POSIX 시스템 콜에 대한 핸들러는 sys_exit_group() 함수 이다.
어셈블리 를 통해 확인해보면 __wake_up_parent 0x0 - 0x4 에 위치한 함수 임을 알 수 있다.
kill -9 방식 과 차이점은 signal 9 없이 스스로 17을 바로 보내 종료한다는 점이다.
아래는 ftrace log 이다. 양이 많아 부분만 가져왔다.
생성
bash-979 [001] .... 4846.913527: copy_process+0x14/0x1860 <-kernel_clone+0xb0/0x43c
1793 bash-979 [001] .... 4846.913528: <stack trace>
1794 => kernel_clone+0xb0/0x43c
1795 => sys_clone+0x78/0xa0
1796 => ret_fast_syscall+0x0/0x28
1797 => 0xbed73260
1798 bash-979 [001] .... 4846.914172: sched_process_fork: comm=bash pid=979 child_comm=bash child_pid=1494
1799 <idle>-0 [002] d... 4846.914217: sched_switch: prev_comm=swapper/2 prev_pid=0 prev_prio=120 prev_state=R ==> next_comm=bash next_pid=1494 next_prio=120
1800 bash-979 [001] d... 4846.914818: sched_switch: prev_comm=bash prev_pid=979 prev_prio=120 prev_state=S ==> next_comm=swapper/1 next_pid=0 next_prio=120
1801 rpi_proc_exit-1494 [002] dns. 4846.915955: sched_wakeup: comm=kworker/2:0 pid=1029 prio=120 target_cpu=002
1802 <idle>-0 [001] dnh. 4846.915994: sched_wakeup: comm=rcu_sched pid=12 prio=120 target_cpu=001
1803 rpi_proc_exit-1494 [002] d... 4846.916008: sched_switch: prev_comm=bash prev_pid=1494 prev_prio=120 prev_state=R+ ==> next_comm=kworker/2:0 next_pid=1029 next_prio=120
1804 <idle>-0 [001] d... 4846.916015: sched_switch: prev_comm=swapper/1 prev_pid=0 prev_prio=120 prev_state=R ==> next_comm=rcu_sched next_pid=12 next_prio=120
1805 kworker/2:0-1029 [002] d... 4846.916047: sched_switch: prev_comm=kworker/2:0 prev_pid=1029 prev_prio=120 prev_state=I ==> next_comm=bash next_pid=1494 next_prio=120
1806 rcu_sched-12 [001] d... 4846.916057: sched_switch: prev_comm=rcu_sched prev_pid=12 prev_prio=120 prev_state=I ==> next_comm=swapper/1 next_pid=0 next_prio=120
1807 <idle>-0 [001] dnh. 4846.919266: sched_wakeup: comm=kworker/u8:3 pid=1370 prio=120 target_cpu=001
1808 <idle>-0 [001] d... 4846.919287: sched_switch: prev_comm=swapper/1 prev_pid=0 prev_prio=120 prev_state=R ==> next_comm=kworker/u8:3 next_pid=1370 next_prio=120
1809 <idle>-0 [000] dnh. 4846.919318: sched_wakeup: comm=sshd pid=953 prio=120 target_cpu=000
1810 kworker/u8:3-1370 [001] d... 4846.919322: sched_switch: prev_comm=kworker/u8:3 prev_pid=1370 prev_prio=120 prev_state=I ==> next_comm=swapper/1 next_pid=0 next_prio=120
1811 <idle>-0 [000] d... 4846.919349: sched_switch: prev_comm=swapper/0 prev_pid=0 prev_prio=120 prev_state=R ==> next_comm=sshd next_pid=953 next_prio=120
1812 rpi_proc_exit-1494 [002] d... 4846.919373: sched_switch: prev_comm=rpi_proc_exit prev_pid=1494 prev_prio=120 prev_state=S ==> next_comm=swapper/2 next_pid=0 next_prio=120
1813 <idle>-0 [001] dnh. 4846.919611: sched_wakeup: comm=kworker/u8:3 pid=1370 prio=120 target_cpu=001
1814 <idle>-0 [001] d... 4846.919626: sched_switch: prev_comm=swapper/1 prev_pid=0 prev_prio=120 prev_state=R ==> next_comm=kworker/u8:3 next_pid=1370 next_prio=120
1815 sshd-953 [000] d... 4846.919664: sched_switch: prev_comm=sshd prev_pid=953 prev_prio=120 prev_state=S ==> next_comm=swapper/0 next_pid=0 next_prio=120
1816 kworker/u8:3-1370 [001] d... 4846.919704: sched_switch: prev_comm=kworker/u8:3 prev_pid=1370 prev_prio=120 prev_state=D ==> next_comm=swapper/1 next_pid=0 next_prio=120
1817 <idle>-0 [001] dnh. 4846.919748: sched_wakeup: comm=kworker/u8:3 pid=1370 prio=120 target_cpu=001
1818 <idle>-0 [001] d... 4846.919765: sched_switch: prev_comm=swapper/1 prev_pid=0 prev_prio=120 prev_state=R ==> next_comm=kworker/u8:3 next_pid=1370 next_prio=120
1819 kworker/u8:3-1370 [001] d... 4846.919794: sched_switch: prev_comm=kworker/u8:3 prev_pid=1370 prev_prio=120 prev_state=I ==> next_comm=swapper/1 next_pid=0 next_prio=120
1820 <idle>-0 [000] dnh. 4846.920834: sched_wakeup: comm=kworker/0:2 pid=1408 prio=120 target_cpu=000
1821 <idle>-0 [000] d... 4846.920855: sched_switch: prev_comm=swapper/0 prev_pid=0 prev_prio=120 prev_state=R ==> next_comm=kworker/0:2 next_pid=1408 next_prio=120
1822 kworker/0:2-1408 [000] d.s. 4846.920951: sched_wakeup: comm=kworker/0:2 pid=1408 prio=120 target_cpu=000
1823 <idle>-0 [001] dnh. 4846.921022: sched_wakeup: comm=kworker/u8:3 pid=1370 prio=120 target_cpu=001
1824 kworker/0:2-1408 [000] d... 4846.921035: sched_switch: prev_comm=kworker/0:2 prev_pid=1408 prev_prio=120 prev_state=I ==> next_comm=swapper/0 next_pid=0 next_prio=120
1825 <idle>-0 [001] d... 4846.921039: sched_switch: prev_comm=swapper/1 prev_pid=0 prev_prio=120 prev_state=R ==> next_comm=kworker/u8:3 next_pid=1370 next_prio=120
1826 kworker/u8:3-1370 [001] d... 4846.921103: sched_switch: prev_comm=kworker/u8:3 prev_pid=1370 prev_prio=120 prev_state=D ==> next_comm=swapper/1 next_pid=0 next_prio=120
1827 <idle>-0 [001] dnh. 4846.921130: sched_wakeup: comm=kworker/u8:3 pid=1370 prio=120 target_cpu=001
1828 <idle>-0 [001] d... 4846.921146: sched_switch: prev_comm=swapper/1 prev_pid=0 prev_prio=120 prev_state=R ==> next_comm=kworker/u8:3 next_pid=1370 next_prio=120
1829 kworker/u8:3-1370 [001] d... 4846.921182: sched_switch: prev_comm=kworker/u8:3 prev_pid=1370 prev_prio=120 prev_state=D ==> next_comm=swapper/1 next_pid=0 next_prio=120
1830 <idle>-0 [001] dnh. 4846.921205: sched_wakeup: comm=kworker/u8:3 pid=1370 prio=120 target_cpu=001
1831 <idle>-0 [001] d... 4846.921221: sched_switch: prev_comm=swapper/1 prev_pid=0 prev_prio=120 prev_state=R ==> next_comm=kworker/u8:3 next_pid=소멸
rpi_proc_exit-1494 [002] .... 4855.920882: do_exit+0x14/0xa90 <-do_group_exit+0x50/0xe0
3732 rpi_proc_exit-1494 [002] .... 4855.920885: <stack trace>
3733 => do_group_exit+0x50/0xe0
3734 => __wake_up_parent+0x0/0x30
3735 => ret_fast_syscall+0x0/0x28
3736 => 0xbeef25d0
3737 rpi_proc_exit-1494 [002] .... 4855.921300: sched_process_exit: comm=rpi_proc_exit pid=1494 prio=120
3738 rpi_proc_exit-1494 [002] dn.. 4855.921380: signal_generate: sig=17 errno=0 code=1 comm=bash pid=979 grp=1 res=0
3739 <idle>-0 [001] dnh. 4855.921396: sched_wakeup: comm=bash pid=979 prio=120 target_cpu=001
3740 rpi_proc_exit-1494 [002] d... 4855.921406: sched_switch: prev_comm=rpi_proc_exit prev_pid=1494 prev_prio=120 prev_state=Z ==> next_comm=swapper/2 next_pid=0 next_prio=120
3741 <idle>-0 [001] d... 4855.921415: sched_switch: prev_comm=swapper/1 prev_pid=0 prev_prio=120 prev_state=R ==> next_comm=bash next_pid=979 next_prio=120
3742 bash-979 [001] d... 4855.921616: signal_deliver: sig=17 errno=0 code=1 sa_handler=57bc0 sa_flags=14000000
3743 <idle>-0 [000] dnh. 4855.922060: sched_wakeup: comm=kworker/u8:3 pid=1370 prio=120 target_cpu=000
3744 <idle>-0 [000] d... 4855.922079: sched_switch: prev_comm=swapper/0 prev_pid=0 prev_prio=120 prev_state=R ==> next_comm=kworker/u8:3 next_pid=1370 next_prio=120
3745 kworker/u8:3-1370 [000] d... 4855.922100: sched_wakeup: comm=sshd pid=953 prio=120 target_cpu=000
3746 kworker/u8:3-1370 [000] d... 4855.922116: sched_switch: prev_comm=kworker/u8:3 prev_pid=1370 prev_prio=120 prev_state=I ==> next_comm=sshd next_pid=953 next_prio=120
3747 sshd-953 [000] d.h. 4855.922177: sched_wakeup: comm=kworker/u8:3 pid=1370 prio=120 target_cpu=000
3748 bash-979 [001] d... 4855.922220: sched_switch: prev_comm=bash prev_pid=979 prev_prio=120 prev_state=S ==> next_comm=swapper/1 next_pid=0 next_prio=120
3749 sshd-953 [000] d... 4855.922331: sched_switch: prev_comm=sshd prev_pid=953 prev_prio=120 prev_state=D ==> next_comm=kworker/u8:3 next_pid=1370 next_prio=120
3750 kworker/u8:3-1370 [000] d... 4855.922363: sched_wakeup: comm=sshd pid=953 prio=120 target_cpu=000
3751 kworker/u8:3-1370 [000] d... 4855.922379: sched_switch: prev_comm=kworker/u8:3 prev_pid=1370 prev_prio=120 prev_state=I ==> next_comm=sshd next_pid=953 next_prio=120
3752 sshd-953 [000] d... 4855.922504: sched_wakeup: comm=kworker/u8:3 pid=1370 prio=120 target_cpu=000
3753 sshd-953 [000] d... 4855.922660: sched_switch: prev_comm=sshd prev_pid=953 prev_prio=120 prev_state=S ==> next_comm=kworker/u8:3 next_pid=1370 next_prio=120반응형