[나날] 동시 요청시 Transaction Propagation 설정으로 인한 CP Deadlock 문제

문제

클라이언트로부터 동시 요청이 들어왔을때, 서버가 잠시동안 정상 동작하지 못하는 상황이 확인되었다.

 

---

문제 분석

Grafana 대시보드에 Connection Timeout Count가 증가된 것이 확인되었다.

서비스 특성상 지정된 connection-timeout 내에 처리가 불가능할만큼의 트래픽이 발생하지는 않았을 것이라 생각했고, Deadlock 발생으로 인한 문제를 예상하며 서버 로그를 확인하였다.

// 스레드가 DB 커넥션을 요청한 시점으로부터 connection-timeout 만큼 지났을때 발생하는 로그들

HikariPool-1 - Connection is not available, request timed out after 5000ms.

[CannotCreateTransactionException] Could not open JPA EntityManager for transaction; nested exception is org.hibernate.
exception.JDBCConnectionException: Unable to acquire JDBC Connection

로그에는 한 번에 여러개의 요청이 들어왔고, 그 요청들중 대부분이 위와 같은 예외를 발생시키며 처리됐다.

문제를 해결하기 위해, 먼저 문제 상황을 재현하고자 했다.

 

---

 

문제 발생 조건

로컬 환경에서 jmeter를 통해 동시 요청 개수를 늘려가며 테스트했고, 그 결과 동시 요청 개수가 connection pool size와 정확하게 일치하는 상황부터 문제가 발생함을 확인할 수 있었다.

문제 발생 조건을 알아냈으니, 이제는 원인을 파악하고자 했다.

 

---

 

예상 원인

DB에서 문제가 생겼을 가능성에 중점을 두며, 처음엔 두 가지 원인을 예상했다.

 

connection pool size 부족

connection pool의 크기 조정은 처리속도가 유입되는 트래픽량을 감당하지 못하여 대기중인 요청이 timeout 되는 상황에서 조정해볼 요소이다.

다시말해 connection이 고갈되더라도 요청 처리는 계속해서 진행되야 한다는 것이다.

현재 상황은 동시 요청 개수가 정확히 connection pool size와 일치하는 순간부터 timeout까지 모든 요청이 진행되지 않는다.

따라서 connection pool size는 이번 문제의 원인이 아니라고 판단했다.

트랜잭션내에서 Deadlock 발생

문제가 발생한 요청이 회원가입이었기에, 데이터 생성 과정에서 Deadlock이 발생했을 가능성에 중점을 두고 INNODB 기록을 확인하였다.

하지만 아래에서 보듯이 이번 문제에 관련된 Deadlock 기록은 없었고, 현재 작업과 무관한 Deadlock 기록만이 남아있었다. 추가적으로 문제 상황에서 Lock을 가지고 있는 프로세스가 존재하는지 확인해봤지만 발견할 수 없었다.

Deadlock 기록

Lock을 가진 프로세스가 존재하지 않음을 확인

 

---

 

문제 발생 지점 특정

DB의 동작에서는 문제가 없음을 확인하고, 검증 범위를 어플리케이션으로 좁혔다. 그리고 다른 API에서도 동일한 상황에서 문제가 발생하는지 확인이 필요했다.

테스트 결과 생성, 수정, 삭제 관련 API 외에, Lock을 걸지않는 단순 조회 API 에서도 동일한 문제가 발생함을 확인했다.

현재 격리 수준은 repeatable read 이다. innodb는 MVCC 기법을 통해 repeatable read 에서 Consistent Nonlocking Reads가 가능하다.

전반적으로 발생한다는 점에서 Spring AOP 에서의 문제 발생을 의심하며, PinPoint로 정확한 문제 발생 지점을 찾고자 했다.

 

정상 처리

 

예외 발생시

콜스택을 보면 한 요청에서 getConnection() 이 두 번 호출되어 커넥션을 획득하고자 하는데,
두 번째 getConnection() 에서 커넥션을 얻어오고 못하고 connection-timeout(5초로 설정) 이 발생했음이 확인된다.

