모니터링 장애 대응 실습 2편 - 자원이 마르면 생기는 일, 커넥션 풀 고갈과 느린 쿼리

이 글의 한 줄: 같은 자원 장애여도 신호는 정반대일 수 있습니다. 에러로 터지거나, 침묵 속에 느려지거나.

“모니터링 장애 대응 실습” 4부작의 2편입니다. 1편. 정상이 뭔지 모르면 장애도 못 본다 · 2편(현재 글) · 3편. 앱이 죽어가는 신호 · 4편(예정)

1편에서 baseline을 확보했습니다. 처리량 8.3 RPS, p95 41.7ms, 에러 0%. 이번 편에서는 그 위에 첫 장애 두 개를 일으킵니다. 커넥션 풀 고갈과 느린 쿼리. 계획할 때는 둘 다 “DB 자원 문제”로 한 묶음이라 신호도 비슷할 줄 알았습니다. 실제로는 정반대였습니다. 하나는 에러율 93%로 대시보드가 뒤집혔고, 하나는 에러가 단 한 건도 없이 조용히 11배 느려졌습니다.

장애 1. 커넥션 5개가 전부 점유된 채였다

이렇게 망가뜨렸다

실무에서 흔한 안티패턴을 그대로 재현했습니다. 트랜잭션 안에서 외부 API를 기다리는 코드입니다. 재현이 잘 보이도록 풀은 작게, 타임아웃은 짧게 잡았습니다(maximum-pool-size=5, connection-timeout=2000).

@Transactional(readOnly = true)
public Product findByIdAndHold(Long id, long holdMillis) {
    Product product = productRepository.findById(id)
            .orElseThrow(() -> new ProductNotFoundException(id));
    Thread.sleep(holdMillis);   // ★ 외부 호출 5초를 모사. 커넥션을 쥔 채 대기
    return product;
}

트랜잭션이 살아있는 동안 DB 커넥션은 반환되지 않습니다. 요청 하나가 커넥션 하나를 5초씩 쥐고 있으니, k6로 50 VU를 걸면 풀(5개)은 즉시 마릅니다.

pending은 서서히 차오르지 않았다

부하를 걸고 대시보드를 보는데, 예상과 다른 게 두 가지였습니다.

첫째, pending(커넥션 대기 스레드)이 “서서히 차오를” 줄 알았는데 첫 scrape 5초 만에 0에서 45로 점프했습니다. 50 VU가 동시에 들어오고 커넥션은 5개뿐이니 당연한 산수인데, 그래프로 보기 전엔 이 속도감을 몰랐습니다. 풀 고갈은 추세형이 아니라 급변형에 가깝게 나타났습니다.

둘째, 에러율이 93%까지 치솟았습니다. 풀 5개가 동시에 처리하는 5건 말고는 전부 2초 타임아웃으로 떨어졌기 때문입니다. timeout_total은 분당 약 1,100건씩 증가했습니다.

고백하자면 위 캡처에서 93%짜리 에러율이 평화로운 초록색 선으로 그려져 있습니다. 당시 패널에 threshold 색상을 안 넣어서입니다. 값은 장애인데 색은 정상. 이 어색함을 겪고 나서야 에러율 패널에 “5% 초과는 빨강” threshold를 넣었습니다. 대시보드는 값만 보여주면 되는 게 아니라 위험한 값을 색으로 구분해야 한다는 걸 배운 대목입니다.

로그의 괄호 안에 답이 다 있었다

Loki에서 ERROR 레벨로 좁히자 스택트레이스가 쏟아졌습니다.

java.sql.SQLTransientConnectionException: HikariPool-1 - Connection is not available,
request timed out after 2010ms (total=5, active=5, idle=0, waiting=2)

괄호 안이 원인 그 자체입니다. total=5, active=5, idle=0. 풀 전체가 점유된 채 놀고 있는 커넥션이 하나도 없습니다. 메트릭(pending 급증)이 “언제”를 알려줬고, 로그의 이 한 줄이 “왜”를 확정했습니다.

검색 팁 하나. request timed out after 2010ms의 시간값은 설정에 따라 바뀝니다. Connection is not available 같은 불변 부분 문자열로 검색해야 재사용 가능한 쿼리가 됩니다.

풀을 늘리지 않고 점유 시간을 줄였다

원인이 “트랜잭션 안의 외부 대기”이므로, 고치는 것도 그 지점입니다. 지연을 트랜잭션 밖으로 옮겼습니다.

// 조회 트랜잭션은 즉시 커밋되어 커넥션을 곧바로 반환한다
Product product = productService.findById(id);
sleepOutsideTransaction(5000);   // 커넥션을 쥐지 않은 채 대기

같은 50 VU를 다시 걸었습니다. pending 0, 타임아웃 0, 에러율 0% (824건 전부 성공). 풀 크기는 여전히 5인데 아무 문제가 없습니다.

maximum-pool-size를 50으로 올리는 선택지도 있었지만 그건 증상 완화입니다. 커넥션 점유 시간이 문제의 본질인데 풀만 키우면 DB 쪽 부담을 늘린 채 같은 장애를 더 큰 규모로 유예할 뿐입니다. 재발 방지 규칙은 “트랜잭션 안에서 외부 I/O 금지”와 pending 알림으로 정리했습니다.

