커널 함수 호출이나 스케줄링 이벤트가 실제로 어떤 순서로 일어나는지 확인하고 싶을 때, printk를 여기저기 넣고 재빌드하는 건 비효율적이다. ftrace(Function Tracer)는 커널을 재빌드하지 않고도 함수 호출과 이벤트를 추적할 수 있게 해주는 커널 내장 도구다. 이 글에서는 ftrace를 활성화하고 이벤트를 추적한 뒤, 남은 메시지를 분석하는 방법을 예제와 함께 정리한다.
ftrace 활성화
ftrace는 tracefs를 통해 제어한다. 최신 배포판은 보통 /sys/kernel/tracing에 마운트돼 있고, 구버전은 /sys/kernel/debug/tracing을 쓴다.
sudo su
echo 1 > /sys/kernel/tracing/tracing_onftrace 이벤트 선택
어떤 이벤트를 추적할지 선택해야 한다. available_events 파일에서 사용 가능한 이벤트 목록을 확인할 수 있다.
cat /sys/kernel/tracing/available_eventsftrace 이벤트 추적
원하는 이벤트를 켠다. 예를 들어 sched_switch 이벤트를 추적하려면 다음과 같이 실행한다.
echo 1 > /sys/kernel/tracing/events/sched/sched_switch/enableftrace 메시지 수집
추적을 시작하면 trace 파일에 메시지가 기록된다.
cat /sys/kernel/tracing/traceftrace 메시지 분석
ftrace 메시지는 커널 함수 호출과 이벤트 정보를 담고 있다. 다음은 sched_switch 이벤트 메시지의 예다.
<...>-1234 [001] d..2 12345.678910: sched_switch: prev_comm=old_process prev_pid=123 prev_prio=99 prev_state=R ==> next_comm=new_process next_pid=456 next_prio=120메시지를 분석할 때는 다음 필드를 본다.
prev_comm,prev_pid,prev_prio: 이전에 실행 중이던 프로세스 정보next_comm,next_pid,next_prio: 다음에 실행될 프로세스 정보prev_state: 이전 프로세스가 스위칭 시점에 가진 상태 (R=실행 가능, S=슬립 등)sched_switch: 이벤트 이름, 즉 컨텍스트 스위치가 발생했다는 뜻
ftrace 메시지 시각화
텍스트 로그만으로는 흐름을 파악하기 어려울 때, KernelShark 같은 GUI 도구로 trace 파일을 열면 CPU별 타임라인 형태로 시각화해서 볼 수 있다. trace-cmd로 기록한 결과를 KernelShark에서 바로 열 수 있다.
trace-cmd record -e sched_switch
kernelshark trace.dat마무리
ftrace는 재빌드 없이 커널 내부에서 발생하는 이벤트와 함수 호출을 그대로 들여다볼 수 있게 해주는 도구다. 사용이 끝나면 tracing_on을 0으로 내리고 켜둔 이벤트를 정리해서, 불필요한 오버헤드가 남지 않도록 한다.