데이터베이스에서 발생한 장애 경험 - 1편

데이터베이스에서 발생한 서버 장애 - 1편

 

퇴근 시간이 다가오는 22년 10월 19일 (수) 예비군 훈련 전 날에 집에갈 준비를 하던 도중 아래와 같은 슬랙 메시지가 울렸다. 회사에 서버 개발자가 나 혼자뿐이라 내일 그 어떤 일이 생겨도 처리가 불가능했기에 빠른 시간 내에 그 원인 파악을 끝내고 해결 해야만 했다.

 

최근 그 어떤 변경도 하지 않았고 다른 날에 비해 트래픽이 몰렸던 것도 아니기 때문에 처음에는 사용자 네트워크 문제가 아닐까 생각했다. 하지만 실제로 앱에 데이터 응답에는 상당한 지연시간이 보였다.

 

 스프링 로그 확인하기 

Caused by: java.io.IOException: Broken pipe
    at sun.nio.ch.FileDispatcherImpl.write0(Native Method) ~[na:1.8.0_342]
    at sun.nio.ch.SocketDispatcher.write(SocketDispatcher.java:47) ~[na:1.8.0_342]
    at sun.nio.ch.IOUtil.writeFromNativeBuffer(IOUtil.java:93) ~[na:1.8.0_342]
    at sun.nio.ch.IOUtil.write(IOUtil.java:65) ~[na:1.8.0_342]
    at sun.nio.ch.SocketChannelImpl.write(SocketChannelImpl.java:470) ~[na:1.8.0_342]
    at org.apache.tomcat.util.net.NioChannel.write(NioChannel.java:138) ~[tomcat-embed-core-9.0.37.jar!/:9.0.37]
    at org.apache.tomcat.util.net.NioBlockingSelector.write(NioBlockingSelector.java:101) ~[tomcat-embed-core-9.0.37.jar!/:9.0.37]
    at org.apache.tomcat.util.net.NioSelectorPool.write(NioSelectorPool.java:152) ~[tomcat-embed-core-9.0.37.jar!/:9.0.37]
    at org.apache.tomcat.util.net.NioEndpoint$NioSocketWrapper.doWrite(NioEndpoint.java:1252) ~[tomcat-embed-core-9.0.37.jar!/:9.0.37]
    at org.apache.tomcat.util.net.SocketWrapperBase.doWrite(SocketWrapperBase.java:764) ~[tomcat-embed-core-9.0.37.jar!/:9.0.37]
    at org.apache.tomcat.util.net.SocketWrapperBase.writeBlocking(SocketWrapperBase.java:584) ~[tomcat-embed-core-9.0.37.jar!/:9.0.37]
    at org.apache.tomcat.util.net.SocketWrapperBase.write(SocketWrapperBase.java:528) ~[tomcat-embed-core-9.0.37.jar!/:9.0.37]
    at org.apache.coyote.http11.Http11OutputBuffer$SocketOutputBuffer.doWrite(Http11OutputBuffer.java:538) ~[tomcat-embed-core-9.0.37.jar!/:9.0.37]
    at org.apache.coyote.http11.filters.IdentityOutputFilter.doWrite(IdentityOutputFilter.java:84) ~[tomcat-embed-core-9.0.37.jar!/:9.0.37]
    at org.apache.coyote.http11.Http11OutputBuffer.doWrite(Http11OutputBuffer.java:190) ~[tomcat-embed-core-9.0.37.jar!/:9.0.37]
    at org.apache.coyote.Response.doWrite(Response.java:601) ~[tomcat-embed-core-9.0.37.jar!/:9.0.37]
    at org.apache.catalina.connector.OutputBuffer.realWriteBytes(OutputBuffer.java:339) ~[tomcat-embed-core-9.0.37.jar!/:9.0.37]
    ... 99 common frames omitted

 

로그를 먼저 확인해 보았다. 로그에서 주기적으로 'Broken pipe' 가 발생했고 해당 에러는 보통 해당 서버 처리 가능량보다 많은 요청이 호출되었을 때 주로 발생한다. 현재 애플리케이션 서버의 경우 Auto Scaling이 가능했고 컴퓨팅 리소스도 여유가 있었기 때문에 데이터 베이스의 문제로 밖에 볼 수 없었다. 또한 트래픽이 늘었던 것도 아니고 최근 변경사항도 없었기 때문에 코드상의 문제로 보기에는 힘들었다.

 

일단 해결

