애플리케이션에서 fsync() 호출이 가끔 몇 ms에서 수십 ms까지 튀는데, iostat의 디바이스 평균 지연시간만 봐서는 그게 큐잉 때문인지 디스크 자체가 느린 건지 구분이 안 될 때가 있다. blktrace는 블록 계층의 각 요청이 큐에 들어가고(Q), 디스패치되고(D), 완료되는(C) 시각을 전부 타임스탬프로 남기기 때문에 이 구간별 지연을 쪼개서 볼 수 있다. 이 글에서는 blktrace로 실제 fsync() 호출을 추적하고, btt로 지연시간이 어느 구간에서 발생하는지 분해해본다.
fsync 호출 추적하기
디스크에 blktrace를 걸어둔 채, 4KB를 쓰고 fsync()하는 동작을 5회 반복하는 파이썬 스크립트를 실행했다.
$ sudo blktrace -d /dev/sda -o sda -w 5 &
$ python3 -c "
import os, time
f = open('/tmp/fsynctest.img', 'wb')
for i in range(5):
t0 = time.time()
f.write(os.urandom(4096))
f.flush()
os.fsync(f.fileno())
print(f'fsync #{i}: {(time.time()-t0)*1000:.2f} ms')
"
fsync #0: 2.55 ms
fsync #1: 2.13 ms
fsync #2: 2.22 ms
fsync #3: 2.32 ms
fsync #4: 2.42 msblkparse로 트레이스를 텍스트로 풀어 프로세스 이름으로 필터링하면, fsync()가 유발한 WS(Write Sync) 요청만 뽑아낼 수 있다.
$ blkparse -i sda | grep python3
8,0 1 131 0.979241574 11686 Q WS 225074888 + 8 [python3]
8,0 1 132 0.979247946 11686 G WS 225074888 + 8 [python3]
8,0 1 135 0.979251543 11686 I WS 225074888 + 8 [python3]
8,0 1 136 0.979258807 11686 D WS 225074888 + 8 [python3]| 액션 | 의미 |
|---|---|
| Q (Queued) | 블록 계층 큐에 요청이 들어온 시각 |
| G (Get request) | 요청 구조체 할당 |
| I (Inserted) | 스케줄러 큐에 삽입 |
| D (Dispatched) | 디바이스 드라이버로 실제 전달된 시각 |
| C (Completed) | 디바이스가 처리를 끝내고 완료 응답한 시각(위 grep 결과에는 미포함, 로그 뒷부분에 존재) |
같은 blktrace를 켜둔 채 fsync() 없이 write()+flush()만 5회 실행하면 어떨까.
$ blkparse -i sda | grep python3
$ echo $?
1 # 매치 결과 없음 — python3가 낸 블록 요청이 5초 트레이스 구간에 전혀 없다flush()는 유저 공간 버퍼(파이썬 파일 객체 내부 버퍼)만 커널로 넘길 뿐 페이지 캐시 이후 단계는 건드리지 않는다. fsync()가 없으면 데이터는 dirty 페이지로만 남고, 실제 디스크 쓰기는 커널 flusher 스레드가 나중에(writeback 주기에 따라) 알아서 처리한다 — 그래서 우리 프로세스 이름으로는 블록 요청이 단 하나도 안 잡힌다.
btt로 구간별 지연시간 분해
이 Q/D/C 타임스탬프를 일일이 손으로 빼는 대신, blktrace 패키지에 포함된 btt가 전체 트레이스를 집계해 구간별 평균·최대 지연을 바로 계산해준다.
$ blkparse -i sda -d sda.bin > /dev/null
$ btt -i sda.bin
ALL MIN AVG MAX N
Q2G 0.000000350 0.000089502 0.003869203 319
I2D 0.000001733 0.000395318 0.002602025 319
D2C 0.000081325 0.000859645 0.003720702 710
Q2C 0.000084019 0.001346916 0.005617673 710
==================== Device Overhead ====================
Q2G G2I Q2M I2D D2C
2.9856% 0.8900% 0.0093% 13.1868% 63.8232%Q2C(큐잉부터 완료까지) 평균이 1.35ms인데 그중 63.8%(D2C, 디스패치~완료)가 디스크 자체 처리 시간이고, 큐잉 단계(Q2G+I2D)는 합쳐도 16% 남짓이다. 즉 이 fsync 지연은 블록 계층 대기가 아니라 스토리지 자체의 쓰기 완료 시간이 대부분이라는 뜻이다.
백그라운드 부하가 있으면 결과가 뒤집힌다
앞의 결과는 디스크가 한가한 상태였기에 나온 것이다. 다른 프로세스가 같은 디스크에 쓰기를 쏟아붓는 중이라면 fsync 지연의 지배적 구간이 바뀌는지, fio로 백그라운드 랜덤 쓰기 부하를 걸어둔 채 같은 fsync 테스트를 다시 실행해 확인했다.
$ sudo blktrace -d /dev/sda -o sda2 -w 8 &
$ fio --name=bgload --filename=/tmp/fio_bg.dat --size=2G \
--rw=randwrite --bs=64k --ioengine=libaio --iodepth=32 \
--numjobs=4 --direct=1 --runtime=6 --time_based &
$ python3 -c "
import os, time
f = open('/tmp/fsynctest2.img', 'wb')
for i in range(5):
t0 = time.time()
f.write(os.urandom(4096))
f.flush()
os.fsync(f.fileno())
print(f'fsync #{i}: {(time.time()-t0)*1000:.2f} ms')
"
fsync #0: 4193.59 ms
fsync #1: 2696.40 ms
fsync #2: 24.90 ms
fsync #3: 389.69 ms
fsync #4: 12.41 ms같은 4KB fsync가 2ms대에서 최대 4.2초까지 튄다. 이 구간의 트레이스를 다시 btt로 분해하면 지배적 구간 자체가 바뀐 걸 볼 수 있다.
$ blkparse -i sda2 -d sda2.bin > /dev/null
$ btt -i sda2.bin
ALL MIN AVG MAX N
Q2G 0.000000420 0.051355381 1.935027318 569
I2D 0.000001323 0.434116189 1.983658287 597
D2C 0.000181445 0.191069188 2.566720836 571
Q2C 0.000518489 0.629951892 3.192698105 571
==================== Device Overhead ====================
Q2G G2I Q2M I2D D2C
8.1237% 0.0112% 0.0000% 72.0505% 30.3308%한가할 때는 D2C(디바이스 처리)가 63.8%로 지배적이었는데, 백그라운드 쓰기 부하가 걸리자 I2D(스케줄러 큐에 들어간 뒤 디바이스로 디스패치되기까지 대기)가 72.1%로 역전됐다. 같은 fsync() 호출이라도 그 순간 디스크가 한가한지 바쁜지에 따라 병목 구간 자체가 다르다는 뜻이다 — 그래서 주의사항에서 다루는 “D2C가 크면 스토리지, 큐잉이 크면 커널 튜닝”이라는 구분이 트레이스를 직접 뜯어보지 않고는 판단하기 어렵다.
주의사항
| 항목 | 내용 |
|---|---|
| WS 필터만으로는 부족할 수 있다 | fsync는 파일시스템·저널링 방식에 따라 FLUSH(REQ_PREFLUSH)나 FUA 플래그가 붙은 별도 요청으로도 나타난다. blkparse -a issue -a complete로 액션을 더 세분화해 확인할 것 |
| 추적 자체가 오버헤드 | 모든 I/O 이벤트를 기록하므로 고부하 프로덕션에서 장시간 켜두면 트레이스 파일 용량과 CPU 사용량이 늘어난다. -w로 짧게 시간 제한을 걸고 재현 구간만 잡을 것 |
| root 권한 필수 | blktrace는 커널 트레이싱 인프라(debugfs)에 접근하므로 sudo 없이 실행 불가 |
| D2C가 크면 스토리지 교체/최적화, 큐잉이 크면 커널 튜닝 | btt 결과에서 어느 구간이 큰지에 따라 대응 방향이 갈린다 — D2C 지배적이면 디바이스 자체 한계, Q2G/I2D가 크면 I/O 스케줄러나 큐 깊이 튜닝 대상 |
마무리
blktrace로 fsync가 유발하는 WS 요청을 프로세스 단위로 잡아내고, btt로 Q2G·I2D·D2C 구간별 비중을 나누면 지연의 원인이 커널 큐잉인지 디스크 자체인지 데이터로 구분할 수 있다. 같은 디스크라도 한가할 때와 부하가 걸렸을 때 지배적 구간이 뒤바뀌므로, 애플리케이션 로그의 fsync 소요시간만 보고 막연히 튜닝하기 전에 문제가 재현되는 그 순간의 트레이스로 이 분해부터 해보는 게 순서다.
참고
Linux 블록 I/O 추적 도구 blktrace 사용법
Kernel.org – Block I/O Documentation