이슈 발생
업무 중에 서버 장애 알람이 연달아서 울리기 시작했다. 다급하게 Datadog을 확인해보니,
이와 같이 들어온 요청에 대해 지속적으로 500 에러가 발생한 것을 확인할 수 있었다.
이슈 해결 과정
디스크 용량 부족
Dashboard를 살펴보니,
쓰기가 굉장히 많이 발생하고 있었고,
디스크의 용량이 급격하게 줄어들었다. 할당된 80GB의 용량에서 여유 공간 32GB를 유지하다가, 16시 언저리를 기점으로 용량이 급속도로 줄어들었다. 그에 자동 증설 설정에 따라 200기가로 용량이 증가했지만, 그마저도 굉장히 빠른 속도로 20분 정도만에 다 소진되어 잔여 여유 공간이 0으로 떨어졌다.
요청들을 보면 실패하는 요청은 전부 POST 요청이고, GET 요청은 응답에 성공한다. 회사의 서버는 조회를 제외한 CUD에 대해 로그를 남긴다. 디스크 용량이 부족해졌기 때문에, CUD를 수행하는 POST 요청에 대해 binlog를 남기기 위해 여유 공간이 생길 때까지 대기하고 50초 이후에 timeout이 발생한 것으로 보인다.
디스크에 많은 데이터를 쓰는 원인 찾기
그렇다면 디스크에 빠른 속도로 많은 데이터를 write하는 원인은 무엇일까. 원인을 찾던 중 인프라 팀에서 특정 쿼리가 굉장히 오랫동안 실행되고 있다는 것을 확인했다.
show full processlist 명령어를 통해 RDS에서 실행중인 프로세스를 확인해보니,
select JSON_EXTRACT(ai.properties, "$.questionNum") as questionNum, ai.properties, ai.*
from AnalysisInterview ai
inner join Interview i on i.analysisSeq = ai.analysisSeq
inner join AnalysisInterviewUnitData aiud on aiud.analysisUnitSeq
inner join Recruit r on i.recruitSeq = r.recruitSeq
where i.recruitSeq = 607537
order by ai.analysisSeq desc
SQL
복사
이와 같은 쿼리가 50분이 넘도록 실행되고 있었다고 한다.
일단 원인 분석에 앞서 조치를 먼저 취해야해서 해당 쿼리를 강제로 kill 하고 나니,
이와 같이 여유 공간이 급격하게 확보되기 시작했고, 그에 따라 이후에 들어오는 모든 요청도 성공적으로 수행되어 응답을 보내면서 서비스가 정상화 되었다.
원인 분석
쿼리 분석
그렇다면 원인이 되었던 쿼리를 다시 살펴보자.
SET STATEMENT SQL_SELECT_LIMIT=501 FOR
select JSON_EXTRACT(ai.properties, "$.questionNum") as questionNum, ai.properties, ai.*
from AnalysisInterview ai
inner join Interview i on i.analysisSeq = ai.analysisSeq
inner join AnalysisInterviewUnitData aiud on aiud.analysisUnitSeq
inner join Recruit r on i.recruitSeq = r.recruitSeq
where i.recruitSeq = ?
order by ai.analysisSeq desc
SQL
복사
inner join 부분을 잘 살펴보면, AnalysisInterviewUnitData를 결합할 때 on 절에 조건이 없는 것을 확인할 수 있다. 이 쿼리는 서비스나 로직에서 발생한 쿼리는 아니고, 다른 개발자 분이 데이터 조회를 위해 직접 입력하신 쿼리이다. 그 과정에서 inner join의 on 절에 조건을 누락했던 것이다.
TEXT 컬럼과 임시 테이블
그렇다면 쿼리가 수행된 것과 디스크 용량이 무슨 상관일까.
관련 내용을 찾던 중 MySQL 공식 문서에서 다음과 같은 내용을 발견했다.
Some query conditions prevent the use of an in-memory temporary table, in which case the server uses an on-disk table instead:
•
Presence of a BLOB or TEXT column in the table. The TempTable storage engine, which is the default storage engine for in-memory internal temporary tables in MySQL 8.4, supports binary large object types. See Internal Temporary Table Storage Engine.
일반적으로 조회 시에 인메모리로 임시 테이블을 생성해 데이터를 정리하지만, TEXT나 BLOB 타입의 컬럼이 있다면 인메모리가 아닌 온디스크 방식으로 임시 테이블을 처리한다는 것이다.
위에서 수행된 쿼리가 조회하는 properties 컬럼은 TEXT 컬럼으로 JSON 데이터가 말려서 들어가있다. 때문에 이를 조회할 때 온디스크 방식의 임시 테이블에 조회하는 데이터를 정리하게 된다. 하지만 on 절이 누락됨으로 인해 카테시안 곱만큼 엄청나게 많은 데이터와 결합하여 조회됨에 따라, 해당 데이터를 처리하기 위해서 엄청나게 많은 디스크 용량을 사용했던 것이다.
후속 조치
사실 이번 장애는 데이터베이스 설정에 슬로우 쿼리 제한을 걸어두지 않았기 때문에 발생했다고도 볼 수 있다. 개발 과정에서 실수로 쿼리를 작성하는 일은 충분히 있을 수 있지만, 해당 쿼리가 50분 동안 실행되며 리소스를 차지한 것은 문제가 된다. 만약 이번 문제가 TEXT 컬럼을 조회하지 않았다면, 메모리 부족으로 서버가 내려갔다가 올라갔을 것이다.
이후 인프라 팀에 요청하여, 쿼리 실행이 3분이 넘어가면 알림을 보내고 10분이 넘어갈 때는 자동으로 프로세스를 끄도록 설정했다.
느낀 점
사실 이번 장애에 있어서 단순히 원인 찾았고 조치했으니까 끝!이 아니라 나 스스로 납득할 수 있을만큼의 이해를 하고 그 원인 분석을 통해 추후 이와 같은 이슈나 장애의 재발을 막고 싶었다.
마침 조회하는 데이터가 TEXT 컬럼이였고, 실수로 join의 on 절 조건을 빼먹어 카테시안 곱만큼의 데이터를 처리해야할 필요가 있었기 때문에 이와 같이 디스크 부족으로 이어지는 결과였다. 사실 이와 같은 각 인과관계를 명확히 찾고 이해하고 난 후에는 조금 허무했지만, 그래도 싸게 배웠다고 생각한다.
이번 일을 다같이 해결하면서 개발자로서도 운영 서버에 쿼리를 작성할 때 신중을 기해야겠다는 생각이 들었다. 조회 쿼리니까 어떻게 수행해도 괜찮겠지라는 안일한 생각이 있었는데, join을 잘못 수행하면 서버에 장애가 발생할 수 있다는 점을 깊게 새기게 되었다.