Arm Linux Kernel Hacks

rousalome.egloos.com

포토로그 Kernel Crash

프로필

This blog contains Linux Kernel Analysis(4.x/5.x), Arm architecture and debugging skills for seminar and lecture.by AustinKim

통계 위젯 (화이트)

11105
637
415734

카테고리

메뉴릿

최근 트랙백

[공유] v5.15 라즈비안 커널에서 '4.11.2 리눅스 유틸리티 프로그램을 이용한 실행 추적' 실습하기 Question_Announcement

Overview

리눅스 커널 버전이 업그레이드 되면서 함수의 이름이나 루틴이 계속 바뀌고 있습니다.
리눅스 커널이 오픈 소스 프로젝트로 운영되니 당연한 현상으로 볼 수 있는데요.

커널 버전이 업그레이드되면서 예전 버전에 잘 동작하던 셸 스크립트도 업데이트해야 합니다. 

   * 집필 시점 라즈비안 커널 버전: v4.19.30
   * 현재(2022년 6월) 라즈비안 커널 버전: v5.15.31

리눅스 커널은 생명체와 같이 살아 숨시는 것 같네요.   
   
4.11.2 절에서 언급된 스크립트

271 페이지를 보면 ftrace 로그를 설정하는 셸 스크립트 코드가 확인됩니다. 

echo do_exit search_binary_handler  copy_process.part.5 > /sys/kernel/debug/tracing/set_ftrace_filter
echo sys_clone _do_fork >> /sys/kernel/debug/tracing/set_ftrace_filter

위 코드는 v4.19 버전에서 잘 동작합니다. 그런데 최신 라즈비안 커널인 v5.15.31에서는 제대로 동작하지 않습니다. 그 이유는 무엇일까요? '/sys/kernel/debug/tracing/available_filter_functions' 파일에 search_binary_handler와 _do_fork 심벌이 존재하지 않기 때문입니다.

업데이트된 셸 스크립트

최신 라즈비안 커널 버전(v5.15.31)에서는 다음 셸 스크립트를 실행하면 실습을 잘 진행할 수 있습니다.

01 #!/bin/bash
02 
03 echo 0 > /sys/kernel/debug/tracing/tracing_on
04 sleep 1
05 echo "tracing_off"
06 
07 echo 0 > /sys/kernel/debug/tracing/events/enable
08 sleep 1
09 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 __audit_bprm  copy_process > /sys/kernel/debug/tracing/set_ftrace_filter
20 #echo sys_clone kernel_clone >> /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_process_exec/enable
26 echo 1 > /sys/kernel/debug/tracing/events/sched/sched_process_exit/enable
27 echo 1 > /sys/kernel/debug/tracing/events/sched/sched_process_fork/enable
28 echo 1 > /sys/kernel/debug/tracing/events/sched/sched_process_free/enable
29 sleep 1
30 echo "event enabled"
31 
32 echo 1 > /sys/kernel/debug/tracing/options/func_stack_trace
33 echo 1 > /sys/kernel/debug/tracing/options/stacktrace
34 echo 1 > /sys/kernel/debug/tracing/options/sym-offset
35 echo "function stack trace enabled"
36 
37 echo 1 > /sys/kernel/debug/tracing/tracing_on
38 echo "tracing_on"
셸 스크립트의 내용을 설명하면요.

19 #echo do_exit search_binary_handler  copy_process.part.5 > /sys/kernel/debug/tracing/set_ftrace_filter
20 #echo sys_clone kernel_clone >> /sys/kernel/debug/tracing/set_ftrace_filter

먼저 19~20번째 줄을 주석 처리합니다. 

그 다음에 33번째 줄을 추가합니다.

33 echo 1 > /sys/kernel/debug/tracing/options/stacktrace

'/sys/kernel/debug/tracing/options/stacktrace'을 1로 설정하면 ftrace 이벤트가 출력될 때
콜 스택을 출력해줍니다. 아래와 같이 /sys/kernel/debug/tracing/set_ftrace_filter을 설정하지 않아도 됩니다.

그래서 아래 코드를 주석 처리하는 것입니다.

19 #echo do_exit search_binary_handler  copy_process.part.5 > /sys/kernel/debug/tracing/set_ftrace_filter
20 #echo sys_clone kernel_clone >> /sys/kernel/debug/tracing/set_ftrace_filter

