whatap china

광군제를 사수해라! – 중국 클라우드 마이그레이션시 발생한 장애 대응기.

blog_signup_banner_b (3)

배경 설명

casestudy_china.002

유명한 K쇼핑몰은, 한국 물리적 서버(Dedicated Server)에 운영중이던 서비스를, 중국 진출을 위해 클라우드로 마이그레이션을 진행했습니다.

그런데 마이그레이션을 한 이후에 성능 저하가 발생했고, 다가오는 광군제(중국의 블랙프라이데이와 같은 큰 이벤트)를 위해 성능 이슈를 반드시 해결해야 하는 상황이었습니다. 이렇게 급박한 상황에서 밤 사이에 WAS(Web Application Server)가 다운되는 장애가 발생해 K사는 와탭에 성능 모니터링을 요청하게 됩니다.

casestudy_china.003

와탭 기술지원팀이 처음 갔을 때 분위기는 위 그림과 같이 심각했습니다. 광군제는 트래픽이 평소의 열 배 정도로 증가하기 때문에 매출을 대폭 상승시킬 수 있는 절호의 기회입니다. 그런데 이 때 서버의 성능 이슈가 발생해 큰 손실로 이어질 수 있는 정말 심각했던 상황이었던거죠.

그렇다면 WAS가 다운되기 전에 무슨 일이 있었던걸까요?

1차 현황 – 클라우드에서 제공하는 기본 VM은 일정 IOPS를 보장하지 못한다 .

casestudy_china.004

먼저 오라클 DB를 물리 서버에서 클라우드로 마이그레이션하는 과정에서 DB Disk IO에 성능 저하가 발생했습니다. 당시 K사는 윈도우 서버를 사용하고 있었는데, Batch job이 돌 때마다 Windows Disk Que Length가 100~200까지 증가합니다. 이 Disk Que Length라는 수치는 IOPS(I/O per second, 초당 IO 처리량)가 임계점에 도달하면 나머지 job들이 que에 쌓이기 때문에 원래 0에 가까워야 하고, 2가 넘어도 문제 상황이 될 수 있는데 200까지 증가하는 말도 안되는 수치가 나왔던거죠.

그래서 AWS의 provisioned IOPS나 Azure의 premium storage와 같이 IOPS를 일정 부분 보장하는 제품으로 Storage를 변경한후,  DB 동기화를 진행하는 방법으로 1차 대응을 진행하였습니다. 

2차 현황 – 대용량 데이터 동기화로 인한 네트워크 구간 단절

casestudy_china.005

그런데, 서비스를 하는 도중에 DB에 대용량 데이터가 동기화되면서 Public Network 구간이 단절돼버렸어요.

DB OS와 Disk가 네트워크로 연결되어 있었는데, 이 네트워크가 단절되면서 Disk를 쓰지 못해 장애가 발생했던거죠. DB 서버의 문제가 WAS의 장애를 일으킨 사례였습니다.

가장 큰 문제는 DB 서버였지만, WAS가 다운된 상황이었고 광군제를 앞둔 상황이라서 고객사에서 WAS의 개선점을 파악해달라고 요청을 하셨습니다.

수술을 해야 하는데, 수술을 할 수 없는 상황..

저희는 점쟁이가 아닙니다.  도착한지 몇 시간 되지도 않았는데 바로 개선점을 파악하기는 어려웠습니다. 전반적인 요청 건수나 TPS조차도 모르는 상황이었기 때문에 튜닝을 위해서는 APM 설치가 불가피했습니다.
기본적으로 APM은 설치 과정 중 서비스 재기동이 필요하기 때문에, K사는 서비스에 영향을 주면 안된다는 이유로 설치를 거절했습니다.

마치 X-ray로 내부를 보지 못하고, 외부에 현상만으로 문제의 원인을 도출해 달라는 이야기 였습니다.  우스개 소리지만 실제 장애가 나면 모니터링 때문에 부하가 더해져서 장애가 났다고 하시는 분도 많습니다.  🙂

