eBPF 를 활용한 Fio application의 Capture

서준표·2025년 10월 25일

대학원 수업을 듣던 중 흥미로웠던 과제가 있어서 슬쩍 짚고 넘어가보려고 합니다.

extended Berkely Packet Filter (eBPF) 라는 다이나믹 캡처 툴을 활용해서 fio 응용의 계층별 context를 단일 흐름으로 파악하고 cache hit / miss 에 대한 관찰 및 병목 지점에 대한 정량적 측정을 해보았습니다.

결과적으로 아래의 영상과 같이 풍성한 정보를 캡처 할 수 있었고 보다 더 시스템 프로그래밍에 친숙해줄 수 있는 기회가 된 것 같습니다.

목표는 응용(fio)의 read()가 Page Cache miss일 때 지연시간과 NVMe request 크기를 계층별(SYSCALL→VFS→FS→BLOCK→DEVICE)로 측정하고, I/O Flow를 한 눈에 보기 쉽게 표현하는 것입니다.

1) 관찰 지점 선정과 순서도

선정 방법

uftrace로 fio가 밟는 커널 경로를 먼저 훑어 진입 시드 함수를 골랐습니다.
- __x64_sys_read에 바인딩되어 read path를 타는 것을 확인했고ftrace/eBPF 훅의 시발점으로 채택했습니다.
ftrace로 계층별 타임라인을 얻었습니다.
- VFS: vfs_read(_ret)
- FS: ext4_file_read_iter(_ret) / generic_file_read_iter(_ret)
- BLOCK: block_bio_queue, block_rq_insert/issue/complete
- DEVICE: nvme_sq, nvme_complete_rq
Miss 시 FS→BLOCK→DEVICE까지 내려가므로, 위 이벤트 조합으로 Cache Hit/Miss, Queue/Service/Device Latency까지 복원 가능하다고 판단했습니다.

관찰 순서도

Syscall
 └─ sys_enter_read / sys_exit_read
    │
    ▼
VFS
 └─ vfs_read / vfs_read_ret
    │
    ▼
File System (ext4)
 └─ ext4_file_read_iter / _ret
    │
    ▼
Block layer (blk-mq)
 └─ block_bio_queue → block_rq_insert → block_rq_issue → block_rq_complete
    │
    ▼
Device (NVMe)
 └─ nvme_sq → nvme_complete_rq

2) I/O Flow를 하나로 묶는 법

같은 Context 안에서

인덱스 체인: thread → syscall_idx → vfs_idx → fs_idx
각 레벨 enter/ret에 타임스탬프(ns) 기록하여 해당 호출의 Flow_*_Lat 계산했습니다.
누적 바이트를 계산할때는 인접한 계층의 callback을 활용해서 Adjacent-only 방식의 전파를 차용했습니다.
- BLOCK → FS → VFS → SYSCALL 방향으로만 상향 누적
- VFS_ret에서 FS 누적이 0이고 사용자 ret>0이면 Page Cache HIT 보정으로 VFS bytes에 더했습니다.

Context가 바뀌는 커널 워커, NVMe 드라이버 구간

BLOCK: (dev, sector, nr_sectors)를 키로 blkkey2flow에 상위 flow를 바인딩함.
NVMe: request* 포인터를 키로 req2flow/req2submit_ns 매핑 → nvme_complete_rq에서 Device Latency 계산했습니다.

index counting

vfs_idx, fs_idx를 각각 증가시켜 동일 함수 다회 호출도 분리 추적했습니다

fio만 필터링

sys_enter_*에서 comm=="fio"인 TGID 화이트리스트
모든 훅에서 allowed_tgid 확인 + 후처리에서 Flow_SYSCALL>0 조건으로 flow source 보존했습니다.

3) eBPF 프로그램 구성

핵심 맵

Flow 인덱스: key_thread2syscall_idx, key_syscall2vfs_idx, key_vfs2fs_idx
타임스탬프: key_syscall2enter_ns, key_vfs2enter_ns, key_fs2enter_ns
누적 바이트(상향 전파): key_fs2bytes → key_vfs2bytes(+HIT 보정) → key_syscall2bytes
상태: key_*2cache_state(UNK/HIT/MISS/DIRECT), key_*2isdirect
Block/NVMe 키:
- blkkey2flow, blkkey2insert_ns, blkkey2issue_ns
- req2flow, req2submit_ns

이벤트 스키마

공통 메타: Time, Hier, Stage, TGID/TID/Comm/CPU
Flow 식별자: Flow_SYSCALL, Flow_VFS, Flow_FS
바이트/주소: Bytes, LBA/NR, SectorSz, ReqPtr, DevDisk
지연: Flow_SYSCALL_Lat, Flow_VFS_Lat, Flow_FS_Lat, Queue_Lat, Service_Lat, Device_Lat
상태: Cache_State(HIT/MISS/DIRECT/UNK), IsDirect

4) 검증: fio로 블록 크기 별 관찰

공통 실행 조건

--direct=0 --ioengine=sync --iodepth=1 --rw=randread

(A) bs=4 KiB

총 행: 75,963
read() 호출: 12,286
Cache(sys_exit_read 기준): HIT 0.1% / MISS 12.2% / DIRECT 0% / UNK 87.6%
Queue p50 8.3 µs / Service p50 97 µs
Syscall p50 38 µs
→ 짧고 빈번한 I/O를 확인할 수 있었습니다. 블록은 빠르나 상위 계층(스케줄링/캐시)에서 롱테일 분포임을 관찰할 수 있었습니다.