우선적으로 문제 해결이 필요했고 현재 서비스중이 었던 API 서버를 재시작을 했음에도 불구하고 문제가 여전히 존재했다. 때문에 데이터베이스의 가능성이 커졌다. 심지어 단일 데이터베이스로 서비스를 했기 때문에 데이터 베이스가 SPOF 이었다. 

 

클라이언트의 전화가 들어와 정상화가 우선 과제였다. 때문에 긴급 서버 점검을 통해 유저 앱 접근을 막아둔 후 데이터베이스의 작업처리를 완료하게 한 후 CPU가 진정된 후 앱 접근을 허용하여 다시 서비스를 가능하게 하였다.

 

😂 추후 확인한 내용이었지만, 복귀 유저에 대한 데이터베이스 부하가 클 것으로 예상되는 상황인 서비스에 기업이나 기관의 유저가 동시 다발적으로 복귀하게 되면서 서비스 데이터베이스에 부하로 이어진 것으로 추측된다.

원인 파악

다음 날 회사의 백엔드 개발자가 혼자 뿐이라 불안한 마음으로 예비군을 다녀왔다. 다녀온 후 저녁 즈음 같은 문제가 발생했다. 원인 파악이 시급해졌다. 문제를 찾으려고 하니 다양한 문제가 보이기 시작했다. 

 

 

첫 번째는 데이터베이스의 환경변수 설정과 스프링 데이터 소스관련 설정의 차이가 눈에 들어왔다. 스프링 설정에 max-lifetime 이 wait_timeout 보다 크게 설정되어 있었다. Spring Boot에서 사용하고 있는 기본 JDBC 커넥션 풀인 HikariCP에서는 max-lifetime에 대해 아래와 같이 명시하고 있다.

 

We strongly recommend setting this value, and it should be several seconds shorter than any database or infrastructure imposed connection time limit.

 

maxLifeTime 설정을 데이터베이스나 인프라 보다 몇 초 더 짧아야 한다고 볼드체로 강조하여 명시 해놓았다. 이는 데이터베이스와의 네트워크 시간 혹은 그 외 작업시간을 고려해 데이터베이스 커넥션이 애플리케이션의 설정보다 먼저 끝나는 것을 막기 위해서 일 것이다. 우선 해당 내용은 변경이 어렵지 않아 변경을 진행할 수 있었다.

 

 

두 번째는 종합적인 문제로 인한 데이터베이스 부하

 

문제가 생겼을 당시에 데이터베이스(RDS) CPU 사용률이다. 데이터베이스의 CPU 사용량이 늘어나면서 처리율이 줄어든 것으로 보인다. 원인이 될 수 있는 요소는 다양하게 존재한다. 

 

우선 단일 데이터베이스를 사용하다 보니 마케팅이나 데이터 가공등을 위해 앱 서비스에서 사용하는 데이터베이스와 같은 데이터베이스를 사용하고 있다는 점이다. 콘솔을 통해 조인이 많이 필요한 쿼리를 날렸을 때 데이터베이스의 CPU 사용률이 급속도로 증가했다. 

 

또 다른 문제는 2억 4천만 로우가 넘는 데이터가 존재하는 테이블이 해당 서비스에 핵심으로 추가, 수정, 조회가 빈번하다는 것이다. 해당 테이블을 사용하고 있는 쿼리의 실행계획을 전체적으로 살펴보았을 때. 인덱스를 타고 있음에도 불구하고 상당한 지연시간이 존재했다. 테이블 자체의 크기가 상당히 크고 배타락이 필요한 수정 작업이 많은 것이 원인으로 보였다. 뿐만아니라 비슷한 특성에 테이블이 여럿 존재하여 추후에 문제는 늘어날 것으로 보였다.

 

대처

문제는 다양하고 복합적이었다. 슬로우 쿼리, RDB로 감당하기 힘들정도의 대용량 데이터베이스, 그러한 데이터를 단일 데이터베이스로 처리하고 있다는 점 외에도 발견하지 못한 문제들이 복합적으로 작용해 더 이상 현재 데이터베이스로는 버틸 수 없는 수준이었다. 하지만 우리 서비스를 믿고 맡긴 다 수의 클라이언트가 존재했기 때문에 빠른 대책이 필요했다.

스케일 업

현재 문제들은 지금 당장 해결할 수는 없는 것들이었다. 학습이 필요한 부분도 있고, 해결에 상당한 시간이나 테스트가 필요한 문제도 있었기 때문에 스케일 업을 통해 시간을 벌어두고 추후 다시 스펙을 낮춰 문제를 해결하고자 하였다. 

