최종 프로젝트 성능 테스트(k6 성능 테스트)

이전 최종 프로젝트 회고 글에서 언급한 성능 테스트 과정을 담은 글이다.

처음 k6와 Grafana를 통해 성능 테스트를 진행하면서 생긴 여러 의문과 해결 과정을 담았다.

(다시보니 숲에서 처음보는 곤충을 관찰하듯이 신기해하는 모습이 담긴 것 같기도 해서 부끄럽다...)

 

https://tangpoo.tistory.com/170

최종 프로젝트 회고 (ECommerce 프로젝트)

 

 

---

테스트 개요

성능 개선 작업을 시작하기 전 API의 성능을 기록하고, 성능 개선 이후 변화한 지표와 비교하기 위해 테스트를 진행한다.

로그인 ~ 결제까지의 해당하는 유저 워크 플로우 테스트를 통해, 우리 서비스의 최대 동시 접속자를 측정하는 테스트 또한 해보고 싶었으나, 비용 문제로 인해 진행하지 못하게 된 것이 아쉬움으로 남았다.

우리 ECommerce 서비스에서 가장 많이 호출되고, 성능 개선이 필요하다고 생각되는 API 위주로 테스트를 진행했다.

테스트는 API의 최대 퍼포먼스를 확인하고, 임계점을 도출하기 위한 '중단점 테스트'를 지향했다.

(지향만 했을 뿐, 정석적인 중단점 테스트와는 거리가 있는 것 같다.)

---

Product 테스트

상품 목록 조회 (데이터 10만개)

• 10초 동안 100명 까지 증가
• 50초 동안 500명 까지 증가
• postman 요청 시 결과 150ms...

11:31:00 ~ 11:32:00 종료

초당 처리 요청 수가 최대 5건으로 굉장히 저조한 성능을 보이고 있다.

또한 11:13:30 이후 서버의 처리속도가 저하되는 지점을 확인할 수 있다.

응답 시간 또한 평균 10초가 넘어가는 저조한 성능.

읽기 작업만 수행했기에 JVM Total 은 터널 현상을 제외하고 영향이 없는 듯 하다.

결과

• 1분 동안 총 1000건 요청
• CPU 터널 현상 발생 (15% 요청 실패는 CPU 부하로 인한 것으로 보임)
• RPS : 5 (응답속도 개선 필요)
• duration : 14.9

---

상품 상세 조회

• 10초 동안 100명 까지 증가
• 50초 동안 500명 까지 증가
• postman 결과 33ms...

12:53:25 ~ 12:54:25 종료

CPU 사용량은 터널 현상은 사라졌지만, 100% 사용으로 인해 임계점을 초과했다.

cpu의 부하는 요청이 끝나고도 천천히 내려오는 지표를 그리고 있다.

가장 의문의 지표. 응답 시간은 Average 만 보면 우상향 이후 잔여 요청을 처리하고 떨어지는 비교적 정상적인 지표인데, Maximum 지표가 보이는 지표 이후에도 13:02:00 까지 이어졌다.

RPS가 줄어든 시점과 차이를 생각하면 부하의 여파가 약 8분동안 이어져 서버의 응답 속도 저하를 일으킨 셈이 된다.

다음은 더 높은 부하를 주어 이전과 같이 지표가 끊어지는 시점을 확인해보자.

13:12:00 ~ 13:13:00

CPU 사용률은 백분율로, 1이 100% 에 해당하는 숫자이니 100% 를 유지하다 부하를 못버틴 것으로 생각할 수 있을 듯 하다.
다만, CPU 가 부하에 못이겨 정지했다면 RPS 가 동일한 시점에 하락해야 했을텐데, 그러한 지표가 보이지 않은걸 보면 위 지표의 해석이 잘못 되었다는 생각이 든다.

마찬가지로 다른 해석이 필요한 CPU 부하 지표.

RPS 는 정상적으로 우상향을 그리다 요청이 끝난 시점에 하락하는 그래프이다.

여전히 Maximum 의 움직임이 이해가 가지 않으며, Average 는 Load Average 와 마찬가지로 이번에도 한참을 평행선을 유지하다가 떨어지는 모습을 보였다.

결과