하지만 다행히 와탭 APM은 재기동 없이도 톰캣 서버를 인식하여, Attach 방식으로 설치가 가능했기 때문에  설득하여 설치를 했습니다.

APM 설치 후 –  현상 및 원인 파악.

casestudy_china.009

당시 APM을 설치한 후의 대시보드 화면인데요, 원형 차트는 아크 이퀄라이저라는 차트로 현재 진행중인 트랜잭션을 모니터링하는 차트입니다. 아크 이퀄라이저를 보면 581건의 트랜잭션이 진행중이고, 그 중 트랜잭션이 실행한지 8초가 넘게 진행중인 상태의 트랜잭션(붉은색 호)이 500개 이상인 병목 상태였습니다.

오른쪽의 차트는 히트맵이라는 차트로, 트랜잭션의 응답시간 별 분포를 보여줍니다. 히트맵을 보니, 일정 구간마다 Batch가 돌아서 트랜잭션이 모두 지연되는 상황이었습니다. 반면 CPU나 Heap Memory의 사용량은 안정적이었습니다. 

casestudy_china.010

해결책 1 – DB 서버의 IO를 분산해라! 

누가 봐도 DB 서버의 성능 이슈가 너무나 컸기 때문에, WAS에서는 개선포인트가 크게 드러나지 않았습니다. 그래서 오라클 튜닝 전문 DBA와 함께  DB 튜닝 작업과 WAS 모니터링 작업을 병렬적으로 진행하게 되었습니다.

casestudy_china.011

먼저 DBA분은 아래와 같은 문제들을 해결했습니다.

  1. 오라클 DB IO 성능 개선을 위해, Redo Log(오라클의 변경 사항 저장)사이즈를 변경했어요. Redo Log를 Write하며 성능 저하가 많이 발생해서 100MB * 3개를 5GB * 5개 로 변경했고, DB 로그 디스크와 Data 디스크를 분리해서 IO 분산 작업을 진행했습니다.
  2. Index가 없는 것들은 찾아서 추가했습니다.
  3. 슬로우 쿼리를 튜닝했습니다.
  4. 아까 말씀드렸던 IOPS를 보장하는 Storage로 개선 작업을 진행합니다.

APM은 전반적인 상황을 파악하는 컨트롤 타워 역할을 했습니다.

WAS를 모니터링하며 히트맵에서 느린 트랜잭션의 Slow query들을 찾아서 DBA분께 전달하였고, 성능 저하가 보통 어느 URL에서 많이 발생했는지, 트래픽이 정상적으로 들어오는 상황이었는지, DB 쿼리가 느린건지, 아니면 자원에 병목이 있었는지 등을 파악했습니다. 

장애 2 – 광군절을 앞둔 예비 프로모션 시작, 그런데…

casestudy_china.012

DB가 앞의 작업들을 통해 어느정도 튜닝이 되면서 서비스가 안정화된것처럼 보였는데요, 저녁에 프로모션을 시작하면서 갑자기 서버가 폭주하게 됩니다. 종료되지 않은 트랜잭션이 3천건이었고, 80초 이상 지연되는 트랜잭션도 같이 폭주하고 있죠. 그런데 이상하게도 WAS의 CPU 사용량은 50%도 넘지 않았습니다.

장애 2 – 엎친데 덮친 격으로.. 또 장애 발생.

casestudy_china.014

엎친 데 덮친 격으로 Debug Log를 켠 상태로 WAS를 운영해 2차 장애가 발생합니다. 보통 이런 장애가 발생했을 때 원인을 찾기는 정말 어렵습니다.

하지만 와탭의 APM은 10초마다 callstack을 기록하며(Active Stack 기능), 여기에서 Debug Log와 관련된 스택들을 발견해 이 상황의 원인을 찾을 수가 있었습니다. 실제 장애의 원인은  Debug Log 였습니다.   callAppenders라는 로직에 있는 sync 블록 때문입니다. 이것때문에 트래픽이 정상적일 때에는 큰 병목이 발생하지 않는데 트래픽이 몰렸을 때 죽는 상황이 발생합니다.

장애 대응 – Debug Log 끄고, Scale Out으로 발빠르게 임시 조치! 

