Arm Linux Kernel Hacks

rousalome.egloos.com

포토로그 Kernel Crash


통계 위젯 (화이트)

34120
1703
402249


[리눅스커널] 커널 디버깅과 코드 학습: ftrace는 어떻게 설정할까? 3. 커널 디버깅과 코드 학습

ftrace에서 제공하는 nop, function, graph_function 트레이서를 쓰려면 ftrace 관련 코드가 커널 이미지에 포함돼야 합니다. 즉, ftrace 코드가 추가된 커널 소스를 빌드해야 합니다. 

이를 위해 다음과 같이 커널 설정 컨피그(configuration)를 활성화합니다. 

CONFIG_FTRACE=y
CONFIG_DYNAMIC_FTRACE=y 
CONFIG_FUNCTION_TRACER=y
CONFIG_FUNCTION_GRAPH_TRACER=y
CONFIG_IRQSOFF_TRACER=y
CONFIG_SCHED_TRACER=y
CONFIG_FUNCTION_PROFILER=y
CONFIG_STACK_TRACER=y
CONFIG_TRACER_SNAPSHOT=y

참고로 라즈비안에서는 ftrace 에 필요한 세부 컨피그가 기본적으로 모두 활성화돼 있습니다. 따라서 라즈비안을 라즈베리 파이에 설치하기만 하면 ftrace 메시지를 볼 수 있습니다.


ftrace는 리눅스 커널의 공통 기능입니다. 라즈비안을 비롯한 다른 리눅스 시스템에서도 ftrace를 지원합니다.

다음과 같은 패치 코드를 입력하면 라즈베리 파이를 비롯한 다른 리눅스 시스템에서도 ftrace 메시지를 볼 수 있습니다.

--- a/arch/arm/configs/your_device_defconfig
+++ b/arch/arm/configs/your_device_defconfig
@@ -778,6 +777,14 @@ CONFIG_DEBUG_SET_MODULE_RONX=y
01  CONFIG_SECURITY_PERF_EVENTS_RESTRICT=y
02  CONFIG_SECURITY=y
03  CONFIG_SECURITY_NETWORK=y
04 +CONFIG_FTRACE=y
05 +CONFIG_DYNAMIC_FTRACE=y 
06 +CONFIG_FUNCTION_TRACER=y
07 +CONFIG_FUNCTION_GRAPH_TRACER=y
08 +CONFIG_IRQSOFF_TRACER=y
09 +CONFIG_SCHED_TRACER=y
10 +CONFIG_FUNCTION_PROFILER=y
11 +CONFIG_STACK_TRACER=y
12 +CONFIG_TRACER_SNAPSHOT=y
13 CONFIG_LSM_MMAP_MIN_ADDR=4096
14 CONFIG_HARDENED_USERCOPY=y
15 CONFIG_SECURITY_SELINUX=y

여기서 arch/arm/configs/your_device_defconfig는 예시 파일입니다. 현재 리눅스 시스템을 빌드할 때 적용하는 컨피그 파일에 04~12번째 줄 코드를 입력하면 됩니다. 앞에서 소개한 ftrace 기능을 켜기 위한 컨피그를 활성화한 후 커널을 빌드하면 ftrace 관련 코드가 커널 이미지에 포함됩니다. 이 같은 방식으로 커널 이미지를 시스템에 설치하고 난 후 재부팅합니다. 


다시 한 번 반복하지만 라즈비안에서는 ftrace의 기본 기능이 모두 활성화돼 있습니다. 따라서 ftrace 컨피그를 새롭게 설정해 커널을 빌드할 필요가 없습니다.

그럼 ftrace 설정 파일을 어디서 확인할 수 있을까요? 다음 경로에서 ftrace 드라이버 설정 폴더와 파일을 볼 수 있습니다.

/sys/kernel/debug/tracing

'ls /sys/kernel/debug/tracing' 명령어를 입력하면 다음과 같이 /sys/kernel/debug/tracing 디렉터리에 있는 파일을 확인할 수 있습니다.

root@raspberrypi:/home/pi#  ls /sys/kernel/debug/tracing
README                     options             snapshot
available_events           per_cpu             trace
available_filter_functions printk_formats      trace_clock
available_tracers          saved_cmdlines      trace_marker
buffer_size_kb             saved_cmdlines_size trace_marker_raw
buffer_total_size_kb       saved_tgids         trace_options
current_tracer             set_event           trace_pipe
dyn_ftrace_total_info      set_event_pid       tracing_cpumask
enabled_functions          set_ftrace_filter   tracing_max_latency
events                     set_ftrace_notrace  tracing_on
free_buffer                set_ftrace_pid      tracing_thresh
instances                  set_graph_function  uprobe_events
max_graph_depth            set_graph_notrace   uprobe_profile

