서버 성능테스트 이야기 4 [ 성능개선 적용기 : StackTrace 최소화 ]

Contents

• 이번 이야기
• StackTrace 최소화 테스트 :  설명
• StackTrace 최소화 테스트 :  결과 분석  - K6 Test Summary 
• StackTrace 최소화 테스트 :  지표 분석 - RPS (Requests Per Second)
• StackTrace 최소화 테스트 :  지표 분석 -  Error Rate
• StackTrace 최소화 테스트 :  지표 분석 -  Blocked 상태 쓰레드 수 
• StackTrace 최소화 테스트 :  지표 분석 -  JVM Heap 영역 + GC 소요시간
• StackTrace 최소화 테스트 :  지표 분석 - CPU Usage
• StackTrace 최소화 테스트 :  결과
• StackTrace 최소화 테스트 :  병목현상의 원인
• 배달중계 서비스. log() 제거 후 테스트 : 지표 분석 - CPU 사용량
• 인접 서버 병목 제거 후 테스트 : 결과 분석
• 데이터베이스 스케일업 후 테스트 : 설명
• 데이터베이스 스케일업 후 테스트 : 결과
• 적정 Throughput 지속가능 여부 테스트 : 설명
• 적정 Throughput 1시간 유지 테스트 결과 : 1 hour, 1000 TPS
• 마치며

 

---

 

이번 이야기

 이번에는 StackTrace 최소화를 통해 성능을 어느 정도 개선되는지 살펴보겠습니다. Exception의 StackTrace는 성능에 무거운 작업이라는 미친다는 점을 바탕으로 성능이 향상될 것이다라는 Theory를 바탕으로 진행해보겠습니다.

 

---

 

StackTrace 최소화 테스트 :  설명

기존 retry 로직(좌) / saveOperation(우)

개선사항

• 프로그램 내부 단 한곳에서 사용하는 리액터의 retry() 기능 삭제
  • retry 삭제는 곧 테스트 Duration 21분 동안 StackTrace가 발생하지 않는다는 것을 의미
  • retry는 지금까지 진행한 테스트의 ErrorRate 1~5%의 거의 유일한 원인으로 관련 내용은 2편 에서 확인할 수 있습니다.

기대하는 결과는?

• StackTrace제거가 성능개선에 도움이 되는 건 기정사실이니 성능개선을 기대하고 있다. 추가로 Netty에서는 소수정예 스레드들로 동작하기 때문에 개선 정도는 Thread-per-Request 스레드 모델의 프레임워크보다 더 클 것으로 예상된다.

걱정되는 부분은?

• 성능개선의 정도

테스트 트래픽

• 21분동안 0 TPS부터 1000 TPS까지 linear 한 증가

 

이제 두번째 성능개선 적용 기를 진행해 보겠습니다.

 

---

 

StackTrace 최소화 테스트 :  결과 분석  - K6 Test Summary 

테스트 결과

 K6로 진행한 테스트의 결과가 출력되었습니다. Retry가 없으니 TimeoutException 이 발생하지 않았고 에러 자체가 사라졌으며 기분 좋은 green check들만 보입니다. 

 

---

 

StackTrace 최소화 테스트 :  지표 분석 - RPS (Requests Per Second)

Before (좌) / After (우)

 위 빨간 수평선은 Rate 그래프 Y-axis의 스케일이  테스트 전과 후 로 달라져서 표시한 공통 지점입니다.

• Before : 첫 테스트에는 최대 400 RPS까지 처리가 가능했으며
• After : 이번 성능개선 적용기에서는 최대 600 RPS까지 처리되었습니다.

 RPS 만 놓고본다면 약 1.5배의 성능 향상이 이루어졌다는 결론을 내릴 수 있겠습니다. 그런데 왜 600 RPS에서 다시 하락세가 발생한 것인지가 의문입니다. JVM의 다른 부분들은 어떻게, 다르게 동작했는 제 살펴보겠습니다.

 

---

 

StackTrace 최소화 테스트 :  지표 분석 -  Error Rate

Before (좌) / After (우)

 이번 성능개선 적용기의 기원이되는 에러 발생 비율입니다 