• CPU 터널 현상 발생
• RPS : 239
• duration : 0.87
• 의문점들 조사 필요

---

새로 주목할 만한 지표가 발견 됐다.
JVM의 Heap 사용량인데, 이 지표는 테스트에서 10분이 지난 지금 시점까지도 떨어지지 않고 있다.

부하 테스트를 시작한 시점부터 전혀 떨어지지 않는 모습

위 지표에 대한 해석도 필요한 시점인 것 같다.

GC에 대한 학습을 어느정도 진행한 이후 다시 Heap 사용량에 변화를 관측했다.
GC Count 지표를 봤을 때 조금씩이지만 꾸준히 GC가 실행되고 있는 것을 확인했다.

또한 GC는 특별한 행동을 취하지 않는 이상 자동으로 수행하는 되는것이 일반적이며,
수행되는 시점은 특정 영역이 가득 찼을때 일어나는 것이라고 한다.
때문에 Heap 사용량을 100%로 만들어 GC의 지표가 어떻게 변화하는지 관측하고자 한다.

이전과 같은 요청(상품 상세 조회)을 보냈을 때의 Heaps 영역이다.
중간에 끊어지는 지표에 대한 것은 잠시 미뤄두고, 실제로 Heap 영역이 가득 찼을 시 Eden Space에서 GC가 일어나며 살아남은 객체는 Survivor Space로, 더 오랫동안 살아남아 객체의 Age가 증가하면 Tenured로 이동하는 모습이 관측됐다.

다만 위와 같이 아무런 요청을 보내지 않고 있더라도 Eden Space는 일정한 패턴을 그리며 객체를 저장하고 GC를 발생시키는 것을 반복하고 있는데, 서버가 실행 중인 상태에서 자동으로 발생하는 작업이 있는 것으로 보인다.

결과

• CPU 터널 현상 발생
• RPS : 246
• duration : 0.892
• 지표 상 끊어짐이 발생하나, 이전과 동일한 결과

---

튜터님께 지표 분석 도움을 요청하여 조언을 받았다.

• CPU 터널 현상(끊김)은 CPU의 부하가 100% 이상을 초과할 경우 발생한다.
  • 완전한 시스템 다운일 수도 있고, 부하로 인해 metric을 grafana에 전송하지 못하는 경우일 수도 있으니, 서버에 직접 접속하여 CPU 사용량을 체크하라는 조언을 받았다.
  • RPS의 흐름에 이상은 없었으니, metric을 전송하지 못한 것으로 예상하지만, 직접 확인해 볼 예정.
• Load Average, Duration 등에서 발생하는 이상 그래프 수치는 grafana가 평균 값을 내는 범위에 의한 현상이라고 한다.
  • 이상 현상이 아니라, Maximum 값을 측정하는 단위가 아마 10분 이상으로 설정된 듯.
• Heap 영역은 70~80% 에 달했다면 문제가 있다고 볼 수 있다.
  • 현재 아무런 요청을 보내지 않아도 자주 70%를 넘어서는 것을 볼 수 있는데, 이는 주기적으로 metric 정보를 전송하는 요청으로 인한 것으로 보인다.
  • 결과적으로 현재 사용하고 있는 EC2 프리티어의 Heap 영역이 너무 작아서 생기는 문제이다.
  • Heap 영역은 최대한 늘리는 것을 추천 받았으며, 2~4GB를 추천해 주셨다.
    • 마냥 크다고 좋지는 않다. GC가 한번에 수거해야 하는 객체가 늘어남으로서 CPU의 부담이 커질 수 있기 때문이다.
  • Heap 영역의 과부하로 인해 생기는 문제는 CPU와 마찬가지로 터널 현상, 처리속도 저하, 서버 다운 등의 문제가 발생한다고 한다.

JVM 관련 부하 테스트 레퍼런스

• https://vince-kim.tistory.com/33?category=973188

---

Order 목록 테스트

• 10초 동안 100명 까지 증가
• 50초 동안 500명 까지 증가
• postman 결과 300ms...

단 건 요청 기준 상품 목록 조회에 비해 2배 가량 오래 걸리는 api 이다.

예상대로 터널 현상 발생

