Sentry 화면이 30초씩 멈춘다 — 17번째에야 안 풀린 snuba-api

9월 28일 오후, 사내 Sentry가 느려졌다. 페이지 틀은 뜨는데 내용이 한참 안 나오고, 결국 30초 타임아웃으로 끝났다. 원인 지점은 데이터베이스가 아니라 그 앞의 조회 창구(snuba-api)였고, 트레이스·로그 화면의 무거운 조회가 방아쇠였다. 웹 로그를 거슬러 올라가 보니 처음이 아니었다. 7주 동안 17번 같은 일이 있었고, 16번은 몇 분 만에 저절로 풀렸다. 이번에만 안 풀렸다.

(사내 인프라 특성상 도메인·IP·서버 이름은 일반화했다.)

snuba-api는 무엇인가

Sentry 웹은 에러 데이터를 저장한 ClickHouse에 직접 붙지 않는다. 읽을 때는 항상 snuba-api라는 창구를 거친다.

[쓰기] SDK → relay → kafka → snuba consumer → ClickHouse
[읽기] 브라우저 → nginx → web ──→ snuba-api ──→ ClickHouse

그래서 snuba-api가 멈추면 조회만 죽는다. 이슈 목록·검색·그래프·대시보드·트레이스 화면, 그리고 “1분에 N번 나면 알림” 같은 빈도 조건 판정까지. 반대로 설정·멤버 화면처럼 PostgreSQL만 쓰는 곳은 멀쩡하고, 이벤트 수집도 그대로 된다. 데이터를 잃지는 않는다는 뜻이다.

어디서 멈췄나 — 서버에 들어가기 전에

서버 접속은 승인을 받아야 해서, 먼저 내 PC에서 잴 수 있는 것부터 쟀다.

경로	평소	멈췄을 때
도메인으로 (`/_health/`, 프록시 경유)	약 0.03초	3.8 / 8 / 10 / 20초, 한 번은 30초 타임아웃
서버 IP로 직접 (`/_health/`)	약 0.003초	19.3 / 17.8초

ping과 TCP 연결은 정상이었고, 첫 바이트가 오기까지(TTFB)만 멈췄다. 프록시를 거치지 않고 직접 붙어도 똑같이 느렸으니 프록시는 아니다. 범위가 Sentry 서버 안으로 좁혀졌다.

헬스 체크(/_health/)까지 멈춘 건, 웹 워커 세 개가 전부 snuba-api의 30초 응답을 기다리느라 묶여서 다른 요청이 줄을 섰기 때문이었다.

서버 안 — DB는 한가했고 창구가 멈춰 있었다

승인을 받고 읽기 전용으로 들어가 봤다.

확인	결과	판정
메모리·스왑 (`free`, `vmstat`)	여유 5.4GiB, 스왑 사용은 있지만 드나듦(si/so) 0	원인 아님
OOM·디스크	없음 / 35%	원인 아님
ClickHouse	CPU 5.7%, 7주간 재시작 없음	DB는 한가했다
snuba-api	unhealthy(헬스 70번 연속 실패), CPU 102%, 메모리 3.8GiB	여기서 멈춤
web 로그	`SnubaError ... Read timed out (read timeout=30)`, 500·504 반복	결과
백그라운드 작업	40분 사이 snuba 호출 실패 약 580건	알림 판정도 같이 멈춤

재시작 후 snuba-api 메모리는 약 300MiB로 돌아왔다.

9월 28일 타임라인

시각	일
17:18:15	snuba-api 로그에 `Error on clickhouse:9000 ping: Unexpected EOF`
17:19:36	누군가 트레이스 화면을 열었고, 로그 조회 요청(`trace-logs`, `per_page=1000`)이 응답 없이 멈춤
17:19:38	같은 화면의 다른 요청은 0.11초에 정상 — 이 순간까진 살아 있었다
17:20:06	그 요청이 30초 만에 504. 화면이 30초마다 다시 요청하며 계속 504
17:49~17:56	다른 사용자들 접속, 이슈 목록·태그까지 전부 504
17:58:24	1차 재시작 — 멈춘 워커가 종료 신호를 무시해 10초 뒤 강제 종료
17:59:04	2차 재시작 → 17:59:45 정상화

첫 판단 두 가지가 틀렸다

처음 정리했을 때는 멈춤이 17:22에 시작됐다고 적었고, “snuba-api 로그가 30분 동안 한 줄도 없었다”를 이상 징후로 봤다. 다음 날 로그를 다시 맞춰 보니 둘 다 틀렸다.

멈춤의 시작은 17:19:36의 로그 조회 요청이었다.
snuba-api는 평소에도 로그를 거의 안 남긴다(전날 하루 0줄). 그러니 “30분간 0줄”은 아무 근거가 못 된다.
17:18의 Unexpected EOF도 범인이 아니었다. 오래 놀던 연결을 ClickHouse가 정리한 흔적이고, 바로 뒤 조회들은 정상이었다. 다음 날 아침에도 똑같은 줄이 찍혔지만 아무 일도 없었다.

처음이 아니었다 — 7주 동안 17번

웹 로그에서 504·500이 몰린 구간을 날짜별로 묶어 봤다.

기간	횟수	대부분의 첫 요청	결과
8월 13일 ~ 9월 21일	16번, 한 번에 1~15분	로그·트레이스 조회(`trace-logs`, `trace-items`)	저절로 회복
9월 28일	40분 이상	`trace-logs`	안 풀려서 수동 재시작

