[Sansam E-commerce] 13. 다시 이 프로젝트를 돌아보며 (feat. Virtual Thread)

👀 들어가기전에

이전 프로젝트를 회고하며

 

Virtual Thread를 학습하고 프로젝트를 돌아보던 중, 이 프로젝트도 주문 ~ 결제까지의 흐름에 I/O Bound가 큰 부분인데

Virtual Thread를 활용하여 개선할 수 있지 않을까?

 

라는 생각이 들어 다시 돌아와보았습니다. 이번 시간에는 Virtual Thread를 사용해보고 스레드가 어떻게 활용되고 있는지를 까보면서 최적화하는 방향으로 내려가보겠습니다.

---

👀 본론

1. Virtual Thread의 적용

우선, Virtual Thread를 적용하기위해 아래와 같이 설정을 진행하였습니다.

Virtual Thread 설정

 

이미 Java 21을 사용하고 있었기에 Virtual Thread 사용은 어렵지 않았습니다.

위와 같이 설정을 하면, OS Thread와 Java Thread의 비중이 1:1 이던 것이 N:M으로 변화하게 됩니다.

Platform Thread 하나당 Virtual Thread 여러개를 사용하게 되는 것입니다.

 

Virtual Thread 확인

현재 진짜로 Virtual Thread를 사용하고 있는지 직접 확인해보기 위해 Log를 찍어 확인해보았습니다.

(Error 레벨로 찍은 것은 Error 필터링으로 좀 더 적은 로그 속에서 찾아보기 위해서인 점 양해부탁드립니다 ☺️)

 

실제 Virtual Thread를 사용 중이었고,

• 요청 처리 단위는 Virtual Thread
• 실제 CPU 위에서 돌리는 carrier는 ForkJoinPool worker thread

인 점을 확인할 수 있었습니다.

우선, 이정도만 변경한 후 기존 700VUser Peak Test를 진행했을 때와 동일한 시나리오로 부하테스트를 진행해보았습니다.

(이전에 warm-up은 진행이 된 상황이었다.)

 

시나리오는 아래와 같습니다.

1. 테스트 시작 시점에 700명의 가상 사용자(VUser)를 동시에 생성합니다.
2. 각 VUser는 독립적으로 주문-결제 E2E 시나리오를 반복 수행합니다.
3. 각 VUser는 사용자 ID와 상품/옵션 정보를 기준으로 주문 데이터를 구성합니다.
4. 주문 생성 API POST /api/orders/save를 호출합니다.
5. 주문 생성 응답에서 주문번호와 총 결제금액을 추출합니다.
6. 실제 사용자 행동 간격을 모사하기 위해 1초간 대기합니다.
7. 추출한 주문번호와 결제금액을 사용하여 결제 승인 API POST /api/pay/confirm을 호출합니다.
8. 결제 승인 후 다시 1초간 대기합니다.

위 과정을 테스트 시간 1분 동안 반복 수행합니다.

 

즉 한 명의 VUser 입장에서는

• 주문 생성
• 1초 sleep
• 결제 승인
• 1초 sleep
• 다시 주문 생성
• 다시 1초 sleep
• 다시 결제 승인
• 다시 1초 sleep

을 반복하는 것입니다.

VUser 700 PeakTest Scenario 결과

 

위 결과를 보면, 하나의 API 당 Max 시간은 4.47s 입니다.

(하지만, 결제의 경우 PG사 외부 API 타는 부분을 Mock처리하고 1s sleep을 내부적으로도 걸어놓았습니다.)

 

이전 결과와 비교를 해보면 아래와 같습니다.

Before After 메트릭 비교

 

 

Min 응답시간은 더 늘어났지만 체감될 정도의 증가는 아니었습니다.

다만, 전체적으로 응답시간에서 유의미한 개선을 보인 것을 알 수 있습니다.

 

특히, After 응답시간이 목표로 했던 2~3초대로 끊은 것을 확인해볼 수 있었습니다.

---

2. Thread Dump 분석

스레드가 지금은 어떻게 활용되고 있는지가 궁금하여 스레드 덤프를 분석해보기로 하였습니다.

 

우선, threaddump를 확인하기 위해서 threadDump를 Actuator를 통해서 확인 가능하도록 설정을 바꿔주었습니다. 

 

Catalina-utility

 

Tomcat 쪽 유틸리티 스레드(Catalina-utility-*)는 대부분 작업을 기다리는 상태라, Tomcat 보조 스레드가 바빠서 막힌 상황은 아니었습니다. 위 사진의 예시만 보더라도, 이 스레드는 지금까지 WAITING / TIMED_WAITING 상태에 총 187번 들어간 것을 확인할 수 있습니다. (근거 : waitedCount = 187)

HikariCP Housekeeper Thread

MySQL abandoned cleanup Thread

 

OkHttp Task Runner

 

HikariPool-1:housekeeper, MySQL abandoned cleanup, OkHttp TaskRunner도 대부분 대기 상태라서,