casestudy_china.015

이어지는 문제들을 해결하기 위해 먼저 Debug Log를 껐습니다. 그리고 한 번 폭주하기 시작한 WAS는 요청을 처리하지 못하는 상태가 되어버리기 때문에 빠르게 재기동 조치를 취하고, 트래픽이 몰렸을 때 처리를 하지 못했기 때문에  Scale Out까지 진행했습니다.

그런데 말입니다..

여전히 풀리지 않은 의문이 있었습니다. 폭주 당시 DB 서버는 어느정도 안정화가 된 상태였기 때문에 원인은 DB 서버가 아니었고, WAS의 CPU량도 50%를 넘지 않는 상태였습니다.   전체적으로 자원이 남아 도는데 장애가 발생했다는 것은, 자원의 문제가 아닌, 또 다른 어딘가에 병목이 존재한다는 의미였습니다. 

장애 3  –  원인이 발견되지 않는 hang 현상

casestudy_china.016

저희는 문제를 찾던 중 원인을 알 수 없는 이상 현상을 발견합니다. 위 그림의 아크 이퀄라이저를 클릭하면 진행중인 트랜잭션의 목록을 볼 수 있어요. 이 목록을 확인해보니, 100초가 넘어도 종료되지 않는 트랜잭션이 계속 발생했습니다. 위 그림을 보시면 700초가 넘은 트랜잭션이 있습니다.

이 트랜잭션은 어떤 상황에서도 종료되었어야 하는 트랜잭션인데 남아있다는 것이 이상했고, 상세 내역을 뒤져보니 select ‘#’ from dual이라는, 1초 이내에 끝나야 하는 쿼리문에서 더이상 진행되지 않고 멈춰있는 hang 현상이 발견되었습니다.

장애 3 원인 파악  – 행 현상 해결을 위한  가설 수립

casestudy_china.017

그래서 현재 상황을 정리하고, 가설을 수립했습니다.

먼저 이미 끝났어야 하는 쿼리에서 트랜잭션이 멈춰서 종료되지 않았습니다.  WAS를 껐다가 다시 재기동할때까지 이러한 트랜잭션이 백 개가 넘도록 계속 쌓이는 상황이었고, 이것들이 Connection을 점유하고 있다면 트래픽이 몰렸을 때 장애로 연결될 수 있는 상황이었습니다.

  1. 첫번째 가설은 Connection Pool 라이브러리의 문제였습니다. 보통은 Tomcat의 DataSource를 사용하는데, K사에서는 중국의 알리바바 Druid Connection Pool을 사용하고 있었어요.
  2. 두번째 가설로는 앞서 DB의 성능 이슈가 많이 있었기 때문에 DB나 네트워크 등의 외부 자원에서 연결 문제를 생각했습니다.

장애 3 원인 파악 – Connection Pool 라이브러리 분석

casestudy_china.018

먼저 와탭 APM의 Active Stack에서 Connection Pool의 이름을 찾았고, 라이브러리의 버전을 확인했습니다. 다음으로 Github에서 해당 버전의 소스코드를 다운받아서 분석했습니다. Connection을 얻고 반환하는 로직을 분석했지만 큰 이상을 발견하지 못했고, 다만 Connection을 관리하는 방식이 Tomcat과 다르다는 점을 발견했습니다.

Tomcat DataSource는 Queue를 사용해서 모든 Connection Pool을 한 번씩 사용하도록 관리하는데, Druid는 Stack으로 관리를 해서 최근에 반환된 Connection Pool을 다시 사용하고 있다는 게 특이한 점이었습니다.

https://github.com/alibaba/druid/blob/master/src/main/java/com/alibaba/druid/pool/DruidDataSource.java 에서 pollLast를 보시면 됩니다.

장애 3 원인 파악 – 사소한 이상현상도 놓치지 말자

casestudy_china.019

저희는 Connection Pool을 Stack으로 관리한다고 해서 Hang 현상을 일으키지는 않을 거라고 생각했습니다. 그러던 중, DBA분께서 DB Tool과 DB의 연결이 자꾸 끊어진다고 말씀을 해주셨어요. 네트워크 부분을 의심하고 있었던 상황에서 이러한 문제가 발생했기 때문에 들어가서 확인을 하게 됐습니다.