코드 레벨에서 확인해본 결과, Spring AOP를 사용하여 로그를 기록하는 부분이 존재하고,
해당 부분에서 쓰기를 하고자 두 번째 getConnection()을 호출하고 있었다.

바로 여기에서 문제가 발생한 것이다.

 

---

 

원인 - REQUIRES_NEW 속성

하지만 기본적으로  getConnection()시에 기존 트랜잭션이 진행되고 있다면, 기존 트랜잭션에 participate 하는 형태로 진행된다. 따라서 추가적인 커넥션이 소비되지 않는 것이다.

그렇기에 해당 메서드의 트랜잭션 전파 속성 설정이 무엇으로 되어있는지 확인이 필요했고,
확인 결과 REQUIRES_NEW 로 설정된걸 찾을 수 있었다.

public interface LogRepository extends JpaRepository<Log, Long> {
	// REQUIRES_NEW는 무조건적으로 새로운 커넥션을 할당받아 물리 트랜잭션을 시작
    @Transactional(propagation = Propagation.REQUIRES_NEW)
    Log save(Log log);
}

 

해당 설정을 제거하여 새로운 트랜잭션을 시작하는게 아닌, 기존 트랜잭션에 participate하여 작업을 수행하도록 설정했다.

이후 문제 발생 상황을 재현한 결과 문제가 발생하지 않았고

다른 케이스들에서도 전파 속성을 변경하고 테스트해본 결과, 정상적으로 동작하였다.

 

그럼 왜 해당 속성이 문제가 되었던걸까? 

스레드들이 로그를 쓰려할 때, REQUIRES_NEW 설정에 따라 새로운 connection을 할당받아 작업을 이어나가려 하지만 connection pool은 이미 connection size 만큼의 동시 요청으로 인해 고갈된 상태가 된다. 그렇기에 추가적인 connection을 할당해주지 못하여 모든 스레드들이 작업을 끝내지 못한 상태에서 계속 connection을 요청하기만 하는 Deadlock이 발생한 것이다.

이런 상황이었기에 동시 요청이 pool size만큼 왔을때부터 문제가 발생한 것이다. 아래는 자세한 문제 발생 흐름이다.

1. 비즈니스 메서드에 @Transactional 이 설정되어 있고, 해당 메서드를 포인트컷으로 하여 로그를 저장하는 aop도 설정되어 있음. 로그 저장시에는 새로운 connection을 할당받아 트랜잭션을 시작함.

2. connection pool size만큼의 요청이 동시에 들어와 connection pool의 모든 connection이 active 상태
-> connection pool 고갈

3. 스레드들이 로그 저장을 위해 새로운 connection 요청하지만 connection pool이 고갈된 상태이기 때문에 새로운 connection이 채워질때까지 대기

4. 스레드들은 자신의 작업을 끝내기전까지 처음에 얻은 트랜잭션을 반납하지 않기때문에 결국에는 모두가 작업을 멈춘채 새로운 connection을 요청하기만 하는 상태 -> Deadlock

 

---

해결

로그 저장시 메서드에 설정해둔 REQUIRES_NEW 를 전부 REQUIRES로 바꾸어 기존 트랜잭션에 참여하는 형태로 변경하였고, 모든 요청에 있어 동일한 문제는 발생하지 않음을 확인할 수 있었다.

또한 의미없이 비즈니스 메서드 전체에 트랜잭션을 거는게 아닌, 트랜잭션의 범위를 최소화해서 정말 필요한 곳에만 트랜잭션이 진행되게했다.

 

---

정리

단순 조회 로직 트랜잭션은 readOnly로 설정하여 dirty checking이 발생하지 않게 하자는 의도에서, REQUIRES_NEW 설정을 통해 단순 조회 로직과 로그 작성의 트랜잭션을 분리했었다.

그 결과 이번 문제가 발생하였고, 해결하는데 있어서 적지 않은 시간이 들었다.

REQUIRES_NEW 같이 side effect 발생 가능성이 매우 큰 설정은 최대한 검증된 상황에서만 써야 한다는 것을 배웠다.