• Before : 첫 테스트에서는 400 RPS를 넘어가는 시기 즈음부터 초당 최대 20개의 TimeoutException 이 발생했습니다. 
• After : 프로젝트 리액터의 timeout, retry 를 제거한 이후 Error 발생률이 최소화된 것이 확인됩니다.

 ErrorRate 지표를 통해 이번 개선 적용기에서 의도한, 주목적인 [StackTrace 최소화]를 성공적으로 반영한 것이 확인됩니다.

 

---

 

StackTrace 최소화 테스트 :  지표 분석 -  Blocked 상태 쓰레드 수 

Before (좌) / After (우)

 위 지표는 Block 상태의 스레드 수를 나타냅니다.

• Before : 첫 테스트에서는 250~300TPS 를 초과하는 시점부터 Blocked 상태의 스레드들이 발생했습니다.
• After : StackTrace 삭제 이후 Block상태의 스레드가 발생하지 않았습니다.

 StackTrace를 제거함으로써 Blocked 상태에 빠지는 스레드가 발생하지 않는 것이 보입니다. 추가로 확인해봐야 할 점은 StackTrace가 Blocking 되는 것인지, 아니면 에러 발생으로 인해 애플리케이션의 다른 부분에서 Blocking 되고 있는지입니다.

 

---

 

StackTrace 최소화 테스트 :  지표 분석 -  JVM Heap 영역 + GC 소요시간

JVM Heap 영역 크기, Before (좌) / After (우)

GC 소요시간 Before (좌) / After (우)

 메모리 관련된 부분도 크게 개선되었습니다.

• Before : 첫 테스트에서 서버 Heap 은 지속적으로 상승했습니다.
• After : 하지만 StackTrace 제거 이후의 JVM Heap 그래프는 매우 안정적입니다. 일정 레벨의 Heap 사이즈를 유지하는 것이 보이기 때문입니다. 이런 개선의 배경은 GC 소요시간을 통해 확인할 수 있습니다. CPU 과부하와 함께 초단위로 상승하는 첫 테스트와는 달리 이번에는 GC 소요시간이 최대 0.15초를 넘지 않고 있습니다.

CPU 성능 향상으로 인해 GC가 가속화, 강력해지고 그로 인해 메모리도 더욱 안정적인 곡선을 유지하는 것을 알 수 있습니다.

 

---

 

StackTrace 최소화 테스트 :  지표 분석 - CPU Usage

Before (좌) / After (우)

CPU 사용량의 변화를 살펴보겠습니다.

• Before : 요청수 증가에 따라 가파르게 상승하고 380 TPS 부근에는 CPU 사용량 90%를 돌파합니다. 이후 100% 에 수시로 도달하며 CPU 과부하가 발생하는 것이 보입니다.
• After : CPU 사용량이 최대 40% 수준까지 서서히 상승하는 것이 보입니다. CPU 사용량은 과부하가 발생하지 않습니다.

 개선된 상황의 CPU 사용량은 매우 안정적인 패턴을 나타내고 있습니다. 하지만 테스트 최대 TPS 처리, CPU 과부하 두 현상 모두 발생하지 않았기 때문에 테스트 정합성이 떨어집니다. 외부요인의 bottleneck 발생을 의심해볼 필요가 있습니다.

 

---

 

StackTrace 최소화 테스트 :  결과

 이번 성능개선 적용 기를 통해 서버의 성능개선 효과를 확인할 수 있었습니다. 최대 RPS 가 1.5배 상승했고, CPU 사용량은 최대 40% 웃돌며, GC 소요시간의 가속화로 메모리도 안정적인 패턴을 그려가며 최대 메모리 사이즈에 40% 수준을 유지하고 있습니다.

 성능 향상의 측면에서 사건의 전개를 생각해보겠습니다. StackTrace에 소모되던 CPU타임이 개선이후 서버작업수행과 GC로 재분배가 되었고 이는 짧은 GC 소요시간, 안정적인 메모리, 성능향상의 선순환으로 이어졌습니다.

 개발 시에는 IDE에서 가려서 안 보이지만 자바에서 에러 발생 시에 원시적인 StackTrace 가 진행되면서 스택 메모리의 프레임을 스레드 끝까지 하나하나 확인하는 작업이 개발자뿐만 아니라 CPU에게도 큰 부담인 것을 생각해볼 수 있습니다.

 StackTrace를 제거하며 성능이 향상했지만 다시 ExceptionHandling 전략이 필요하게 되었습니다 에러 발생 시 StackTrace 포함 여부, Catch 후 별도의 메시지를 생성할지 등을 고민해볼 수 있습니다.

 

 

