[ 선착순 쿠폰 발급 시스템 ] GCP 기본 서버 1대로 10,000 동시 요청 처리 해보기(dial timout 처리 방법)

[ 개발 배경 ]

 선착순 쿠폰 발급 시, 대규모 트래픽이 동시에 발생하여 다양한 문제가 발생할 수 있습니다. 이번 글은 대규모 트래픽 발생 시 발생한 문제들을 개선해 나가는 과정을 기록하였습니다.

 

[  Workflow & Architecture ]

 

위와 같은 Workflow이며

외장 tomcat 과 Spring Boot , Mysql로 쿠폰 발급 시스템을 만들었습니다.

 

 외장 tomcat을 쓴 이유는 jar파일을 만들어 GCP 인스턴스에 배포할 경우, ssh로 접속해서 jar파일을 올려야하는데 이는 시간이 너무 오래걸렸기 때문입니다. 따라서 외장 tomcat을 설치 후 초기 애플리케이션 클래스 파일들을 올린 후 수정이 있을 경우 수정된 클래스 파일을 그 경로에 맞게 배포하는 방식으로 배포 시간을 줄였습니다.

 

또한 선착순 쿠폰 발급 특성 상 대규모 트래픽이 발생하여 동시에 쿠폰 재고 차감 시 정합성 문제가 발생할 수 있기에,

 

쿠폰 발급 이력 확인

          ↓

쿠폰 재고 존재 확인 시 비관적 락

          ↓

쿠폰 재고 차감

          ↓

쿠폰 발급 내역 저장

 

위의 과정이 하나의 트랜잭션 안에서 실행하도록 작성하였습니다.

 

[ 인프라 구성 및 서버 스펙 ]

 이번 테스트에서는 GCP(Google Cloud Platform)환경에서 VPC 기반 네트워크를 구성하고, 각 VM 서버는 동일한 사양으로 설정하여 진행하였습니다. 테스트에 사용된 서버 사양은 아래와 같습니다.

os	cpu 및 memory
debian	코어 1개 vCPU 2개, 메모리 4GB

 

 

[ K6를 활용한 부하테스트 ]

 다양한 테스트 툴과 테스트 방법이 있지만, 아래와 같은 이유로 K6와 Spike 테스트 방법을 선택했습니다.

 

- K6를 사용한 이유

 K6는 JavaScript로 테스트 시나리오를 작성할 수 있으며 HTTP 기반 웹 서비스에 대해 동시 사용자(virtual users) 시뮬레이션과 요청 패턴을 쉽게 구성할 수 있기에 테스트 툴로 K6를 사용하였습니다.

 

- Spike 테스트

선착순 쿠폰 발급이라는 서비스 특성상, 특정 순간에 동시 접속 유저가 폭발적으로 증가할 가능성이 높기 때문에 이번 테스트는 Spike 테스트 방식으로 진행하였습니다. 

---

# 부하테스트 진행 하면서 마주친 문제들

[ dial: i/o timeout ]

 테스트 중 1000번 , 5000번의 동시 요청 시 정합성 문제 없이 100% 쿠폰 발급 성공 하였으나, 10000번의 동시 요청 시 k6로그에 dial: i/o timeout 이 발생하였고 80% 정도의 쿠폰 발급만 성공 하였습니다.

 

아래는 k6 부하테스트 후 결과 일부분을 가져온 것입니다.

    █ TOTAL RESULTS 

 

    checks_total.......: 10000  162.249583/s
    checks_succeeded...: 83.95% 8395 out of 10000
    checks_failed......: 16.05% 1605 out of 10000

    HTTP
    http_req_duration..............: avg=27.77s min=0s    med=29.67s max=58.99s p(90)=46.93s p(95)=49.04s

 

- dial I/O timeout이란? 

 TCP 연결을 시도할 때, 정해진 시간 안에 연결(TCP handshake)이 완료되지 않으면 발생하는 에러 입니다.

이 문제의 원인은 OS의 backlog가 꽉 차서 이후 들어오는 요청을 수락하지 못하는 것 입니다.

 

그렇다면 왜 backlog가 가득 차게 되었을까요?

클라이언트의 요청은 아래와 같은 과정을 거치게 됩니다.

 

Tomcat에서 Acceptor thread가 accept()를 호출

           ↓

OS backlog에 있는 소켓을 꺼내 JVM의 Connection Queue에 넣습니다.

           ↓

