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
2
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
최근 덧글