(B) bs=128 MiB

총 행: 12,842
read() 호출: 1,442
Cache: HIT 2.1% / MISS 5.3% / DIRECT 0% / UNK 92.5%
Queue p50 17.4 µs / Service p50 821 µs
Syscall p50 8.5 µs
→ 소수의 대형 I/O 중심이었습니다. 디바이스 서비스 시간이 지연 지배를 하는 점을 확인할 수 있었습니다.

5) 타임라인 복원 예시

ASCII 타임라인:

read()
│
├─ sys_enter_read (0 μs)
├─ vfs_read (~4.8 μs)
├─ ext4_file_read_iter (~10.4 μs)
│   ├─ block_rq_insert (~42 μs)
│   ├─ nvme_queue_rq / block_rq_issue (~60 μs)
│   ├─ nvme_complete_rq (~438 μs)   ← Device
│   └─ block_rq_complete (~445 μs)  ← Q≈18 μs, S≈415 μs
├─ ext4_file_read_iter_ret (~465 μs)
├─ vfs_read_ret (~471 μs)
└─ sys_exit_read (~506 μs)

관찰 포인트

Cache=MISS, 블록으로 내려가 NVMe까지 왕복하는 것을 볼 수 있었습니다.
Bytes=12 KB로 보이는 건 연속 3페이지(4K×3)가 묶여 반환된 케이스인 것으로 추정됩니다.
Device≈416 µs가 전체의 큰 덩어리이지만, 스케줄링 OUT/IN 구간이 끼면서 F_SY가 F_FS보다 조금 더 길어지는 것입니다.

6) 인사이트

블록 크기 변화에 따른 병목 이동
- 4 KiB: Block 계층은 빠르지만, 상위 계층(스케줄링/캐시/VFS/FS)의 롱테일이 전체 변동성 주도했습니다.
- 128 MiB: 호출 수가 적고 Device Service가 지연의 대부분이었습니다. 즉, 디바이스 전송/큐 처리 최적화가 중요하다는 것을 직관적으로 확인할 수 있습니다.
Cache 판정은 sys_exit 기준으로 보는 게 덜 왜곡됩니다.
Block 이벤트는 한 번의 read()에 여러 번 찍히므로 exit 시점의 사용자 반환 단위가 더 현실적인 척도입니다.

7) Codes

uftrace(경로 파악)

UFTRACE_DIR=./uftrace_run
UFTRACE_DATA="$UFTRACE_DIR/uf.data"
RESULT_FILE=result_uftrace_nodirect.txt

rm -rf "$UFTRACE_DIR" "$RESULT_FILE"; mkdir -p "$UFTRACE_DIR"

uftrace record -k -d "$UFTRACE_DATA" -P 'fio*' -- \
  fio --filename=/nvmeDir/testfile --rw=randread --size=256k \
      --bs=4k --direct=0 --ioengine=sync --thinktime=10 \
      --iodepth=1 --name=test --numjobs=1

uftrace graph -k -d "$UFTRACE_DATA" > "$RESULT_FILE"

ftrace(function_graph + block/nvme TP)

TR=/sys/kernel/tracing
echo 0 > $TR/tracing_on
echo nop > $TR/current_tracer
: > $TR/trace; : > $TR/set_ftrace_pid; : > $TR/set_graph_function
: > $TR/set_ftrace_notrace

echo '__x64_sys_read' > $TR/set_graph_function
echo function_graph > $TR/current_tracer

# block/nvme tracepoints
for e in block_bio_queue block_rq_insert block_rq_issue block_rq_complete; do
  echo 1 > $TR/events/block/$e/enable
done
for e in nvme_sq nvme_complete_rq nvme_async_event; do
  echo 1 > $TR/events/nvme/$e/enable
done

fio --filename="/nvmeDir/testfile" --rw=randread --size=256k --bs=4k \
    --direct=0 --ioengine=sync --thinktime=10 --iodepth=1 \
    --name=test --numjobs=1 &

echo $! > $TR/set_ftrace_pid
echo 1 > $TR/tracing_on
wait $!
echo 0 > $TR/tracing_on

cat $TR/trace > ~/HW/hw2/result_ftrace_nodirect.txt
echo "trace saved."

# reset
for e in block_bio_queue block_rq_insert block_rq_issue block_rq_complete; do
  echo 0 > $TR/events/block/$e/enable
done
for e in nvme_sq nvme_complete_rq nvme_async_event; do
  echo 0 > $TR/events/nvme/$e/enable
done
echo nop > $TR/current_tracer
: > $TR/set_ftrace_pid; : > $TR/set_graph_function

fio 시나리오

# 4 KiB
fio --filename="/nvmeDir/testfile" --rw=randread --size=1024m --bs=4k \
    --direct=0 --ioengine=sync --thinktime=10 --iodepth=1 \
    --name=test --numjobs=1

# 128 MiB
fio --filename="/nvmeDir/testfile" --rw=randread --size=1024m --bs=128m \
    --direct=0 --ioengine=sync --thinktime=10 --iodepth=1 \
    --name=test --numjobs=1

서준표

이전 포스트

Neurips Accept 그리고 zero-shot style transfer에 관하여..?!

다음 포스트