사내 시스템이 갑자기 느려졌을 때, 문의 화면 폴링 한 줄이 범인이었던 사례

로그인 한 번에 8초에서 21초가 걸렸습니다. 같은 서버의 상태 점검 주소는 0.02초 안에 답했습니다.

멈춘 건 DB를 거치는 요청뿐이었습니다. 이 사실에 닿기까지 저는 두 번 틀렸습니다.

직원들이 매일 여는 사내 그룹웨어였습니다. 틀린 지점마다 끊어서 옮기겠습니다.

"서버가 모자라다"는 짐작

"시스템이 너무 느려졌다"는 말을 들으면 먼저 사양이 떠오릅니다. 저도 서버 전반부터 봤습니다.

숫자는 나빴습니다. 부하 평균이 12.4였고 디스크 사용률은 상시 99.7%였습니다.

DB에 1,000행을 넣는 데 3.3초가 걸렸습니다. 디스크 기록을 확정하는 fsync는 중앙값 1,291ms였습니다.

그 서버는 HDD 두 개를 미러로 묶은 NAS 한 대입니다. 그 위에 컨테이너 44개가 올라가 있으니 천장이 낮은 건 사실입니다.

같은 시기 디스크에서는 정합성 점검이 사흘째 돌고 있었습니다. 진행률 75.9%에 남은 예상 시간이 122시간이었습니다.

여기까지만 보면 "장비가 모자라다"로 끝내기 쉽습니다. 그렇게 결론을 내면 손댈 곳이 장비 하나만 남습니다.

404를 받고도 넘어간 첫 측정

외부 경유 구간을 빼고 서버 안에서 앱 주소를 직접 재 봤습니다. 32ms가 나왔습니다.

첫 결론은 "서버는 정상이고 외부 경유 구간이 문제"였습니다. 이게 첫 번째 오보였습니다.

그때 잰 주소는 같은 서버에 있는 다른 앱이었습니다. 로그인 경로를 부르면 404가 돌아왔는데 그걸 그냥 넘겼습니다.

404는 "여기는 당신이 찾는 앱이 없다"는 신호였습니다. 404를 받은 측정은 측정이 아닙니다.

비율도 틀렸습니다. 첫 정리에서는 외부 경유 구간이 느림의 절반쯤이라고 봤습니다.

실제로는 앱 쪽이 8~21초, 외부 경유 구간은 0.6초였습니다. 그 정리를 받은 쪽에서는 외부 경유를 우회하는 방법부터 물어 왔습니다.

틀린 진단이 다음 질문의 방향까지 정해 버린 겁니다. 결국 첫 결론을 통째로 뒤집어야 했습니다.

대조 경로 하나로 갈린 것

진짜 앱 주소를 찾아 다시 쟀습니다. 이번에는 두 경로를 나란히 놓았습니다.

상태 점검 경로는 DB를 건드리지 않고 살아 있다는 것만 답합니다. 그 경로가 10번 내내 빨랐으니 앱 프로세스는 멀쩡했습니다.

"앱이 느리다"가 "DB를 타는 요청만 멈춘다"로 좁혀졌습니다. 0.5초가 한 번 섞인 것도 단서였습니다.

늘 느린 상태와는 모양이 다릅니다. 무언가에 걸렸다가 풀리기를 반복한다는 뜻이었습니다.

DB는 무엇을 기다리고 있었나

PostgreSQL은 지금 도는 쿼리가 무엇을 기다리는지 보여 줍니다. 제가 쓴 조회는 이렇습니다.

SELECT pid, state, wait_event_type, wait_event,
       now() - query_start AS elapsed, left(query, 60) AS query
FROM pg_stat_activity
WHERE state <> 'idle'
ORDER BY query_start;

현장이 그대로 잡혔습니다. 한 줄은 디스크 기록 확정(WALSync)을 5.0초째 기다리고 있었습니다.

다른 줄은 같은 쿼리였습니다. 첫 줄이 쥔 행 잠금이 풀리길 기다리는 중이었습니다.

fsync가 늦으니 잠금이 길어지고, 잠금이 길어지니 뒤가 줄을 섭니다. 디스크 IOPS 그래프만 봤다면 이 연쇄는 끝내 안 보였을 겁니다.

그 쿼리는 둘 다 "마지막 접속 시각"을 지금으로 바꾸는 UPDATE였습니다.

2.5초마다 한 줄씩

쿼리를 따라 코드로 들어갔습니다. 외부 고객이 쓰는 문의 화면 쪽이었습니다.

문의자 화면은 새 답변이 왔는지 보려고 2.5초마다 서버를 부릅니다(폴링). 서버는 그 요청을 받을 때마다 문의자의 접속 시각을 조건 없이 UPDATE하고 있었습니다.

화면 하나만 열어 둬도 1분에 24번 쓰기가 생깁니다. 앱이 DB와 맺어 두는 연결은 5개뿐이었습니다.

디스크가 점검으로 막히자 쓰기 한 번이 5초씩 연결을 쥐었습니다. 로그인처럼 DB가 필요한 요청은 빈 연결을 기다려야 했습니다.

이 사고는 예고돼 있었습니다. 그달 초 코드 감사 때 연결 풀 설정 옆에 주석을 남겨 두었습니다. 요지는 이랬습니다.

"연결 풀이 5개인데 쿼리 실행 상한이 없어서, 디스크 IO가 멈춰 연결 5개를 전부 쥐면 앱 전체가 겉보기엔 정상인 채로 먹통이 된다."

