printk 또는 dump_stack 을 사용하면서 불편하답니다.
저는 많이 안써봤습니다.
그래서 ftrace 를 많이 현업에서도 사용한다고 합니다.
주요 특징은
- 함수 호출 흐름을 소스코드 수정하지 않고도 보고싶다.
- 커널의 세부 실행 정보를 출력해줬으면 좋겠다.
- 1초에 수십번 호출해도 성능에 부담을 주지 않는다.
- 커널 로그도 함께 본다.
- 인터럽트, 스케쥴링, 커널 타이머 등의 커널 동작 상세히 추적
- 함수 필터를 지정하면 지정한 함수를 호출한 함수와 전체 콜 스택까지 출력
- 함수를 어느 프로세스가 실행하는지 알 수 있다.
- 함수가 실행된 시각 정보를 알 수 있다.
- ftrace 로그 활성화해도 시스템 동작에 부하를 거의 주지 않는다.
과연 그럴까 생각들정도로 강력한 것은 사실입니다.
How to do configuration
ftrace 에서 제공하는 nop, function, function_graph 트레이서를 쓰려면 관련코드가 커널이미지에 포함되어야 한다.
즉, 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다행히? 라즈베리파이는 모든 Configuration 이 활성화 되어있다고합니다.
Configuration 위치는 아래와 같다.
ftrace 설정파일을 어디서 확인할 수 있을까?
다음 경로에서 ftrace 드라이버 설정 폴더와 파일을 볼 수 있다.
/sys/kernel/debug/tracing
ftrace 설정
쉘스크립트를 통해 ftrace 설정을 해보도록합니다.
#!/bin/bash
echo 0 > /sys/kernel/debug/tracing/tracing_on
sleep 1
echo "tracing_off"
echo 0 > /sys/kernel/debug/tracing/events/enable
sleep 1
echo "events disabled"
echo secondary_start_kernel > /sys/kernel/debug/tracing/set_ftrace_filter
sleep 1
echo "set_ftrace_filter init"
echo function > /sys/kernel/debug/tracing/current_tracer
sleep 1
echo "function tracer enabled"
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
sleep 1
echo "event enabled"
echo rpi_get_interrupt_info > /sys/kernel/debug/tracing/set_ftrace_filter
sleep 1
echo "rpi_get_interrupt_infois enabled"
#echo bcm2835_mmc_irq > /sys/kernel/debug/tracing/set_ftrace_filter
#sleep 1
#echo "bcm2835_mmc_irq is enabled"
echo "set_ftrace_filter enabled"
echo 1 > /sys/kernel/debug/tracing/options/func_stack_trace
echo 1 > /sys/kernel/debug/tracing/options/sym-offset
echo "function stack trace enabled"
echo 1 > /sys/kernel/debug/tracing/tracing_on
echo "tracing_on"tracing_on : 트레이서 활성화/비활성화
tracer Option
- nop : 기본 트레이서 , ftrace event only output
- function : 함수 트레이서 , set_ftrace_filter 로 지정한 함수를 누가 호출하는지 출력
- function_graph : 함수 실행시간과 세부 호출 정보를 그래프 포맷으로 출력
ftrace event setting
ftrace 에서 커널을 구성하는 서브 시스템과 기능별로 세부 동작을 출력하는 기능을 지원
이를 이벤트라고 합니다.
쉘 스크립트 코드를 보면
echo 0 > /sys/kernel/debug/tracing/events/enable
# ftrace all event disable다음 코드는
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스케쥴링 동작을 기록하는 sched_wakeup / sched_switch 이벤트를 활성화
인터럽트 핸들링의 시작과 종료시점을 기록하는 irq_handler_entry / irq_handler_exit 이벤트를 활성화하는 코드
필터 설정 : set_ftrace_filter
set_ftrace_filter 파일에 트레이싱하고싶은 함수를 지정합니다.
현재 트레이서를 function_graph 와 function 으로 설정할 경우 작동하는 파일
이를 가르켜 함수 필터를 지정한다고 표현 ㅇ
리눅스 커널에 존재하는 모든 함수를 필터로 지정할 수는 없고, available_filter_functions 파일에 포함된 함수만 지정할 수 있다.
라즈베리파이에서 available_filter_function 파일에 없는 함수를 set_ftrace_filter 파일에 지정하면 락업되니 주의
available_filter_function 파일의 위치는 '/sys/kernel/debug/tracing/available_filter_functions' 입니다.
echo secondary_start_kernel > /sys/kernel/debug/tracing/set_ftrace_filtersecondary_start_kernel() 함수를 필터로 설정합니다.
이 함수는 부팅도중에 한번 호출 됩니다. 더미로 secondary_start_kernel 함수를 필터로 설정하는 것입니다.
현재 트레이서를 function_graph 와 function으로 설정할 경우 set_ftrace_filter 에 지정한 함수를 트레이싱합니다.
그런데 sencondary_start_kernel 을 실행하지않고 set_ftrace_filter 를 설정하지 않으면 어떻게 동작할까요?
set_ftrace_filter 파일에 필터로 함수를 지정하지 않으면 모든 커널 내부 의 함수를 트레이싱합니다.
즉, 시스템이 수많은 커널 함수를 트레이싱하다가 결국 락업 상태에 빠지게 되고, 이를 방지하려는 코드 입니다.
※ 라즈베리파이에서 set_ftrace_filter 파일에 필터로 함수를 지정하지 ㅇ낳으면 시스템이 100% 락업
ftrace 메시지는 어떻게 분석할까?
ftrace 를 제대로 활용하려면 먼저 ftrace 메시지를 읽고 해석하는 방법을 알아야한다.
ftrace 커널 동작을 세부 로그로 출력하기 때문에 임베디드 리북스 개발자에게 축복이라고 합니다.
ftrace 이벤트에서 가장많이 활용하는 sched_switch , sched_wakeup, irq_handler_entry, irq_handler_exit 이벤트를 해석하는 방법을 살펴봅니다.
pid 가 1723 인 cat 프로세스가 실행중이고 cpu 번호는 001 이다.
세부 컨텍스트 정보는 ftrace 메시지에서 항상 출력되면 4개의 알파벳으로 출력됩니다.
| d | n | h/s | 0~3 |
d : 인터럽트 비활성화 ==> 해당 CPU라인의 인터럽트를 비활성화한 상태입니다.
b : 선점 스케쥴링 요청 ==> 현재 프로세스가 선점 스케쥴링 될 수 있는 상태입니다.
h/s : 인터럽트 컨텍스트 ==> h 이면 인터럽트 컨텍스트 , s 이면 soft IRQ 컨텍스트
0~3 : preempt_count ==> 프로세스의 thread_info 구조체의 preempt_count 필드 값
위와 같이 세부항목이 활성화 되어있지 않으면 "." 을 출력합니다.
ftrace 로그 추출하는 방법?
#!/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각 이벤트를 출력하는 함수 목록
| ftrace event | Output function |
| sched_swich | trace_sched_switch |
| irq_handler_entry | trace_irq_handler_entry |
| irq_handler_exit | trace_irq_handler_exit |
sched_switch 이벤트는 trace_sched_switch()함수가 실행될 때 프로세스가 스케쥴링되는 정보를 출력