쿠폰 발급의 동시성 테스트를 진행하다 예상치 못하게 커넥션 타임아웃이 발생했다.
이 문제를 발견하게 된 상황과 문제 이해, 해결 과정을 정리해 본다.

TL;DR

• JPA의 기본키 생성전략 AUTO 는, MySQL에서 TABLE 로 동작
• TABLE 생성전략은 식별자를 가져오기 위해 추가 커넥션을 필요로 한다.

문제상황

MySQL에서 분산락과 비관락의 비교를 위해 쿠폰 발급의 동시성 테스트를 하고 있었는데 비관락 테스트중 예상치 않은 커넥션 타임아웃이 발생했다.

크기가 10인 스레드풀을 만들고 동시에 각 스레드에서 쿠폰 발급 요청을 보내 정확히 10개의 쿠폰 발급이 이루어지는지 테스트를 진행중이였다.

// 테스트 코드
        for (int i = 0; i < 10; i++) {
            executors.submit(() -> {
                couponService.issueCoupon(coupon.getId(), user.getId());
            });
        }

// 테스트 수행 로직
    @Transactional
    public Long issueCoupon(String couponId, Long userId) {
        log.info("try lock");
        Coupon coupon = getCoupon(couponId);
        log.info("get lock!");
        User user = userRepository.getReferenceById(userId);
        UserCoupon userCoupon = coupon.issueCoupon(user);
        userCouponRepository.save(userCoupon);
        return userCoupon.getId();
    }

HikariCP 의 크기는 스레드풀과 동일한 10 이였기 때문에 커넥션이 부족한 상황은 없어야 했다.

하지만 커넥션 타임아웃이 발생했고 테스트에 실패했다.

문제이해

로그를 분석해 보니 최초로 락을 얻은 8번 스레드 가 작업을 수행하다 커넥션을 얻지 못해 타임아웃이 난것을 확인할 수 있었다.

8번 스레드를 포함한 10개의 요청 스레드가 각각 1개의 커넥션을 가져간 상태다.

또한 락을 얻은 8번 스레드를 제외한 9개의 스레드는 8번이 락을 해제할때까지 커넥션을 점유하며 대기하게 된다. 즉 8번이 작업을 끝내기 커넥션을 주지 않는다.

로그대로라면 8번 스레드가 추가적인 커넥션을 요청했지만, 커넥션을 얻을 수 없어 타임아웃이 난 상황이다.

가설 1) 8번 스레드가 작업 도중 커넥션을 릴리즈하고, 다시 얻는 과정에서 얻지 못했다.

@Transactional 의 동작에 따르면 작업이 끝나기 전에 커넥션을 릴리즈 하지 않는다. 게다가 커넥션을 릴리즈 했다는 말은 트랜잭션이 커밋이든 롤백이든 종료 되었다는 의미다.

그렇다면 다른 9개의 스레드중 하나가 락을 얻어 작업을 수행했을 것이다.

즉 8번 스레드는 기존 작업중인 커넥션을 릴리즈 한 적이 없다.

가설 2) 하나의 자원에 동시에 많은 for update 요청이 들어가 DB에 버그가 발생한다.

지금 상황은 단 하나의 자원에 여러개의 요청이 동시에 접근하는 상황이다.

만약 어떠한 이유로 하나의 자원에 요청이 몰려 버그성 동작이 발생할 수도 있다고 생각해 테스트를 진행해봤다.

자원 하나에 동시에 100개의 for udpate 문을 날려 봤지만 한번에 하나의 요청이 처리되었고, 이경우에 아주 정상적으로 동작했다.

즉 하나의 자원에 for update 요청을 아무리 많이 날려도 추가적인 자원을 요구하지 않는 이상 데드락은 발생하지 않는다.

가설 3) 8번 스레드가 작업도중 추가적인 커넥션을 요청한다.

사실 로그를 보더라도 남은 원인이 이것밖에 없다.

8번 스레드가 락을 얻은 상태에서 추가적인 커넥션 (자원) 을 요구했고 이 상황에서 자신이 점유한 락 (자원)때문에 자신 또한 커넥션 (자원) 을 얻을 수 없고 이로 인해 데드락이 발생하는 상황