---

 

StackTrace 최소화 테스트 :  병목현상의 원인

 결과가 당장은 긍정적인 결과로 보입니다. 하지만 나머지 성능개선 포인트들을 적용하기 전에 해결해야 할 문제가 있습니다.

 왜 설정한 테스트 최대치인 1000 RPS까지 상승하지 않고 왜 CPU와 메모리에도 부하가 발생하지 않았을까요?

 서버 외에 어딘가에 병목이 발생하고 있다는 생각이 듭니다.

 

인근 병목현상의 원인 후보들

배달정보서비스 인근에서 의존하는 서비스가 부하가 발생했을 수도 있고 MongoDB에 Write Operation이나  서비스 간의 네트워크 I/O 가 한계에 도달했을 수도 있습니다.

 

병목현상의 원인 : 배달중계 서비스

 배달정보서비스가 의존하는 배달중계 서비스의 성능 지표를 살펴봣습니다. (우측) 중계서비스의 지표를 들여다보니 배달정보서비스가 RPS 최대치에 도달하는 시점에 배달중계 서비스에서 CPU 사용량이 급상승하고 있습니다. 언덕 위의 성을 측면에서 바라보고 있는 것 같습니다.

 CPU 사용량이 급격히 상승한 이유를 찾기 위해 배달중계 서비스 여러 지표들을 둘러봤습니다. 모두 시스템 자원의 40~60%을 활용하는 정상적인 상태였지만 (Thread States)와 요청 소요시간(Duration)은CPU 사용량과 유사한 패턴을 보입니다. Blocked 쓰레드 수와 소요시간도 확인했지만 CPU가 수직상승할 정도의 문제는 없어보입니다. 

 결과를 보니 에러도 발생하지 않았습니다. 대신 배달중계서비스 서버의 로그를 확인하며 로그가 참 많다는 생각이 들었습니다. 중계 서비스에서 로그를 발생시키는 지점을 보니 컨트롤러의 모든 핸들러 메서드에 추가해놓은. log() 부분이었습니다. 현시점 서버의 로깅 기능은 단순한 RollingFileAppender 설정한 것이어서 과도한 로깅에 의한 I/O 부담이 의심스럽습니다. 로깅 부분을 제거하고 다시 테스트해보겠습니다.

 

 

 

---

 

 

 

배달중계 서비스. log() 제거 후 테스트 : 지표 분석 - CPU 사용량

logging 제거 (전) / logging 제거 (후)

 위 그래프는 인접 서버인 배달중계 서비스의 Logging 제거 전과 후의 CPU Usage를 나타낸 그래프입니다. CPU Usage 가 정말 크게 감소한 것을 확인할 수 있습니다. 이로써 인접 서버의 병목으로 인한 성능 테스트의 문제는 해결될 것으로 보입니다. 삭제한 기존 로깅은 현시점 비즈니스에서 중요도가 매우 낮은 부분이며 구체적으로 해결하려는 문제가 없기 때문에 삭제했지만. 추후 비동기로 로깅을 처리해야 할 필요성이 느껴집니다. 비동기 로깅 기능 개발 시 제가 최근에 본 NHN Cloud에서 발표한 테크 블로그를 먼저 참고하게 될 예정입니다. 

 

---

 

 

인접 서버 병목 제거 후 테스트 : 결과 분석

 

 위 그래프는 인접한 서버의 병목을 해결함으로써 개선된 성능 테스트 결과 지표입니다. 주목할만한 부분은 다음과 같습니다.

• Rate 최대치 (Request Per Second)
  • RPS가 추가로 상승했습니다. 첫 테스트 결과(약 380) 대비 200%, 최근 개선한 버전(600) 대비 30% 가까이 개선되었습니다.
• JVM Heap
  • Heap 영역 크기는 지속적인 트래픽 증가에도 불구하고 매우 안정적인 규모를 유지하고 있습니다.
• Duration 
  • 요청 평균 소요시간은 200ms 부근에서 머물고 있습니다. 200ms라는 수치에 기분 좋아할 수도 있지만 평균이라는 단어에 내재되어있는 함정에 주의해야 합니다.