Tomcat의 worker thread가 이 Connection Queue에서 소켓을 가져가 요청을 처리

하지만  worker thread가 모두 바쁘면 Connection Queue에 소켓이 계속 쌓이게 되고

           ↓

Queue가 포화되면 Acceptor Thread는 더 이상 accept()를 호출하지 않습니다.

이로 인해 OS backlog가 계속 점유되어 새로운 연결을 받을 수 없게 되고, 결국 클라이언트에서 I/O timeout(dial timeout)이 발생하게 됩니다.

 

따라서 먼저는 worker thread가 db요청 처리하는 부분에 병목이 생길 수 있을 것 같다고 예상하여, spring 로그를 확인해보니 아래와 같았습니다.

 

Connection not added, stats (total=10/10, idle=0/10, active=10, waiting=190)

 

 현재 tomcat의 db connection pool은 최대 10개였으며, 모든 커넥션이 사용 중인 상태에서 190개의 worker thread가 db connection을 얻기 위해 대기하고 있었습니다. 이 상황을 파악하고 db cpu 사용률을 보니 약 20% 정도였습니다. db cpu 사용률이 낮으므로 더 많은 요청을 처리할 수 있다고 판단하여, tomcat의 db connection pool를 최소 100, 최대 200으로 조정하였습니다.

 

문제 해결 시도 #1-1. tomcat의 db connection pool 사이즈 조정

  █ TOTAL RESULTS 

    checks_total.......: 10000  163.178115/s
    checks_succeeded...: 82.97% 8297 out of 10000
    checks_failed......: 17.03% 1703 out of 10000

    HTTP
    http_req_duration..............: avg=28.77s min=0s    med=30.02s max=58.98s p(90)=52.34s p(95)=54.19s

 

waiting 로그는 사라졌지만, 큰 변화는 없었습니다. 또한 아래와 같은 로그가 생기기 시작했습니다.

 

java.sql.SQLNonTransientConnectionException: Connection exception, SQL-server rejected establishment of SQL-connection,  message from server: "Too many connections"

 

 이 예외는 db의 기본 connection보다 많은 connection 요청이 발생하여 생긴 예외입니다. connection 요청이 너무 많아서 cpu에서 처리하지 못하는 것일까 싶어 db cpu 사용률을 확인해보니 대략 20% 정도였습니다.

 

db cpu 사용률 여유가 있으므로 db의  maximum connection을 151 → 250으로 조정하여 테스트를 진행했습니다.

 

문제 해결 시도 #1-2. db의 maximum connection 사이즈 조정 

  █ TOTAL RESULTS 

    checks_total.......: 10000  175.586703/s
    checks_succeeded...: 83.01% 8301 out of 10000
    checks_failed......: 16.98% 1699 out of 10000


    HTTP
    http_req_duration..............: avg=26.29s min=0s    med=29.54s max=54.05s p(90)=45.46s p(95)=47.33s

테스트 결과 Too many connections 예외는 사라지고 db cpu 사용률 약 5% 상승했습니다. 하지만 전체적으로 결과는 기존과 크게 다르지 않았으며 여전히 dial i/o timeout이 발생했습니다. 

 

문제 해결 시도 #1-3. 조건부 update로 로직 변경 

지금까지 테스트들 결과를 보면 평균 latency는 대부분 26~28초 이며 전체 요청 중 90%는 45.46초 이하인 매우 느린 결과입니다. 그 이유는 쿠폰 발급 로직이라 추측을 하였습니다.

 

기존 쿠폰 발급 로직에서 db 요청 처리하는 과정은 아래와 같습니다. 

 

쿠폰 발급 이력 확인

           ↓

쿠폰 재고 존재 확인 시 비관적 락

          ↓

쿠폰 재고 차감

          ↓

