디버깅을 통해 배우는 리눅스 커널의 구조와 원리 1, 도서 공부하기 7 - ftrace 사용법 및 분석해 보기
안녕하세요.
이전 글에서 printk()와 dump_stack() 함수를 확인했습니다. 두 함수에는 사용할 때 자주 호출하는 함수에는 사용하기가 어렵다는 주의점이 있었습니다. 이런 부족한 점을 충족하기 위한 커널 디버깅 소프트웨어가 필요했습니다.
1. ftrace 란?
기존의 커널 디버깅 부족함을 해결해 줄 수 있는 요구사항(함수 호출 흐름을 소스코드 수정하지 않고 확인하고 싶다, 커널의 세부 실행 정보를 출력 원함, 수십 번 호출해도 성능에 부담 주지 않았으면 함, 커널 로그도 함께 보고자 함)을 충족하는 디버깅 기능의 소프트웨어입니다.
ftrace 특징으로
- 인터럽트, 스케줄링, 커널 타이머 등의 커널 동작 추적
- 코드 수정할 필요 없이 함수 필터 지정한 함수와 호출한 함수 콜 스택 출력
- 함수가 어느 프로세스에서 실행하는지 알 수 있음
- 함수가 실행된 시각정보 확인 가능
- ftrace로그를 활성화해도 시스템 동작에 부하를 거의 주지 않음
2. ftrace 설정 방법
우선 라즈베리 파이에서는 기본적으로 ftrace 관련 코드가 추가된 커널 이미지 소스를 빌드해야 합니다. 이를 위해 커널 설정 컨피그(configuration)를 활성화해야 합니다.
그러나 앞에서 이미 예습으로 실행해 보았듯이 라즈베리 파이에서는 ftrace가 이미 활성화돼 있습니다. 참고 삼아 어디에 있는지 확인할 수 있습니다. 책에서는 your_device_defconfig 파일 내용으로 보여주고 있는데, 텍스트 기반 메뉴로 선택되어 있는 것을 알 수 있습니다.
your_device_defconfig 파일은 라즈베리 파이4 경우, arch/arm/configs/bcm2711_defconfig 파일이라고 생각하면 됩니다.
메뉴형태로 확인하기 위해서는 먼저 ncurses 패키지를 설치하고 커널 설정 메뉴를 실행해야 합니다. Kernel hacking -> Tracers 이동해서 체크된 항목을 확인합니다. tracer 체크가 되어 있다면 변경할 필요 없이 Exit 해서 나오면 됩니다.
linux# apt install libncurses-dev
linux# make menuconfig
3. ftrace 설정 파일 확인
아래 경로를 확인하면 설정 폴더와 파일을 볼 수 있습니다.
linux# ls /sys/kernel/debug/tracing/
4. ftrace 설정
이전 ftrace 예습에 사용했던 설정파일에서 조금 스크립트 추가되어 있습니다.
irq_trace_ftrace.sh 파일 내용에 변경된 부분을 수정해서 ftrace_setting.sh로 바꿔 사용하겠습니다.
linux# cp ../irq_trace_ftrace.sh ../ftrace_setting.sh
linux# vim ../ftrace_setting.sh
--- ftrace_setting.sh (첨부파일 참고)
1) ftrace 셀 스크립트 설명
상세한 내용은 책을 참조하면 됩니다. 여기서는 간단하게 요약해서 남겨보았습니다.
3, 37번 줄 : /tracing_on파일에 0과 1을 저장합니다. ftrace를 활성화(1), 비활성화(0) 한다는 의미입니다.
7번 줄 : ftrace는 커널을 구성하는 서브시스템과 기능별로 세부 동작을 출력하는 기능을 지원하는 이벤트를 가지고 있습니다. 이 이벤트를 비활성화합니다.
11번 줄 : secondary_start_kernel() 함수를 필터로 설정합니다. secondary_start_kernel() 함수는 부팅 도중 한번 호출되지만 더미로 처음에 넣어 줍니다. 처음에 지정하지 않으면 모든 커널 내부 함수를 트레이싱 함으로써 락업에 빠지게 될 수 있기 때문입니다.
29번 줄 : 실제 필터를 설정하는 부분으로 schedule, ttwu_do_wakeup를 필터로 지정합니다.
15번 줄 : 트레이서의 기능 설정하는 부분으로 nop는 이벤트만 출력, function은 지정한 함수를 누가 호출하는지 출력, function_graph는 함수 실행 시간과 세부 호출 정보를 그래프 포맷으로 출력합니다.
19, 20번 줄 : 스케줄링 동작을 기록하는 sched_wakeup, sched_switch 이벤트를 활성화합니다.
22, 23번 줄 : 인터럽트 핸들링의 시작과 종료 시점을 기록하는 irq_handler_entry, irq_handler_exit 이벤트를 활성화합니다.
33, 34번 줄 : options 하위 폴더에 추가 설정하는 파일로 func_stack_trace은 콜 스택을 볼 수 있는 옵션을 활성화합니다. 그렇게 하기 위해서는 15번 줄처럼 function으로 지정이 필요합니다.
sym-offset 활성화 기능은 콜 스택 출력 포맷지정 합니다. 함수를 호출할 때 주소의 오프셋을 출력합니다.
사이사이에 "sleep 1"이 있는 이유는 1초 동안 딜레이를 주는 것이고, ftrace설정 명령이 커널 내부 내에서 충분히 수행할 시간을 확보해 주기 위해서입니다.
set_ftrace_filter 파일에 트레이싱하고 싶은 함수를 지정할 수 있습니다. 그런데 리눅스 커널에 존재하는 모든 함수를 필터로 지정할 수는 없고, avalilable_filter_functions 파일에 포함된 함수만 지정할 수 있습니다.
라즈베리 파이에서 /sys/kernel/debug/trackingavalilable_filter_functions 파일에 없는 함수를 호출하면 락업이 될 수 있으므로 주의가 필요합니다.
책을 보다가 조금 더 궁금한 것이 있어 찾아보았습니다.
avalilable_filter_functions 파일에는 어떻게 추가되는 것인가? 그리고 개발자가 만든 함수도 포함할 수 있을까 궁금해서 GPT에 질문을 했습니다. ChatGPT의 도움받은 내용을 정리해 봤습니다.
커널이 빌드할 때 -pg(profiling) 옵션으로 컴파일된 함수들만 포함됩니다.
그렇다면 -pg 옵션은 무엇인가? GCC 컴파일러의 Profiling(프로파일링) 옵션으로, 함수 호출을 추적할 수 있도록 특정 코드를 삽입하는 역할을 합니다.
모든 함수를 다 포함되는가?
5. ftrace 메시지 분석
ftrace를 제대로 활용하려면 메시지를 읽고 해석하는 방법을 알아야 합니다. 여기서는 이해할 수 있는 범위 내에서 내용을 요약하고 자세한 내용은 책을 참조 하시면 됩니다.
1) ftrace 메시지 구성
똑같이 트레이싱할 수 없을 것 같아, 아래 사진을 책에서 가지고 왔습니다. 요약하자면,
- sched_switch 이벤트 로그이며 PID가 1436인 chromium-browse 프로세스가 실행 중입니다.
- [002]는 CPU 번호에서 실행 중이고, 컨텍스트 정보로 "d..."는 인터럽트만 비활성화한 상태입니다. 항목별 내용을 자세히 보면 아래와 같습니다. "."은 비활성화 의미입니다.
d : 해당 cpu 라인의 인터럽트 활성화 상태
n : 현재 프로세스가 선점 스케줄링될 수 있는 상태
h/s : h이면 인터럽트 컨텍스트, s면 softIRQ 컨텍스트
0~3 : 프로세스의 thread_info구조체의 preempt_count 필드값
- 타임스탬프는 9445.131875로 커널 로그에서 출력하는 타임스탬프와 같은 시간 정보입니다. sched_switch는 이벤트 이름입니다.
2) ftrace 이벤트 분석
ftrace 중에서 가장 많이 쓰는 2가지 이벤트를 분석합니다.
sched_switch, irq_handler_entry/irq_handler_exit
(1) irq_handler_entry와 irq_handler_exit 분석
이전 사용했던 ftrace_log.c 파일에서 내용을 가져왔습니다.
irq_handler_entry는 인터럽트 핸들러를 실행하기 직전에 출력
irq_handler_exit는 인터럽트 핸들러를 마무리한 직후 출력
위 로그 첫 번째 줄을 해석하면 "PID가 1679인 kworker/1:2 프로세스가 실행되는 도중 18번 인터럽트가 발생했습니다."
2번 줄은 18번 인터럽트가 실행을 마무리했다고 해석할 수 있습니다. 결론적으로 18번 "arch_timer" 인터럽트 핸들러를 1703.305762초에 실행하고 1703.305771초에 마무리했다는 의미가 됩니다.
(2) sched_switch 이벤트 분석
이전 글에 rpi_get_interrupt_info 디버깅에 사용했던 셀 스크립트의 내용 약간 수정해 보았습니다.
echo 1 > /sys/kernel/debug/tracing/events/sched/sched_wakeup/enable
echo 1 > /sys/kernel/debug/tracing/events/sched/sched_switch/enable
#echo 1 > /sys/kernel/debug/tracing/events/irq/irq_handler_entry/enable
#echo 1 > /sys/kernel/debug/tracing/events/irq/irq_handler_exit/enable
메시지 정보를 보면 prev 프로세스의 PID는 10이고 이름은 rcu_sched입니다. 우선순위는 120이고 프로세스 상태는 I입니다.
다음 실행될 프로세스로 PID는 113이며 이름은 systemd-journal입니다. 우선순위는 120입니다. 내용을 정리하면, rcu_sched 프로세스에서 systemd-journal 프로세스로 스케줄링하는 동작을 출력합니다.
3) ftrace 로그 추출 방법
이 내용이 위에 나와야 할 것 같지만, 책 순서를 따라가 보겠습니다.
이전 내용에서 본 셀 스크립트(get_ftrace.sh)와 동일합니다.
ftrace를 멈추고, 트레이스 파일을 복사한 후 현재 경로로 파일을 이동하는 스크립트 내용이며, 아래와 같이 권한부여 없이 실행할 수 있습니다.
/rpi_kernel_src# sh get_ftrace.sh
--- get_ftrace.sh 내용
#!/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
6. ftrace 분석의 안내자
ftrace 이벤트의 이름으로 커널 내부의 어떤 소스코드에서 이벤트를 출력하는지 알 수 있기 때문에 ftrace 메시지는 커널 코드 분석의 안내자라고 할 수 있습니다.
실제로 각 이벤트별 frace를 출력하는 함수 이름은 이벤트 이름 앞에 "trace_"가 붙습니다.
"trace_" + "ftace_event_name"
예) sched_switch -> trace_sched_switch
예) irq_handler_entry -> trace_irq_handler_entry
1) sched_switch 이벤트 확인
sched_switch 이벤트는 trace_sched_switch 함수가 실행될 때 프로세스가 스케줄링되는 정보를 출력합니다. irq_handler_entry 이벤트는 trace_irq_handler_entry함수가 호출될 때 인터럽트 핸들러가 실행되기 직전에 인터럽트 이름과 번호를 출력합니다.
코드 상에 어떻게 되어 있는지 확인하기 위해서 키워드로 먼저 검색해 봅니다. core.c 파일의 3512 줄에서 확인할 수 있다고 나옵니다.
/linux# egrep -nr trace_sched_switch *
static void __sched notrace __schedule(bool preempt) 안에 trace_sched_switch 함수가 있다는 것을 알 수 있습니다.
sched_switch 이벤트는 __schedule() 함수 3512번째 줄에서 프로세스가 스케줄링하는 동작을 출력한다는 사실을 알 수 있고 컨텍스트 스위칭은 __schedule() 함수에서 context_switch() 코드를 호출한다는 것을 알 수 있습니다.
2) irq_handler_entry 이벤트 확인
동일하게 trace_irq_handler_entry도 커널 소스에서 찾아봅니다. handle.c 파일 148줄에 있는 것을 알 수 있습니다.
irqreturn_t __handle_irq_event_percpu() 함수 안에 trace_irq_handler_entry와 trace_irq_handler_exit가 있는 것을 알 수 있습니다.
148번째 줄에서 인터럽트 핸들러를 호출하기 직전에 trace_irq_handler_entry() 함수를 호출해 irq_handler_entry 이벤트 처리 전 인터럽트 정보를 출력합니다.
150번째 줄에서 인터럽트 핸들러의 실행을 종료한 후 바로 trace_irq_handler_exit() 함수를 호출해 irq_handler_exit 이벤트로 인터럽트 핸들러 처리가 끝났음을 알려줍니다.
위에서 나온 내용 이벤트 외에도 커널을 구성하는 ftrace 이벤트가 있고, 이러한 여러 이벤트의 출력 메시지를 이해하면서 커널 코드를 분석한다면 더 빨리 익힐 수 있습니다.
7. 임베디드 디거버의 전설 TRACE32
TRACE32 사용방법과 내용은 저자도 책 범위를 넘어서므로 다루지 않는다고 적었습니다.
그러나 책의 저자가 사용방법에 대해 올린 동영상이 있어 링크를 걸어 놓았습니다.
참고하실 분은 아래링크를 참고하시면 됩니다.
https://www.youtube.com/watch?v=WBn4gD86rv8
감사합니다.
<참고 자료>
1. [도서] 디버깅을 통해 배우는 리눅스 커널의 구조와 원리, wikibook