풀 관리 스레드 자체가 병목은 아니라고 판단하였습니다.

 

하나 눈에 띄는 건 관측성, 에이전트 쪽이었습니다. BatchSpanProcessor_WorkerThread-1 이 계속 돌고 있고,

일부 스레드 스택에는 OpenTelemetry 쪽 변환 코드가 직접 보였습니다.

 

특히 lettuce-timer-3-1 근처에서 ByteBuddy/OpenTelemetry instrumentation 스택이 잡힌 건, 피크 구간에 Java agent/metrics/tracing 오버헤드가 실제 실행 경로에 끼어들고 있었다는 신호로 볼 수 있었습니다.

OpenTelementry 실행 중

Open Telementry

 java 메트릭 수집이랑 peak가 겹치면서 문제가 발생한 것일 수도 있다고 판단하게 되었습니다.

 

아래와 같은 이유였습니다.

요청 1개 처리 시
→ span 생성
→ 메모리 구조 생성
→ protobuf 직렬화
→ HTTP 전송
→ background 관리 thread

 

위 작업을 모두 하고 있다는 것인데, 요청 처리 + tracing 전송 → I/O 2배가 발생하는 것입니다.

이에 현재 시스템은 I/O bound 구조 위에 tracing 처리 오버헤드가 추가된 상태이며,

피크 트래픽 상황에서 이러한 오버헤드가 누적되어 성능 저하를 가중시켰을 가능성이 있다고 판단하였습니다.

---

3. OpenTelementry를 꺼서 다시 측정해보자.

애초에 Prod 환경에서 OpenTelementry 쓰는건 적절하지 않다고 판단했습니다.

 

허나, 개발 단계에서 적용된 설정이 그대로 올라가서 사용되고 있었습니다.

이후 OpenTelementry 설정을 전부 끄고 확인해보았습니다.

 

시나리오는 동일하게 위와 같이 진행하였으며, RampUp 또한 존재합니다.

OpenTelemetry 껐을 때 나온 결과

 

이전과 한 번에 비교를 해보면, 

변화 비교

 

Min 처리 시간은 약간의 증가가 있었으나 성능이 대체적으로 대폭 개선된 점을 확인할 수 있습니다.

처리량 (Throughput) 또한 220까지 증가한 모습을 확인할 수 있습니다.

처리량 증가

 

API Latency 또한, 목표한 2~3s 이내를 제대로 달성한 부분을 확인할 수 있습니다.

각 API 별 Latency

 

추가적으로 VUser 1,000의 상황도 다시 확인해보고 싶어 다시 테스팅을 진행하게 되었습니다.

---

4. VUser 1,000의 PeakTest와 RPS 측정 테스트

PeakVUser 1,000의 상황

 

확실히 Max 시간이 오래걸리는 것을 확인할 수 있습니다.

URL 별로 걸린 시간을 알아보면 아래와 같습니다.

URL별 걸린시간

 

Throughput

 

VUser 1,000을 안정적으로 버티기는 하지만, 위 지표에서 볼 수 있듯이 오히려 처리량은 203으로 감소한 것을 확인할 수 있습니다.

VUser가 늘었는데 처리량이 줄었다는 것은 결국 병목이 발생했다는 것입니다.

어디가 문제일지를 파악해보도록 하겠습니다. 

---

요청이 Tomcat으로 들어와서 나가는 전체 처리의 흐름은 아래와 같습니다.

전체 요청 처리 흐름

 

TCP 요청이 들어오고 Tomcat에서 Worker Thread가 Server로 요청을 보냅니다.

이때, Transaction 내부에서 WorkerThread와 N:M 관계로 동작하는 VirtualThread가 잡아서 일을 하기 시작합니다.

이때, DB에 요청을 보낼 일이 생기면, Hikari CP (Spring Boot에서 기본적으로 제공하는 DBCP)에서 Connection을 관리하게 되고, 

Database로 요청을 보냅니다.

그리고 Database의 Thread 핸들링은 one-thread per connection입니다.

실제로 DB에서 아래 쿼리문을 통해 Thread 핸들링을 어떻게 하는지를 확인할 수 있습니다.

SHOW VARIABLES LIKE 'thread_handling';

DB Thread Handling

 

지금 현재 처리 흐름을 봤을 때, Hikari에서 아래와 같은 문제가 발생하고 있었습니다.

Hikari CP 모니터링

 

즉, 활성 스레드 50개로 50개가 전부 Active하게 동작하고 있을 때, 즉, DB Connection을 획득하여 작업 중인 50개의 스레드를 제외하고도 대기열에 621개의 요청이 Connection을 얻기를 기다리고 있는 것입니다. 우선, DB 자체의 처리량부터 확인해보기 위해 DB에서의 Max Connection을 살펴보았습니다.

MySQL DB Max_Connections

 