• CPU Usage
  • CPU 사용량은 800 RPS까지 트래픽 동일하게 상승했습니다.

다시 벽에 부딪혔습니다. 외부요인으로 인한 병목이 해결된 것으로 생각했지만, CPU 과부하도 발생하지 않았고 TPS도 최대치를 돌파하지도 않았습니다.

 

---

 

 

데이터베이스 스케일업 후 테스트 : 설명

현재 상황

• 지금까지 서버의 비효율적인 StackTrace와 인접 서버의 비효율적인 Logging을 부분들을 제거함으로써 첫 테스트 결과 대비 성능을 두배 가까이 끌어올렸습니다.
• 하지만 아직까지 서버에 과부하가 발생하지 않았으며 또한 테스트의 성능 최대치까지 인접하지 않았습니다.
• 병목이 데이터베이스에서 발생하는 것으로 예상되며 테스트 대상 서버의 성능 최대치 확인이 어렵습니다.

조치

• 데이터베이스 서버의 AWS EC2 인스턴스를 200% Scale Up 하겠습니다.
• AWS EC2 인스턴스는 MongoDB 서버로 최적인 여러 인스턴스 중 i3.2 xLarage (Storage Optimzed)를 가동하겠습니다.

 

테스트 시나리오 변경사항

• 이번에는 서버 과부하가 확실하게 발생할 수 있도록 트래픽을 두배로 늘리겠습니다.

기대하는 점?

• 이번 테스트에서는 더 이상 외부 서비스의 병목이 발생하지 않을 것으로 예상
• 과부하(Overload)를 테스트 대상 서버로 격리

 

---

 

 

데이터베이스 스케일업 후 테스트 : 결과

 

테스트 결과 정리

 설명하는 동안 편의를 위해 분홍색 수직선이 표시된 지점을 잠시 "체크포인트"라 부르겠습니다.

 우선 JVM 힙 메모리부터 확인해봅니다. JVM Heap 영역 크기는 거의 수평선을 그리는 트렌드를 보여주고 있으며 이는 GC가 적절히 발생하고 있다는 것을 확인할 수 있습니다. 확인해보니 역시나 GC 소요시간은 100~200ms 지점에 머무르고 있습니다.

 체크포인트에서 시스템 로드가 2.0입니다. 시스템 로드로 2 vCPU에 걸쳐있습니다. 같은 시점에 CPU Usage 또한 80%에 도달합니다.

 체크포인트 이후에는 서버 성능이 불안정적인 패턴을 나타냅니다. 25ms 인근에 머물던 평균 HTTP Duration이 50ms, 100ms 넘기 시작합니다. 1200~1300까지도 증가하는 RPS는 불안정하게 상승, 하락을 반복하며 CPU 사용량은 100%를 지르고 있습니다. System Load가 CPU 코어수를 초과하는 시점부터 성능에 문제가 보이기 시작합니다.

 

다음 테스트는 적정 트래픽을 유지할 수 있는지를 확인하기

 지금까지는 트래픽이 선형으로 상승하게 설정해두어서 어느 시점에 서버 성능에 문제가 발생하기 시작하는지 확인했으며 이번 테스트를 통해 현시점 서버의 적정 Throughput은  CPU를 Over-Utilize 하지 않는 선에서  1000~1100 RPS 정도인 것을 예상할 수 있습니다.

 이 점을 확실히 하기 위해 마지막으로 서버가 1000~1100 RPS를 지속할 수 있는지를 테스트하겠습니다..

 

---

 

적정 Throughput 지속가능 여부 테스트 : 설명 

테스트 설정

• Duration : 20m
• RPS : 1/s에서 1000/s까지 3분 동안 증가, 이후 17분 동안 1000/s 유지

 

기대치

• CPU Usage 60~80% 선에서 유지
• 나머지 지표 (Heap, HTTP Duration) 모두 안정적인 패턴 표출

테스트 결과 지표

 

 

테스트 결과 분석