쿠폰 발급 내역 저장

    @Transactional
    public String issueCouponPes(IssueCouponDto issueCouponDto) {
        // 쿠폰 발급 이력 확인
        boolean isIssued = historyRepository.existsByCouponIdAndUserId(issueCouponDto.getCouponId(), issueCouponDto.getUserId());

        if(isIssued){
            return "이미 쿠폰이 발급 되었습니다.";
        } else {
            // findByIdsPes 시점부터 락이 걸림
            return couponRepository.findByIdPes(issueCouponDto.getCouponId())
                    .filter(Coupon::hasStock)
                    .map(coupon -> {
                        int updated = couponRepository.decreaseStock(coupon.getCouponId());

                        if (updated == 1) {
                            CouponIssueHistory history = CouponIssueHistory.builder()
                                    .couponId(issueCouponDto.getCouponId())
                                    .userId(issueCouponDto.getUserId())
                                    .build();
                            historyRepository.save(history);

                            return "쿠폰 발급 완료";
                        }
                        return "쿠폰 발급 실패";
                    })
                    .orElse("쿠폰 발급 실패");
        }
    }

 

  위와 같은 경우 발급 여부 및 재고 확인을 위해 요청 수 만큼 select 쿼리를 수행하고 각 요청마다 락 점유 시간이 쌓여서 전체 응답 시간 자체가 느려진다는 것입니다.

또한 정합성에서도 문제가 발생했었습니다.

 

 이를 개선하기 위해 조건부 update를 사용하여, 재고 확인과 차감을 하나의 쿼리로 처리하고 발급 이력은 unique제약을 활용한 insert로 검증하도록 변경하였습니다.  따라서 db에 쿼리를 요청하는 횟수가 4번에 2번으로 줄어들게 되었습니다.

 

변경 로직은 아래와 같습니다.

 

쿠폰 재고 조건부 차감 (update)
        ↓
쿠폰 발급 이력 insert (userId,couponId를 unique 제약으로 중복 방지)

    @Transactional
    public String issueCouponV2(IssueCouponDto dto){

        int update = couponRepository.decreaseStock(dto.getCouponId());

        if(update == 0){
            return "쿠폰 재고 부족";
        }

        int result = historyRepository.insertIgnore(dto.getCouponId(), dto.getUserId());

        if(result <= 0){
            // 재고 없음 → 롤백
            return "쿠폰 이미 발급 됨";
        }
        return "쿠폰 발급 성공";
    }

 

변경 후 테스트 결과는 아래와 같습니다.

 

  █ TOTAL RESULTS 

    checks_total.......: 10000  161.530052/s
    checks_succeeded...: 86.26% 8626 out of 10000
    checks_failed......: 13.74% 1374 out of 10000

    HTTP
    http_req_duration..............: avg=16.62s min=0s    med=16.6s  max=58.99s p(90)=24.59s p(95)=26.89s

평균 latency가 26초에서 16초로, 전체 요청 중 90%는  45초에서 24초로 처리 속도가 향상 되었고 정합성 문제 또한 해결이 되었습니다. 하지만 여전히 dial i/o timeout 발생하고 있었습니다.

 

문제 해결 시도 #1-4. tomcat의 maxConnections 조정

 지금까지는 tomcat의 worker thread 작업 처리 시간이 길어져 OS backlog에서 요청을 거부한 것이라고 추정했으나, 작업 처리 시간을 개선해도 timeout은 여전히 발생했습니다.

 

 작업 처리 시간을 개선했음에도 공통적으로 나타나는 현상이 있었는데, latency의 max 값이 일정하게 나타난다는 것이었습니다. latency max 값은 테스트 동안 관찰된 가장 느린 요청의 응답 시간을 의미하는데, 이를 힌트 삼아 아래와 같이 추측을 하였습니다.

 

 tomcat JVM에 생성되는 socket 갯수는 tomcat의 server.xml에 maxConnections으로 정할 수 있으며 기본값은 8192개 입니다.

지금까지 테스트 현상을 보면 K6에서 약 8,100개 요청까지 가면 멈추는 현상이 공통적으로 있었습니다. 이는 JVM에  socket 객체 수가 maxConnections 만큼 생성되었고, 나머지 요청은 Acceptor가 accept 를 하지 못해서 발생한 것이라고 예측할 수 있었습니다. 

 

예측이 맞는지 확인하기 위해 was서버에서 socket이 얼마나 생성되는지 확인하였습니다.

먼저 was 서버를 모니터링 하기 위한 스크립트 입니다.

 

while true;

do   clear;  

date;     

echo "=====================================================";  

echo " 1. LISTEN QUEUE (Backlog Check - 8080)";  

echo "====================================================="

  printf "%-10s %-10s %-10s\n" "PORT" "Recv-Q" "Send-Q";  

  ss -lnt | grep :8080 | awk '{printf "%-10s %-10s %-10s\n", $4, $2, $3}';   

echo "";  

echo "=====================================================";  

