들어가며
나는 다른 사람이 만든 AI 모델을 실행해주는 인프라 라인을 구축하고 운영하고 있다.
백엔드 서버, Lambda, ECS 위에서 돌아가는 여러 서비스들이 SQS를 통해 메시지를 주고받으며 하나의 작업을 처리한다. 각 서비스는 독립적으로 동작하고, 나는 그 흐름 전체를 연결하는 역할을 한다.
운영을 하다 보니 자연스럽게 이런 질문이 생겼다.
"지금 이 작업, 어디서 얼마나 걸리고 있는 걸까?"
에러는 거의 없다. 예외처리도 되어 있고, 각 서비스마다 에러 로그도 남기고 있다. 그런데 정작 "전체 흐름이 어떻게 흘러가고 있는가"는 보이지 않았다. 각 서비스의 로그는 파편화되어 있었고, 하나의 작업이 시작부터 끝까지 얼마나 걸렸는지, 어느 구간에서 지연이 발생하는지 파악하기가 어려웠다.
이 글은 그 문제를 해결하기 위해 통합 로깅을 설계한 과정을 기록한 것이다.
문제 인식 — 무엇을 모르고 있었나
파이프라인의 구조는 다음과 같다.
Backend → inference-op → snapshot → inference → postprocess각 단계는 SQS 메시지로 연결되고, Lambda와 ECS가 혼합된 환경에서 실행된다.
기존에 각 서비스가 남기는 로그는 있었다. 하지만 그 로그들은 서로 연결되어 있지 않았다. CloudWatch에서 각 서비스의 로그를 따로 뒤져야 했고, 하나의 작업 요청이 전체 파이프라인을 통과하는 데 얼마나 걸렸는지는 계산할 방법이 없었다.
내가 명확하게 파악하고 싶었던 것은 두 가지였다.
- 각 단계별 처리 시간 — 어느 서비스가 얼마나 걸리는가
- 전체 소요 시간 — 사용자에게 결과가 전달되기까지 실제로 얼마나 걸리는가
특히 두 번째가 중요했다. SQS를 통해 메시지가 전달되는 구조이기 때문에, 각 서비스의 처리 시간만으로는 전체 시간을 알 수 없다. 큐에서 대기하는 시간, 즉 네트워크와 스케줄링에 의한 지연이 포함되어야 진짜 소요 시간이 된다.
로깅 설계의 어려움 — 무엇을 남겨야 하는가
솔직히 처음에는 어떤 로그를 남겨야 하는지 감을 잡기가 어려웠다.
에러 로그는 명확하다. 무언가 잘못됐을 때 그 내용을 남기면 된다. 하지만 통합 로그는 달랐다. "정상적으로 흘러가는 과정"을 기록하는 것이라, 어떤 정보가 나중에 의미 있을지 판단하기가 쉽지 않았다.
내가 구축한 건 AI 모델 추론 파이프라인이다. 모델 자체의 품질이나 추론 결과는 내 영역이 아니다. 내가 책임지는 건 메시지가 제대로 전달되고, 각 서비스가 제시간에 실행되며, 전체 흐름이 막히지 않는 것이다.
그렇게 생각하니 필요한 정보가 명확해졌다.
- 각 단계가 메시지를 언제 받았는가 (
receivedAt) - 각 단계가 처리를 마치고 다음 큐에 언제 전달했는가 (
publishedAt) - 그 차이로 계산되는 실행 시간 (
executionMs) - 이전 단계의
publishedAt부터 현재 단계의publishedAt까지의 단계 소요 시간 (stepElapsedMs, 큐 대기 시간 포함) - 전체 파이프라인의 총 소요 시간 (
totalElapsedMs)
executionMs와 stepElapsedMs의 차이가 곧 큐 대기 시간이다. 이 두 값을 비교하면 지연이 서비스 자체에서 발생하는 것인지, 큐에서 기다리는 것인지 구분할 수 있다.
설계 — 메시지에 시간을 싣는다
핵심 아이디어는 단순하다. 각 서비스가 시간을 직접 측정하는 게 아니라, SQS 메시지에 타임스탬프를 누적해서 실어 나르는 것이다.
메시지 구조는 다음과 같이 설계했다.
{
"userId": 1,
"modelId": "ORD071122861289",
"uuid": "79cef664-...",
"toothNumber": 36,
"trace": {
"originatedAt": "2026-05-18T07:11:38.872Z",
"totalElapsedMs": 8500,
"steps": [
{
"step": "BACKEND",
"publishedAt": "2026-05-18T07:11:38.872Z"
},
{
"step": "INFERENCE_OP",
"receivedAt": "2026-05-18T07:11:39.154Z",
"publishedAt": "2026-05-18T07:11:41.257Z",
"executionMs": 2103,
"stepElapsedMs": 2385
},
{
"step": "SNAPSHOT",
"receivedAt": "2026-05-18T07:11:41.388Z",
"publishedAt": "2026-05-18T07:11:46.884Z",
"executionMs": 5496,
"stepElapsedMs": 5627
}
]
}
}각 서비스는 메시지를 받으면 다음을 수행한다.
- 메시지 수신 즉시
receivedAt기록 - 처리 로직 실행
- 다음 큐에 발행 직전
publishedAt기록 executionMs와stepElapsedMs계산trace.steps에 자신의 단계를 추가해서 다음 서비스로 전달
마지막 단계인 postprocess에서는 totalElapsedMs를 계산해서 trace에 추가하고, 전체 trace를 통합 로그로 기록한다.
이 방식의 장점은 각 서비스가 DB에 직접 접근할 필요가 없다는 것이다. 메시지 자체에 모든 추적 정보가 담기기 때문에, 최종 단계에서 한 번에 기록할 수 있다.
구현 — 각 서비스별 적용
시간 기록의 원칙
모든 서비스에서 시간은 UTC로 통일했다. 서비스들이 Lambda와 ECS에 분산되어 있기 때문에, 타임존 혼란을 원천 차단하기 위해서다.
Java(백엔드)에서는 Instant.now().toString()을 사용했다. Instant는 타임존 없이 UTC 기준으로 동작하고, toString()이 2026-05-18T07:11:38.872Z 형식으로 출력된다.
Python 서비스들에서는 아래 유틸 함수를 공통으로 사용했다.
from datetime import datetime, timezone
def utc_now() -> str:
return datetime.now(timezone.utc).strftime('%Y-%m-%dT%H:%M:%S.%f')[:-3] + 'Z'JavaScript(snapshot)에서는 new Date().toISOString()을 사용했다. 기본이 UTC이고 Z suffix가 포함된다.
백엔드 — 최초 메시지 발행
백엔드는 파이프라인의 시작점이다. trace를 초기화하고 BACKEND 단계의 publishedAt을 기록해서 메시지에 담는다.
public static ModelingRequestDTO create(Long userId, String modelId, String uuid, short toothNumber) {
String publishedAt = Instant.now().toString();
List<Trace.Step> steps = new ArrayList<>();
steps.add(Trace.Step.builder()
.step("BACKEND")
.publishedAt(publishedAt)
.build());
Trace trace = Trace.builder()
.originatedAt(publishedAt)
.steps(steps)
.build();
return new ModelingRequestDTO(userId, modelId, uuid, toothNumber, trace);
}originatedAt과 BACKEND.publishedAt은 동일한 시각이다. 백엔드 발행 시점이 곧 전체 파이프라인의 시작점이기 때문이다.
Python/JavaScript 서비스 — trace 누적
각 서비스는 동일한 패턴으로 trace를 누적한다. step 이름만 다를 뿐 로직은 모두 같다.
def build_trace_step(trace: dict, step_name: str, received_at: str, published_at: str) -> dict:
steps = trace.get('steps', [])
prev_published_at = steps[-1]['publishedAt'] if steps else trace.get('originatedAt')
fmt = '%Y-%m-%dT%H:%M:%S.%fZ'
received_dt = datetime.strptime(received_at, fmt)
published_dt = datetime.strptime(published_at, fmt)
prev_published_dt = datetime.strptime(prev_published_at, fmt)
steps.append({
'step': step_name,
'receivedAt': received_at,
'publishedAt': published_at,
'executionMs': int((published_dt - received_dt).total_seconds() * 1000),
'stepElapsedMs': int((published_dt - prev_published_dt).total_seconds() * 1000),
})
return { **trace, 'steps': steps }그리고 핸들러에서 수신 시각을 가장 먼저 찍는다. 이 순서가 중요하다. 메시지 파싱이나 기타 처리보다 먼저 receivedAt을 기록해야 큐 대기 시간이 정확하게 측정된다.
def handler(event, context):
received_at = utc_now() # 가장 먼저
event_body = json.loads(event['Records'][0]['body'])
# ... 처리 로직 ...
send_to_next_queue(event_body, received_at)postprocess — 전체 시간 계산 및 기록
마지막 단계인 postprocess에서는 totalElapsedMs까지 계산해서 trace를 완성한다.
originated_dt = datetime.strptime(trace.get('originatedAt'), fmt)
total_elapsed_ms = int((published_dt - originated_dt).total_seconds() * 1000)
return {
**trace,
'steps': steps,
'totalElapsedMs': total_elapsed_ms,
}완성된 trace는 기존 통합 로그(log_integrated_message)에 포함되어 기록된다. 별도의 로그 저장소를 추가하지 않고, 기존 로깅 흐름에 자연스럽게 녹아들게 했다.
마주친 문제들
기존 비즈니스 데이터와 trace의 분리
처음에는 payload라는 별도 네임스페이스 아래 비즈니스 데이터를 두는 구조를 고려했다.
{
"payload": { "userId": 1, "modelId": "..." },
"trace": { ... }
}하지만 Python 서비스들이 event_body['userId']처럼 최상위에서 직접 필드를 읽고 있어서, 이 구조로 바꾸면 모든 서비스를 동시에 수정해야 했다. 로깅 기능을 붙이는 작업이 전체 마이그레이션 작업이 되는 건 리스크가 너무 크다고 판단했다.
대신 기존 필드를 그대로 유지하고 trace 필드만 추가하는 방향을 선택했다. trace는 기존 로직과 완전히 독립적인 필드라서, 기존 서비스들은 trace를 무시하고 그대로 동작할 수 있었다. 덕분에 각 서비스를 순차적으로 마이그레이션할 수 있었다.
로그로 보이게 된 것들
trace가 완성되면 하나의 작업에 대해 다음과 같은 정보를 한눈에 볼 수 있다.
originatedAt : 2026-05-18T07:11:38.872Z
totalElapsedMs : 8500ms
BACKEND publishedAt : 07:11:38.872
INFERENCE_OP executionMs : 2103ms | stepElapsedMs : 2385ms (큐 대기: 282ms)
SNAPSHOT executionMs : 5496ms | stepElapsedMs : 5627ms (큐 대기: 131ms)
INFERENCE executionMs : ... | stepElapsedMs : ...
POSTPROCESS executionMs : ... | stepElapsedMs : ...executionMs와 stepElapsedMs의 차이가 해당 구간의 큐 대기 시간이다. 이 값들을 쌓아보면 어느 서비스가 느린지, 큐에서 병목이 발생하는 건지 구분할 수 있다.
마치며
통합 로깅을 설계하면서 가장 크게 느낀 건, 무엇을 알고 싶은지를 먼저 정의해야 한다는 것이다.
에러 로그는 문제가 생겼을 때 원인을 찾기 위한 것이다. 통합 로그는 다르다. 문제가 없는 상황에서도 시스템이 어떻게 동작하는지 이해하기 위한 것이다. 그 목적이 명확하지 않으면 어떤 정보를 남겨야 할지 판단하기 어렵다.
나의 경우, 목적은 명확했다.
"각 단계가 얼마나 걸리는지, 그리고 사용자에게 결과가 전달되기까지 전체적으로 얼마나 걸리는지 알고 싶다."
그 목적에서 출발하니 필요한 정보가 자연스럽게 도출됐다. 메시지에 타임스탬프를 싣고, 각 서비스가 자신의 구간을 계산해서 누적하는 구조는 그 목적에 가장 잘 맞는 방식이었다.
인프라를 구축하고 운영하는 사람에게 로깅은 단순한 디버깅 도구가 아니다. 시스템이 어떻게 살아있는지를 보여주는 창이다.