p6spy 사용시 Transactional readOnly 옵션이 먹히지 않는 문제

프로젝트에서 데이터베이스 트랜잭션 분산과 SPOF를 막기 위해 두 개의 데이터베이스(Source, Replica)를 생성해 Replication을 적용했습니다. 스프링 부트에서 읽기 작업과 쓰기 작업을 각각 다른 데이터베이스에서 처리하기 위해 RoutingDataSource에서 서비스 메서드에 달린 @Transactional의 readOnly 옵션에 따라서 적절한 DataSource를 반환해 주는 작업을 하는 중 두 가지 문제가 발생했습니다.

우선, 기대한 시나리오는 서비스 메서드에 적용된 @Transactional의 readOnly옵션에 따라 적절한 DataSource를 반환해 줘야 하므로, @Transactional을 통해 생성된 TransactionDefinition을 사용하여 트랜잭션 정보(readOnly)들이 동기화 된 이후의 DataSource에서 Connection을 생성하는 것이었습니다.

• @Transactional의 readOnly옵션에 따라 SOURCE(쓰기용) 또는 REPLICA(읽기용) DataSource를 반환한다.
  

• Lazy하게 DataSource를 생성중(아래 dataSource빈 참고).
  

본래 DataSource에서 Connection을 가져오는 과정이 트랜잭션 정보가 동기화되는 코드보다 더 빨리 실행되지만, RoutingDataSource를 LazyConnectionDataSourceProxy로 감쌌기에 실제 Connection을 사용하는 시점에 Lazy하게 Connection객체를 생성하게 해서 동기화된 트랜잭션 정보들을 가져오게 했습니다.

이 과정에서 발생한 첫 번째 문제는 RoutingDataSource를 반환하기 위해 TransactionSynchronizationManager로 부터 readOnly값을 가져올 때 항상 false가 반환되는 문제였습니다. 때문에 읽기 작업은 읽기용 데이터베이스에 접근하지 못하고, 쓰기용 데이터베이스에 접근하게 되었습니다.

문제의 원인을 찾기 위해 트랜잭션을 시작하고 커넥션을 할당받는 과정을 디버깅 해보았습니다. 결론부터 말씀드리면 쿼리 로그를 보기 위해 사용한 p6spy의 DataSource가 트랜잭션이 동기화되기 전에 커넥션을 만든 것이 원인이었습니다.

처음에는 readOnly이 false이므로 TransactionDefinition이 제대로 초기화되지 않았거나, Lazy하게 Connection이 생성되지 않았을 거라 생각했지만 디버깅을 하면서 Transaction Definition의 서비스에 붙은 @Transactional 정보가 잘 들어가 readOnly이 true로 세팅되는 것을 확인했습니다. LazyConnectionDataSourceProxy 또한 잘 할당되는 것을 확인했습니다.

그러나 예측한 시나리오대로면,

1. 트랜잭션이 동기화되기 전 LazyConnectionDataSourceProxy로 부터 생성한 프록시 Connection객체
2. 실제 prepatedStatement가 실행되는 시점에 RoutingDataSource로부터 생성하는 Connection 객체

이렇게 두 개의 Connection이 생성되어야 하는데, p6DataSource에서 Connection이 하나 더 생성되는 것을 확인할 수 있었습니다.

저희 프로젝트는 dev서버에서도 쿼리의 로그를 찍어보고 싶었기에 쿼리를 로깅해주는 p6spy가 dev서버에 적용된 상태였습니다. p6DataSource는 트랜잭션이 동기화되기 이전에 Connection 객체를 생성해 주고 있었기에 readOnly값이 default인 false로 항상 초기화되고 있었습니다.

즉, LazyConnectionDataSourceProxy로 트랜잭션이 동기화된 이후 Lazy하게 Connection을 만들 것을 기대했으나, p6DataSource로 인해 트랜잭션이 동기화되기 전에 Connection객체가 생성되어 문제가 발생한 것이었습니다.