실습 

위에서 언급한 셸 스크립트를 설정한 후 273 페이지에 명시된 내용을 따라서 실습을 하면 됩니다. 
실습 과정을 요약하면 다음과 같습니다. 

1. 셸 스크립트 설정: ftrace 설정 
2. 터미널에서 아래 명령어 입력 

   $ whoami
   $ cat /proc/interrupts 
   
3. get_ftrace.sh 명령어를 입력해 ftrace 메시지 추출 

ftrace 메시지 분석 #1   

whoami 명령어를 입력했을 때 프로세스가 생성, 실행 그리고 종료되는 메시지는 다음과 같습니다.

01 bash-1558    [002] .....  2150.857123: sched_process_fork: comm=bash pid=1558 child_comm=bash child_pid=2935
02 bash-1558    [002] .....  2150.857129: <stack trace>
03 => __traceiter_sched_process_fork+0x44/0x58
04 => kernel_clone+0x1bc/0x470
05 => sys_clone+0x80/0x9c
06 => ret_fast_syscall+0x0/0x1c
07 => 0xbe933240
08 whoami-2935    [003] .....  2150.860094: sched_process_exec: filename=/usr/bin/whoami pid=2935 old_pid=2935
09 whoami-2935    [003] .....  2150.860100: <stack trace>
10 => __traceiter_sched_process_exec+0x4c/0x60
11 => bprm_execve+0x600/0x668
12 => do_execveat_common+0x17c/0x194
13 => sys_execve+0x40/0x48
14 => ret_fast_syscall+0x0/0x1c
15 => 0xbeacb760
16 whoami-2935    [003] .....  2150.864758: sched_process_exit: comm=whoami pid=2935 prio=120
17 whoami-2935    [003] .....  2150.864763: <stack trace>
18 => __traceiter_sched_process_exit+0x3c/0x50
19 => do_exit+0x674/0xb88
20 => do_group_exit+0x50/0xe0
21 => __wake_up_parent+0x0/0x2c
22 => ret_fast_syscall+0x0/0x1c
23 => 0xbeacb5e0

먼저 01~07번째 줄을 보겠습니다.

01 bash-1558    [002] .....  2150.857123: sched_process_fork: comm=bash pid=1558 child_comm=bash child_pid=2935
02 bash-1558    [002] .....  2150.857129: <stack trace>
03 => __traceiter_sched_process_fork+0x44/0x58
04 => kernel_clone+0x1bc/0x470
05 => sys_clone+0x80/0x9c
06 => ret_fast_syscall+0x0/0x1c
07 => 0xbe933240

PID가 1558인 bash 프로세스가 PID가 2935인 whoami 프로세스를 생성하는 메시지입니다. 
책에 설명된 바와 같이 부모 프로세스가 자식 프로세스를 생성하는 단계에서 자식 프로세스의 이름은 부모 프로세스의 이름과 같습니다.

여기서 눈여겨 볼 메시지는 04번째 줄입니다. v4.19 버전에서 04번째 줄은 다음과 같이 출력될 것입니다.

04 => _do_fork+0x1bc/0x470

그런데 커널 버전이 업그레이드 되면서 _do_fork() 함수의 이름이 kernel_clone() 함수로 변경됐습니다.
관련 커밋과 소스 위치는 다음과 같습니다. 

[커밋]

https://lkml.org/lkml/2020/8/18/987
...
diff --git a/kernel/fork.c b/kernel/fork.c
index 4d32190861bd..34e37cee239f 100644
--- a/kernel/fork.c
+++ b/kernel/fork.c
@@ -2384,7 +2384,7 @@ struct mm_struct *copy_init_mm(void)
  *
  * args->exit_signal is expected to be checked for sanity by the caller.
  */
