🚀 요약
SUMMARY
특정 API 엔드포인트가 290ms
48초까지 걸리는 문제를 추적했다. performance_schema가 꺼져 있어서 slow query log(1초 임계값, 54MB, 1413건)를 직접 뜯어봤다. 알림 테이블이 전체 슬로우 쿼리의 47%를 차지했고, 컨테이너 이력 테이블이 16%. 원인은 단순했다. 인덱스가 없었다. 수백만 건 테이블에 secondary index가 01개뿐이었다. 거기에 버퍼 풀(4GB)이 데이터(7.3GB)의 55%밖에 안 되어 디스크 I/O가 터지고, 앱은 async def 안에서 sync DB 드라이버를 써서 이벤트 루프를 막고 있었다.
⚙️ 환경
- MariaDB (Galera 3노드), mariadb-operator 관리, Kubernetes 위에 배포
- 애플리케이션: Python + SQLAlchemy (Uvicorn/Gunicorn 4 worker)
- 데이터베이스 엔진: 4개 이상 독립 SQLAlchemy engine
- 슬로우 쿼리 로그: 1초 임계값, 활성
- performance_schema: 비활성
- 테이블명은 기능으로 서술했고, 실제 이름과 다르다.
💬 이슈
특정 API가 느리다는 리포트가 들어왔다. 구체적으로 알림 카운트 조회 엔드포인트가 290ms씩 걸리고 있었다.
처음엔 Istio 프록시 지연을 의심했다. envoy access log를 보니 p50=174ms, p90=765ms. 메시 수준의 지연인가 싶었다. 근데 애플리케이션 로그를 보니 패턴이 달랐다. 헬스체크와 인증 요청은 1~12ms로 정상인데, 특정 엔드포인트만 290ms로 일관되게 느렸다. 메시 문제가 아니라 애플리케이션 안의 특정 쿼리가 느린 거였다.
NOTE
“전체가 느리다”와 “특정 엔드포인트만 느리다”는 전혀 다른 진단 경로로 이어진다. 전자는 인프라(CPU·메모리·네트워크)를 의심하고, 후자는 애플리케이션 로직과 쿼리를 의심한다. 이번엔 후자였다. 엔드포인트별 지연을 먼저 비교하는 게 진단의 첫 단추다.
🧗 해결
1. performance_schema가 꺼져 있다
DB 수준에서 쿼리 프로파일링을 하려고 performance_schema.events_statements_summary_by_digest를 찔러봤다. 결과가 텅 비어 있었다.
-- 상위 쿼리를 실행 시간별로 뽑아보려 했으나 결과 없음.
SELECT * FROM performance_schema.events_statements_summary_by_digest
ORDER BY avg_timer_wait DESC LIMIT 10;
-- → empty set@@performance_schema = 0. 비활성화되어 있었다. 즉 DB 내장 프로파일러를 쓸 수 없었다.
IMPORTANT
performance_schema가 꺼져 있으면 DB 자체 진단이 불가능하다. 운영 중 켜려면 재시작이 필요할 수 있어, 당장은 slow query log에 의존해야 한다. performance_schema를 기본값으로 켜두는 걸 습관화하면 장애 대응이 훨씬 빨라진다.
2. 슬로우 쿼리 로그: 54MB, 1413건
대신 slow query log를 봤다. 1초 임계값으로 설정되어 있었고, 1413건이 넘었다. 로그 파일 크기가 54.1MB.
mysqldumpslow로 집계하려 했으나 결과가 안 나와서(버전 이슈로 추정), 직접 tail과 grep으로 뜯어봤다.
패턴이 두 가지로 나뉘었다.
- N+1 패턴: 단순
COUNT(*)쿼리가 연속으로 실행되며, 각각 15초씩 걸린다. 5천8천 행을 풀스캔하면서. 인덱스가 있으면 즉시 끝나야 할 쿼리들이다. - 복잡한 서브쿼리:
EXISTS서브쿼리가 SELECT 절에 들어가 행마다 재평가되는 패턴. 한 쿼리는 43만 행을 검사했다. SQLAlchemy가 생성한 쿼리로 보인다.
슬로우 쿼리 로그를 끝까지 뜯어보니 병목이 특정 테이블에 집중되어 있었다. 여기서 테이블명은 기능으로 서술한다.
| 테이블 (기능) | 슬로우 쿼리 수 | 비율 | 평균 실행시간 | 최대 |
|---|---|---|---|---|
| 알림 테이블 | 668 / 1413 | 47% | 8.955s | 48.6s |
| 컨테이너 이력 테이블 | 232 / 1413 | 16% | 2.099s | 10.0s |
| 사용자 인증 로그 테이블 | (고비용) | — | 3.862s | 35.1s |
| 사용자 테이블 (distinct join) | (고비용) | — | 9.943s | 87.6s |
알림 테이블 하나가 전체 슬로우 쿼리의 절반을 차지하고 있었다.
3. 원인: 인덱스가 없다
테이블 스키마를 보니 답이 바로 나왔다. 인덱스가 없었다.
| 테이블 (기능) | 행 수 | secondary index 수 |
|---|---|---|
| 알림 테이블 | 228K | 1개 (user_id 단일) |
| 컨테이너 이력 테이블 | 35K | 0개 |
| 사용자 인증 로그 테이블 | 41K | 0개 |
| 채팅 발행 이력 테이블 | 1.7K | 0개 |
| 승인 테이블 | 9.8K | 0개 |
| 워크플로우 큐 테이블 | 11.5M | 1개 |
| 서빙 큐 테이블 | 9.3M | 1개 |
수백만 건짜리 큐 테이블은 secondary index가 1개뿐이고, 잦은 쿼리가 들어오는 작은 테이블들은 아예 0개였다.
알림 테이블에 있는 단일 인덱스(user_id)도 효율이 형편없었다. user_id만 잡고 있어서, 실제 쿼리의 WHERE 조건(user_id + 다른 컬럼)을 커버하지 못한다. 슬로우 로그를 보면 이 인덱스를 쓰긴 하는데, 수천 행을 검사한 후 WHERE 필터로 99.5%73%를 걸러낸다. 즉 인덱스를 타긴 하지만 필터링 효율이 0.350.70%에 불과하다.
IMPORTANT
“인덱스가 있다”와 “인덱스가 효과적이다”는 다르다. 단일 컬럼 인덱스가 있어도, 실제 쿼리의 WHERE 조건이 복합 컬럼이면 그 인덱스는 대부분의 행을 검사한 뒤 필터링하는 셈이 된다. 복합 인덱스(composite index)를 WHERE 조건 순서에 맞게 만들어야 진짜 효과가 난다.
구체적인 WHERE 패턴을 뜯어보니 이런 복합 인덱스가 필요했다.
- 사용자 인증 로그 테이블:
(user_id, type_code, reg_date)— 쿼리가 항상 이 세 컬럼으로 필터링한다. - 컨테이너 이력 테이블:
(resource_type, resource_id, resource_revision_id, status)+ORDER BY (timestamp, id)— WHERE + 정렬 컬럼까지 인덱스에 넣어야 filesort를 피할 수 있다. - 알림 테이블:
user_id단일 →(user_id, ...)복합으로 교체.
4. 버퍼 풀이 데이터의 절반도 안 된다
인덱스만 문제가 아니었다. 버퍼 풀을 보니 4GB로 설정되어 있었다. 그런데 활성 데이터가 7.32GB. 버퍼 풀이 데이터의 54.7%밖에 커버하지 못한다.
Buffer pool: 4GB configured
Active data: 7.32GB
Coverage: 54.7%
Cache misses: 70,304 (99.91% hit rate)
Read requests: 80M
99.91% hit rate면 높아 보이지만, 절대치로 70,304 cache miss다. 8천만 건의 read 요청 중 7만 건이 디스크로 간다. 인덱스가 없어서 풀스캔을 하는 상황에서 디스크 I/O까지 더해지면, 단순 COUNT(*)가 1~5초 걸리는 게 설명된다.
NOTE
hit rate 99.91%는 “문제 없다”로 읽히기 쉽다. 하지만 절대 miss 수(70K)가 중요하다. 풀스캔 쿼리가 디스크를 때리면, hit rate는 높아도 실제 지연은 커진다. hit rate만 보고 “DB는 멀쩡하다”고 판단하면 안 된다.
5. 애플리케이션: async def 안에서 sync DB 드라이버
여기까지 DB 쪽이었다. 애플리케이션 쪽을 보면 문제가 더 깊었다.
애플리케이션은 async def 핸들러를 쓴다. 근데 DB 드라이버가 sync인 mysqlconnector를 쓴다. 137개 파일이 @async_transactional 데코레이터를 쓰고, 38개 파일이 @transactional을 쓴다. 즉 async 핸들러 안에서 sync DB I/O를 호출하는 구조다.
sync DB 호출이 1~5초 걸리면, 그 동안 Uvicorn 워커의 이벤트 루프가 통째로 멈춘다. 그 워커에 대기 중인 다른 async 요청도 전부 블로킹된다. 전통적인 thread-per-request 모델이었다면 한 스레드만 막혔을 텐데, async + sync driver 조합에서는 워커 전체가 막힌다.
거기에 Gunicorn 워커가 4개뿐이다. 4개의 이벤트 루프 중 하나가 5초 동안 멈추면, 시스템 throughput의 25%가 그 5초 동안 사라진다.
IMPORTANT
async def 핸들러에 sync DB 드라이버를 쓰면, async의 이점이 사라진다. 한 쿼리가 느려지면 그 워커의 모든 async 요청이 대기한다. async를 쓴다면 DB 드라이버도 async(
asyncmy등)로 맞추거나, sync 드라이버를 쓴다면 thread pool로 실행해 이벤트 루프를 보호해야 한다.
6. SQLAlchemy 연결 풀: 기본값에 “사용자 많음” 에러로 대응
마지막 하나. 애플리케이션이 4개 이상의 독립 SQLAlchemy engine을 만드는데, 풀 설정을 명시하지 않아서 기본값(pool_size=5, max_overflow=10)을 쓰고 있었다. 엔진당 최대 15개 연결, 4개 엔진이면 ~60개. 실제로 57개 연결이 관측됐다.
느린 쿼리(1~5초)가 연결을 오래 점유하면, 풀이 빠르게 고갈된다. 그리고 앱 코드에 이런 게 있었다.
# QueuePool 고갈 시 사용자에게 보여주는 에러 메시지.
error_code = '00020004'
message = "Too many users, please try again later"즉 개발자가 연결 풀 고갈을 알고 있었다. 근데 근본 원인(풀 사이즈 설정)을 고치는 게 아니라, 에러를 잡아서 사용자에게 “사용자가 너무 많다”고 보여주는 걸로 대응하고 있었다.
IMPORTANT
에러 핸들링은 근본 해결이 아니다. “Too many users”는 사용자에게 책임을 떠넘기는 메시지인데, 실제로는 느린 쿼리 + 작은 풀의 조합이 원인이다. 풀 사이즈를 올리고, 느린 쿼리에 인덱스를 달면, 이 에러 자체가 나올 일이 없어진다.
✅ 확인
이 글은 진단까지의 기록이다. 실제 수정(인덱스 추가, 버퍼 풀 상향, 풀 설정, async 드라이버 전환)은 별도 작업으로 진행했다.
확인 포인트는 이렇다.
-- 1. 추가한 복합 인덱스가 실제로 쓰이는지 EXPLAIN으로 확인한다.
EXPLAIN SELECT ... FROM 알림_테이블 WHERE user_id = X AND ...;
-- → type: ref, rows: (수십 건 이하)면 OK. type: ALL이면 인덱스 안 타는 거다.
-- 2. 슬로우 쿼리 수가 줄었는지 확인한다.
SHOW GLOBAL STATUS LIKE 'Slow_queries';
-- → 1413건 기준에서 증가 속도가 둔화되어야 한다.
-- 3. 버퍼 풀 히트율과 miss 수를 다시 찍어본다.
SHOW ENGINE INNODB STATUS\G
-- → Buffer pool hit rate / cache miss 수 비교.NOTE
이 진단의 핵심은 “performance_schema가 없어도 slow query log로 충분히 파고들 수 있다”는 거다. 54MB 로그를 직접 뜯어보는 건 성가시지만, 병목이 어디 있는지는 명확하게 보여준다. 인덱스 부재, 버퍼 풀 부족, 애플리케이션 드라이버 불일치 — 세 층이 한 번에 드러난다. DB 진단은 도구가 아니라 데이터를 읽는 끈기가 핵심인 것 같다.