개요

리눅스 커널에서 커널 내부의 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    |    }

참고

  1. https://lwn.net/Articles/365835/
  2. https://medium.com/@hyoje420/linux-ftrace-%EC%82%AC%EC%9A%A9%EB%B2%95-31b4dc7ac93c