-long _do_fork(struct kernel_clone_args *args)
+int kernel_clone(struct kernel_clone_args *args)
 {
  u64 clone_flags = args->flags;
  struct completion vfork;

[소스 위치]
https://elixir.bootlin.com/linux/v5.15.31/source/kernel/fork.c#L2503
pid_t kernel_clone(struct kernel_clone_args *args)
{
u64 clone_flags = args->flags;
struct completion vfork;
struct pid *pid;

이어서 08~15번째 줄을 보겠습니다.

08 whoami-2935    [003] .....  2150.860094: sched_process_exec: filename=/usr/bin/whoami pid=2935 old_pid=2935
09 whoami-2935    [003] .....  2150.860100: <stack trace>
10 => __traceiter_sched_process_exec+0x4c/0x60
11 => bprm_execve+0x600/0x668
12 => do_execveat_common+0x17c/0x194
13 => sys_execve+0x40/0x48
14 => ret_fast_syscall+0x0/0x1c
15 => 0xbeacb760

위 콜 스택에서 13번째 줄의 함수를 눈여겨 볼 필요가 있습니다. 
sys_execve() 함수는 execve 시스템 콜 핸들러 함수이므로 유저 공간에서 execve 시스템 콜을 
실행했다는 사실을 유추할 수 있습니다.

08번째 줄은 프로세스의 자세한 실행 정보를 출력합니다.

08 whoami-2935    [003] .....  2150.860094: sched_process_exec: filename=/usr/bin/whoami pid=2935 old_pid=2935

PID가 2935인 whoami 프로세스의 정체는 /usr/bin/whoami이란 사실을 알 수 있습니다.
리눅스 커널 버전이 업그레이드되도 리눅스 배포판에서 지정한 유틸리티 파일의 디렉토리는 자주 변경되지 않습니다. 

마지막으로 16~23번째 줄을 분석하겠습니다.

16 whoami-2935    [003] .....  2150.864758: sched_process_exit: comm=whoami pid=2935 prio=120
17 whoami-2935    [003] .....  2150.864763: <stack trace>
18 => __traceiter_sched_process_exit+0x3c/0x50
19 => do_exit+0x674/0xb88
20 => do_group_exit+0x50/0xe0
21 => __wake_up_parent+0x0/0x2c // sys_exit_group 심벌이 맞는 정보입니다.
22 => ret_fast_syscall+0x0/0x1c
23 => 0xbeacb5e0

whoami 프로세스가 종료되는 함수 호출 흐름을 볼 수 있습니다. 

위 메시지로 유저 공간에서 exit() 함수가 호출된 다음에 exit 시스템 콜이 유발됐다는 
사실을 유추할 수 있습니다.

ftrace 메시지 분석 #2   

이어서 cat 명령어를 입력했을 때 프로세스가 생성, 실행 그리고 종료되는 메시지는 다음과 같습니다.

01 bash-1558    [002] .....  2159.250439: sched_process_fork: comm=bash pid=1558 child_comm=bash child_pid=2937
02 bash-1558    [002] .....  2159.250445: <stack trace>
03 => __traceiter_sched_process_fork+0x44/0x58
04 => kernel_clone+0x1bc/0x470
05 => sys_clone+0x80/0x9c
06 => ret_fast_syscall+0x0/0x1c
07 => 0xbe933240
08 cat-2937    [003] .....  2159.253458: sched_process_exec: filename=/usr/bin/cat pid=2937 old_pid=2937
09 cat-2937    [003] .....  2159.253464: <stack trace>
10 => __traceiter_sched_process_exec+0x4c/0x60
11 => bprm_execve+0x600/0x668
12 => do_execveat_common+0x17c/0x194
13 => sys_execve+0x40/0x48
14 => ret_fast_syscall+0x0/0x1c
15 => 0xbeade760
16 cat-2937    [003] .....  2159.257431: sched_process_exit: comm=cat pid=2937 prio=120
17 cat-2937    [003] .....  2159.257436: <stack trace>
18 => __traceiter_sched_process_exit+0x3c/0x50
19 => do_exit+0x674/0xb88
20 => do_group_exit+0x50/0xe0
21 => __wake_up_parent+0x0/0x2c
22 => ret_fast_syscall+0x0/0x1c
23 => 0xbeade5e0

먼저 01~07번째 줄을 분석하겠습니다. 

01 bash-1558    [002] .....  2159.250439: sched_process_fork: comm=bash pid=1558 child_comm=bash child_pid=2937
02 bash-1558    [002] .....  2159.250445: <stack trace>
03 => __traceiter_sched_process_fork+0x44/0x58
04 => kernel_clone+0x1bc/0x470
05 => sys_clone+0x80/0x9c
06 => ret_fast_syscall+0x0/0x1c
07 => 0xbe933240

PID가 1558인 bash 프로세스가 PID가 1558인 cat 프로세스를 생성하는 메시지입니다. 
04번째 줄과 같이 kernel_clone 심벌이 보이니 프로세스가 생성되는 실행 흐름이란 사실을 
알 수 있습니다. 

이어서 08~15번째 줄을 보겠습니다.

08 cat-2937    [003] .....  2159.253458: sched_process_exec: filename=/usr/bin/cat pid=2937 old_pid=2937
09 cat-2937    [003] .....  2159.253464: <stack trace>
10 => __traceiter_sched_process_exec+0x4c/0x60
11 => bprm_execve+0x600/0x668
12 => do_execveat_common+0x17c/0x194
13 => sys_execve+0x40/0x48
14 => ret_fast_syscall+0x0/0x1c
15 => 0xbeade760

역시 위 콜 스택에서 13번째 줄의 함수를 눈여겨 볼 필요가 있습니다. 
유저 공간에서 execve 시스템 콜을 실행해 execve 시스템 콜 핸들러 함수인 sys_execve() 함수가 호출됐습니다. 

08번째 줄은 프로세스의 자세한 실행 정보를 출력합니다.

08 cat-2937    [003] .....  2159.253458: sched_process_exec: filename=/usr/bin/cat pid=2937 old_pid=2937

PID가 2937인 cat 프로세스의 정체는 /usr/bin/cat이란 사실을 알 수 있습니다.

마지막으로 16~23번째 줄을 보겠습니다.

16 cat-2937    [003] .....  2159.257431: sched_process_exit: comm=cat pid=2937 prio=120
17 cat-2937    [003] .....  2159.257436: <stack trace>
18 => __traceiter_sched_process_exit+0x3c/0x50
19 => do_exit+0x674/0xb88
20 => do_group_exit+0x50/0xe0
21 => __wake_up_parent+0x0/0x2c
22 => ret_fast_syscall+0x0/0x1c
23 => 0xbeade5e0

cat 프로세스가 종료되는 함수 호출 흐름입니다. 핵심 함수인 do_exit() 함수가 19번째 줄에서 확인됩니다.




포스트 메타 정보

퍼블리싱 및 추천

  • 내보내기
    • 밸리 : IT 2022/06/06 06:02

같은 카테고리의 글

트랙백(0) 덧글(7)

덧글

  • 송문규 2022/06/06 11:50 # 삭제 답글

    친절한 답변 감사합니다!!

  • duicleme 2022/06/30 02:32 # 삭제 답글

    잘 읽었습니다. 감사합니다...

  • AustinKim 2022/07/04 19:45 #

    많은 도움이 됐으면 좋겠습니다.

  • supultti 2023/01/01 17:24 # 삭제 답글

    커널 5.15 64비트에서 해보는중입니다.
    5.15에서 secondary_start_kernel 관련 필터에서 에러가 발생합니다.
    에러 내용은 "./irq_trace_ftrace.sh: 11 줄: echo: 쓰기 오류: 부적절한 인수"
    입니다.

    available_filter_functions 파일에서 확인해보니 secondary_start_kernel 관련함수가 없습니다.
    어떤걸로 대처해야 할까요?
    "cpu_startup_entry" 이걸로 대처했긴 해봤습니다.

    다만 rpi_get_interrupt_info 함수를 (available_filter_functions 에는 존재함) 필터링에 넣었는데 ftrace 로그에 남지 않네요.

    echo 1 > $TRACING/options/stacktrace 이것도 넣었습니다.

  • supultti 2023/01/06 13:57 # 삭제

    32비트 커널로 체크해본결과 동일결과가 나타났습니다.
    왜 그러나 보니 호출은 되고 있고 show_interrupt 까지 호출되는 것을 확인하였고
    noinline 을 추가하여 컴파일하여 보니 잘 잡힙니다.

  • AustinKim 2023/01/07 12:55 #

    다행이군요. 컴파일러가 최적화를 하는 과정에서 심벌을 삭제하는데요. 그래서 제대로 설정되지 않은 것 같습니다.
    감사합니다.

  • JohnLee 2023/01/13 15:25 # 삭제 답글

    오오 저도 그 부분에서 멈추었는데 감사합니다 우와와왕!!!!!!!
댓글 입력 영역
rousalome.egloos.com is powered by Egloos. Subscribe to RSS Skin design by egloos.