이번엔 RPS와 duration도 터널 현상이 확인되었다.
이번 테스트를 통해 지표상으로 CPU 터널 현상이 일어난 뒤, 더 큰 부하를 가했을 때 실제로 시스템이 다운되는 것을 확인할 수 있었다.

Heap 메모리 영역의 문제는 Scale up을 통해 해결된 모습을 확인했다. (250mb -> 2GB)

지난번엔 확인하지 못한 에러 로그를 발견했다.
실행 중인 서버의 로그를 살펴본 결과는 이렇다.

2024-04-26T15:56:29.814Z ERROR 1 --- [io-8080-exec-10] o.h.engine.jdbc.spi.SqlExceptionHelper : HikariPool-1 - Connection is not available, request timed out after 30000ms.
2024-04-26T15:56:29.814Z ERROR 1 --- [io-8080-exec-10] o.a.c.c.C.[.[.[/].[dispatcherServlet] : Servlet.service() for servlet [dispatcherServlet] in context with path [] threw exception [Request processing failed: org.springframework.transaction.CannotCreateTransactionException: Could not open JPA EntityManager for transaction] with root cause

원인
커넥션 풀에 존재하는 모든 커넥션이 사용 중인 상황에서 커넥션 획득을 위해 대기하다가 일정시간(기본 30초)이 지나면 발생하는 에러이다.

활성화 된 커넥션 풀은 10개 이지만, 200개에 달하는 대기가 발생했다.

default 설정 값인 30초를 넘어 CannotCreateTransactionException 이 발생.

해결 방법

• 응답 속도를 개선한다.
• Connection timeout 시간을 늘린다.
• 트랜잭션 범위를 작게 설정한다.
• HikariCP 의 Connection pool 사이즈를 늘린다.

결과

• CPU 터널 현상 발생 이후 시스템 다운 -> 45초 이후 복구
• HikariCP에 대한 조사와 커넥션 풀의 size up 등의 조치 필요
• 응답속도 개선 필요
• RPS : 3.8
• duration : 22.2

---

Order Create 테스트

• 10초 동안 100명 까지 증가
• 50초 동안 500명 까지 증가
• postman 결과 42ms...

테스트 시작과 동시에 아래와 같은 에러가 발생했다.

com.mysql.cj.jdbc.exceptions.MySQLTransactionRollbackException: Deadlock found when trying to get lock; try restarting transaction

동시성 제어를 하고있지 않기에 예상할 수 있었던 부분이다.
해당 에러는 잠시 미뤄두고 계속 진행해보자.

17:48:30 ~ 17:49:30

동시성 문제라면 트랜잭션을 요청하는 시점에 생기는 에러일 것이고, 요청의 8% 만 성공했기에 지표에 큰 의미를 두지는 않겠다.

CPU 사용량은 임계점을 넘어 100%에 도달했으며, 역시 읽기 작업과 달리 메모리 지표의 우상향을 확인할 수 있었다.

결과

• Deadlock 발생
• 동시성 제어 필요

---

1차 성능 테스트 종료

결과

• 전체적으로 응답속도의 개선이 필요하다.
• 메모리 scale up 1GB -> 4GB
• JVM 힙 메모리 scale up 250MB -> 2GB
• 주문 생성시 동시성 제어 필요
• 응답속도 개선 이후 order 목록 조회 시에 커넥션 풀 문제가 다시 발생하는지 확인

---

2차 성능 테스트

테스트 조건 변경

• vus가 500이나 200이나 응답 대기 시간으로 인해 서버에 요청하는 수는 동일한 것을 확인
• 터널 현상을 없애고, 보다 정확한 지표를 분석하기 위해 vus:200으로 유지하도록 설정
• 20초 동안 200명 까지 증가
• 40초 동안 200명 유지

Product 테스트

상품 목록 조회 (데이터 10만개)

개선한 점

• 쿼리 최적화
• CDN 적용 (S3 이미지 캐싱)
• postman 요청 시 결과 500ms...?
  • 이전 응답시간은 150ms 로 단 건 요청의 응답시간이 늘어났다.
  • 원인은 인덱싱 관련하여 두 가지 트러블이 있었다.
  • soft_delete 정책으로 인해 조회 시 항상 해당 컬럼이 where문에 들어가는 것을 간과했다.
    검색에 사용하는 businessNumber와 is_deleted를 결합 인덱스로 묶었다.
  • orderBy가 추가되어 O(n) 만큼의 시간복잡도가 증가했다.
    created_at 또한 인덱싱 적용.
• 결과 postman 요청 시 60ms로 개선.

정리 : 쿼리 메서드에서 querydsl로 변경하여 생성날짜 순 정렬 기능을 추가했고, 인덱싱, CDN 적용

5 -> 40으로 성능 향상 확인

14.9 -> 4.8로 성능 향상 확인

결과

• 1분 동안 총 2500건 요청
• RPS : 5 -> 40으로 개선
• duration : 14.9 -> 4.8으로 성능 개선

의문

• 서버가 소화할 수 있는 해당 API의 요청 수는 vus:200 ~ 500을 비교해도 확인할 수 있듯이 약 2500건이 한계이다. 이 이상 vus를 늘려도 CPU의 부하만 늘어날 뿐 RPS, Duraction이 변화하지는 않는다.
• 결국 서버가 낼 수 있는 최대 퍼포먼스는 일정하지만, 요청 대기 수가 많아질 수록 CPU의 부하가 상승한다는 뜻이다.
• 실제로 CPU가 대기중인 요청을 어떻게 처리하는지, 임계점이라 칭하는 70% 부터 ~100% 까지의 성능 변화는 어떻게 되는지, 터널 현상이 목격될 정도로 부하를 받았을 때 요청이 실패하는 자세한 과정을 조사해 볼 필요가 있는 것 같다.

---

Order 목록 테스트

개선한 점

• 쿼리 최적화
• fetch join으로 N+1 해결
• 캐싱
• postman 결과 50ms...

결과

• 1분 동안 총 18300건 요청
• RPS : 6.8 -> 296
• duration : 22.2 -> 0.564

---

OrderCreate 테스트

개선한 점

• 쿼리 최적화
• Redis 분산락으로 동시성 제어
• postman 요청 결과 42ms...

Lock 획득 실패로 인한 21건의 실패가 있었고, 총 2100건의 요청이 발생했다.

동시성 제어 전 92%의 요청이 실패했던 이전 회차의 테스트 결과는 의미가 없기에, 비교는 생략한다.

결과

• 1분 동안 총 2100건 요청
• RPS : 33.4
• duration : 6.1
• 동시성 제어 목표 달성

---

테스트 후기와 개선할 점

 

각 API의 최대 퍼포먼스가 어느정도인지 파악할 수 있었고, 부하 발생 시 생기는 문제점을 찾아내어 개선하는 과정 또한 조금이나마 이룰 수 있었다.

또한 우리가 적용한 응답속도를 개선하는 작업들을 시각화 된 자료를 통해 확인함으로써, 조금 더 명확하게 개선되는 모습을 확인할 수 있었다.

다만 2차 OrderCreate 테스트를 제외하면 모두 CPU 사용량 100%를 찍는 모습이다...

임계점 밑 수준의 CPU 사용량을 유지하려면 Load Balancer와 AutoScaling를 적용한 후의 테스트가 필요할 것 같다.

또한 시간상의 이유로 다양한 성능 테스트 방식을 통해 아래와 같은 검증을 모두 거치지 못한 것이 아쉽다.

• 어느 정도의 부하를 견딜 수 있는가? [v]
• 시스템(데이터베이스, 서버), 자원(cpu, disk, memory 등)에서 병목 이 생기진 않는가? [v]
• 자원을 효율적으로 사용하는가? [x]
• 메모리 누수, 오류, 오버플로우 는 발생하지 않는가? [v]
• 최악의 상황에선 어떤 동작을 하는가? (예측하고 대비하기 위하여) [x]
• 장애 조치와 복구가 잘 동작을 하는가? [x]

[v] 표시를 한 것도 솔직히 자신있게 대답할 수 있는 정도로 검증을 거친 것은 아니라고 느낀다.

더 많은 학습과 경험을 통해 위 체크 리스트에 모두 자신있게 [v]를 칠 수 있도록 하자.