안녕하세요. 지난 포스팅에서는 성능테스트를 계속 모니터링하면서 새로운 문제점을 찾고, 문제의 원인이 될만한 부분을 하나씩 확인하고 수정해보면서 총 8차시의 재 테스트를 걸쳐 문제를 해결해나가는 과정을 보았습니다. 다행히 처음 발견된 문제는 개선할 수 있었으나, 다른 문제가 또 나타나게 되었는데요. 바로 테스트 진행 시 일정시간만 지나면 다음과 같이 TPS가 급감해버리는 부분이었습니다. 해당 글을 작성한 후 몇번이고 테스트를 반복해보았지만 약 3분이 경과되는 시점에서 항상 똑같은 문제가 발생했습니다.
이번 포스팅은 위의 문제에 대한 해결 과정을 요약해서 다뤄보고자 합니다.
문제 해결과정
1) pinpoint & JvisualVM/JvvisualVM 살펴보기
가장 먼저 좀 더 나은 지표 확인을 위해 성능테스트 모니터링을 위해 꾸준히 사용해왔던 핀포인트 외에도 JMC(JDK Mission Control)과 JVisualVM을 서버에 연결하기로 결정했습니다. 연결하는 방법은 크게 어렵지 않았기에 간단히 언급만 하자면, WAS 서버에서 java -jar 명령어를 통해 배포한 jar 파일을 실행할 때 아래의 옵션을 함께 넣어줍니다.
-Dcom.sun.management.jmxremote.port=(지정 포트)\
-Dcom.sun.management.jmxremote.rmi.port=(지정 포트) \
-Dcom.sun.management.jmxremote.ssl=false \
-Dcom.sun.management.jmxremote.authenticate=false \
-Dcom.sun.management.jmxremote=true \
-Djava.rmi.server.hostname=(WAS 서버 IP) \
서버 구동이 완료되면 JMC를 열고 다음 버튼을 클릭합니다.
이후 아래 Host에는 측정할 서버의 IP를, 그리고 Port에는 위의 스크립트에서 지정한 포트를 넣어주고, Test Connection을 클릭하여 연결이 올바르게 이루어지는 지 확인하고, 올바르게 되었다면 Finish를 확인해주면 끝입니다. JVisualVM 연결 과정은 WAS 실행 시 주었던 같은 옵션을 활용해 JMC와 마찬가지로 손쉽게 연결할 수 있기 때문에 생략하였습니다.
이후 이전과 같은 조건에서 다시 테스트를 구동하여 커넥션 풀, Heap 영역, GC 여부 등등 성능에 영향을 미칠만한 부분은 모두 찾아봤지만 안타깝게도 특이한 문제점은 발견되지 않았습니다. 다만 핀포인트의 Call Tree를 살펴보니 다음과 같은 지표를 얻을 수 있었습니다.
어떤 연유인지는 모르겠으나, 로그인 메소드를 수행할 때, 로그인 정보를 가져오는 부분이나 쿼리를 실행하는 부분에서 시간이 지연되고 있었습니다. 잠깐 동안 쿼리에 문제가 있나 싶었으나, 이는 말이 안되는 부분이었습니다. 해당 쿼리가 다음과 같기 때문입니다.
SELECT
u.userId AS userId,
u.password AS password,
t.token AS token
FROM users AS u
LEFT OUTER JOIN tokens AS t on u.userId = t.userId
WHERE u.userId = #{userId} AND isDeactivated = 'N';
푸시알림을 보낼 때 사용할 토큰을 저장해두고, 로그인 시 토큰의 변경여부를 함께 확인하고 변경된 경우는 업데이트를 해줘야하기 때문에 위와 같이 조인이 들어가긴 했지만 기본적으로 users나 tokens 모두 제대로 된 인덱싱이 되어있어 불필요한 데이터의 스캔없이, 일치하는 단 하나의 row를 빠르게 찾을 수 있기 때문에 문제가 없어야 했습니다. 실행계획 상에도 큰 문제가 없었으며, 실제로 혹시나 하는 마음에 로그인 시 token을 받을 필요가 없도록 소스코드를 변경함으로써 조인을 없애고 다시 테스트를 실행했으나 여전히 똑같은 문제가 계속되었습니다.
2) 슬로우 쿼리 및 QPS (Query Per Second) 확인
위의 핀포인트 CallTree에서 쿼리 실행 시 1초가 넘는 시간이 걸렸다는 사실을 보여주었으니, DB 서버 내부에 존재하는 슬로우 쿼리 로그를 확인해보았습니다. 몇 개의 로그가 기록되어 있었는데, 문제는 위의 쿼리에 대한 수행시간에 대한 기록이었기 때문에 크게 도움이 되지 않았습니다.
다음으로는 MySQL 서버로 들어오는 쿼리의 양 자체를 확인해보는 것이었습니다. 테스트 중간 지점부터 DB에 들어오는 요청의 양이 줄어들어서 TPS가 떨어지는건가 하는 생각에 QPS를 확인해보기로 했습니다. QPS확인은 MySQL 서버의 커맨드 창에 mysqladmin -u root -p status -i3 을 입력하여 3초마다 한 번씩 조회함으로써 손쉽게 확인할 수 있었습니다. 해당 명령어가 수행되는 동안 테스트를 다시 실행했는데, QPS가 약 2000대 정도를 보여주었기에 이 부분도 문제를 일으키는 원인이 아님을 확인할 수 있었습니다.
3) my.cnf 설정 값들 조정하기
기존에 DB 관련 설정 파라미터들을 거의 조정해주지 않은 상태였기 때문에 현재 발생하는 문제가 설정 값들과 관련이 있지 않을까 생각해보았습니다. 물론 Real MySQL을 읽었을 때 명시되어 있었던 부분이 '기본 값의 의미'에 대한 부분이었습니다. 기본 값이라고 해서 설정이 안된 값이 아니라, 전문가들이 섬세한 튜닝과정을 통해 최대한 범용적으로 사용할 수 있는 설정 값을 기본 값으로 부여했다는 내용이었습니다. 혹시나 하는 마음에 이전에 학습했던 Real MySQL 책을 열어 설정 파일 내부에 존재하는 파라미터들에 관해서 하나 씩 복습하고, 해당 내용을 직접 my.cnf에 반영했습니다. (ex. innodb_buffer_pool_size 설정값 변경) 이후 MySQL 서버를 재시작해 변경내용을 적용해주고 테스트를 수행했으나 예상했던대로 문제는 해결되지 않았습니다.
4) redis stat을 활용한 레디스 서버 모니터링
로그인 시 '요청 -> 요청 받은 정보와 DB에 저장되어 있는 해당 사용자의 정보 비교 -> 일치 시 레디스에 세션 데이터 저장'의 과정을 거치기 때문에 마지막으로는 레디스 서버를 모니터링해보기로 했습니다. redis stat을 활용하면 웹과 콘솔을 통해 모두 모니터링이 가능하다고 해서 redis-stat 을 설치하기로 결정했는데 선행 요건인 Ruby를 설치하는 도중 원인 불명의 오류로 더 이상 진행이 불가능한 문제가 발생하였습니다. 다행히 redis-stat 측에서 jar 파일을 배포하고 있었기에 wget https://github.com/junegunn/redis-stat/releases 을 활용해 jar 파일을 다운받고, 이를 직접 실행함으로써 redis-stat을 구동시킬 수 있었습니다. 다만, 문제는 레디스에서도 아무 특별한 문제점을 찾을 수 없었다는 점이 문제였습니다.
5) Thread Dump 분석
MySQL과 레디스 둘을 직접 모니터링했으나 별다른 문제점을 찾을 수 없었기에, 시선을 WAS 서버 쪽으로 돌리기로 했습니다. 사실 이미 1)번에서 모니터링 도구를 활용해 필요한 지표들은 모두 확인을 했었기에, 더 추가적으로 체크해볼만 한 부분은 쓰레드 덤프 정도가 있었습니다. 쓰레드 덤프를 떠내는 방법은 WAS 서버 커맨드 창에서 kill -3 를 활용하는 등 여러가지가 있었는데, 이미 사용중인 JVisualVm에서 아래 사진처럼 간편하게 쓰레드 덤프를 추출할 수 있게 도와주었기 때문에 이를 활용했습니다.
이렇게 추출한 파일들은 쓰레드 덤프는 읽기 편하게 분석해주는 https://fastthread.io/ 사이트에 업로드하여 그 결과를 제공받아서 내용들을 살펴보았습니다. Lock 점유 시간이나 혹시 모를 Dead Lock 발생 여부를 위주로 결과 리포트를 확인했는데, 아무래도 테스트 대상은 로그인 메소드가 유일했으므로 애초에 동기화 등의 복잡한 로직이 존재없었기에 쓰레드 덤프에서도 큰 특징은 찾아낼 수 없었습니다.
혹시나 하는 마음에...
여러 부분을 살펴보았으나 몇 주간 진척이 없던 시점, 본격적인 Docker 학습을 위해 GCP에 새로운 서버 인스턴스를 만들면서 무언가 눈에 띄는 점을 확인하게 됩니다.
기본 설정으로 CPU는 두 개였지만, 일반 코어가 아니라 공유 코어가 포함되어 있었다는 점입니다. 그간 생각해보지 못한 부분이었는데, 이것을 보자마자 혹시나 하는 마음이 다시 들었고 곧바로 일반코어 2개로 서버를 생성했습니다.
이후 새롭게 생성한 서버에 다시 MySQL을 설치했고 설치가 완료되자마자 곧바로 테스트를 진행하려고 했으나, 테스트를 위한 데이터가 하나도 없다는 것을 깨달았습니다. 그래서 기존 MySQL 서버에서 데이터를 Dump하고 scp 명령어를 활용해 서버간 복제-전송을 해준 뒤, 전송받은 새 MySQL 서버에 덤프 데이터를 적재하고, 해당 서버를 WAS에 연결해주었습니다.
문제가 해결되었을까요?
DB 서버의 이전을 모두 마치고, 다시 테스트를 수행해보았습니다. 새로운 DB서버를 활용해 테스트를 진행하는 만큼 vUser수를 곧장 3000으로 지정해서 테스트를 진행하는 것이 아니라 1000으로 살짝 낮춰서 실행해보기로 했습니다.
그리고 마침내!!! 테스트 수행시간이 3분이 지났음에도, WAS 서버 내부의 CPU 사용률 80~90% 대로 계속 유지되는 모습을 보여주었습니다.
DB 서버 사용률 또한, 40%대를 초과하는 일은 없었습니다. 드디어 WAS 서버 CPU 사용률은 높고, DB 서버의 CPU 사용률은 낮은 이상적인 구조를 띄게 된 것입니다.
결과 또한 TPS가 1000대에서 2000대로 상승했으며, 부하가 낮은 지점에서부터 시간이 갈수록 TPS가 점점 올라가고, nGrinder의 agent가 vUser를 모두 생성한 시점부터는 나름 일정한 TPS를 유지하는 그래프가 완성되었습니다. 즉, 이전까지 테스트 도중 TPS가 뚝 떨어졌던 현상이 마침내 해결된 것입니다.
조금 아쉬운 부분은 아래와 같이 중간에 갑작스럽게 레디스 서버와의 연결이 잠깐 끊어졌다 재연결되어서 중간에 TPS가 0이 되어버린 부분인듯 합니다.
다행히 테스트를 다시 한 번 돌렸을 때, 레디스 연결 끊김 문제는 다시 발생하지 않았으며, TPS 그래프도 우상향의 모습을 유지하였습니다.
무엇이 원인이었을까요?
일단 공유코어가 포함된 듀얼코어를 그냥 일반 듀얼코어로 변경하고 나서 문제가 해결되었으니 문제의 원인은 공유코어가 제공하고 있었다고 볼 수 있겠습니다. 다만, 일반코어와 비교했을 때, 공유코어의 정확한 사양을 확인할 수가 없었으므로 코어 간의 성능차이가 존재한다고는 결론짓지 못할 듯 합니다. 다만, 추측을 해보자면 공유코어는 말 그대로 여러 인스턴스가 공유해서 사용하는 코어이므로 일정 이상의 부하를 받게되면 시스템 상에서 해당 코어자체에 성능적인 제약을 가하게되어, CPU 사용률은 높게 나오면서도 TPS는 뚝 떨어지는 현상이 발생하지 않았을까 생각해봅니다.
다음 포스팅 예고
성능테스트... 아직 끝나지 않았습니다. TPS 수직 낙하 문제를 해결한 뒤, 안심하고 3천명의 부하를 넣었으나또 다른 문제가 발생하기 시작합니다. 이번에는 무엇이 문제를 일으켰을까요? 다음 포스팅에서 원인과 해결과정을 알아보도록 하겠습니다.
추가
나중에 다른 서버의 인스턴스를 수정하면서 알게되었는데 기존 서버의 사양을 바꾸기 위해서 새로 인스턴스를 만들 필요가 없이 해당 인스턴스의 세부정보로 들어가 위에 있는 수정 버튼을 클릭하면 간단하게 해당 서버의 사양을 변경할 수 있습니다. 혹시나 저처럼 DB 재설치부터 데이터 덤프까지 하시는 분들이 없으시길 바라며 이 글을 마칩니다. ㅜㅜ
References
- Real MySQL
- 실무로 배우는 시스템 성능 최적화
프로젝트 링크
https://github.com/f-lab-edu/Hello-World
f-lab-edu/Hello-World
언어교환 상대찾기 서비스. Contribute to f-lab-edu/Hello-World development by creating an account on GitHub.
github.com
https://github.com/f-lab-edu/food-is-coming
f-lab-edu/food-is-coming
a delivery service that facilitates one's life to the fullest extent - f-lab-edu/food-is-coming
github.com