QueryDSL 데드락 해결하기

문제

• 프론트에서 특정 페이지에 접속하면 결과가 계속 넘어오지 않는 이슈를 전달
• 디버깅을 위해 페이지에서 호출하는 각 쿼리를 일일이 호출한 결과 문제 없이 수행
• 정말 딱 해당 페이지에 접속할때만 결과가 넘어오지 않음
  
• 더 큰 문제는, 이러한 과정이 반복되면 모든 요청이 처리되지 않는 문제가 발생

  원인 파악

  1. 커넥션 확인

• 현 프로젝트는 JPA 를 사용하고 있으며, connection leak 이 발생하면 로그를 출력하도록 설정해둠
• 위 버그를 재현하면 다른 로그 없이 connection leak 로그가 출력
• 커넥션의 상태를 추적하고자 함
• 라이브러리에서 커넥션을 흭득하는 과정을 보면 다음과 같이 metricTracker에 로그를 남기는 모습을 볼 수 있음

public Connection getConnection(final long hardTimeout) throws SQLException  
{  
   suspendResumeLock.acquire();  
   final var startTime = currentTime();  

   try {  
      var timeout = hardTimeout;  
      do {  
         var poolEntry = connectionBag.borrow(timeout, MILLISECONDS);  
         if (poolEntry == null) {  
            break; // We timed out... break and throw exception  
         }  

         final var now = currentTime();  
         if (poolEntry.isMarkedEvicted() || (elapsedMillis(poolEntry.lastAccessed, now) > aliveBypassWindowMs && isConnectionDead(poolEntry.connection))) {  
            closeConnection(poolEntry, poolEntry.isMarkedEvicted() ? EVICTED_CONNECTION_MESSAGE : DEAD_CONNECTION_MESSAGE);  
            timeout = hardTimeout - elapsedMillis(startTime);  
         }  
         else {  
            metricsTracker.recordBorrowStats(poolEntry, startTime);  
            return poolEntry.createProxyConnection(leakTaskFactory.schedule(poolEntry));  
         }  
      } while (timeout > 0L);  

      metricsTracker.recordBorrowTimeoutStats(startTime);  
      throw createTimeoutException(startTime);  
   }  
   catch (InterruptedException e) {  
      Thread.currentThread().interrupt();  
      throw new SQLException(poolName + " - Interrupted during connection acquisition", e);  
   }  
   finally {  
      suspendResumeLock.release();  
   }  
}

• 이를 이용하기 위해서 로컬에 로그를 남기는 구현체를 새로 생성

package com.gabia.securityportal.config;

import org.slf4j.Logger;
import org.slf4j.LoggerFactory;

import com.zaxxer.hikari.metrics.IMetricsTracker;
import com.zaxxer.hikari.metrics.PoolStats;

public class LoggingMetricsTracker implements IMetricsTracker {

    private static final Logger logger = LoggerFactory.getLogger(LoggingMetricsTracker.class);
    private final String poolName;
    private final PoolStats poolStats;

    public LoggingMetricsTracker(String poolName, PoolStats poolStats) {
        this.poolName = poolName;
        this.poolStats = poolStats;
    }

    private String getPoolStatsLog() {
        return String.format("Pool Name: %s, Total Connections: %d, Active Connections: %d, Idle Connections: %d, Threads Awaiting Connection: %d",
                poolName,
                poolStats.getTotalConnections(),
                poolStats.getActiveConnections(),
                poolStats.getIdleConnections(),
                poolStats.getThreadsAwaitingConnection());
    }

    @Override
    public void recordConnectionCreatedMillis(long connectionCreatedMillis) {
        logger.debug("Connection created in {} ms, {}", connectionCreatedMillis, getPoolStatsLog());
    }

    @Override
    public void recordConnectionAcquiredNanos(long elapsedAcquiredNanos) {
        logger.debug("Connection acquired in {} ns, {}", elapsedAcquiredNanos, getPoolStatsLog());
    }

    @Override
    public void recordConnectionUsageMillis(long elapsedBorrowedMillis) {
        logger.debug("Connection used for {} ms, {}", elapsedBorrowedMillis, getPoolStatsLog());
    }

    @Override
    public void recordConnectionTimeout() {
        logger.warn("Connection timeout occurred, {}", getPoolStatsLog());
    }

    @Override
    public void close() {
        // No resources to close
    }
}

• 구현체를 등록하기 위해 구현체 인스턴스를 반환하는 MetricsTrackerFactory 생성

import com.zaxxer.hikari.metrics.IMetricsTracker;
import com.zaxxer.hikari.metrics.MetricsTrackerFactory;
import com.zaxxer.hikari.pool.PoolStats;

public class LoggingMetricsTrackerFactory implements MetricsTrackerFactory {

    @Override
    public IMetricsTracker create(String poolName, PoolStats poolStats) {
        return new LoggingMetricsTracker();
    }
}

• BeanPostProcessor를 이용해 구현한 LoggingMetricsTracker를 HikariDataSource의 MetricsTracker로 등록

import com.zaxxer.hikari.HikariDataSource;
import com.zaxxer.hikari.metrics.MetricsTrackerFactory;
import org.springframework.beans.BeansException;
import org.springframework.beans.factory.config.BeanPostProcessor;
import org.springframework.context.annotation.Bean;
import org.springframework.context.annotation.Configuration;

@Configuration
public class HikariMetricsConfiguration {

    @Bean
    public MetricsTrackerFactory metricsTrackerFactory() {
        return new LoggingMetricsTrackerFactory();
    }

    @Bean
    public BeanPostProcessor hikariMetricsPostProcessor(MetricsTrackerFactory metricsTrackerFactory) {
        return new BeanPostProcessor() {
            @Override
            public Object postProcessBeforeInitialization(Object bean, String beanName) throws BeansException {
                if (bean instanceof HikariDataSource) {
                    ((HikariDataSource) bean).setMetricsTrackerFactory(metricsTrackerFactory);
                }
                return bean;
            }
        };
    }
}

• 위 기능을 이용해서 커넥션의 상태를 확인한 결과 pending 이 걸리는 요청 개수 만큼 active 상태로 유지되는 커넥션이 지속해서 쌓이는 것을 확인.
• 이 과정이 누적되면서 사용가능한 커넥션이 줄어들고 결국엔 사용할 수 있는 커넥션이 없어 모든 조회에서 pending 이 발생하는 것을 확인
• DB 세션을 조회한 결과 해당 커넥션은 아무 작업도 수행하고 있지 않는 것을 확인
• 이는, 커넥션을 흭득한 작업이 무한 루프에 빠져 탈출하고 있지 못하고 있다는 것을 의미, 다른 원인을 찾아보기로함

  2. Step Debugging

• 무한 루프에 걸리는 부분을 찾기 위해서 디버깅 모드를 켜고 한 줄씩 실행
• 그 중, queryDSL 로 쿼리를 생성하는 부분에서 다음 스텝으로 넘어가지 않는 현상을 확인
• 좀더 정확한 부분을 찾기 위해 스텝인 진행
• 라이브러리가 만들어준 QEntity 인스턴스를 참고하는 과정에서 예외 발생
  
• 구글링을 통해 유사한 이슈 검색
• queryDSL 공식문서에서 멀티스레딩 환경에서 Q-type 초기화 문제 를 확인
• 멀티스레딩 환경에서 Q-type 을 초기화하면 데드락이 발생할 수 있다는 문제
• 정확히 나의 현재 상황과 일치했기때문에 Repository 에서 별도의 QEntity 인스턴스를 생성해 사용
• 그 결과 기존 문제가 해결되고 커넥션도 잘 반환되는 것을 확인