/sys/kernel/debug/tracing 디렉터리에 수많은 파일이 있지만 정작 자주 사용하는 파일은 많지 않습니다. 먼저 ftrace를 설정하는 방법을 통해 위 디렉터리에 있는 파일이 어떤 기능을 수행하는지 확인해보겠습니다.

ftrace 설정

먼저 ftrace를 설정하는 방법을 설명하겠습니다. 이 책에서는 다음과 같은 셸 스크립트를 실행해 ftrace를 빨리 설정하겠습니다. 다음 셸 스크립트 코드를 보면서 ftrace 세부 설정 방법을 소개합니다.

1 #!/bin/bash
3 echo 0 > /sys/kernel/debug/tracing/tracing_on
4 sleep 1
5 echo "tracing_off"
6
7 echo 0 > /sys/kernel/debug/tracing/events/enable
8 sleep 1
9 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 1 > /sys/kernel/debug/tracing/events/sched/sched_wakeup/enable
20 echo 1 > /sys/kernel/debug/tracing/events/sched/sched_switch/enable
21
22 echo 1 > /sys/kernel/debug/tracing/events/irq/irq_handler_entry/enable
23 echo 1 > /sys/kernel/debug/tracing/events/irq/irq_handler_exit/enable
24
25 echo 1 > /sys/kernel/debug/tracing/events/raw_syscalls/enable
26 sleep 1
27 echo "event enabled"
28
29 echo  schedule ttwu_do_wakeup > /sys/kernel/debug/tracing/set_ftrace_filter
30
31 sleep 1
32 echo "set_ftrace_filter enabled"
33
34 echo 1 > /sys/kernel/debug/tracing/options/func_stack_trace
35 echo 1 > /sys/kernel/debug/tracing/options/sym-offset
36 echo "function stack trace enabled"
37
38 echo 1 > /sys/kernel/debug/tracing/tracing_on
39 echo "tracing_on"

먼저 각 명령어 다음에 보이는 “sleep 1”은 무엇일까요? 바로 1초 동안 딜레이를 주는 동작입니다. ftrace 설정 명령어를 입력하면 커널 내부에서 ftrace를 설정하는 함수가 실행됩니다. 이때 ftrace 설정 명령어를 커널 내에서 충분히 수행할 만한 시간을 확보하기 위해 딜레이를 주는 것입니다. 


앞의 ftrace 설정 스크립트는 필자가 라즈베리 파이에서 실행해 정상적으로 동작하는 것을 확인했습니다. 만약 코드 순서가 바뀌면 시스템이 멈추거나 크래시가 발생할 수 있으니 주의합시다.

tracing_on: 트레이서 활성화/비활성화하기

ftrace를 활성화/비활성화하려면 tracing_on 파일을 설정해야 합니다. tracing_on은 부팅 후 기본적으로 0으로 설정돼 있습니다.

3~38 번째 줄 코드를 보겠습니다. 

3 echo 0 > /sys/kernel/debug/tracing/tracing_on
...
38 echo 1 > /sys/kernel/debug/tracing/tracing_on

먼저 3번째 줄 코드를 보면 /sys/kernel/debug/tracing/tracing_on 파일에 0을 저장합니다. 이는 ftrace를 비활성화하는 동작입니다. 반대로 38번째 줄 코드와 같이 /sys/kernel/debug/tracing/tracing_on 파일에 1을 저장하면 ftrace를 활성화할 수 있습니다. 정리하면 tracing_on은 ftrace를 활성화하거나 비활성화하기 위해 설정해야 하는 파일입니다.

tracer 설정
ftrace는 nop, function, graph_function 트레이서를 제공합니다. ftrace에서 다양한 트레이서를 제공하는데, 중요한 부분만 추려 소개하면 다음과 같습니다.

nop: 기본 트레이서입니다. ftrace 이벤트만 출력합니다. 
function: 함수 트레이서입니다. set_ftrace_filter로 지정한 함수를 누가 호출하는지 출력합니다.
graph_function: 함수 실행 시간과 세부 호출 정보를 그래프 포맷으로 출력합니다.

