없는 페이지 요청시 Hikari 연결 누수

어떤 문제가 생겼나요?

@Configuration
public class QuerydslConfig {
    @PersistenceContext
    private EntityManager entityManager;

    @Bean
    public JPAQueryFactory jpaQueryFactory() {
        return new JPAQueryFactory(entityManager);
    }

}

public class IdeaRepositoryCustomImpl extends QuerydslRepositorySupport implements IdeaRepositoryCustom {

    private QIdea qIdea = QIdea.idea;
    private QUsers qUsers = QUsers.users;
    private JPAQueryFactory queryFactory;

    public IdeaRepositoryCustomImpl(JPAQueryFactory jpaQueryFactory) {
        super(Idea.class);
        this.queryFactory = jpaQueryFactory;
    }

    @Override
    public Optional<IdeaResponse> findIdeaOne(Long ideaId) {
        return Optional.ofNullable(queryFactory.select(Projections.constructor(IdeaResponse.class,
                        qUsers.nickname.as("writer"),
                        qIdea.title,
                        qIdea.content,
                        qIdea.imageName.concat(ServerIpAddress.s3Address).as("imageUrl"),
                        qIdea.auctionStatus.as("status"),
                        qIdea.minimumStartingPrice,
                        qIdea.bidWinPrice
                ))
                .where(qIdea.id.eq(ideaId))
                .from(qIdea)
                .leftJoin(qIdea.users, qUsers)
                .fetchOne());
    }

    @Override
    public List<IdeaResponse> findIdeaAll(Pageable pageable) {
        return queryFactory.select(Projections.constructor(IdeaResponse.class,
                        qUsers.nickname.as("writer"),
                        qIdea.title,
                        qIdea.content,
                        qIdea.imageName.concat(ServerIpAddress.s3Address).as("imageUrl"),
                        qIdea.auctionStatus.as("status"),
                        qIdea.minimumStartingPrice,
                        qIdea.bidWinPrice
                ))
                .from(qIdea)
                .leftJoin(qIdea.users, qUsers)
                .orderBy(qIdea.createdAt.desc())
                .offset(pageable.getOffset())
                .limit(pageable.getPageSize())
                .fetch();
    }

    @Override
    public List<IdeaResponse> findCategoryAndTitleAll(Category category, String keyword, Pageable pageable) {
        return queryFactory.select(Projections.constructor(IdeaResponse.class,
                        qUsers.nickname.as("writer"),
                        qIdea.title,
                        qIdea.content,
                        qIdea.imageName.concat(ServerIpAddress.s3Address).as("imageUrl"),
                        qIdea.auctionStatus.as("status"),
                        qIdea.minimumStartingPrice,
                        qIdea.bidWinPrice
                ))
                .where(
                        ideaTitleContains(keyword),
                        ideaCategoryEq(category)
                )
                .from(qIdea)
                .leftJoin(qIdea.users, qUsers)
                .orderBy(qIdea.createdAt.desc())
                .offset(pageable.getOffset())
                .limit(pageable.getPageSize())
                .fetch();
    }

    private BooleanExpression ideaTitleContains(String keyword) {
        return isEmpty(keyword) ? null : qIdea.title.contains(keyword);
    }

    private BooleanExpression ideaCategoryEq(Category category) {
        return isEmpty(category) ? null : qIdea.category.eq(category);
    }

}

    @Transactional(readOnly = true)
    public List<IdeaResponse> findAllIdea(String keyword, Category category, Integer page) {

        if (StringUtils.hasText(keyword) && !Objects.isNull(category)) {
            throw new IdeaFindException(IdeaFindErrorCode.KEYWORD_CATEGORY_SAME);
        }

        List<IdeaResponse> findList;
        Sort sort = Sort.by(Sort.Direction.ASC, "createdAt");
        Pageable pageable = PageRequest.of(page, 10, sort);

        if (!StringUtils.hasText(keyword) && Objects.isNull(category)) {
            findList = ideaRepository.findIdeaAll(pageable);
        } else {
            findList = ideaRepository.findCategoryAndTitleAll(category, keyword, pageable);
        }
        return findList;
    }

