개요
리눅스 커널에서 커널 내부의 Latency와 Function call을 확인하기 위하여 제공하는 Tracing Tool 이다.
사용법
우선 debugfs을 적절한 위치 (여기서는 default인 /sys/kernel/debug)에 마운트 시킨다.
mount -t debugfs nodev /sys/kernel/debug
또한 ftrace를 사용하려면, 커널에 다음과 같은 configuration을 주어야 한다. (menuconfig 혹은 kconfig 파일)
CONFIG_FUNCTION_TRACER CONFIG_FUNCTION_GRAPH_TRACER CONFIG_STACK_TRACER CONFIG_DYNAMIC_FTRACE
현재 사용할 수 있는 traces들의 종류를 보기 위해선, available_tracers에 어떤 내용이 있는지 확인하면 된다.
cat /sys/kernel/debug/tracing/available_tracers
또한 여기서 확인한 trace중에서 사용할 trace는 current_tracer에 적용시키면 된다.
echo function(한 예시) > current_tracer
마지막으로 사용된 tracer에 대해서 tracing된 결과는 trace 파일에 포함되게 된다.
cat /sys/kernel/debug/tracing/trace
또한 trace를 시작하고 멈추는 것은 tracing_on에 1 (트레이싱 함), 혹은 0 (트레이싱 안함)을 표시시켜서 조절하게 된다.
echo 1 > tracing_on
만약 trace 하고 싶은 함수가 따로 있을 경우,
cat available_filter_functions
로 가능한 함수를 확인한후
echo "*vfs*" > set_ftrace_filter echo "*write*" >> set_ftrace_filter
다음과 같이 regx를 이용하여 설정한 후 트레이싱하면 된다. 여기서 만약 초기화 하기 위해서는
echo " " > set_ftrace_filter
다음과 같이 설정하면 된다.
NOP tracing
echo nop > current_tracer
NOP은 인스트럭션중 아무 일도 하지 않는 인스트럭션을 말한다. 이 상황에서는 tracer는 아무 output도 만들지 않는다.
# tracer: nop # # entries-in-buffer/entries-written: 0/0 #P:4 # # _-----=> irqs-off # / _----=> need-resched # | / _---=> hardirq/softirq # || / _--=> preempt-depth # ||| / delay # TASK-PID CPU# |||| TIMESTAMP FUNCTION # | | | |||| | |
Function tracing
echo function > current_tracer
gcc의 -pg (gprof를 통해서 시스템 분석을 가능하게 하는 옵션임)옵션을 통해서 이루어 지는데, 모든 커널의 함수의 시작 부분에 mcount라는 함수를 호출하게 된다. 이 함수는 C ABI를 따르지 않기 때문에 어셈블리로 구현되게 된다. 커널에 이미 구현되에 있는 mcount라는 함수의 콜을 통해서 ftrace로그를 가지게 된다.
이때 만약 CONFIG_DYNAMIC_FTRACE를 enable하게 되면, 부팅 시간에는 모든 mcount들이 NOP으로 변환되게 되며, NOP을 처리하는 것은 거의 무시할 수 있는 system overhead를 가져오기 때문에, 시스템의 영향을 거의 미치지 않게 할 수 있다. 또한 CONFIG_DYNMAMIC_FTRACE를 통한다면, 어떤 함수에서 벤치를 돌리 것인지 설정할 수 있다.
# tracer: function
#
# TASK-PID CPU# TIMESTAMP FUNCTION
# | | | | |
bash-16939 [000] 6075.461561: mutex_unlock <-tracing_set_tracer
<idle>-0 [001] 6075.461561: _spin_unlock_irqrestore <-hrtimer_get_next_event
<idle>-0 [001] 6075.461562: rcu_needs_cpu <-tick_nohz_stop_sched_tick
bash-16939 [000] 6075.461563: inotify_inode_queue_event <-vfs_write
<idle>-0 [001] 6075.461563: mwait_idle <-cpu_idle
bash-16939 [000] 6075.461563: __fsnotify_parent <-vfs_write
Function graph
echo function_graph > current_tracer
이 옵션은 함수의 콜 관계를 C의 Annotation을 사용해서 표현한다. Duration에 표시되는 annotation인 + 와 !는 각각 10마이크로 세커드 보다 duration이 김을, 100마이크로 세컨드보다 duration이 김을 표시한다. Function graph로 표시하기 위해서 ftrace유틸은 함수의 종료 주소를 hijack하는데, 이는 cpu의 branch prediction을 방해하기 때문에 실제 실행시간보다 약간이지만 조금 길어질 수 있다.
# tracer: function_graph
#
# CPU DURATION FUNCTION CALLS
# | | | | | | |
1) 1.015 us | _spin_lock_irqsave();
1) 0.476 us | internal_add_timer();
1) 0.423 us | wake_up_idle_cpu();
1) 0.461 us | _spin_unlock_irqrestore();
1) 4.770 us | }
1) 5.725 us | }
1) 0.450 us | mutex_unlock();
1) + 24.243 us | }
1) 0.483 us | _spin_lock_irq();
1) 0.517 us | _spin_unlock_irq();
1) | prepare_to_wait() {
1) 0.468 us | _spin_lock_irqsave();
1) 0.502 us | _spin_unlock_irqrestore();
1) 2.411 us | }
1) 0.449 us | kthread_should_stop();
1) | schedule() {
trace_printk
printk를 통해서 대부분의 커널 디버깅을 진행 할 수는 있지만, interrupt context나 timer처럼 많은 로그가 남거나 stack overflow가 날 수 있는 문제의 환경에서 사용할 수 없다는 문제가 있다. 이때 ftrace의 ring buffer를 그대로 활용하여, trace에 로그가 남도록 하는 방법이 있는데, 이 방법이 바로 trace_printk이다. printk처럼 trace_printk를 써서 로그를 남기면 trace에 표출되게 된다.
function mode...
# TASK-PID CPU# TIMESTAMP FUNCTION
# | | | | |
<...>-10690 [003] 17279.332920: : read foo 10 out of bar ffff880013a5bef8
function_graph mode...
3) | do_one_initcall() {
3) | /* read foo 10 out of bar ffff88001191bef8 */
3) 4.221 us | }