트레이서를 설정하려면 다음과 같이 current_tracer 파일에 트레이서의 이름을 저장해야 합니다.

15 echo function > /sys/kernel/debug/tracing/current_tracer

참고로 라즈베리 파이가 부팅되면 current_tracer 파일에 기본적으로 nop 트레이서가 설정돼 있습니다.

ftrace 이벤트 설정

ftrace에서는 커널 서브시스템과 기능별로 세부 동작을 출력하는 기능을 지원합니다. 이를 이벤트라고 합니다. 

셸 스크립트 코드를 보면서 이벤트를 설정하는 방법을 알아봅시다. 먼저 다음은 ftrace 이벤트를 모두 비활성화하는 코드입니다.

7 echo 0 > /sys/kernel/debug/tracing/events/enable

다음 코드를 보겠습니다.

19 echo 1 > /sys/kernel/debug/tracing/events/sched/sched_wakeup/enable
20 echo 1 > /sys/kernel/debug/tracing/events/sched/sched_switch/enable
...
22 echo 1 > /sys/kernel/debug/tracing/events/irq/irq_handler_entry/enable
23 echo 1 > /sys/kernel/debug/tracing/events/irq/irq_handler_exit/enable

19~20번째 줄 코드를 실행하면 스케줄링 동작을 기록하는 sched_wakeup, sched_switch 이벤트를 활성화합니다. 이어서 22~23번째 줄은 인터럽트 핸들링의 시작과 종료 시점을 기록하는 irq_handler_entry, irq_handler_exit 이벤트를 활성화하는 설정입니다. 

ftrace 이벤트의 종류에 대해서는 다음 절에서 살펴보겠습니다.

필터 설정: set_ftrace_filter

set_ftrace_filter 파일에 트레이싱하고 싶은 함수를 지정합니다. set_ftrace_filter는 현재 트레이서를 function_graph과 function로 설정할 경우 작동하는 파일입니다. 이 파일에 디버깅하고 싶은 함수의 이름을 지정하면 됩니다. 이를 가리켜 함수 필터를 지정한다고 표현합니다. 그런데 여기서 주의해야 할 점이 있습니다.

리눅스 커널에 존재하는 모든 함수를 필터로 지정할 수는 없고 available_filter_functions 파일에 포함된 함수만 지정할 수 있다는 것입니다. 라즈베리 파이에서 available_filter_functions 파일에 없는 함수를 set_ftrace_filter 파일에 지정하면 시스템은 락업됩니다. 이 점에 주의합니다.

락업은 실전 개발에서 사용하는 용어로 시스템이 아무런 반응을 하지 않는 상황을 의미합니다. 예를 들어, 라즈베리 파이가 락업되면 화면은 가만히 멈춰 있고 마우스나 키보드를 움직여도 아무런 반응을 하지 않습니다.

ftrace에서 함수 필터를 설정하는 방법을 다음 코드를 보면서 알아보겠습니다.

11 echo  secondary_start_kernel  > /sys/kernel/debug/tracing/set_ftrace_filter
...
29 echo  schedule ttwu_do_wakeup > /sys/kernel/debug/tracing/set_ftrace_filter

11번째 줄에서는 secondary_start_kernel() 함수를 필터로 설정합니다. 사실 secondary_start_kernel() 함수는 부팅 도중 한 번 호출됩니다. 더미로 secondary_start_kernel() 함수를 필터로 설정하는 것입니다. 

반복해서 설명하지만 현재 트레이서를 function_graph와 function으로 설정할 경우 set_ftrace_filter에 지정한 함수를 트레이싱합니다. 그런데 11번째 줄 코드를 실행하지 않고 set_ftrace_filter 필터를 설정하지 않으면 어떻게 동작할까요? set_ftrace_filter 파일에 필터로 함수를 지정하지 않으면 모든 커널 함수를 트레이싱합니다. 즉, 시스템이 수많은 커널 함수를 트레이싱하다가 결국 락업 상태에 빠지게 됩니다. 이런 상황을 방지하려는 코드입니다. 


라즈베리 파이에서 set_ftrace_filter 파일에 필터로 함수를 지정하지 않으면 시스템이 100% 락업된다는 데 주의합니다.


실제 함수 필터를 거는 부분은 29번째 줄 코드입니다. 29번째 줄에서는 schedule() 함수와 ttwu_do_wakeup() 함수를 필터로 지정합니다. 

