특정 syscall이나 함수 하나가 얼마나 걸리는지, 그 안에서 어떤 하위 함수가 시간을 잡아먹는지 알고 싶을 때 perf는 샘플링 기반이라 호출 빈도가 낮은 함수는 놓치기 쉽다. ftrace의 function_graph 트레이서는 지정한 함수의 호출 트리 전체를 들여쓰기와 함께 마이크로초 단위 소요시간으로 보여줘, 커널 재빌드 없이 “이 함수 안에서 정확히 뭐가 느린지”를 바로 확인할 수 있다. 이 글에서는 vfs_write() 하나를 대상으로 이 트레이서를 실전에서 쓰는 법을 정리한다.
function_graph 트레이서 켜기
$ cd /sys/kernel/tracing
$ echo 0 > tracing_on
$ echo function_graph > current_tracer
$ echo vfs_write > set_graph_function # 이 함수 호출부터 추적
$ echo > trace # 버퍼 비우기
$ echo 1 > tracing_on
$ echo "hello world" > /tmp/target.txt # 추적 대상 트리거
$ echo 0 > tracing_on
$ cat traceset_graph_function에 함수 이름을 지정하면 그 함수가 호출된 시점부터 리턴할 때까지의 전체 콜스택만 추적한다. 지정하지 않으면 커널의 모든 함수 호출을 다 기록해 버퍼가 순식간에 찬다.
추적할 함수 이름 찾기
정확한 함수명을 모르면 available_filter_functions에서 검색해서 찾는다. 이 목록에 없는 함수는 set_graph_function/set_ftrace_filter 대상이 될 수 없다.
$ cat available_filter_functions | grep vfs_ | head -6
vfs_fadvise
vfs_fallocate
vfs_truncate
vfs_fchmod
vfs_fchown
vfs_open
$ cat available_filter_functions | grep -c vfs
111vfs_로 시작하는 함수만 111개다. VFS 계층에서 어떤 함수를 추적할지 감이 안 잡힐 때 이렇게 먼저 후보를 좁혀두면 된다.
결과 읽기
1) | vfs_write() {
1) | rw_verify_area() {
1) | security_file_permission() {
1) | apparmor_file_permission() {
1) | aa_file_perm() {
1) 0.191 us | __rcu_read_lock();
1) 0.190 us | __rcu_read_unlock();
1) 1.282 us | }
1) 1.834 us | }
1) 2.254 us | }
1) 2.706 us | }
...
1) 0.260 us | __fsnotify_parent();
1) + 25.599 us | }| 표기 | 의미 |
|---|---|
| 1열 숫자 | 이 함수가 실행된 CPU 번호 |
| 들여쓰기 | 호출 깊이. 중첩될수록 오른쪽으로 밀림 |
| 숫자 us | 그 함수(와 하위 호출 전체)가 소요한 시간 |
+ 접두사 | 10us 초과(기본 임계값). !는 100us 초과 — 눈에 띄게 느린 구간을 빠르게 찾는 표시 |
이 호출에서 vfs_write() 전체는 25.599us 걸렸다. 콜스택 그대로 보여주므로 어느 하위 함수가 큰 비중을 차지하는지 코드를 뒤지지 않고도 바로 보인다.
와일드카드로 함수 패밀리 통째로 추적
정확한 함수 하나가 아니라 특정 서브시스템 전체가 궁금할 때는 set_graph_function에 와일드카드를 쓸 수 있다. fsync()가 실제로 어느 함수에서 시작하는지 몰라서 ext4_*sync* 패턴으로 걸어봤다.
$ echo 'ext4_*sync*' > set_graph_function
$ echo > trace; echo 1 > tracing_on
$ python3 -c "
import os
f = open('/tmp/t.txt', 'wb')
f.write(b'hi'); f.flush(); os.fsync(f.fileno())
"
$ echo 0 > tracing_on; cat trace | grep -v '^#' | head -6
2) | ext4_sync_file() {
2) | file_write_and_wait_range() {
2) | filemap_writeback() {
2) 0.351 us | inode_to_bdi();
2) | wbc_attach_fdatawrite_inode() {
2) 0.241 us | _raw_spin_lock();패턴에 매칭된 ext4_sync_file()이 진입점으로 잡혔고, 그 아래 콜스택은 이름에 ext4가 없는 file_write_and_wait_range·filemap_writeback 같은 범용 VFS 함수까지 전부 포함된다. 와일드카드는 “어디서부터 추적을 시작할지”만 고르는 것이지, 그 안에서 호출되는 하위 함수까지 이름으로 걸러주지는 않는다.
tracing_thresh로 노이즈 줄이기
실전에서는 수백~수천 줄짜리 전체 콜스택보다 “느린 구간만” 보고 싶을 때가 많다. tracing_thresh(ns 단위, 위 예시는 5us)를 걸면 이 이하로 걸린 함수는 아예 기록하지 않는다.
$ echo 5 > tracing_thresh
$ echo > trace; echo 1 > tracing_on
$ echo "hello world 2" > /tmp/target.txt
$ echo 0 > tracing_on; cat trace | grep -v '^#'
1) + 85.011 us | } /* vfs_write */
1) + 33.593 us | } /* ext4_da_write_begin */
1) + 27.732 us | } /* balance_dirty_pages_ratelimited */
1) + 22.222 us | } /* ext4_block_write_begin */전체 96줄로 줄었고, 이번 호출에서는 85.011us 중 ext4_da_write_begin(33.593us)와 balance_dirty_pages_ratelimited(27.732us)가 대부분을 차지한다는 게 바로 드러난다. dirty page 처리 관련 로직임을 감안하면 writeback 튜닝과도 직접 연결되는 지점이다.
max_graph_depth로 깊이 제한
tracing_thresh가 “느린 것만” 걸러낸다면, max_graph_depth는 아예 몇 단계까지만 파고들지를 정한다. 최상위 함수와 그 직계 호출만 보고 싶을 때 유용하다.
$ echo vfs_write > set_graph_function
$ echo 2 > max_graph_depth # 2단계까지만
$ echo > trace; echo 1 > tracing_on
$ echo "depth test" > /tmp/target.txt
$ echo 0 > tracing_on; cat trace | grep -v '^#'
1) | vfs_write() {
1) 1.503 us | rw_verify_area();
1) + 14.567 us | ext4_file_write_iter();
1) 6.933 us | __fsnotify_parent();
1) + 24.547 us | }ext4_file_write_iter()가 앞서 본 예시처럼 ext4_da_write_begin 등으로 계속 파고들지 않고 총 소요시간(14.567us)만 한 줄로 요약됐다. 깊이 제한 덕에 트레이스가 56줄로 끝나, 전체 콜스택(수천 줄)을 다 받아보지 않고도 1단계 자식 함수들의 비중부터 빠르게 훑을 수 있다.
더 가벼운 대안 — plain function 트레이서
소요시간이 아니라 “이 함수가 언제, 누구에게 호출됐는지”만 필요하다면 function_graph 대신 더 가벼운 function 트레이서로도 충분하다.
$ echo function > current_tracer
$ echo 'vfs_write ext4_file_write_iter' > set_ftrace_filter
$ echo > trace; echo 1 > tracing_on
$ echo "hello" > /tmp/target.txt
$ echo 0 > tracing_on; cat trace | grep -v '^#'
sudo-27989 [001] vfs_write <-ksys_write
rs:main Q:Reg-1112 [004] vfs_write <-ksys_write
rs:main Q:Reg-1112 [004] ext4_file_write_iter <-vfs_write
bash-27905 [005] vfs_write <-ksys_write| 트레이서 | 보여주는 것 | 오버헤드 |
|---|---|---|
function | 함수 진입 시각 + 호출자(<-caller) 한 줄 | 낮음(진입 훅만) |
function_graph | 진입+리턴 전체, 들여쓰기로 중첩 구조, 소요시간까지 | 더 높음(진입/리턴 양쪽 훅) |
같은 트리거로 function_graph는 1981줄이 나왔지만 function은 24줄뿐이었다. 시스템 전체에서 이 함수를 누가 얼마나 자주 호출하는지 빈도만 보고 싶을 땐 function으로 가볍게 훑고, 특정 호출 하나의 소요시간까지 뜯어봐야 할 때만 function_graph로 좁히는 순서가 오버헤드를 최소화하는 방법이다.
주의사항
| 항목 | 내용 |
|---|---|
| 추적 후 반드시 원상복구 | current_tracer를 nop으로, set_graph_function·set_ftrace_filter·tracing_thresh·max_graph_depth를 전부 비우거나 0으로 되돌리지 않으면 다음에 ftrace를 쓰는 사람이 예상치 못한 필터에 걸린다 |
| function_graph도 공짜는 아니다 | function tracer보다 진입/리턴 양쪽을 다 후킹해 오버헤드가 더 크다. 프로덕션에서는 짧게, 필요한 함수만 지정해서 쓸 것 |
| 재귀·인라인 함수는 안 보일 수 있다 | 컴파일러가 인라인 처리한 함수는 애초에 별도 심볼이 없어 set_graph_function 대상이 될 수 없다 |
| root 권한 필요 | tracefs 제어 파일 전부 sudo 없이 쓰기 불가능 |
마무리
“이 함수가 왜 느린가”를 printk 재빌드 없이 알고 싶다면 set_graph_function으로 대상을 좁히고 tracing_thresh로 노이즈를 걷어내는 조합이 가장 실전적이다. 이벤트 기반 추적(sched_switch 등)이 “언제 무슨 일이 있었는지”를 본다면, function_graph는 “그 함수가 정확히 얼마나 걸렸는지”를 코드 수준으로 보여준다는 차이가 있다.