2023-08-23T00:34:39.769+09:00  WARN 1 --- [o-8080-exec-409] o.h.engine.jdbc.spi.SqlExceptionHelper   : SQL Error: 0, SQLState: null
2023-08-23T00:34:39.769+09:00 ERROR 1 --- [o-8080-exec-409] o.h.engine.jdbc.spi.SqlExceptionHelper   : HikariPool-1 - Connection is not available, request timed out after 30000ms.
2023-08-23T00:34:39.769+09:00 ERROR 1 --- [o-8080-exec-409] o.a.c.c.C.[.[.[/].[dispatcherServlet]    : Servlet.service() for servlet [dispatcherServlet] in context with path [] threw exception [Request processing failed: org.springframework.transaction.CannotCreateTransactionException: Could not open JPA EntityManager for transaction] with root cause

java.sql.SQLTransientConnectionException: HikariPool-1 - Connection is not available, request timed out after 30000ms.

먼저 세운 가설은 기본 defult 값인 maximumPoolSize 은 10 인데 10개가 넘어가서 에러가 나왔다. 처음에 몰라서 내가 처음에 생각하기에는 연결 누수문제라서 EntityManager 에서 close 를 안하는건가? 이생각을 하였지만 생각해보니 EntityManager 는 Spring 에서 관리하기때문에 문제가 되지 않을것 같았다.

2번째 세운 가설은 페이지 조회인데 해당 페이지가 존재하지 않은데 요청을 보내게 되면 응답이 늦어지면서 연결 풀을 가지고 있으면서 그게 늦어지고 여러명이 요청을 보내니깐 연결 풀이 부족하다. 라는 가설을 세우고 아래의 시도를 통해

근거가 되었다.

 

어떤 시도를 하였나요?

로깅 레벨과 연결 누수의 시간을 설정하였다.

spring:
  datasource:
    hikari:
      leak-detection-threshold: 100000
logging:
  level:
    com.zaxxer.hikari.HikariConfig: DEBUG
    com.zaxxer.hikari: TRACE

위와 같은 설정으로

2023-08-23T01:49:18.310+09:00  INFO 18788 --- [nio-8080-exec-8] com.zaxxer.hikari.pool.ProxyLeakTask     : Previously reported leaked connection org.postgresql.jdbc.PgConnection@30dc893f on thread http-nio-8080-exec-8 was returned to the pool (unleaked)
2023-08-23T01:49:19.707+09:00 DEBUG 18788 --- [l-1 housekeeper] com.zaxxer.hikari.pool.HikariPool        : HikariPool-1 - Pool stats (total=10, active=6, idle=4, waiting=0)
2023-08-23T01:49:19.707+09:00 DEBUG 18788 --- [l-1 housekeeper] com.zaxxer.hikari.pool.HikariPool        : HikariPool-1 - Fill pool skipped, pool has sufficient level or currently being filled (queueDepth=0).
2023-08-23T01:49:32.976+09:00  INFO 18788 --- [nio-8080-exec-3] com.zaxxer.hikari.pool.ProxyLeakTask     : Previously reported leaked connection org.postgresql.jdbc.PgConnection@131d4feb on thread http-nio-8080-exec-3 was returned to the pool (unleaked)
2023-08-23T01:49:32.976+09:00  INFO 18788 --- [nio-8080-exec-2] com.zaxxer.hikari.pool.ProxyLeakTask     : Previously reported leaked connection org.postgresql.jdbc.PgConnection@2c1decb3 on thread http-nio-8080-exec-2 was returned to the pool (unleaked)
2023-08-23T01:49:33.074+09:00  INFO 18788 --- [io-8080-exec-10] com.zaxxer.hikari.pool.ProxyLeakTask     : Previously reported leaked connection org.postgresql.jdbc.PgConnection@4645c60 on thread http-nio-8080-exec-10 was returned to the pool (unleaked)
2023-08-23T01:49:33.273+09:00  INFO 18788 --- [nio-8080-exec-9] com.zaxxer.hikari.pool.ProxyLeakTask     : Previously reported leaked connection org.postgresql.jdbc.PgConnection@5025a22a on thread http-nio-8080-exec-9 was returned to the pool (unleaked)
2023-08-23T01:49:33.277+09:00  INFO 18788 --- [nio-8080-exec-6] com.zaxxer.hikari.pool.ProxyLeakTask     : Previously reported leaked connection org.postgresql.jdbc.PgConnection@57bf298f on thread http-nio-8080-exec-6 was returned to the pool (unleaked)
2023-08-23T01:49:33.281+09:00  INFO 18788 --- [nio-8080-exec-7] com.zaxxer.hikari.pool.ProxyLeakTask     : Previously reported leaked connection org.postgresql.jdbc.PgConnection@47195169 on thread http-nio-8080-exec-7 was returned to the pool (unleaked)
2023-08-23T01:49:49.715+09:00 DEBUG 18788 --- [l-1 housekeeper] com.zaxxer.hikari.pool.HikariPool        : HikariPool-1 - Pool stats (total=10, active=0, idle=10, waiting=0)

hikari 에서 연결된 풀이랑 쓰고 있는 풀 안쓰고 있는 풀 대기중인 풀 을 확인할수 있었다.

 

이를 통해 새롭게 알게된것들

현재 존재하는 페이지 조회하면 되지만 그 외의 페이지를 조회하면 DB 에서의 응답이 느려진다.
이유는.. 진짜 모르겠다..