그때 쿼리 실행 상한 15초(statement_timeout)를 넣어 둔 덕에 완전히 멈추지는 않았습니다. 로그인 최장 시간이 21초 근처에서 끊긴 이유입니다.

다만 막히는 길 자체는 열려 있었고, 상한은 피해의 크기만 줄여 주었습니다.

고른 처방, 고르지 않은 처방

먼저 UPDATE에 조건을 붙였습니다. 접속 시각이 5분보다 오래됐을 때만 씁니다.

UPDATE requesters
SET last_seen_at = now()
WHERE id = $1
  AND last_seen_at < now() - interval '5 minutes';

폴링은 2.5초 그대로여도 쓰기는 화면 하나당 1분 24번에서 5분 1번으로 줄어듭니다. 이어서 연결 풀을 5개에서 15개로 늘렸습니다.

한 경로가 막혀도 다른 요청이 쓸 칸을 남겨 두려는 조치입니다. 단위 시험 148개와 DB 시험 69개를 통과시켰고, 실제 화면 동작 7가지를 하나씩 눌러 확인했습니다.

배포된 번들을 열어 조건문이 실제로 들어갔는지도 봤습니다. 빌드 통과만으로는 라이브 반영을 알 수 없어서입니다.

고르지 않은 선택지도 있었습니다. 비교하면 이렇습니다.

마지막 줄은 설정 한 줄이면 됩니다. 그런데 이 DB는 재해 대비 복제를 달고 있었습니다.

성능 문제 하나 때문에 그룹웨어 전체 데이터의 내구성을 낮추는 교환은 맞지 않다고 봤습니다. 원인이 "요청마다 쓰는 코드"였으니 거기를 막았습니다.

같은 모양의 UPDATE가 두 곳 더 있었지만 손대지 않았습니다. 사람이 대화를 여는 순간에만 불리는 코드라 폴링 빈도와 상관이 없었습니다.

0.6초의 몫

결과만 보면 로그인이 8~21초에서 0.6초가 됐습니다. 이 숫자를 코드 수정의 성과로 쓰면 과장입니다.

같은 시기에 디스크 정합성 점검을 멈췄고, 회복의 대부분은 그쪽 덕입니다. 점검이 디스크를 붙잡고 있는 동안 모든 쓰기가 느려졌던 겁니다.

점검을 없애지는 않았습니다. 새벽 1시부터 7시까지만 돌고, 멈추면 멈춘 자리에서 이어 검사하도록 옮겼습니다.

코드 수정이 산 것은 따로 있습니다. 디스크가 조금만 느려져도 2.5초 폴링이 연결을 다 잡아먹는 증폭을 끊었습니다.

값은 재발 방지 쪽에 있습니다. 그 효과는 새벽 점검 창이 실제로 돈 뒤 지연 기록과 대조해야 제대로 확인됩니다.

20초 만에 내린 판정

점검을 멈춘 효과를 잴 때 한 번 더 틀릴 뻔했습니다. 멈추고 20초 뒤에 잰 값은 그대로였고 오히려 나빠 보였습니다.

저는 "이번엔 점검이 범인이 아니다"라고 잠정 결론을 냈습니다. 그리고 3분 뒤 같은 측정을 다시 돌렸습니다.

DB 1,000행 쓰기가 3,318ms에서 64.8ms가 됐습니다. 51배입니다.

fsync 중앙값도 1,291ms에서 149ms로 내려갔습니다. 디스크에 밀려 있던 쓰기가 빠질 시간이 필요했던 겁니다.

멈춘 직후의 수치는 멈추기 전 상태를 보여 줍니다. 한 번만 쟀다면 틀린 결론을 들고 다음 단계로 넘어갔을 겁니다.

느릴 때 점검 절차

제가 이번에 틀렸다가 바로잡은 순서를 그대로 절차로 옮겼습니다. 다음에 "느리다"는 말이 나오면 이 순서로 재 보세요.

1. DB를 안 거치는 대조 경로를 같이 잽니다. 상태 점검 주소와 로그인을 같은 자리에서 열 번씩 재고, 응답 코드도 함께 적으세요. 404나 401이 섞인 숫자는 버리세요.
2. DB가 무엇을 기다리는지 봅니다. 위 조회로 wait_event를 확인하세요. IO 대기와 잠금 대기가 나란히 보이면 쓰기가 줄을 세우고 있는 겁니다.
3. 요청마다 쓰는 코드를 찾습니다. 접속 시각, 조회수, 마지막 활동 같은 갱신이 폴링 경로에 붙어 있는지 보세요. 폴링 횟수에 열린 화면 수를 곱하면 쓰기 횟수가 나옵니다.
4. 같은 시기 바뀐 다른 변수와 효과를 나눕니다. 디스크 점검이나 백업, 동기화 작업이 겹쳤는지 보고 처방마다 몫을 따로 적으세요.
5. 안정될 시간을 주고 다시 잽니다. 디스크 쪽을 바꿨다면 몇 분 뒤 한 번 더 재세요. 20초 시점 값으로 판정하지 마세요.

직원들이 느리다고 하는데 원인을 사양으로만 짐작하고 있다면, 장비를 바꾸기 전에 이 순서부터 밟아 볼 만합니다. 이 사례의 그룹웨어는 결재와 회의실 예약, 프로젝트 관리를 한곳에 둔 자체 개발 시스템이고 화면 구성은 그룹웨어 데모에서 볼 수 있습니다.

운영 중인 시스템을 함께 짚어 보고 싶다면 진단 상담에 서버 지표와 느린 화면 이름을 남겨 주세요. 그 두 가지만 있어도 어디부터 잴지 정할 수 있습니다.