echo " 2. SYSTEM WIDE SUMMARY (ss -s)";  

echo "=====================================================";  

ss -s | grep -E "Total:|TCP:";   

echo "";  

echo "=====================================================";  

echo " 3. DETAILED STATE (PORT 8080)";  

echo "=====================================================";   

 EST=$(ss -ant | grep :8080 | grep -c ESTAB);  

 SYN=$(ss -ant | grep :8080 | grep -c SYN-RECV);  

 TIME_WAIT=$(ss -ant | grep :8080 | grep -c TIME-WAIT);  

 CLOSE_WAIT=$(ss -ant | grep :8080 | grep -c CLOSE-WAIT);  

 LISTEN=$(ss -ant | grep :8080 | grep -c LISTEN);   

echo "ESTABLISHED : $EST    (JVM이 처리 중인 연결)";  

echo "SYN_RECV    : $SYN    (OS 대기열에도 못 들어온 시도)";  

echo "TIME_WAIT   : $TIME_WAIT (종료 절차 중)";  

echo "CLOSE_WAIT  : $CLOSE_WAIT (비정상 종료 확인 필요)";  

echo "LISTEN      : $LISTEN";  

echo "=====================================================";    sleep 0.5; done

 

 저의 추정이 맞는지 확인하기 위해  Tomcat이 최대 유지할 수 있는 TCP connection 수인 maxConnections 값을 10,000 으로 조정 후 테스트를 진행하였고 아래는 테스트 결과입니다. 

 

 █ TOTAL RESULTS 

    checks_total.......: 10000   367.699242/s
    checks_succeeded...: 100.00% 10000 out of 10000
    checks_failed......: 0.00%   0 out of 10000

    ✓ status is 200

    HTTP
    http_req_duration..............: avg=15.85s min=1.61s med=16.5s  max=24.36s p(90)=23.25s p(95)=23.73s

드디어 10,000건의 요청 모두 성공하게 되었습니다. Tomcat 기본 maxConnections(8,192) 한계로 인해 10,000 동시 요청 시 TCP conneciotn을 수립하지 못하며 dial timeout 발생한 문제였던 것입니다. 따라서 maxConnections 10,000으로 증가시켜 모든 요청 정상 처리하였습니다.

 

서버 1대로 10,000건의 요청을 처리하였지만 요청의 95%의 latency가 23초나 됩니다. 이는 너무 느린 값으로 다음에는 latency 개선하는 것을 목표로 글을 써보겠습니다.

 

[ 이번에 배운것들 ]

# Tomcat은 어떤 방식으로 OS backlog 에서 요청을 가져와 처리하는걸까?

 Tomcat의 Acceptor 스레드가 OS의 Accept Queue(Backlog)에 대기 중인 연결을 가져와서 NIO 방식으로 처리할 수 있도록 Poller에게 넘겨주는 구조입니다.

 

 Tomcat 8.5 버전 이후부터는 BIO(Blocking I/O) 방식이 삭제되고 NIO(Non-blocking I/O)가 기본이 되었기 때문에, 현재 사용하시는 대부분의 환경에서는 이 메커니즘으로 동작합니다.

 

클라이언트와 서버 OS 간의 TCP 3-Way Handshake가 완료되면, 해당 연결은 OS의 Accept Queue(Backlog)에 들어갑니다.

  ↓

 

Tomcat 내부의 Acceptor라는 별도의 스레드가 serverSocket.accept()를 호출합니다. 이때 OS 큐에서 완성된 연결(Socket)을 하나씩 꺼내옵니다. 이 때 Acceptor가 OS의 Accept Queue에서 연결을 꺼내올 때, 가장 먼저 확인하는 것이 바로 현재 활성화된 연결 수입니다. 현재 연결된 수 ≥ maxConnections 이면, Acceptor는 더 이상 accept()를 호출하지 않고 잠시 대기(Block) 상태에 빠집니다.

  ↓

 

Acceptor가 소켓을 꺼내면, 이를 그대로 처리하지 않고 Poller 스레드에게 전달합니다.

  ↓

 

Poller는 NIO의 핵심인 Selector를 가지고 있으며 읽기 준비가 된 소켓을 발견하면, 실제 비즈니스 로직을 수행할 Worker 스레드에게 작업을 할당합니다. 이 때 Worker 스레드의 수는 maxThreads 설정으로 정해집니다. 따로 설정하지 않을 시 기본값은 200입니다.