커널이 제공하는 트레이스 이벤트는 Ubuntu 24.04 기준 1789개다. 어떤 이벤트를 봐야 할지 모르겠다고 events/enable에 1을 써버리면 1초 만에 수십만 건이 링 버퍼에서 밀려나 사라지고, 정작 보려던 이벤트도 그 안에 묻힌다. ftrace의 이벤트 트레이싱은 필터(filter)·트리거(trigger)·히스토그램(hist)을 커널 안에서 적용해, 사용자 공간으로 넘어오기 전에 기록 대상을 좁힐 수 있다. 이 글에서는 이 세 가지와 set_event_pid, instance 버퍼 분리까지 실제 출력과 함께 정리한다.
테스트 환경은 Ubuntu 24.04 / 커널 7.0.0-28-generic(6코어)이고, tracefs는 /sys/kernel/tracing에 마운트되어 있다. 아래 명령은 모두 root로 이 디렉터리에서 실행한다.
이벤트를 전부 켜면 벌어지는 일
$ cd /sys/kernel/tracing
$ dd if=/dev/zero of=/tmp/test.img bs=1M count=1500 conv=fsync & # 디스크 부하
$ echo 1 > events/enable # 이벤트 1789개 전부
$ echo > trace; echo 1 > tracing_on; sleep 1; echo 0 > tracing_on
$ echo 0 > events/enable
$ wc -l < trace
36241
$ grep -H ^overrun per_cpu/cpu*/stats
per_cpu/cpu0/stats:overrun: 0
per_cpu/cpu1/stats:overrun: 0
per_cpu/cpu2/stats:overrun: 0
per_cpu/cpu3/stats:overrun: 0
per_cpu/cpu4/stats:overrun: 0
per_cpu/cpu5/stats:overrun: 847388overrun은 버퍼가 가득 차서 덮어써진, 즉 영영 못 보게 된 이벤트 수다. 1초 동안 3만 6천 건을 건지는 대신 84만 건을 버린 셈이라, 무엇을 켤지 좁히는 작업이 먼저다.
이벤트가 가진 필드 확인하기
필터 표현식에는 각 이벤트가 기록하는 필드 이름을 그대로 쓴다. 어떤 필드가 있는지는 이벤트 디렉터리의 format 파일에 있다.
$ grep -E "^\s+field" events/block/block_rq_issue/format
field:unsigned short common_type; offset:0; size:2; signed:0;
field:unsigned char common_flags; offset:2; size:1; signed:0;
field:unsigned char common_preempt_count; offset:3; size:1; signed:0;
field:int common_pid; offset:4; size:4; signed:1;
field:dev_t dev; offset:8; size:4; signed:0;
field:sector_t sector; offset:16; size:8; signed:0;
field:unsigned int nr_sector; offset:24; size:4; signed:0;
field:unsigned int bytes; offset:28; size:4; signed:0;
field:unsigned short ioprio; offset:32; size:2; signed:0;
field:char rwbs[10]; offset:34; size:10; signed:0;
field:char comm[16]; offset:44; size:16; signed:0;
field:__data_loc char[] cmd; offset:60; size:4; signed:0;common_으로 시작하는 네 개는 모든 이벤트가 공통으로 갖고, 나머지가 이 이벤트 고유 필드다. 필터에서 쓸 수 있는 연산자는 다음과 같다.
| 연산자 | 대상 | 예 |
|---|---|---|
== | 숫자, 문자열 | comm == "dd" |
!= | 숫자, 문자열 | comm != "kworker/0:1H" |
< <= > >= | 숫자 | bytes >= 262144 |
& | 숫자(비트 검사) | flags & 0x40 |
~ | 문자열 glob | __filename_val ~ "*passwd*" |
&& || | 조건 결합 | comm == "dd" && bytes >= 262144 |
filter로 이벤트 좁히기
이벤트 디렉터리의 filter 파일에 표현식을 쓰면, 조건에 맞지 않는 이벤트는 버퍼에 기록되지 않는다. 시스템 전체에서 /etc/passwd를 여는 프로세스만 잡아보면 이렇다.
$ ls -R /usr/lib >/dev/null 2>&1 & # openat 노이즈 부하
$ echo 'syscalls:sys_enter_openat' > set_event
$ echo 0 > events/syscalls/sys_enter_openat/filter # 필터 없이
$ echo > trace; echo 1 > tracing_on
$ for i in 1 2 3; do getent passwd root >/dev/null; id -u nobody >/dev/null; sleep 0.2; done
$ echo 0 > tracing_on; grep -c "sys_openat(" trace
6855
$ echo '__filename_val ~ "*passwd*"' > events/syscalls/sys_enter_openat/filter
$ echo > trace; echo 1 > tracing_on
$ for i in 1 2 3; do getent passwd root >/dev/null; id -u nobody >/dev/null; sleep 0.2; done
$ echo 0 > tracing_on; grep -c "sys_openat(" trace
9
$ grep "sys_openat(" trace | head -4
getent-7379 [001] ..... 880.156642: sys_openat(dfd: 4294967196, filename: 138258862109472 "/etc/passwd", flags: O_RDONLY|O_CLOEXEC)
id-7380 [003] ..... 880.159581: sys_openat(dfd: 4294967196, filename: 123995588195104 "/etc/passwd", flags: O_RDONLY|O_CLOEXEC)
id-7380 [003] ..... 880.159591: sys_openat(dfd: 4294967196, filename: 123995588195104 "/etc/passwd", flags: O_RDONLY|O_CLOEXEC)
getent-7382 [003] ..... 880.930340: sys_openat(dfd: 4294967196, filename: 135933393171232 "/etc/passwd", flags: O_RDONLY|O_CLOEXEC)같은 1초 부하에서 6855건이 9건으로 줄었다. filename 필드는 유저 공간 포인터라 값 자체로는 쓸모가 없고, 커널이 문자열로 복사해둔 __filename_val에 glob을 걸어야 한다 — 이 필드가 없는 커널도 있으니 format으로 먼저 확인한다.
표현식이 틀리면 write가 EINVAL로 실패하는데, 이유는 error_log에 남는다.
$ echo 'filename_val ~ "*passwd*"' > events/syscalls/sys_enter_openat/filter
bash: line 27: echo: write error: Invalid argument
$ tail -4 error_log
[ 883.012292] event filter parse error: error: Field not found
Command: filename_val ~ "*passwd*"
^캐럿이 문제가 된 위치를 가리킨다. 필터를 걸었는데 이벤트가 하나도 안 잡힐 때 가장 먼저 볼 파일이다.
특정 프로세스만 추적하기
syscall 이벤트에는 comm 필드가 없어 필터로 프로세스를 고를 수 없다. 대신 set_event_pid에 PID를 쓴다.
$ bash -c 'while :; do cat /etc/hostname >/dev/null; sleep 0.05; done' & TARGET=$!
$ ls -R /usr/lib >/dev/null 2>&1 & # 추적 대상이 아닌 노이즈
$ echo $TARGET > set_event_pid
$ echo 'syscalls:sys_enter_openat' > set_event
$ cat options/event-fork
0
$ grep -c 'sys_openat(' trace # 1초 추적 결과
0
$ echo 1 > options/event-fork # 자식까지 따라가기
$ grep -c 'sys_openat(' trace
252
$ grep 'sys_openat(' trace | awk '{print $1}' | sort | uniq -c | sort -rn | head -3
16 sleep-7663
16 sleep-7661
16 sleep-7659셸 자신은 openat을 거의 하지 않고 실제 작업은 cat/sleep 자식이 하므로, options/event-fork를 켜지 않으면 0건이 나온다. 이 옵션을 켜면 이후 fork되는 자식 PID가 set_event_pid에 자동으로 추가된다.
조건이 맞을 때만 동작하는 트리거
필터가 "기록할지"를 정한다면, 트리거는 "이벤트가 발생했을 때 무엇을 할지"를 정한다. 이벤트 디렉터리의 trigger 파일에 쓴다.
| 트리거 | 동작 |
|---|---|
traceon / traceoff | 트레이싱 전체를 켜거나 끈다 |
snapshot | 그 시점의 버퍼를 스냅샷 버퍼로 복사한다 |
stacktrace | 해당 지점의 커널 콜스택을 기록한다 |
enable_event / disable_event | 다른 이벤트를 켜거나 끈다 |
hist | 필드 값을 키로 히스토그램을 누적한다 |
모든 트리거는 if <필터식>을 붙여 조건을 걸 수 있고, :1처럼 발동 횟수도 제한할 수 있다. 먼저 /etc/shadow가 열리는 순간 버퍼를 얼려 직전 상황을 보존해 본다.
$ echo 'syscalls:sys_enter_openat sched:sched_process_exec' > set_event
$ echo 'traceoff if __filename_val ~ "*/shadow"' > events/syscalls/sys_enter_openat/trigger
$ cat events/syscalls/sys_enter_openat/trigger
traceoff:unlimited if __filename_val ~ "*/shadow"
$ echo 1 > tracing_on
$ getent shadow root >/dev/null # 트리거 조건 발생
$ cat tracing_on
0
$ tail -5 trace
getent-7674 [005] ..... 905.720775: sys_openat(dfd: 4294967196, filename: 133921041982351 "/etc/ld.so.cache", flags: O_RDONLY|O_CLOEXEC)
getent-7674 [005] ..... 905.720789: sys_openat(dfd: 4294967196, filename: 133921041752384 "/lib/x86_64-linux-gnu/libc.so.6", flags: O_RDONLY|O_CLOEXEC)
getent-7674 [005] ..... 905.720956: sys_openat(dfd: 4294967196, filename: 133921039534256 "/usr/lib/locale/locale-archive", flags: O_RDONLY|O_CLOEXEC)
getent-7674 [005] ..... 905.721005: sys_openat(dfd: 4294967196, filename: 133921039510930 "/etc/nsswitch.conf", flags: O_RDONLY|O_CLOEXEC)
getent-7674 [005] ..... 905.721029: sys_openat(dfd: 4294967196, filename: 133921039512391 "/etc/shadow", flags: O_RDONLY|O_CLOEXEC)조건이 걸린 이벤트가 버퍼의 마지막 줄로 남고 그 앞이 통째로 보존되므로, "문제가 터지기 직전에 무슨 일이 있었는지"를 그대로 읽을 수 있다.
stacktrace는 조건을 만족한 이벤트의 커널 콜스택을 남긴다. 1MB 이상 크기로 발행된 블록 요청의 경로를 한 번만 찍어보면 이렇다.
$ echo 'block:block_rq_issue' > set_event
$ echo 'stacktrace:1 if bytes >= 1048576' > events/block/block_rq_issue/trigger
$ dd if=/dev/zero of=/tmp/test.img bs=4M count=30 conv=fsync
$ sed -n "/<stack trace>/,+10p" trace
dd-7844 [001] ..... 930.130344: <stack trace>
=> do_trace_event_raw_event_block_rq
=> trace_event_raw_event_block_rq
=> blk_mq_start_request
=> scsi_queue_rq
=> blk_mq_dispatch_rq_list
=> __blk_mq_do_dispatch_sched
=> __blk_mq_sched_dispatch_requests
=> blk_mq_sched_dispatch_requests
=> blk_mq_run_hw_queue
=> blk_mq_dispatch_list스택 상단 두 프레임은 트레이스 이벤트 자신이고, 그 아래부터가 실제 I/O 제출 경로다.
hist 트리거로 커널 안에서 집계하기
이벤트를 전부 사용자 공간으로 내보내 awk로 합산하는 대신, hist 트리거를 쓰면 커널이 해시 테이블에 직접 누적한다. 프로세스별 블록 쓰기량 집계는 한 줄이면 된다.
$ echo 'hist:keys=comm:vals=bytes:sort=bytes.descending' > events/block/block_rq_issue/trigger
$ echo 'block:block_rq_issue' > set_event
$ echo 1 > tracing_on # dd 2개 + find|md5sum 부하를 4초간
$ cat events/block/block_rq_issue/hist
# event histogram
#
# trigger info: hist:keys=comm:vals=hitcount,bytes:sort=bytes.descending:size=2048 [active]
#
{ comm: dd } hitcount: 1588 bytes: 345829376
{ comm: kworker/1:2H } hitcount: 25 bytes: 25387008
{ comm: kworker/2:2H } hitcount: 57 bytes: 21254144
{ comm: kworker/3:0H } hitcount: 85 bytes: 12963840
{ comm: kworker/5:1H } hitcount: 13 bytes: 8437760
{ comm: md5sum } hitcount: 4 bytes: 172032
{ comm: kworker/u24:0 } hitcount: 2 bytes: 151552
{ comm: jbd2/sda2-8 } hitcount: 1 bytes: 90112
{ comm: kworker/u24:5 } hitcount: 2 bytes: 16
{ comm: kworker/0:1H } hitcount: 1 bytes: 0
Totals:
Hits: 1778
Entries: 10
Dropped: 0버퍼에는 아무것도 안 쌓이고 집계 결과만 hist 파일에 남는다. kworker/*H가 상위에 보이는 것은 페이지 캐시에 쌓인 쓰기를 커널 워커가 대신 발행하기 때문이다.
키는 콤마로 여러 개를 줄 수 있고, 필드 뒤에 .log2를 붙이면 값을 2의 거듭제곱 구간으로 묶는다.
$ echo 'hist:keys=comm,bytes.log2:sort=hitcount.descending' > events/block/block_rq_issue/trigger
$ head -12 events/block/block_rq_issue/hist
# event histogram
#
# trigger info: hist:keys=comm,bytes.log2:vals=hitcount:sort=hitcount.descending:size=2048 [active]
#
{ comm: dd , bytes: ~ 2^12 } hitcount: 6000
{ comm: dd , bytes: ~ 2^22 } hitcount: 48
{ comm: kworker/u24:0 , bytes: ~ 2^3 } hitcount: 2
{ comm: kworker/3:0H , bytes: ~ 2^22 } hitcount: 2
{ comm: kworker/0:1H , bytes: ~ 2^0 } hitcount: 1
{ comm: kworker/1:2H , bytes: ~ 2^0 } hitcount: 1
{ comm: kworker/1:2H , bytes: ~ 2^12 } hitcount: 1같은 dd라도 oflag=direct로 4KB씩 쓴 6000건(2^12)과 페이지 캐시를 거쳐 4MB로 병합된 48건(2^22)이 분리돼 보인다.
synthetic 이벤트로 I/O 지연시간 재기
두 이벤트의 시간 차를 커널 안에서 계산하려면 synthetic 이벤트를 하나 만들고, 시작 이벤트에 타임스탬프를 저장했다가 끝 이벤트에서 onmatch로 이어 붙인다. 블록 요청의 발행→완료 지연시간을 히스토그램으로 뽑는 전체 절차는 네 줄이다.
$ echo 'io_lat u64 lat; u32 nr_sector' >> synthetic_events
$ echo 'hist:keys=sector:ts0=common_timestamp.usecs' > events/block/block_rq_issue/trigger
$ echo 'hist:keys=sector:lat=common_timestamp.usecs-$ts0:onmatch(block.block_rq_issue).trace(io_lat,$lat,nr_sector)' > events/block/block_rq_complete/trigger
$ echo 'hist:keys=lat.log2:sort=lat' > events/synthetic/io_lat/trigger
$ dd if=/dev/zero of=/tmp/test.img bs=64k count=1500 oflag=direct
$ cat events/synthetic/io_lat/hist
# event histogram
#
# trigger info: hist:keys=lat.log2:vals=hitcount:sort=lat.log2:size=2048 [active]
#
{ lat: ~ 2^0 } hitcount: 1212
{ lat: ~ 2^6 } hitcount: 1
{ lat: ~ 2^7 } hitcount: 2
{ lat: ~ 2^8 } hitcount: 209
{ lat: ~ 2^9 } hitcount: 14
{ lat: ~ 2^10 } hitcount: 21
{ lat: ~ 2^11 } hitcount: 8
{ lat: ~ 2^12 } hitcount: 17
{ lat: ~ 2^13 } hitcount: 6
{ lat: ~ 2^15 } hitcount: 3
{ lat: ~ 2^16 } hitcount: 7
Totals:
Hits: 1500
Entries: 11
Dropped: 0단위는 마이크로초라 대부분(1212건)은 2µs 미만에 끝났지만, 2^16 구간 즉 65ms를 넘긴 요청도 7건 있다. 이런 꼬리는 평균값만 보면 절대 안 보인다.
instance로 버퍼 분리하기
최상위 버퍼는 하나뿐이라 다른 도구나 다른 작업과 설정이 충돌한다. instances/ 아래에 디렉터리를 만들면 이벤트 설정과 버퍼를 통째로 따로 갖는 트레이싱 공간이 생긴다.
$ echo 'sched:sched_process_exec' > set_event # 최상위 버퍼는 다른 용도로 사용 중
$ mkdir instances/diskwatch
$ echo 'comm == "dd"' > instances/diskwatch/events/block/block_rq_issue/filter
$ echo 'block:block_rq_issue' > instances/diskwatch/set_event
$ echo 1 > instances/diskwatch/tracing_on
$ dd if=/dev/zero of=/tmp/test.img bs=64k count=2000 oflag=direct
$ grep -c block_rq_issue instances/diskwatch/trace
2000
$ grep -c block_rq_issue trace
0
$ grep -c sched_process_exec trace
2
$ rmdir instances/diskwatch # 버퍼까지 함께 해제instance 쪽에만 2000건이 쌓이고 최상위 버퍼는 원래 보던 sched_process_exec만 유지한다. 버퍼 크기(buffer_size_kb)나 트레이서도 instance마다 따로 잡을 수 있다.
주의사항
- 필터는 이벤트 발생 자체를 막지 못한다. 이벤트 핸들러가 실행되고 인자를 채운 뒤에 기록 여부만 결정하므로, 켜 둔 이벤트 수 자체를 줄이는 것이 오버헤드를 줄이는 유일한 방법이다.
- 트리거와 필터는 이벤트를 꺼도 남는다. 지우려면
!를 앞에 붙여 등록할 때 쓴 표현식 그대로 다시 써야 한다(예:echo '!hist:keys=comm:vals=bytes:sort=bytes.descending' > .../trigger). hist해시 테이블은 기본 2048 엔트리다. 키 종류가 그보다 많으면 새 키가 버려지므로, 결과를 믿기 전에Dropped값을 확인하고size=로 늘린다.trace_pipe는 읽는 순간 버퍼에서 이벤트를 소비한다. 같은 내용을 두 번 봐야 하면trace를 쓴다.- 설정은
tracing_on을 0으로 둔 상태에서 하고, 마지막에echo > trace로 버퍼를 비운 뒤 켠다. 설정 중에 들어온 이벤트가 결과에 섞이지 않는다.
테이블이 넘칠 때의 동작은 size=를 작게 줘서 바로 확인할 수 있다.
$ echo 'hist:keys=sector:size=128' > events/block/block_rq_issue/trigger
$ dd if=/dev/zero of=/tmp/test.img bs=64k count=800 oflag=direct
$ tail -4 events/block/block_rq_issue/hist
Totals:
Hits: 128
Entries: 128
Dropped: 672섹터 번호처럼 키가 계속 새로 생기는 필드는 800건 중 672건이 통째로 버려졌다. 이런 필드는 키가 아니라 vals이나 .log2 구간으로 쓰는 게 맞다.
마무리
이벤트 트레이싱의 실전 요령은 결국 "커널 안에서 최대한 줄여서 내보내기"다. 켤 이벤트를 고르고(set_event), 필드로 거르고(filter), 조건이 맞는 순간에만 반응하고(trigger), 가능하면 집계까지 커널에 맡긴다(hist). 여기까지 하면 별도 도구 설치 없이 tracefs만으로 "누가 이 파일을 여는가", "어느 프로세스가 디스크를 쓰는가", "I/O 지연시간 분포가 어떤가" 같은 질문에 답할 수 있다.