• Rate : 설정된 트래픽(적정 Throuhgput)을 서버가 전부 처리해내는 것이 확인됩니다.
• Duration : 요청 처리시간은 트래픽이 급증하는 첫 3분 동안 최대 50ms까지 상승했습니다. 하지만 이후 트래픽을 유지하는 기간 동안 다시 하락하는 것을 확인할 수 있습니다. 예상하기를 데이터베이스 Duration의 변동폭을 줄이기 위해서는 별도 Warm 기간을 주는 것도 하나의 방법이라 생각됩니다.
• JVM Heap : 수평적인 패턴을 유지하는 것을 통해 GC가 적절히 발생하고 있다는 것을 확인할 수 있습니다.
• Load : 시스템이 커버 가능한 경계를 아슬아슬하게 넘나들고 있습니다. 현시점 1000 RPS 이상은 무리일 것으로 보입니다.
• CPU Usage : 기대했던 대로 1000/s의 트래픽을 발생시키는 동안 60~80% 선을 유지하고 있습니다.
• Thread States : 스레드 상태는 테스트 시간 동안 유의미한 변동이 일어나지 않았습니다.

결론

 예상했던 결과가 나왔습니다. 적정 Throughput을 예상한 CPU 사용량 범위 내에서 문제없이 처리했습니다. System Load는 주어진 범위를 다소 벗어납니다. 스레드 상태는 이전 테스트들에 비해 매우 안정적인 상태입니다. 메모리도 변동폭이 크지 않습니다.이 정도 결과라면 "현시점 vCPU2, 4 GiB 메모리 서버의 적정 Throughput은 1000 TPS입니다."라고 이야기할 수 있을 것 같습니다.

 

 

적정 Throuhgput 1시간 동안 유지하기

 적정 Throughput이 1000/s이고 17분 동안 지속되는 것은 알겠으니 마지막으로 1시간 동안 테스트를 해보겠습니다.

 서버가 1시간 동안 1000TPS를 유지하고, 메모리누수도 없이 잘 동작할 수 있을까요? 1시간동안 1000TPS를 유지할 수 있다면 프로젝트를 진행하면서 ScaleOut이 필요한 경우 더 큰 확신을 가지고 트래픽을 분배할 수 있을 것같습니다. 1시간동안 실행해보겠습니다.

 

---

 

적정 Throughput 1시간 유지 테스트 결과 : 1 hour, 1000 TPS

테스트 시나리오

 

분석

 다행스럽게도 1시간동안 1000~1100 TPS를 유지하면서 큰 문제없이 성능을 유지하는 것을 확인할 수 있었습니다.

 

https://aminoapps.com/c/cartoon/page/blog/adventure-time-nearing-the-end/z6RH_xuY7bb4Y4PQa63M1Md4boneXnL

 

---

 

 

 

마치며 

 요약정리

 이번 성능 테스트 이야기에서는 이전에 도출한 개선 포인트 "StackTrace 최소화"를 적용하고 그 외 외부 요인들에서 발생하는 병목도 해결하는 시간을 가졌습니다. 라이브로 진행되다 보니 여러 번 테스트를 진행했습니다. 다행히 변경한 만큼 서버 성능에도 적극적인 변화가 있었으며 이 점은 성능 테스트와 개선을 더 수월하게 진행할 수 있었던 요인으로 작용했다고 생각합니다.

 

 적용된 부분

 이번 성능테스트 블로그 진행 후 달라진 점 몇 가지를 짚어보겠습니다.

 기능적인 면에서 달라진 점은 비효율적으로 구현된 상태의 StackTrace와 logging 제거한 부분입니다. 이 두 가지 기능은 지금까지 큰 활용도를 찾지 못했으며 서버의 성능에 악영향을 미치는 것으로 판단되어 과감하게 제거했습니다. 추후 개선된 로직으로 적용하는 방향으로 나아갈 예정입니다.

 성능적인 면에서도 변화가 있었습니다. 처음 실행한 성능 테스트에서 처리량의 최고점은 380 RPS이었으며 이번 성능 테스트 이야기 마무리 시점에는 처리량 최고점이 1200 RPS로 약 3배 가까이 상승했습니다.

 운영하는 관점에서도 큰 성과를 얻은 것 같습니다. 2 vCPU 4 MiB의 서버의 적정 Throughput을 계산해보는 시간을 가졌습니다. 여러 상황에서 유용한 지표가 될 것으로 생각됩니다.

 

 서버는 아직도 여러모로 개선이 필요해 보입니다.