즉, DB 자체의 처리 수가 문제라기보다는, 151개의 커넥션이 가능한 곳에서, 50개의 Connection만 사용하고 있기에 처리 자체가 밀리게 되고, 결과적으로 621개의 요청이 Pending된 것으로 판단했습니다.

DB 커넥션이 필요한 구간에서 풀 포화가 발생했고, 이는 커넥션 회전이 충분하지 못했다는 것을 의미하기도 합니다.

 

현재 Transaction의 상태를 봤을 때, 더이상 분리할 구간은 없어보였습니다. 

현재 Transaction 상태

 

이에 어플리케이션 측 로그를 확인해보기로 하였습니다.

getImageUrl

 

AOP 기반 실행 시간 로깅과 Hibernate SQL 로그를 통해 요청 흐름을 단계별로 분석하였습니다.

위 사진과 같이 이미지 URL을 조회하는 getImageUrl 로직에서 약 1.7초 이상의 시간이 소요되고 있었으며, 이는 전체 요청 시간의 상당 부분을 차지하는 것이었습니다.

---

5. 원인 분석 후 쿼리 구조 개선

원인은 orderSave 경로에서 DB 조회가 아이템 수만큼 반복되던 구조입니다.

OrderService.java에서 기존엔 상품마다 fileService.getImageUrl() 를 호출했고,

FileService.java의 구현이 file_management 1번 + file_detail 1번이라 상품당 최소 2쿼리였습니다.

 

주문에 5개 상품이면 이미지 URL만으로도 10쿼리라서, 동시 요청 시 Hikari pending 이 늘기 쉬운 구조였습니다.

여기에 AfterConfirmOrderService.java 에서 호출하는 

productService.getDetailId() 도 기존엔 상품별로 product -> details -> connects 를 다시 읽고 있었고,

그 반복 조회가 겹쳐 orderSave 전체 latency를 밀어 올리는 상태였습니다.

이전 프로젝트 진행 중이라면 제가 코드를 바꾸면 안되었지만,

프로젝트가 종료되고 혼자 작업을 해볼 수 있어 상품 부분의 쿼리문을 변경해보았습니다.

 

주문 경로를 배치 조회로 바꿨습니다. 

ReadOnlyOrderService에서 상품 preload 시 fileManagement 를 같이 fetch 하도록 했고, 

ReadOnlyOrderService.java

 

ProductJpaRepository와 FileDetailJpaRepository.java에 배치 조회 쿼리를 추가했습니다.

FileDetailJpaRepository.java

ProductJpaRepository.java

 

그 결과 OrderService.java에서는 이미지 URL을 한 번에 가져오고, 

ProductService.java

ProductService.java에서는 옵션 detail id 도 직접 쿼리 1번으로 찾도록 바꿨습니다.

 

OrderService.java에서는 이미지 URL을 한번에 가져올 수 있도록 아래와 같이 변경되었습니다.

OrderService.java getImageUrl

 

우선, VUser 700일때의 부하테스트 결과는 아래와 같습니다.

VUser 700 Peak Test

 

아주 큰 개선을 시킬 수 있었던 점을 확인할 수 있습니다.

전체적으로 

 

정리해보면,

• getImageUrl 병목은 실제로 N+1 문제가 발생하며 나오게 되는 부분이었습니다.
• 이번 수정으로 주문당 이미지 조회는 2N 에서 사실상 1회 배치 조회 로, 옵션 detail 조회도 불필요한 로딩 없이 직접 조회로 줄일 수 있었습니다.

이대로 VUser 1,000일때의 부하테스트를 진행해보았습니다.

VUser 1,000명 기준 Peak Test

 

이전과 비교했을때 비교적 개선된 수치를 확인할 수 있습니다.

Peak VUser 1,000 Throughput

 

Throughput 또한 이전 VUser 1,000환경에서 203에서 215까지 증가한 부분을 확인할 수 있었습니다.

실제 K6 출력값을 비교해보면, 아래와 같습니다.

Before vs. After

 

이전에 비해 많은 부분이 개선된 점을 확인할 수 있습니다.

모놀리식 아키텍처로 VUser 1,000명에도 버틸 수 있는 서버를 만들 수 있었습니다.

---

👀 마무리하며...

이번 과정을 통해 시스템의 실제 병목이 어디에 존재하는지를 구조적으로 파악하는 것이 얼마나 중요한지를 다시 한 번 체감할 수 있었습니다. 처음에는 Virtual Thread를 통해 I/O Bound 구조를 개선했고, 로그를 통해 DB 커넥션 점유와 N+1 쿼리 구조, 그리고 관측성 오버헤드를 발견할 수 있었습니다.

 

결과적으로

• Virtual Thread 적용
• Observability 오버헤드 제거
• 쿼리 구조 개선 (N+1 제거, 배치 조회)

까지 이어지며, 실제로 Throughput 증가와 Latency 감소라는 유의미한 성과를 만들어낼 수 있었습니다.