snuba-api 컨테이너는 8월 11일에 만들어진 뒤 9월 28일까지 한 번도 재시작된 적이 없었다. 앞의 16번은 전부 저절로 풀린 것이다. 사용자가 화면을 보고 있을 때만 로그가 남으니, 실제로 멈춘 시간은 이 표보다 길 수도 있다.

“한두 번 느렸다”로 넘겼을 일이 로그로 다시 세 보니 패턴이었다.

upstream과 맞춰 보기

같은 증상이 self-hosted 저장소에 이미 올라와 있었다.

#4305: Logs 화면을 열면 snuba-api CPU 100%, 다른 페이지까지 타임아웃, 몇 분 뒤 저절로 회복, 며칠 가동한 뒤에만 발생, 재시작하면 해결. 같은 Unexpected EOF 로그까지 거의 전부 일치했다. 답 없이 자동으로 닫혔다.
메인테이너 설명: snuba-api가 uWSGI에서 Granian으로 바뀌면서 HTTP 요청 타임아웃·취소 처리가 없어졌다. 웹이 30초에 포기해도 snuba 안의 쿼리는 계속 돈다.
#4453(열려 있음): Granian 워커 메모리가 계속 늘어난다(15일에 7.3GB). 워커를 주기적으로 교체하는 설정이 snuba에는 있는데, self-hosted의 compose 파일이 그 값을 넘겨주지 않는다.

우리 서버에서 확인해 보니 #4453의 조건이 그대로였다.

확인	결과
버전	self-hosted 26.6.0, Granian 2.7.6 (#4453과 같음)
컨테이너 환경변수	`UWSGI_MAX_REQUESTS=10000` 같은 uWSGI 시절 설정만 있고, 지금 서버(Granian)는 이걸 읽지 않는다
snuba 안의 실제 값	워커 교체 주기 `None`, 메모리 상한 `None` — 워커 재활용이 꺼져 있다
재시작 후 16시간	워커 메모리 197MB로 거의 안 늚

마지막 줄이 흥미로웠다. 천천히 새는 게 아니라 무거운 조회가 들어올 때 순간적으로 불어났을 가능성이 크다.

정리하면 이렇게 추정했다. 로그·트레이스 쿼리가 snuba-api 안에서 무겁게 돌고, 웹은 30초에 포기하지만 쿼리는 취소되지 않는다. 화면이 30초마다 다시 요청하면서 스레드 8개가 다 찬다. 그러면 모든 조회가 멈춘다. 보통은 쿼리가 끝나면서 풀리지만, 6주 동안 불어난 워커에서는 이번에 안 풀렸을 가능성이 있다. snuba-api 안에서 정확히 무엇이 CPU를 먹었는지는 확인하지 못했다. ClickHouse의 쿼리 기록이 꺼져 있었고, 재시작 전에 스냅샷을 뜨지 않았다.

대응안 — 그리고 보류

안	내용	비고
A	`docker-compose.override.yml`로 워커 교체 주기(하루)와 메모리 상한(1GiB)을 넘겨준다	메모리 누적 조건을 없앤다. upstream이 아직 안 받은 값이라 로컬 우회
B	감시 스크립트: 5분 동안 unhealthy면 스냅샷을 남기고 재시작하고 Slack으로 알림	안 풀리는 멈춤을 5분 안에 복구하면서 증거도 쌓는다
C	로그·트레이스 화면은 기간을 짧게 보라고 안내	방아쇠 빈도를 줄인다
D	진단용으로 ClickHouse 쿼리 기록 켜기(하루 보관)	다음 재발 때 실제 쿼리를 특정

A는 이런 파일 하나다.

# /opt/sentry/docker-compose.override.yml — self-hosted #4453 우회
services:
  snuba-api:
    environment:
      SNUBA_API_WORKERS_LIFETIME: "86400"   # 하루에 한 번 워커 교체
      SNUBA_API_WORKERS_MAX_RSS: "1024"     # 1GiB 넘으면 교체 (평소 약 200MB, 멈췄을 때 3.8GiB)

원인 분석은 여기서 끝냈고, 설정 변경은 보류하기로 했다. 바꾸는 건 나중에, 적용할 때는 변경 전후를 보여 주고 승인을 받는다. 운영 서버도 같은 날 같은 증상이 있었다고 들었지만, 접근 권한이 없어 확인하지 못했다.

대신 다음에 멈추면 할 일은 런북에 적어 뒀다. 재시작하기 전에 docker top과 docker stats로 스냅샷부터 뜨고, 그다음 docker compose restart snuba-api(수집에는 영향 없음). 이번에 놓친 증거를 다음엔 남기려는 것이다.

마치며

진짜로 배운 것

느리다는 증상은 층으로 쪼갠다. ping·TCP는 정상인데 첫 바이트만 늦다면, 그리고 직접 붙어도 똑같다면, 네트워크와 프록시를 빼고 서버 안을 본다.
“로그가 없다”는 평소에도 없는지부터 본다. 원래 조용한 프로세스의 침묵은 이상 징후가 아니다. 첫 판단 두 개가 이걸로 뒤집혔다.
저절로 풀린 장애도 장애다. 16번이 몇 분 만에 풀려서 아무도 몰랐다. 로그로 과거를 다시 세 보니 같은 방아쇠가 보였다.
이름만 남은 설정을 의심한다. compose 파일의 UWSGI_* 설정은 서버가 바뀐 뒤 아무도 읽지 않았고, 정작 필요한 설정은 빠져 있었다.
재시작 전에 증거를 뜬다. 재시작하면 바로 풀리지만 원인도 같이 사라진다.