ftrace는 리눅스 커널에 내장(!)되어 있는 트레이싱 유틸이다. 많은 배포판에서 이미 ftrace를 기본적을 활성화 시켜두니 간단하게라도 사용법을 알아두면 좋을것이다. 무엇보다 printk나 dump_stack은 커널 코드를 수정하고 다시 빌드하는 번거로운 과정이 필요하고 자칫하다 부팅이 안된다거나 1초에 100~1000번 빈도로 실행되는 함수를 잘못 후킹했다가 커널이 죽어버리는 위험이 있는데 ftrace는 효율적으로 (비교적) 안전하게 커널 내부에서 어떤 일이 일어나고 있는지 확인할 수 있다.
ftrace는 마땅한 man page도 없고 binary도 없다(!) 그래서 처음에 만든사람부터 찾아봤더니
Steven Rostedt가 개발하여 2008년 10월 9일 Linux 2.6에 들어왔다고 한다. 그리고 입문용으로 읽을 문서를 찾는것은 어렵지 않았다. ftrace 메인 개발자가 lwn에 올린 시리즈와 커널 문서다.
- Debugging the kernel using Ftrace - part 1
- Debugging the kernel using Ftrace - part 2
- /Documentation/trace/ftrace.txt
ftrace에 대한 기본적인 내용은 위 자료들을 읽으며 정리했다. 맨 처음글은 작성 시기가 시기인만큼 지금과 차이가 다소 있어 두번째 커널 문서와 실습을 병행했다.
ftrace를 쓰기 위해 ftrace를 입력하면 command not found만 볼 수 있다. 대충 $PATH에서만 찾아봐도 그런 파일은 없다는걸 볼 수 있다.
[8:13:04] dongho:~ find ${(s/:/)PATH} -name '*trace*' | paste - - -
/usr/bin/trace /usr/bin/trace-cmd /usr/bin/mtrace
/usr/bin/tracegen /usr/bin/tracepath /usr/bin/strace-log-merge
/usr/bin/xtrace /usr/bin/autrace /usr/bin/ltrace
/usr/bin/strace /usr/bin/lou_trace /usr/bin/tracegen-qt5
/usr/bin/cairo-trace대신 tracefs라는 pseudo file system을 활용한다. Linux 4.1 이전에는 "/sys/kernel/debug/tracing"에 있었지만 지금은 "/sys/kernel/tracing"으로 옮겨지고 이전 경로는 하위호환을 위해 남겨두었으니 참고하자. 이후 작업경로는 "/sys/kernel/tracing"라 가정하고 진행한다.
ftrace의 가장 유용한 tracer중 하나는 function tracer(a.k.a. ftrace)로 gcc의 -pg 옵션을 사용해 커널내 모든 함수들이 mcount()를 호출하게 한다. CONFIG_DYNAMIC_FTRACE가 설정되어 있으면 부팅시에 mcount가 NOP으로 치환되어 퍼포먼스 손실을 최소화 해주니 참고하면 좋겠다. 나머지 tracer들도 아래처럼 확인 가능하다.
[root@dongho-arch tracing]# cat available_tracers
timerlat osnoise hwlat blk mmiotrace function_graph wakeup_dl wakeup_rt wakeup function nopfunction tracer를 활성화 시키고 싶다면? echo로 파일에 직접 써주면 된다.
[root@dongho-arch tracing]# echo function > current_tracer
[root@dongho-arch tracing]# cat /current_tracer
function
[root@dongho-arch tracing]# cat trace
# tracer: function
#
# entries-in-buffer/entries-written: 0/0 #P:8
#
# _-----=> irqs-off
# / _----=> need-resched
# | / _---=> hardirq/softirq
# || / _--=> preempt-depth
# ||| / _-=> migrate-disable
# |||| / delay
# TASK-PID CPU# ||||| TIMESTAMP FUNCTION
# | | | ||||| | |
[root@dongho-arch tracing]#하지만 아직 tracing을 활성화 하지 않았기에 trace 로그를 봐도 아무것도 보이지 않는다. 직관적인 헤더 덕에 로그 포맷은 한눈에 이해할 수 있었다.
활성화는 마찬가지로 파일에 쓰면 된다. 그전에 대충 로그가 얼마나 쌓이는지 보자. 아무것도 안하고 크롬으로 글만 쓰고 있을뿐인데 초당 20만줄 가량 로그가 쌓이는것을 볼 수 있었다.
[root@dongho-arch tracing]# echo 1 > tracing_on && sleep 1 && echo 0 > tracing_on
[root@dongho-arch tracing]# wc trace
206769 1240590 18979785 trace
[root@dongho-arch tracing]# 로그는 아까처럼 cat으로 조회할 수 있다.
[root@dongho-arch tracing]# cat trace | head -20
# tracer: function
#
# entries-in-buffer/entries-written: 206750/233865 #P:8
#
# _-----=> irqs-off
# / _----=> need-resched
# | / _---=> hardirq/softirq
# || / _--=> preempt-depth
# ||| / _-=> migrate-disable
# |||| / delay
# TASK-PID CPU# ||||| TIMESTAMP FUNCTION
# | | | ||||| | |
bash-42148 [004] ..... 48544.665621: mutex_unlock <-rb_simple_write
bash-42148 [004] ..... 48544.665623: syscall_exit_work <-syscall_exit_to_user_mode
bash-42148 [004] ..... 48544.665624: __audit_syscall_exit <-syscall_exit_work
bash-42148 [004] ..... 48544.665624: path_put <-__audit_syscall_exit
bash-42148 [004] ..... 48544.665624: dput <-path_put
bash-42148 [004] ..... 48544.665625: mntput <-__audit_syscall_exit
bash-42148 [004] ..... 48544.665625: unroll_tree_refs <-__audit_syscall_exit
bash-42148 [004] ..... 48544.665625: kfree <-__audit_syscall_exit
[root@dongho-arch tracing]# 어떤 함수가 어떤 함수를 언제 어떤 cpu에선 무슨 맥락으로 호출했는지 볼 수 있다. 하지만? 함수의 흐름을 따라가기 다소 불편한 느낌이 있다. 이를 위해 함수의 진입과 반환을 같이 tracing하는 function graph tracer를 쓸 수 있다. 덕분에 호출된 함수의 depth를 알 수 있고, 나아가 사람 눈으로 보기 편하게 결과를 출력해준다.
[root@dongho-arch tracing]# echo function_graph > current_tracer
[root@dongho-arch tracing]# echo 1 > tracing_on && sleep 1 && echo 0 > tracing_on
[root@dongho-arch tracing]# cat trace | head -20
# tracer: function_graph
#
# CPU DURATION FUNCTION CALLS
# | | | | | | |
4) 1.185 us | mutex_unlock();
4) | syscall_exit_work() {
4) | __audit_syscall_exit() {
4) | path_put() {
4) 0.124 us | dput();
4) 0.128 us | mntput();
4) 0.615 us | }
4) 0.126 us | unroll_tree_refs();
4) 0.123 us | kfree();
4) 1.352 us | }
4) 1.612 us | }
4) 0.149 us | exit_to_user_mode_prepare();
4) | syscall_trace_enter.constprop.0() {
4) | __audit_syscall_entry() {
4) 0.128 us | ktime_get_coarse_real_ts64();
4) 0.397 us | }
[root@dongho-arch tracing]#function graph tracer는 함수의 return address를 치환해 작동하는데 이 과정에서 CPU의 branch prediction이 영향을 받아 function tracer보단 오버헤드가 큰 편이니 참고하자.
만약 DURATION이 10ms 이상이라면 +, 100ms 이상이라면 !가 표시된다.
커널 내부에서 어떤 일이 일어나고 있는지도 중요하지만 유저 스페이스와 커널을 동시에 봐야할 때도 있다. 이를 위해 trace_marker를 사용한다. 아래 예시를 보자. 유저 스페이스에서 trace_marker를 사용해 ftrace ring buffer에 로그를 찍었다.
[root@dongho-arch tracing]# echo 1 > tracing_on && echo hello world > trace_marker && echo 0 > tracing_on
[root@dongho-arch tracing]# cat trace | grep -C3 hello
bash-42148 [000] ..... 53092.064559: rw_verify_area <-vfs_write
bash-42148 [000] ..... 53092.064559: security_file_permission <-vfs_write
bash-42148 [000] ..... 53092.064559: bpf_lsm_file_permission <-security_file_permission
bash-42148 [000] ..... 53092.064559: tracing_mark_write: hello world
bash-42148 [000] ...1. 53092.064560: __check_object_size <-tracing_mark_write
bash-42148 [000] ...1. 53092.064560: check_stack_object <-__check_object_size
bash-42148 [000] ...1. 53092.064560: __virt_addr_valid <-__check_object_size
[root@dongho-arch tracing]#만약 function_graph 라면 아래 처럼 주석으로 보이게 된다.
[root@dongho-arch tracing]# cat trace | grep -C3 hello
0) 0.390 us | }
0) 0.615 us | }
5) 4.440 us | }
0) | /* hello world */
5) | fput() {
5) 0.130 us | fput_many();
0) | __check_object_size() {
[root@dongho-arch tracing]# 맨 왼쪽의 숫자는 CPU를 나타낸다. 특정 CPU만 tracing하기 위해 grep 이나 per_cpu 파일을 사용할 수 있다.
[root@dongho-arch tracing]# ls per_cpu/
cpu0 cpu108 cpu118 cpu13 cpu23 cpu33 cpu43 cpu53 cpu63 cpu73 cpu83 cpu93
cpu1 cpu109 cpu119 cpu14 cpu24 cpu34 cpu44 cpu54 cpu64 cpu74
...
cpu107 cpu117 cpu127 cpu22 cpu32 cpu42 cpu52 cpu62 cpu72 cpu82 cpu92
[root@dongho-arch tracing]# cat per_cpu/cpu5/trace | head -10
# tracer: function_graph
#
# CPU DURATION FUNCTION CALLS
# | | | | | | |
5) | syscall_exit_work() {
5) | __audit_syscall_exit() {
5) | path_put() {
5) 0.149 us | dput();
5) 0.127 us | mntput();
5) 0.810 us | }
[root@dongho-arch tracing]# 마지막으로 소개할 tracer는 stack tracer다. 커널 내에서 함수가 호출될때마다 그 함수가 사용중인 커널 스택 크기를 기록해서 어떤 부분이 가장 많이 커널 스택을 사용하고 있는지 파악할 수 있다.
[root@dongho-arch tracing]# echo 1 > /proc/sys/kernel/stack_tracer_enabled
[root@dongho-arch tracing]# cat stack_max_size
3672
[root@dongho-arch tracing]# cat stack_trace | head -20
Depth Size Location (36 entries)
----- ---- --------
0) 3672 48 __accumulate_pelt_segments+0x5/0xb0
1) 3624 72 __update_load_avg_se+0x310/0x390
2) 3552 80 update_load_avg+0x4db/0x600
3) 3472 32 put_prev_entity+0x108/0x1e0
4) 3440 56 pick_next_task_fair+0x257/0x400
5) 3384 176 __schedule+0x186/0x1530
6) 3208 16 preempt_schedule_notrace+0x40/0x60
7) 3192 88 preempt_schedule_notrace_thunk+0x16/0x18
8) 3104 56 ftrace_ops_list_func+0x166/0x180
9) 3048 136 ftrace_call+0x5/0x44
10) 2912 48 __rcu_read_lock+0x5/0x30
11) 2864 48 blk_mq_sched_insert_requests+0x6d/0xf0
12) 2816 96 blk_mq_flush_plug_list+0x10f/0x1d0
13) 2720 16 io_schedule+0x3d/0x70
14) 2704 136 rq_qos_wait+0xbb/0x140
15) 2568 64 wbt_wait+0xab/0x110
16) 2504 24 __rq_qos_throttle+0x23/0x40
17) 2480 128 blk_mq_submit_bio+0x167/0x650
[root@dongho-arch tracing]# 아래는 tracefs 각 컴포넌트의 역할을 정리한 것이다.
-
current_tracer: 현재 tracer를 설정하거나 조회할 때 사용
-
available_tracers: 현재 커널에 컴파일된 tracer 종류를 조회할 때 사용
-
tracing_on: ftrace ring buffer 활성화 여부를 설정하거나 조회할 때 사용. tracing overhead는 계속 남아있을 수 있음에 유의
-
trace: trace의 출력을 담고 있는 파일. 파일이 열려있는 동안에는 잠시 tracing이 중단됨
-
trace_pipe: 내용은 trace와 동일하나 pipe로 넘길 수 있음. 읽을 로그가 없으면 block 되고 한번 읽은 로그는 consume됨
-
options: trace option들을 설정할 수 있는 디렉토리. 0/1을 사용하며 여기서 설정된 값은 trace_options에서 한번에 조회가 가능하다.
-
buffer_size_kb: 각 CPU의 버퍼 크기를 kb 사이즈로 설정하거나 조회할 때 사용. per_cpu로 각각의 크기를 따로 지정 가능
-
set_ftrace_filter: dynamic ftrace가 설정되어 있다면 특정 함수만 tracing할 수 있다. 사용 가능한 함수들은 available_filter_functions에서 조회할 수 있다. 이 파일의 반대는 set_ftrace_notrace이다.
ftrace에 대한 나머지 더 자세한 내용은 다른 글에서 정리할 계획이다.
