갈만해 프로젝트를 소개합니다
'갈만해'라는 웹서비스를 운영하고 있습니다. 블로그에 웹 서비스를 개발하며 겪은 문제점과 해결 과정을 공유하려고 합니다. 이번 글은 갈만해 프로젝트의 후반부에 겪었던 서버 병목현상과 그 추적과정, 해결을 다루려합니다.
갈만해 프로젝트는 실시간으로 서울 인구밀집 장소들의 날씨와 혼잡도를 계산하여 외출하기 적합한 정도를 알려주는 서비스입니다.
운영환경 구축
갈만해 프로젝트에서 배포와 운영 서버, 모니터링 환경을 구축하였습니다. 클라우드 서비스는 GCP를 사용했고 최대한 비용을 아끼기 위하여 운영서버, 모니터링 서버, db서버 3개를 가장 낮은 인스턴스로 구성했습니다.
배포 흐름을 설명하면 개발자가 main에 코드를 푸쉬하면 Github Actions는 프로젝트를 Dockerfile로 이미지화 하여 Dockerhub로 업로드합니다. 운영서버내에서 해당 이미지를 받아와서 Docker 컨테이너로 스프링 부트 프로젝트를 실행합니다.
모니터링의 경우는 서버와 분리시켜 장애가 나도 영향을 받지 않고 관찰을 할수 있게 하였고 DB도 마찬가지로 애플리케이션 서버와 분리시켜 (혹시나 있을지도 모르는) 애플리케이션 확장이나 장애에 영향을 받지 않게 했습니다.
애플리케이션 서버는 Nginx를 웹 기본포트(80, 443)에 매칭 시키고 spring boot로 포워딩 시키는 방식을 택했습니다. 스프링 부트의 포트를 기본포트에 매칭시키면 이후 여러개의 스프링부트가 있는 상황(혹시나 있을지도 모르는 무중단 배포 등)에서 유연하게 대응하기 힘들기 때문이었습니다.
내 서버의 한계는?
운영서버 환경을 구축하고 해야할 일이 있습니다. 서비스의 성능을 가늠하는 건데요. 부하를 점점 늘리면서 서버의 한계점을 알고 목표를 세우고 개선 계획을 잡기 위해서 입니다.
부하테스트 툴은 k6를 사용했고 이를 그라파나로 시각화했습니다.
k6 스크립트로 모든 엔드포인트를 vUser가 한번씩 조회하는 스크립트를 작성하였습니다.
(파란줄 p99, 노란줄 tps, 회색줄 vUser, 빨간줄 오류응답)
오마이.. 예상은 했지만 vUser가 50을 늘어나는 시점부터 응답시간이 심상치 않더니 이후 부터는 거의 p99(응답시간 상위 1프로)가 1분을 치솟는 군요. 오류율은 덤입니다.
저는 이 결과를 토대로 vUser100명에게 모든 엔드포인트에서 p99 1초 미만의 응답을 내린다는 목표를 잡게 되었습니다. 하지만..
이해할 수 없는 현상
위 수치가 보이시나요? 이 수치와 패턴이 vUser가 20명이든, 50명이든, 100명이든, 어떤 엔드포인트를 테스트하는지 상관없이 동일하게 반복해서 나타납니다.
패턴은 동일합니다. 일정시간(2,3분) 이상 테스트가 진행되면 응답시간 p99가 갑자기 2~30초로 치솟기 시작하면서 일정 간격으로 반복됩니다.
서버의 CPU는 응답시간이 늘어나는 시점에 사용량이 떨어지고 DB커넥션에서는 에러가 발생하지 않고(서버 로그도 마찬가지) 거의 idle, 즉 널널한 상태를 유지하고 있습니다. 이미지로 첨부하진 않았지만 jvm old gen, 서버의 메모리도 평안 그자체 였습니다.
갈만해 서비스는 일정 간격으로 데이터를 처리하는 로직 이외에 유저가 사용하게 되는 엔드포인트(모든 장소 조회, 장소 상세 조회, 검색)에는 복잡한 로직이 거의 없습니다. 그냥 DB조회가 다죠.
중요한 것은 해당 현상이 가장 간단한 쿼리를 사용하는 엔드포인트인 단일 장소 조회에서도 동일하게 나타나는 것이었습니다.
SELECT *
FROM congestion c
WHERE c.place_id = 390
ORDER BY c.created_at DESC
LIMIT 1;실행계획은 다음과 같습니다.
복합인덱스인 'placeidcreated_at'을 사용해 인덱스 레인지 스캔으로 한 개의 row로 검색범위를 줄여서 디스크에서 한 개의 row만 가져옵니다.
혹시나 싶어서 DB의 슬로우 쿼리 로그도 살펴봤지만 해당 쿼리는 찾을 수 없었고 MySQL에서 제공하는 Performance 스키마도 살펴보았지만
쿼리 실행시간이 빠르다는 사실만 알게 되었습니다..
뭐가 문제일까?
현재 가지고 있는 메트릭, 저의 지식만으로는 문제가 되는 원인을 찾을 수가 없었습니다. 좀 더 딥다이브가 필요하다는 생각이 들었습니다.
그래서 말로만 듣던 힙덤프를 떠서 MAT로 분석해보기도 하고..
(a)는 ClassLoader였습니다. ClassLoader의 메모리 사용량이 6MB라고? 메모리 누수가 의심된다고? 처음에는 놀랐지만, JVM 쪽 메트릭은 안정 그 자체였기 때문에 무시해도 좋을 수준의 크기라고 판단했습니다.
말로만 듣던 스레드 덤프를 떠보기도 하고..
Timed_waiting이 26이라고? tomcat 워커 스레드풀의 기본상태로 스레드가 재사용될 준비가 되어 있다는 뜻입니다. weather-로 시작하는 스레드들은 외부 API를 호출할 때 커스텀한 고정 스레드풀입니다. 가린 포트는 모니터링을 위해 열어놓은 포트입니다.
여기서도 원인을 알아낼 수가 없어 테스트 환경을 바꿔 보기로 했습니다. 성능테스트는 운영서버에 직접(..)했었는데요. (테스트 환경을 구축할 돈이..) 로컬에서도 동일한 현상이 발생한다면 정말 코드를 하나하나 검사할 작정이었습니다.
그런데..
로컬에서 운영 환경 설정으로 실행한 테스트에서는 같은 현상이 발생하지 않는 것을 확인했습니다. 즉 로컬과 운영서버와의 차이 때문에 발생한 문제라는 판단이 들었습니다.
로컬과 운영서버간에 가장 큰 차이는 뭘까요? 바로 'DB서버와 네트워크로 통신한다'는 점, 그리고 '애플리케이션을 docker로 띄웠다는 점' 입니다.
네트워크가 문제다! 라는 시각을 가지고 보니 어떤 정보가 필요한지 확실해졌습니다.
tcpdump 분석
tcpdump는 실행 동안 네트워크 인터페이스들에서 전송되는 패킷을 캡처하고 분석할 수 있는 cli 도구입니다. 저는 파일로 일정 시간의 tcpdump를 캡쳐하고 이를 패킷분석도구인 wireshark로 분석해보았습니다.
그리고 TCP 오류 재전송이 계속해서 일어나는 tcp 스트림을 찾아냈습니다..!
이 패킷들은 docker container 가상 네트워크 내부 ip인 172.17.x.x와 GCP VPC DB서버의 내부 ip 10.x.x.x 사이의 통신입니다. 패킷이 손실되거나 제대로 전송되지 않았을 때 dup ack이 송신측으로 오고 이를 3번 이상 받으면 재전송이 진행되는 걸로 알고 있는데요 (불현듯 떠오르는 네트워크 시간.. ) 성능 테스트 도중에 이러한 현상이 계속 발생했던 것입니다.
저는 Docker를 기본 설정으로 띄우면 bridge라는 가상 네트워크가 형성되고 이 가상 네트워크를 통해 컨테이너끼리 소통이 가능하다. 외부에서의 접근은 라우팅된다. 정도로만 알고 있었습니다.
하지만 컨테이너 내부에서 외부로의 네트워크는 어떻게 되지?라는 부분을 생각하지 못했던 것입니다.
spring boot는 기본적으로 DB 커넥션풀을 생성하기 때문에 컨테이너의 가상네트워크에서 10.x.x.x 처럼 외부 ip가 주어지면 docker 가상네트워크의 NAT테이블을 참고하여 요청을 라우팅하는데 이 라우팅 과정을 제대로 명시해주거나 네트워크 설정을 따로 해주지 않아 패킷 전송에 오류가 나고 있었던 것입니다.
Docker의 공식문서는 기본설정인 bridge를 레거시로 칭하고 유저가 커스텀한 네트워크를 사용하는 것을 권장하고 있습니다.
갈만해 프로젝트는 도커 컨테이너끼리의 네트워킹이 그렇게 필요한 상태가 아닙니다. 따라서 저는 디버깅하기 어렵고 NAT 테이블 라우팅 과정을 하지 않아 성능적으로 유리한 host로 네트워크 환경을 바꿨습니다. host는 말 그대로 호스트 서버의 네트워크 인터페이스를 바로 사용하기에 위와 같은 설정이 필요하지 않습니다.
그리고..
이렇게 네트워크 설정 하나를 바꿨을 뿐인데 p99가 목표로 했던 1초 미만이 된 것을 확인했습니다.
마치며
저의 허접한 병목 추적기는 여기까지입니다. 해당 과정을 경험하면서 현상을 분석하기 위해서는 언제나 원리에 대한 기반지식이 필요하다는 사실을 깨닫게 되었습니다. 또한 서버의 곳곳에는 이게 문제가 된다고? 싶은 것들이 산재하고 있다는 것도요!