모니터링 결과 알람

현재 서버에 문제가 발생했을 때 확인할 방법이 존재하지 않았다. 때문에 문제가 발생했다 하더라도 누군가 앱을 통해 확인해주지 않으면 확인이 불가능했다. 이는 유저의 만족도나 서비스 안정성 측면에서 큰 문제라고 할 수 있다. 때문에 문제가 발생했을 때 해당 문제가 발생했다는 사실을 알려줄 알람 기능이 필요했다.

 

 

현재 CloudWatch를 통해 RDS를 모니터링 하고 있기 때문에 CloudWatch에 경보를 SNS와 Lambda를 활용해 Slack에 메시지를 보내는 방식으로 개발하였다. CPU 사용률이 보통 특정 지점을 넘어서면 급격하게 상승하는 문제를 보여 그 지점을 베이스라인으로 두고 해당 지점을 3분 이상 넘어섰을 때 슬랙으로 메시지를 보내게 한 후 혹시라도 슬랙으로 CPU 관련 이상 알람이 왔을 때 내가 ✅ 하지 않으면 바로 전화주는 것을 사내 규칙으로 선정하였다.

 

해당 방식을 통해 최대한 빠르게 문제를 파악하고 전달 받을 수 있도록 하였다.

 

슬로우 쿼리 로깅

스케일 업과 문제 발생시 알람을 통해 확인 가능한 상태를 만들었지만, 스케일 업은 서버 비용이 상당히 증가하며 또한 해당 문제는 언제든지 다시 발생할 수 있는 시한폭탄과 같다. 그저 시간을 벌었을 뿐 문제를 해결한 것은 아니었다. 때문에 문제가 발생하고 있는 지점을 정확하게 파악하여 대처가 필요했다. 

 

문제가 해결하는 방법으로는 레플리케이션을 사용해 데이터베이스 분산시스템을 구축하거나 2억여건이 넘는 테이블을 샤딩하는 방법 그 외에도 해당 테이블 성격에 적합한 RDBMS가 아닌  다른 데이터베이스 솔루션을 사용하는 방법도 있을 것이다. 하지만, 우선은 해당 작업들은 R&D와 수많은 테스트 과정이 필요했고 현재 혼자뿐인 상황에 검증도 되지않은 방법들을 시도하는 것은 효율적이지 않은 방법이라 판단했다. 때문에 우선은 쿼리 튜닝을 할만한 대상이 있는지 확인해보기로 하였다.

 

현재 RDS 와 CloudWatch를 사용하고 있었기 때문에 파라미터 그룹을 설정하는 것 만으로 Slow Query 수집이 가능했다. 

• 'slow_query_log' : 슬로우 쿼리에 대한 로그를 수집 여부를 결정할 수 있다 값이 1일 때는 수집하고 0일 때는 수집하지 않는다.
• 'slow_query_log_file' : 슬로우 쿼리 로그를 수집하여 저장하는 파일의 경로를 의미한다.
• 'long_query_time' : 슬로우 쿼리의 판단 기준으로 해당 시간보다 긴 쿼리의 경우 슬로우 쿼리로 판단한다.

설정 추가로 슬로우 쿼리에 대한 로그를 수집하고 해당 로그들을 통해 문제가 될 수 있는 지점들을 파악할 수 있게 되었다.

 

 

다음 작업

지금까지는 빠른 대처와 추후 다시 발생했을 때에 대한 대비 그리고 문제지점을 파악하기 위한 설정을 진행하였다. 스케일 업을 통해 시간을 벌어두기는 했지만 문제를 파악한 이상 그대로 두기는 힘들다. 다음 작업에 대한 계획이 필요하다.

 

지금 당장할 수 있는 것은 로깅해둔 슬로우 쿼리를 순차적으로 튜닝하는 것이 최선이라고 생각한다. 때문에  우선적으로 쿼리튜닝을 진행할 예정이다. 하지만 현재 문제라고 판단되는 테이블이 데이터수가 2억 4천만 로우가 넘고 증가하는 속도가 무시할 수 없는 수준이다.

 

때문에 추후 변경할 수 있는 방법들에 대해 검증이 필요했고 쿼리 튜닝을 진행한 후 레플리카를 통해 읽기/쓰기 분리, 문제되는 테이블을 MongoDB로 마이그레이션 등의 방법과 현재 방법을 비교해 보고 추후 변경할 방법을 결정할 필요가 있어보인다.