느린 API를 EXPLAIN으로 봤더니 SQL은 0.5ms였다

상황

수검자 상세 화면이 느리다는 이야기에서 시작됐다. 앱이 이 화면을 그릴 때 testSub(검사 하위 항목)를 28번이나 호출하고 있었다. 그래서 처음 나온 질문은 이거였다.

"앱에서 testSub를 28번 호출하는데, 한 방에 받는 API를 만들면 빨라지지 않을까?"

자연스러운 접근이다. 호출이 많으니 묶으면 빨라질 것 같고, 그 28번이 느린 쿼리라면 더더욱. 그런데 API를 새로 만들기 전에 확인할 게 있었다. 정말 쿼리가 느린 게 맞는지다.

일단 EXPLAIN부터

나는 성능 문제를 만나면 밑단부터 보는 편이다. 대부분의 서비스에서 병목은 DB에서 일어나기 때문이다. 그래서 이번에도 메인 쿼리부터 EXPLAIN (ANALYZE, BUFFERS, VERBOSE)로 실행 계획을 떴다.

결과가 예상과 달랐다.

Execution Time: 0.522 ms
Planning Time:  0.412 ms

실행 시간이 0.5ms였다. 느릴 게 없었다. 체감 지연이 초 단위인데 쿼리는 1ms도 안 걸린다. 범인이 SQL이 아니라는 뜻이다.

계획을 더 뜯어봐도 문제될 게 없었다.

Seq Scan on test    (Rows Removed by Filter: 2156)
Seq Scan on staff   (146 rows filter)

Seq Scan이 보이니까 "인덱스가 없어서 풀스캔이네" 싶지만, 이 경우엔 정상이다. test 테이블이 2158행, staff가 작은 테이블이라 planner가 인덱스를 타는 것보다 그냥 전부 읽는 게 빠르다고 판단한 거다. 데이터가 더 쌓이면 인덱스가 필요해지겠지만 지금은 아니다.

한 가지 눈에 띈 건 Planning Time이 Execution Time과 비슷하다는 점이었다. 실행만큼 계획 짜는 데 시간을 쓴다는 건, Hibernate가 native query를 매번 새로 파싱하고 있다는 신호다. 그래도 둘 다 1ms 미만이라 이게 체감 지연의 원인일 수는 없었다.

결론은 분명했다. SQL은 빠르다. 지연은 SQL 바깥에서 온다.

진짜 범인들

쿼리가 아니라면 어디서 시간이 새고 있나. 응답 경로를 따라가 보니 범인이 한 둘이 아니었다.

1. N+1 (이게 제일 컸다)

메인 쿼리로 결과 N개를 가져온 뒤, 후처리에서 각 결과마다 testSubRepository.findAllByTestId를 다시 호출하고 있었다. 결과가 N개면 추가 쿼리가 N번. 개별 쿼리는 0.5ms로 빠르지만, 그게 수십 번 쌓이면 왕복 비용이 선형으로 늘어난다. 각각은 빠른데 합치면 느린, 전형적인 N+1이다.

2. 같은 응답을 3번 받고 있었다

이건 좀 황당했다. 앱이 검사 stage 3종(SNSB 계열 세 단계)을 각각 따로 호출하는데, 서버 쪽 필터가 stage 파라미터를 제대로 안 걸러서 세 번 다 똑같은 전체 응답을 받고 있었다. 즉 같은 데이터를 세 번 받아서 앱이 그중 필요한 걸 골라 쓰고 있었던 거다. 네트워크도, 직렬화도 세 배로 쓰면서.

3. JSONB 직렬화

검사 원본 데이터(rawData)가 JSONB로 들어있는데, 이게 응답마다 직렬화/역직렬화되면서 비용을 더했다. 한 건이면 작지만 위의 N+1과 3중 호출에 곱해지면 무시 못 할 양이 된다.

4. testSub 28번 호출

처음 질문의 그 28번. 이건 위 문제들의 결과이기도 했다. 화면이 데이터를 잘게 나눠 부르는 구조라 호출 수 자체가 많았다.

그래서 새 API는 안 만들었다

처음 질문이 "28번을 한 방에 받는 API를 만들까"였는데, EXPLAIN을 떠보고 나니 그게 답이 아니었다. 묶는 API를 새로 만들어도 N+1과 3중 중복 호출이 남아있으면 근본 해결이 안 된다. 게다가 testSub를 한 번에 받는 엔드포인트는 이미 있었다. 새로 만들 게 아니라 앱의 호출 구조를 정리하고, N+1을 묶고, 중복 stage 호출을 없애는 게 맞는 방향이었다.

만약 EXPLAIN 안 보고 "느리다니까 쿼리겠지" 하고 바로 묶음 API부터 만들었으면, 일은 일대로 하고 체감은 별로 안 나아졌을 거다.

마치며

성능 문제를 만나면 나는 밑단부터 본다. 대부분의 서비스에서 병목은 DB에서 일어나니까, 쿼리와 실행 계획부터 보는 게 보통 빠른 길이다. 그런데 이번엔 그 습관이 정반대 결론을 내줬다. 밑단을 봤더니 밑단은 멀쩡했고, 문제는 그 위 애플리케이션 단에 있었다.

전에 슬로우 쿼리를 복합 인덱스로 잡은 적이 있다. 그때는 EXPLAIN이 "인덱스가 답"이라고 알려줬다. 이번엔 같은 EXPLAIN이 "인덱스는 답이 아니다, SQL을 건드리지 마라"라고 알려줬다. 도구는 같은데 결론이 정반대인 게 핵심이다. EXPLAIN은 "어디를 고쳐야 하는가"가 아니라 "여기가 문제인가 아닌가"를 먼저 알려준다. 그 답이 "아니오"면 시선을 위로 올려야 한다.

대부분의 지연은 SQL에서 온다. 하지만 항상은 아니다. 애플리케이션 단에도 얼마든지 병목이 숨어 있을 수 있다. 그걸 가르는 건 추측이 아니라 측정이다. 느리다는 말을 들었을 때 코드부터 고치는 대신 EXPLAIN 한 줄을 먼저 떠보는 게, 엉뚱한 데 일하는 걸 막아준다.