이 이유 말고는 설명이 안된다.

그렇다면 왜 8번 스레드가 커넥션을 요구했는지 알아보자.

접근

장애 지점 찾기

로그를 찍어 어디서 커넥션을 요구하는지 알아봤다.

	@Transactional
    public Long issueCoupon(String couponId, Long userId) {
        log.info("try lock");
        Coupon coupon = getCoupon(couponId);
        log.info("get lock!");
        User user = userRepository.getReferenceById(userId);
        log.info("log 1");
        UserCoupon userCoupon = coupon.issueCoupon(user);
        log.info("log 2");
        userCouponRepository.save(userCoupon);
        log.info("log 3");
        return userCoupon.getId();
    }

그 결과 log 2 까지는 정상적으로 출력되고 타임아웃 전까지 log 3 이 출력되지 않았다.

즉 save 에서 새로운 커넥션을 요청한다는 말이다.

자세한 로그 출력

좀더 자세한 원인을 알아보기 위해 로그 레벨을 낮춰 출력해봤다.

logging:
  level:
    sql: trace
    hikari: debug
    com:
      zaxxer:
        hikari: debug
    org:
      springframework:
        transaction: debug
        orm:
          jpa: debug

로그를 보면 이번엔 6번 스레드가 락과 커넥션, 트랜잭션을 얻어 실행하다 갑자기 커넥션을 요구하더니 5초후 커넥션 타임아웃이 난것을 확인할 수 있다.

이후 아까와 동일하게 롤백으로 트랜잭션이 끝나게 된다.

한마디로 쿠폰을 발급하는 도중에 추가 커넥션이 필요한것은 확인된거고, 왜 필요한것인지를 알아봐야 한다.

HikariCP 크기 증가

커넥션 풀의 크기를 20으로 증가시켰다.

로그를 보면 UserCoupon 의 식별자를 가져오기 위해 새로운 커넥션을 만든다는것을 확인할 수 있다.

기존 12번 커넥션이 있지만, 새로운 18번 커넥션을 새로 생성해 for update 로 식별자 값을 안전하게 가져오는걸 알 수 있다.

왜 이런 동작이 발생하는가?

@GeneratedValue 의 기본 전략은 AUTO 다. 또한 MySQL에서 AUTO의 기본 동작은 TABLE 로 동작하게 된다.

나의 경우 기본값을 사용했고, 그로 인해 MySQL 에서 @GeneratedValue 의 전략이 TABLE 로 사용된 것이다.

그렇다면 TABLE 전략은 왜 추가 커넥션을 필요로 하는가?

이 부분은 생각보다 간단하고 당연하다.

TABLE 은 새 엔티티의 식별자를 DB의 시퀀스 테이블로부터 배타락을 걸고 값을 가져와 증가시킨다.

이때 기존 커넥션(트랜잭션) 으로 시퀀스 테이블에 접근시 현재 트랜잭션이 종료되기 전까지 다른 모든 트랜잭션이 새 식별자값을 만들지 못하게 된다.

이경우 다른 트랜잭션이 특정 자원을 점유한 상태에서 식별자를 가져오지 못해 데드락의 위험성이 아주 높아지게 된다.

이러한 문제를 예방하기 위해 시퀀스 테이블로부터 식별자를 가져오는 동작은 추가적인 커넥션을 만들어 가져오는것이 Hibernate의 기본 동작인 것이다.

문제 해결

문제 해결 방법은 간단하다.

HikariCP의 크기를 증가시키거나, @GeneratedValue 의 전략을 TABLE 이 아닌 IDENTITY 로 변경하면 된다.

정리

10개의 커넥션 풀이 있는 상황에서 10개의 요청을 동시에 테스트하니 커넥션 타임아웃이 발생했다.
이유는 식별자 자동 생성 전략이 TABLE 이였기 때문에 하나의 요청에서 최대 2개의 커넥션이 필요로 하기 때문이다.
그래서 10개의 커넥션이 모두 사용된 상태에서 자원을 점유한 스레드가 추가적인 커넥션을 요구하자 제공할 수 있는 커넥션이 없기 때문에 타임아웃이 발생하게 된 것이다.