29 echo  schedule ttwu_do_wakeup > /sys/kernel/debug/tracing/set_ftrace_filter

이 책에서는 set_ftrace_filter 기능을 활용해 커널 함수의 콜스택을 분석합니다.

ftrace: func_stack_trace/sym-offset 
options 하위 폴더에 추가로 ftrace를 설정하는 파일이 있습니다. 34 번째 줄을 봅시다.

34 echo 1 > /sys/kernel/debug/tracing/options/func_stack_trace

options/func_stack_trace 파일을 1로 설정하면 ftrace를 통해 콜스택을 볼 수 있습니다. 즉, set_ftrace_filter 파일에 필터로 지정된 함수의 콜스택을 기록합니다. options/func_stack_trace를 설정하기 전에 current_tracer는 function으로 지정돼 있어야 합니다. 

이어서 34 번째 줄을 보겠습니다. 

35 echo 1 > /sys/kernel/debug/tracing/options/sym-offset

ftrace에서 콜스택을 출력할 때 포맷을 지정합니다. 함수를 호출할 때 주소 오프셋을 출력합니다. 다음은 options/sym-offset 옵션을 활성화했을 때 출력되는 함수의 정보입니다.

1 lxterminal-840 [001] .... 8632.128798: schedule+0x10/0xa8 <-schedule_hrtimeout_range_clock+0xd8/0x14c
2 lxterminal-840 [001] .... 8632.128816: <stack trace>
3 => poll_schedule_timeout+0x54/0x84
4 => do_sys_poll+0x3d8/0x500
5 => sys_poll+0x74/0x114
6 => __sys_trace_return+0x0/0x10


위 로그에서 함수 호출 방향은 6번째 줄에서 3번째 줄 방향입니다.

3~6 번째 줄의 로그와 같이 함수명 오른쪽에 16진수 형태의 숫자가 보입니다. 함수를 호출한 주소를 함수 시작 주소를 기준으로 출력합니다.

3 => poll_schedule_timeout+0x54/0x84
4 => do_sys_poll+0x3d8/0x500

이것은 4번째 줄의 do_sys_poll() 함수의 시작 주소에서 0x3d8 오프셋만큼 떨어진 주소에서 poll_schedule_timeout() 함수를 호출한다는 의미입니다. 나머지 함수도 같은 의미로 해석하면 됩니다.

추가 설정 파일

다음으로 추가 설정 파일을 간략하게 소개하겠습니다.

buffer_size_kb
ftrace 로그의 버퍼 크기이며, 킬로바이트 단위입니다. ftrace 로그를 더 많이 저장하고 싶을 때 설정합니다.

available_filter_functions
트레이싱할 수 있는 함수 목록을 저장한 파일입니다. 리눅스 드라이버나 커널에 새로운 함수를 새로 구현했으면 이 파일에 새롭게 작성한 함수의 이름을 볼 수 있습니다.

events
ftrace에서 제공하는 이벤트의 종류를 알 수 있는 디렉터리입니다. 수많은 이벤트 중 가장 대표적인 부분만 추려서 소개하겠습니다.

   sched
    프로세스 스케줄링 동작과 스케줄링 프로파일링을 트레이싱하는 이벤트를 볼 수 있습니다.
      sched_switch: 컨텍스트 스위칭 동작
      sched_wakeup: 프로세스를 깨우는 동작

   irq
    인터럽트와 소프트웨어 인터럽트를 트레이싱하는 이벤트들이 있습니다.
      irq_handler_entry: 인터럽트가 발생한 시각과 인터럽트 번호 및 이름을 출력 
      irq_handler_exit: 인터럽트 핸들링이 완료
      softirq_raise: Soft IRQ 서비스 실행 요청
      softirq_entry: Soft IRQ 서비스 실행 시작
      softirq_exit: Soft IRQ 서비스 실행 완료

이 책의 모든 장에서는 ftrace 이벤트를 설정해 커널 디버깅 실습을 진행합니다. 이번 절에서는 ftrace 이벤트를 설정하는 패턴에 초점을 맞춥니다.

이어지는 절에서는 ftrace 메시지를 분석하는 방법을 소개합니다. 

* 유튜브 강의 동영상도 있으니 같이 들으시면 더 많은 걸 배울 수 있습니다. 






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

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


# Reference: For more information on 'Linux Kernel';

디버깅을 통해 배우는 리눅스 커널의 구조와 원리. 1