확인을 해 보니, DB Tool은 연결이 끊어졌는데, DB 서버는 연결중이라고 상태를 표현하고 있는 이상한 상황이었습니다. 이상해서 연결 과정을 추적해봤더니 DB Tool이 DB 서버에 바로 연결된 것이 아니라 중간에 Load Balancer가  있었습니다. .  

이 수상한 LB를 더 자세히 보니, 기본 idle timeout이 4분으로 설정되어 있었습니다. 즉  4분 이상 아무 행동을 하지 않으면 LB가 네트워크를 끊었고, DB Tool은 연결이 끊겼는데 DB 서버는 연결됐다고 인지를 하는 이상한 상황이 된거죠.

이러한 상황을 발견하고, 테스트 애플리케이션을 작성해서 테스트를 하게 됩니다. Sleep을 5분 이상으로 세팅한 후 테스트를 했더니, 트랜잭션 hang 현상이 callstack까지 동일하게 재현되었습니다.

장애 3의 원인은 – LB Timeout과 Stack으로 관리되는 Connection Pool

casestudy_china.020

사실 idle timeout이 4분이라고 해서 문제가 되는 것은 아니고, 마찬가지로 Connection Pool을 Stack으로 관리한다고 해서 문제가 되는 것은 아니지만 이 두 가지 원인이 결합하며 hang을 유발하는 상황이 되어버렸습니다. Connection Pool의 위에 있는 Connection들만 사용되다 보니, 아래의 Connection들은 timeout 시간을 지나버렸고, 연결이 끊어진 Connection을 사용하다 보니까 트랜잭션에 hang이 걸리는 상황이 되었던 것입니다.

Stack 방식의 Connection Pool 교체는 개발팀에서 코드를 수정해야 하는 부분이었기 때문에 어떻게 하지 못했지만, idle timeout을 30분으로 변경함으로써 트랜잭션 hang이 걸리는 현상을 거의 다 해결합니다.

결론

정말 긴 이야기였습니다.  문제와 대응 방안은 아래 이미지와 같이 정리해봤습니다.

casestudy_china.021

또 성능 개선 전과 개선 후의 차트로 데이터를 비교하면 아래와 같습니다.

casestudy_china.022

성능 개선 전에는 행 걸린 트랜잭션이 500건 이상이었고, 80초까지 트랜잭션이 지연되었습니다. 반면 성능 개선 후 진행중인 트랜잭션은 0건으로 나옵니다. 아크 이퀄라이저는 5초마다 스냅샷을 뜬 상황을 보여주기 때문에, 0건이라는 수치는 트랜잭션이 아무것도 유입이 안된다는 의미가 아니라 트랜잭션이 1초도 걸리지 않고 금방 끝난다는 의미입니다. 오른쪽 히트맵에서도 모든 트랜잭션이 1초 이하로 종료되는 것을 확인하실 수 있습니다.

오라클 IO 성능은 10배에서 30배정도 개선이 되었고, 1초에서 80초까지 다양하게 지연되던 트랜잭션 응답시간이 1초 이하로 개선되는 성과를 거뒀습니다. 이후에도 여러 문제가 있었지만 대부분의 이슈들이 해결되면서 K사는 광군제를 성공적으로 진행할 수 있었습니다.

casestudy_china18

실제 튜닝은 각 분야의 전문가들이 진행을 하게 됩니다.  각자가 자신의 분야를 잘 알지만, 결국 필요한 것은 모든 분야의 문제를 통합적으로 보여줘서 각 전문가들이 공감하고 소통할 수 있는 데이터였습니다.

와탭의 APM은 이렇게 통합된 데이터를 보여주는 툴이며, 특히 의사결정권자가 튜닝에 대한 지식이 없다면 APM은 더욱 효과적인 커뮤니케이션 수단으로 활용될 수 있을 것입니다.

blog_signup_banner_b (3)

위 장애 이야기 강의 영상