서비스 운영중 HikariCP 에서 커넥션 누수가 발견되었다. 어느정도 api를 호출하다보면 더이상 db로 쿼리 요청이 가지 않는 상황이 발생했다.
Could not open JPA EntityManager for transaction; nested exception is org.hibernate.exception.JDBCConnectionException: Unable to acquire JDBC Connection
j.s.SQLSyntaxErrorException: (conn=1415204) Connection.setNetworkTimeout cannot be called on a closed connection
at o.m.j.e.ExceptionFactory.createException(ExceptionFactory.java:270)
at o.m.j.e.ExceptionFactory.create(ExceptionFactory.java:324)
at o.m.jdbc.Connection.setNetworkTimeout(Connection.java:725)
at c.z.h.pool.PoolBase.setNetworkTimeout(PoolBase.java:566)
at c.z.h.pool.PoolBase.isConnectionAlive(PoolBase.java:173)
at c.z.h.p.HikariPool.getConnection(HikariPool.java:186)
... 168 common frames omitted
Wrapped by: j.s.SQLTransientConnectionException: HikariPool-1 - Connection is not available, request timed out after 5004ms.
at c.z.h.p.HikariPool.createTimeoutException(HikariPool.java:696)
at c.z.h.p.HikariPool.getConnection(HikariPool.java:197)
at c.z.h.p.HikariPool.getConnection(HikariPool.java:162)
at c.z.h.HikariDataSource.getConnection(HikariDataSource.java:128)
at o.h.e.j.c.i.DatasourceConnectionProviderImpl.getConnection(DatasourceConnectionProviderImpl.java:122)
at o.h.i.NonContextualJdbcConnectionAccess.obtainConnection(NonContextualJdbcConnectionAccess.java:38)
at o.h.r.j.i.LogicalConnectionManagedImpl.acquireConnectionIfNeeded(LogicalConnectionManagedImpl.java:108)
... 163 common frames omitted
Wrapped by: o.h.e.JDBCConnectionException: Unable to acquire JDBC Connection
at o.h.e.i.SQLExceptionTypeDelegate.convert(SQLExceptionTypeDelegate.java:48)
at o.h.e.i.StandardSQLExceptionConverter.convert(StandardSQLExceptionConverter.java:37)
at o.h.e.j.s.SqlExceptionHelper.convert(SqlExceptionHelper.java:113)
at o.h.e.j.s.SqlExceptionHelper.convert(SqlExceptionHelper.java:99)
at o.h.r.j.i.LogicalConnectionManagedImpl.acquireConnectionIfNeeded(LogicalConnectionManagedImpl.java:111)
at o.h.r.j.i.LogicalConnectionManagedImpl.getPhysicalConnection(LogicalConnectionManagedImpl.java:138)
at o.h.i.SessionImpl.connection(SessionImpl.java:516)
at o.s.o.j.v.HibernateJpaDialect.beginTransaction(HibernateJpaDialect.java:152)
at o.s.o.j.JpaTransactionManager.doBegin(JpaTransactionManager.j...장애 발생 전 상황 (설정 변경)
장애가 발생하기 전에 성능 최적화를 위해 HikariCP의 설정을 다음과 같이 수정했다.
maximum-pool-size: 기존 100 → 30으로 축소minimum-idle: 기존 값(2) 제거 → default 적용auto-commit: 기존false→ 제거 (default인true로 변경)
이 설정들은 구글링을 통해 확인한 값으로, local 테스트 후 운영환경에 배포했다.
장애 발생 및 원인 파악 과정
배포 직후엔 문제가 없었으나, 일정 시간 후 장애가 발생하기 시작했다.
원인을 찾기 위해 아래와 같은 과정을 거쳤다.
1. auto-commit 설정에 대한 혼란
처음엔 설정을 변경한 직후 장애가 발생했기에, 가장 의심스러웠던 건 auto-commit 옵션이었다.
- auto-commit이 true일 경우 각 쿼리가 독립된 트랜잭션으로 처리되어 문제가 될 것으로 예상했다.
- 특히 스프링의
@Transactional사용 시 auto-commit이 자동으로 false로 강제된다는 것을 뒤늦게 알게 되었다. (참조 문서)
이상하게도 auto-commit을 false로 재설정하자 문제가 해결된 것으로 보였다.
이후 HikariCP의 trace 로그를 활성화해 설정 적용 여부를 확인해보니, 실제로는 auto-commit 설정이 적용되지 않은 상태였다. Docker 이미지 배포가 최신 이미지로 이루어지지 않아 이전 이미지가 배포된 것이었다.
정확한 이미지를 재배포한 후 auto-commit이 false로 정상 적용되었으나, 다시 동일한 장애가 발생했다. 즉, auto-commit은 실제 원인이 아니었다.
2. maximum-pool-size 값의 적절성
HikariCP의 maximum-pool-size 값이 적절하지 않다는 의심이 들었다. 관련 자료(우아한형제들 기술블로그)에서 제공한 공식에 따라 계산했다.
- 개발 환경 (
cpu:4, mem:4G)의 Tn을 4로 보고 Cm을 보수적으로 2로 설정하여,maximum-pool-size를 8 이하로 설정해 테스트했다. - 놀랍게도
maximum-pool-size: 1로 설정해도 정상 작동했다. 결국 maximum-pool-size도 원인이 아니었다.
장애의 재현 불가 및 원인 불명확
다음 날 다양한 환경에서 여러 조건(HikariCP 타임아웃, RDS 설정 등)을 변경하며 추가 테스트를 진행했지만, 더 이상 장애를 재현할 수 없었다.
심지어 장애 당시의 Docker 이미지로 다시 배포해도 장애가 발생하지 않았다. 이전에는 반드시 장애가 발생했던 환경에서 동일한 조건임에도 불구하고, 장애는 재현되지 않았다.
Spring batch job까지 모두 정상적으로 작동했다.
결국 장애가 발생했던 당시 Docker Swarm 클러스터 내부 또는 네트워크와 같은 외부 환경적인 요인이 있지 않았을까 추정하며 회고를 마무리했다.
비록 명확한 결론을 내리지 못하고 삽질만 반복한 느낌이지만, 이 과정을 통해 HikariCP의 동작 방식에 대해 깊게 이해할 수 있었다는 데 의미를 두었다.
추가로 배포 시 컨테이너 교체 시점에 502 및 CORS 에러로 인해 잠시 다운타임이 발생하는 별도의 문제가 있다. 이에 대한 해결 과정은 다음 포스팅에서 정리할 예정이다.