p6DataSource는 p6spy의 p6SpyDataSourceDecorator라는 클래스로부터 생성되고 있었습니다. p6SpyDataSourceDecorator는 p6spy의 로그 포맷을 지정하는 등 기능을 제공하고 있습니다.
p6SpyDataSourceDecorator를 상속받은 커스텀 Decorator를 만들어 Lazy한 Connection을 반환하는 것을 고려했으나, 현재 p6spy에 추가적인 설정을 할 필요성을 느끼지 못해 default 설정을 사용하고 있었습니다. 때문에 p6SpyDataSourceDecorator 자체가 불필요하다고 생각해 프로퍼티 설정 파일에서 p6spy의 decorate옵션을 꺼줌으로써 p6DataSource가 생성되지 않게 했습니다. 자동으로 p6DataSource의 Connection객체를 사용하는 코드도 사라져 readOnly이 항상 false로 반환되는 문제가 해결되었습니다.

• application.yml에서 p6spy decorate옵션 비활성
  

두 번째 문제는 쿼리를 카운트하는 AOP에서 실제로 발생하는 쿼리 개수보다 3배 더 많은 수로 출력해주는 문제였습니다. 문제를 말씀드리기 전, 저희 프로젝트는 하나의 API마다 발생하는 쿼리의 개수를 카운트하기 위해, 쿼리의 개수를 나타내는 ThreadLocal 변수를 만들고, MethodInterceptor를 사용해 쿼리를 실행하는 메서드("executeQuery", "execute", "executeUpdate")가 호출될 때마다 ThreadLocal의 변수를 카운트했습니다.
관련 포스팅은 이곳에 있습니다.

그러나 Replication을 적용한 후, 쿼리 카운트가 세 배가 되는 문제가 발생했습니다. LazyConnectionDataSourceProxy와 p6DataSource로 인해 생성되는 Connection이 세 개가 되면서 각 Connection이 지닌 쿼리가 전부 카운트되었기 때문입니다.
세 개의 Connection이 실제로 DB에 쿼리를 날리는 것은 아니지만, 프록시 Connection또한 prepareStatement에서 쿼리를 execute하는 메서드를 실행하고 있기에 MethodInterceptor에서 세 커넥션이 쿼리를 날린다고 판단하고 카운트하고 있었습니다.

해당 문제는 MethodInterceptor에서 받은 MethodInvocation을 실행한 클래스가 HikariProxyConnection일 때만 카운트하는 로직을 추가해 해결했습니다.

@RequiredArgsConstructor
public class ConnectionProxyHandler implements MethodInterceptor {

    private static final String JDBC_PREPARE_STATEMENT_METHOD_NAME = "prepareStatement";
    private static final String HIKARI_CONNECTION_NAME = "HikariProxyConnection";

    private final Object connection;
    private final LoggingForm loggingForm;

    @Nullable
    @Override
    public Object invoke(@Nonnull final MethodInvocation invocation) throws Throwable {
        final Object result = invocation.proceed();

        if (hasConnection(result) && hasPreparedStatementInvoked(invocation)) {
            final ProxyFactory proxyFactory = new ProxyFactory(result);
            proxyFactory.addAdvice(new PreparedStatementProxyHandler(loggingForm));
            return proxyFactory.getProxy();
        }

        return result;
    }

    private boolean hasPreparedStatementInvoked(final MethodInvocation invocation) {
        final Object targetObject = invocation.getThis();
        if (targetObject == null) {
            return false;
        }
        final Class<?> targetClass = targetObject.getClass();
        final Method targetMethod = invocation.getMethod();
        
        // hikari 커넥션일때만 카운트하게 설정
        return targetClass.getName().contains(HIKARI_CONNECTION_NAME) &&
                targetMethod.getName().equals(JDBC_PREPARE_STATEMENT_METHOD_NAME);
    }

    private boolean hasConnection(final Object result) {
        return result != null;
    }

    public Object getProxy() {
        final ProxyFactory proxyFactory = new ProxyFactory(connection);
        proxyFactory.addAdvice(this);
        return proxyFactory.getProxy();
    }
}