ftrace 메세지로 시스템 콜 exit() 프로세스 생성과 종료 과정 분석

ftrace 메세지로 시스템 콜 exit() 프로세스 생성과 종료 과정 분석

소스코드

1 #include <stdio.h>
  2 #include <unistd.h>
  3 #include <stdlib.h>
  4
  5 #define PROC_TIMES 3
  6 #define SLEEP_DURATION 3 //sec unit
  7
  8 int main()
  9 {
 10     int proc_times = 0;
 11
 12     for(proc_times = 0; proc_times < PROC_TIMES; proc_times++) {
 13         printf("rpi tracing\\n");
 14         sleep(SLEEP_DURATION);
 15     }
 16
 17     exit(EXIT_SUCCESS);
 18     return 0;
 19 }

ftrace 활성화 → 위 소스코드 실행 → ftrace 비활성화

프로세스 생성 로그

1101             bash-20507 [003] .... 260833.154530: sys_clone+0x14/0x38 <-ret_fast_syscall+0x0/0x28
1102             bash-20507 [003] .... 260833.154557: <stack trace>
1103  => sys_clone+0x18/0x38
1104  => ret_fast_syscall+0x0/0x28
1105  => 0x7e9d5170
1106             bash-20507 [003] .... 260833.154560: _do_fork+0x14/0x464 <-sys_clone+0x30/0x38
1107             bash-20507 [003] .... 260833.154571: <stack trace>
1108  => _do_fork+0x18/0x464
1109  => sys_clone+0x30/0x38
1110  => ret_fast_syscall+0x0/0x28
1111  => 0x7e9d5170
1112             bash-20507 [003] .... 260833.154574: copy_process.part.3+0x14/0x1af0 <-_do_fork+0xc0/0x464
1113             bash-20507 [003] .... 260833.154587: <stack trace>
1114  => copy_process.part.3+0x18/0x1af0
1115  => _do_fork+0xc0/0x464
1116  => sys_clone+0x30/0x38
1117  => ret_fast_syscall+0x0/0x28
1118  => 0x7e9d5170
1119             bash-20507 [003] .... 260833.155233: sched_process_fork: comm=bash pid=20507 child_comm=bash child_pid=20520
1120           <idle>-0     [002] d... 260833.155275: sched_switch: prev_comm=swapper/2 prev_pid=0 prev_prio=120 prev_state=R ==> next_comm=bash next_pid=20520 next_prio=120
1121             bash-20507 [003] d... 260833.155764: sched_switch: prev_comm=bash prev_pid=20507 prev_prio=120 prev_state=S ==> next_comm=swapper/3 next_pid=0 next_prio=120
1122           <idle>-0     [000] dnh. 260833.156383: sched_wakeup: comm=in:imklog pid=423 prio=120 target_cpu=000
1123           <idle>-0     [000] dnh. 260833.156397: sched_wakeup: comm=systemd-journal pid=115 prio=120 target_cpu=000

위는 프로세스 생성 시점이다. 스택 트레이스가 쌓이면서 do fork가 호출되는 것을 확인할 수 있다.

1119번 라인을 보면 20520 pid를 가진 자식 프로세스가 생성된 것을 확인할 수 있다.

프로세스 종료 로그

1888    rpi_proc_exit-20520 [002] .... 260842.160358: do_exit+0x14/0xbe8 <-do_group_exit+0x50/0xe8
1889    rpi_proc_exit-20520 [002] .... 260842.160388: <stack trace>
1890  => do_exit+0x18/0xbe8
1891  => do_group_exit+0x50/0xe8
1892  => __wake_up_parent+0x0/0x30
1893  => ret_fast_syscall+0x0/0x28
1894  => 0x7eada538
1895    rpi_proc_exit-20520 [002] .... 260842.160714: sched_process_exit: comm=rpi_proc_exit pid=20520 prio=120
1896    rpi_proc_exit-20520 [002] d... 260842.160802: signal_generate: sig=17 errno=0 code=1 comm=bash pid=20507 grp=1 res=0
1897    rpi_proc_exit-20520 [002] d... 260842.160820: sched_switch: prev_comm=rpi_proc_exit prev_pid=20520 prev_prio=120 prev_state=Z ==> next_comm=swapper/2 next_pid=0 next_prio=120

exit함수를 호출하면 커널공간에서 실행되는 sys_exit_group() 함수가 호출된다.

유저단과 비교하자면 유저단은 signal을 받아들여서 커널에서 호출되고, exit함수는 바로 sys_exit_group() 함수를 호출한다.