장애 2. 에러는 0인데 11배 느리다

이렇게 망가뜨렸다

이번엔 코드가 아니라 없는 것이 원인입니다. product 테이블 100만 행, name 컬럼에 인덱스 없음. 그 컬럼으로 검색하는 API에 k6 30 VU를 걸었습니다.

GET /api/products/search?name=product-0194756   (WHERE name = ? 풀스캔)

이번엔 에러율 패널이 끝까지 0%였다

장애 1을 겪은 직후라 에러율 패널부터 봤습니다. 정작 치솟은 건 레이턴시 패널이었습니다.

지표	baseline	incident
p95	41.7ms	450ms (약 11배)
p99	40ms대	~500ms (약 12배)
실패율	0%	0% (8,871건 전부 성공)
처리량	없음	74 RPS

모든 요청이 “성공”하고 있었습니다. 느리게. 이게 장애 1과의 결정적 차이입니다. “느리지만 죽지 않는” 장애는 에러율 패널만 보면 존재 자체를 모릅니다. 1편에서 baseline p95(41.7ms)를 박아두지 않았다면 450ms를 보고도 “원래 이런가?” 했을 것입니다.

p95와 p99가 각각 무엇을 재는 값이고 이 숫자가 어떻게 만들어지는지는 응답 시간 백분위에 정리해뒀습니다.

느린 쿼리 로그 926건이 원인을 확정했다

PostgreSQL에 log_min_duration_statement=100(100ms 초과 쿼리 기록)을 켜뒀었습니다. 장애 구간 동안 같은 모양의 쿼리가 926건 쌓여 있었습니다.

duration: 100~128ms ... where p1_0.name=$1

Loki의 Logbook 로그에서 같은 시각 GET /api/products/search?name=... 요청들을 requestId와 함께 확인해 엔드포인트를 특정했고, EXPLAIN으로 확정했습니다.

[BEFORE] 인덱스 없음: Parallel Seq Scan
  워커 3개가 100만 행 전수 스캔, Buffers 14,290 read
  Execution Time: 30.657 ms

[AFTER] CREATE INDEX idx_product_name ON product (name);
  Index Scan, Buffers 4
  Execution Time: 0.080 ms   (약 380배)

EXPLAIN의 30.657ms는 단건 실행 계획을 확인한 값이고, 앞서 느린 쿼리 로그의 100~128ms는 30 VU 부하 중 병렬 스캔이 경합하며 관측된 값입니다. 둘의 성격이 다르니 수치도 다릅니다.

인덱스 한 줄, 그리고 헛다리 하나

인덱스를 만들고 곧바로 같은 부하를 다시 걸었습니다. 그런데 p99가 325ms. 순간 “인덱스가 안 먹나?” 싶어 EXPLAIN을 다시 돌릴 뻔했습니다. 40초쯤 지나자 20ms대로 뚝 떨어졌습니다. cold cache 워밍업, 또는 rate(...[1m])의 1분 집계 윈도우에 남아 있던 직전 느린 요청의 잔상으로 보였습니다. 후자라면 실제 요청은 이미 빨라졌어도 분위수 계산이 직전 1분치 버킷을 계속 포함해 p99가 한동안 높게 유지됩니다. 어느 쪽이든 새 인덱스 직후의 과도기였고, 아래 캡처의 마지막 스파이크가 그 순간입니다.

워밍업 후 최종 수치:

지표	incident	recovery
p95	450ms	19.6ms (baseline 수준)
처리량	74 RPS	약 1,500 RPS (20배)
실패율	0%	0.01% (총 요청 197,509건)

의외의 수확은 처리량이었습니다. 인덱스는 레이턴시만 고치는 게 아니었습니다. 같은 30 VU에서 처리량이 20배 뛰었습니다. 요청 하나가 빨리 끝나니 같은 시간에 더 많이 처리되는, 당연하지만 그래프로 보면 통쾌한 결과입니다.

재발 방지는 느린 쿼리 로깅 상시화, 조회 컬럼 인덱스 점검, 엔드포인트별 레이턴시 SLO 패널로 정리했습니다.

두 장애가 남긴 것

	장애 1. 풀 고갈	장애 2. 느린 쿼리
가장 먼저 반응한 신호	pending (5초 만에 0에서 45)	p95/p99 (11배 급등)
에러율	93%	0%
원인을 확정한 로그	Connection is not available (total=5, active=5...)	duration: ... 느린 쿼리 926건
해결	점유 시간 단축 (트랜잭션 밖으로)	인덱스 추가
풀·인프라 증설	불필요	불필요

같은 “자원 경합”인데 하나는 에러율로 드러나고 하나는 조용히 느려집니다. 에러율 패널만 보면 절반의 장애를 놓칩니다. 레이턴시와 자원 패널(pending, active)까지가 한 세트입니다.

다음 편은 더 고약한 놈입니다. 메모리 누수는 에러 한 줄 없이 힙만 우상향하다 앱째로 죽었고, 정작 죽는 순간의 로그는 어디에도 남지 않았습니다. 로그로 원인을 좁힌다는 이 시리즈의 공식이 처음으로 막히는 이야기입니다.

다음 편: 모니터링 장애 대응 실습 3편 - 앱이 죽어가는 신호, 메모리 누수와 에러율 급증