High-Precision Latency Tracing with Monotonic Clock

로그에 단조 시간 델타 추가하기

로깅/프로파일링 정확도를 한 단계 끌어올리는 핵심 팁을 공유한다: 벽시계(wall‑clock)와 함께 “모노토닉 since‑start 카운터”를 같이 기록하라. 벽시계는 시스템 시간 변경(NTP, 관리자 수동 변경, DST) 영향을 받지만, 모노토닉 카운터는 부팅 이후 단조 증가하여 크로스‑스레드 지연, 스톨, 지터를 안정적으로 분석할 수 있다.

왜 필요한가

• 시간 점프 방지: 서버 시간이 조정되어도 지연 측정값이 흔들리지 않는다.

• 스레드 간 상호 비교 용이: 공통 기준(프로세스 시작 시점)으로 각 이벤트 간 Δt를 정확히 산출한다.

• 초미세 구간 분석: 마이크로초(μs) 단위 이상의 정밀도로 I/O 블로킹, 컨텍스트 스위치, 락 경합을 드러낸다.

실전 적용 패턴

로그 한 줄에 최소 3가지를 넣는다:

1. 벽시계 타임스탬프(ISO8601)

2. since‑start 모노토닉 시각(μs 또는 ns)

3. 선택: 스레드 ID, 코어/CPU, 태그

예:

2025-11-26T13:49:08.814273Z | t=518.234.μs | tid=42 | openat start

POSIX (Linux, macOS)

• 시계: clock_gettime(CLOCK_MONOTONIC) 또는 CLOCK_MONOTONIC_RAW

• 권장 단위: 나노초(ns) 또는 마이크로초(μs)

• 퍼프로세스 기준을 원하면 t0_ns를 프로세스 시작에 한 번 초기화한다.

• 커널/라이브러리 오버헤드가 민감하면 CLOCK_MONOTONIC_RAW를 벤치마킹해 선택한다.

Windows

• 시계: QueryPerformanceCounter + QueryPerformanceFrequency

• HPET/Invariant TSC 기반 고정밀, 벽시계 조정의 영향을 받지 않는다.

로그 포맷 예시(공통)

• JSON 권장: 파싱 용이, 이후 CloudWatch/Elastic/ClickHouse에 바로 적재 가능.

분석 워크플로우 요령

• Δt 파이프라인: begin/end 이벤트의 t_us 차로 단계별 비용을 구한다.

• 스레드 상관분석: 동일 태그(요청 ID)로 스레드별 t_us 타임라인을 합쳐 컨텐션/lock 대기 확인.

• 샘플링 주기: 고주파 로그는 비용이 크다. 릴리스 빌드에서는 샘플링(예: 1/N) 또는 링버퍼 후 덤프.

흔한 함정

• gettimeofday()/std::chrono::system_clock만 쓰면 NTP 조정 시 음수 Δt가 나온다.

• CLOCK_REALTIME는 벽시계라 지연 측정에 부적합하다.

• 단위 혼용(ns/μs/ms)로 그래프가 깨지는 실수 잦다 → 필수로 단위 필드화.