디버깅을 통해 배우는 리눅스 커널의 구조와 원리. 2


 




핑백

덧글

  • 사바14 2020/10/01 00:31 # 삭제 답글

    안녕하세요. 저자님 책을 보면서 열심히 공부하고 있습니다.
    ftrace를 설정하는 와중에 궁금한 점이 있어 질문 남깁니다.
    /sys/kernel/debug/tracing 하위에 available_filter_functions 파일을 보면 사전에 build 했던 /kernel/irq/proc.c 에 추가한 rpi_get_interrupt_info() 함수가 보이는데요.
    available_filter_functions에 등록하기 위한 별도 절차가 필요한 것이 아니라, 자동으로 등록된다고 이해하면 될까요?
  • AustinKim 2020/10/01 11:38 #

    제대로 이해하신 것 같습니다. 조금 더 구체적으로 말씀드리면 부팅 과정에서 다음과 같은 동작을 수행합니다.

    ❑ /sys/kernel/debug/trace/available_filter_functions 파일을 생성한다.
    ❑ /sys/kernel/debug/trace/available_filter_functions 파일로 출력할 심볼 정보를 준비한다.

    rpi_get_interrupt_info() 함수를 빌드한 상태면, 심볼 정보에는 rpi_get_interrupt_info() 함수가 이미 포함돼 있을 겁니다.
    관련 커널 코드의 내용은 아래 링크를 참고하시면 됩니다.

    [리눅스커널] ftrace: available_filter_functions 관련 분석
    http://rousalome.egloos.com/10012600

    감사합니다.
  • 2020/10/01 11:37 # 답글 비공개

    비공개 덧글입니다.
  • 우유우유 2020/10/05 19:30 # 삭제 답글

    책내용과는 무관하지만 저자님께 여쭤보고 싶은것이 있어서 질문을 남겨봅니다.

    요즘 안드로이드 커널과 구글에서 개발하는 차세대 os인 퓨시아의 커널인 zircon에 관심이 가고있는데요
    1.퓨시아os가 나오게되면 리눅스 os가 경쟁력을 잃게될수도 있을것 같은데 리눅스커널을 계속 공부한는것이 좋은 경쟁력이 될수있을까요?

    2. 그리고 리눅스커널공부를 하게되면 후에 다른커널(ex 지르콘 커널)을 공부할때에도 도움이 될까요?
  • AustinKim 2020/10/05 21:07 #

    질문에 간단히 답을 드리면요;

    1. 만약에 퓨시아os가 리눅스 커널을 위협하는 존재가 되려면, 먼저 다음과 같은 조건을 만족해야 할 것 같아요.

    * 퀄컴을 비롯한 여러 SoC에서 퓨시아os를 탑재
    * 'ARM이나 인텔 x86 개발자들이 퓨시아 os의 커널에 자신의 CPU에 최적하는 코드를 반영(contribution)
    * 컴퓨터나 모바일 제조사들이 퓨시아os 기반의 제품을 선택

    근데 생태계를 구축하는데 아직 가야 할 길이 좀 먼 것 같네요.

    2. 퓨시아os는 '마이크로 커널'이라 커널의 아주 기본적인 기능만 제공하므로, '마이크로 커널' 기반인 리눅스 커널과 다른 성격의 운영체제입니다. 퓨시아os는 IoT 기반의 RTOS 시장에 진출할 것 같아 보입니다.

    3. 한 가지 커널은 잘 배워놓으면 다른 RTOS나 커널을 잘 파악할 가능성이 높습니다. 기본적인 개념은 대동소이하거든요.
  • 2020/10/05 21:07 # 답글 비공개

    비공개 덧글입니다.
  • 반바지당나귀 2020/11/05 11:06 # 삭제 답글

    set_ftrace_filter 로 함수를 trace 할때 함수의 return 값을 확인할수 있는 방법은 없나요??
  • AustinKim 2020/11/05 14:34 #

    보통 함수는 void와 int와 같은 키워드로 선언되어 있는데요.
    return 값을 확인하려면 r0이나, x0 레지스터에 저장된 값을 ftrace로 출력을 해야 할 겁니다.

    이 내용은 linux-trace-devel 메일링 리스트로 문의하시면 관련 정보를 얻으실 수 있을 것 같아요.

    감사합니다.
  • 2020/11/05 14:34 # 답글 비공개

    비공개 덧글입니다.
댓글 입력 영역