DEV ℧ Developer Diary

[Java] Hikari CP에 대해 알아보자. (3)

22 Dec 2022

원래는 2편으로 종료될 예정이었으나, Trouble Shooting 과정에서 HikariCP의 로깅 방법에 대해 알아본 것이 있어서 해당 내용을 정리해 보았다.

HikariCP Logging

HikariCP logging

HikariCP의 Config 설정 값, Connection의 열림/닫힘, Connection Pool의 상태를 확인하는 로그를 출력합니다.

설정 방법

logging:
  level:
    com.zaxxer.hikari.HikariConfig: DEBUG
    com.zaxxer.hikari: TRACE

출력

위의 설정을 추가한다면, 위에서 볼 수 있듯이 Connection이 추가되거나 닫히는것을 확인 할 수 있습니다. 만약 Added가 발생한 뒤 Closing이 발생하지 않는다면, 해당 커넥션은 실종된거나 다름이 없다. 또한 Pool stats 로그에서 확인이 가능합니다.

2022-12-22 01:18:07.315 DEBUG 22340 --- [onnection adder] com.zaxxer.hikari.pool.HikariPool        : HikariPool-1 - Added connection conn5: url=jdbc:h2:mem:testdb user=SA
2022-12-22 01:18:08.080 DEBUG 22340 --- [nnection closer] com.zaxxer.hikari.pool.PoolBase          : HikariPool-1 - Closing connection conn2: url=jdbc:h2:mem:testdb user=SA: (connection has passed maxLifetime)
2022-12-22 01:18:08.156 DEBUG 22340 --- [l-1 housekeeper] com.zaxxer.hikari.pool.HikariPool        : HikariPool-1 - Pool stats (total=5, active=0, idle=5, waiting=0

Pool stats

  • total : 전체
  • active : 사용중
  • idle : 유후
  • waiting : 대기중인 요청

또한 Connection이 Closing 되는 상태는 다섯가지정도 있습니다.

  1. 연결 확인에 실패할 경우 : 연결이 만료되고 교체됩니다. Failed to validate connection… 로 시작하는 로그가 출력됩니다.
  2. 오랫동안 연결이 유휴상태 일 경우 : idleTimeout 설정에 의해 유휴상태의 Connection이 만료되고 교체됩니다. Closing … (connection has passed idleTimeout) 과 같은 로그가 출력됩니다.
  3. 연결이 maxLifeTime 설정 시간까지 도달한 경우 : maxLifetime 설정에 의해 Connection이 만료되어 종료된 경우 입니다. Closing … (connection has passed maxLifetime) 과같은 로그가 출력됩니다. 만약 시간이 만기됨에도 Connection이 사용중일 경우 사용 후 (connection is evicted or dead) 문구가 출력됩니다.
  4. 사용자가 수동으로 연결을 제거한 경우 : Connection이 만료되고 교체되며 closing … (connection evicted by user) 의 로그가 출력됩니다.
  5. JDBC 호출에서 복구가 불가능한 SQLException인 경우 : JDBC에서 Connection을 복구 할 수 없는 SQLException가 발생했을 경우를 의미합니다. (connection is broken) 로 끝나는 로그가 출력됩니다.

leak-detection-threshold

Connection의 leak 의심 현상을 검출해서 console log의 WARN 등급으로 출력 (무조건 누수가 아니다)

위에 설명했던 hikari의 logging 설정을 하지 않아도 leak이 의심될 경우 로그로 출력된다.

설정 방법

spring:
  datasource:
    hikari:
      leak-detection-threshold: 2000

기본값은 0(무제한 검출 X) 최소값 2초 (2000ms) 최대값은 max-lifetime(기본값 30분) 설정값 보다는 크면 안된다.

출력

Connection이 leak(누수)가 의심 될경우 아래와 같이 ERROR 등급이 아닌 WARN 등급으로 로그에 출력

Exception 로그에 아래와 같이 누수 예상 되는 경로가 포함

또한 누수가 된 Connection이 반환되었는지는 log의 Connection 인스턴스 주소(conn0)를 통해 판단

2022-12-22 01:52:53.888  WARN 18620 --- [l-1 housekeeper] com.zaxxer.hikari.pool.ProxyLeakTask     : Connection leak detection triggered for conn0: url=jdbc:h2:mem:testdb user=SA on thread http-nio-8080-exec-7, stack trace follows

java.lang.Exception: Apparent connection leak detected
	at com.zaxxer.hikari.HikariDataSource.getConnection(HikariDataSource.java:128) ~[HikariCP-4.0.3.jar:na]
	at org.hibernate.engine.jdbc.connections.internal.DatasourceConnectionProviderImpl.getConnection(DatasourceConnectionProviderImpl.java:122) ~[hibernate-core-5.6.7.Final.jar:5.6.7.Final]
	...
	at com.tax.refund.domain.user.service.UserService$$EnhancerBySpringCGLIB$$317f9a0.login(<generated>) ~[main/:na]
	at com.tax.refund.domain.user.api.UserController.login(UserController.java:41) ~[main/:na]
    ...

누수로 의심되었던 Connection이 반환 될 경우 아래와 같이 반환 되었다는 log 출력한다.

2022-12-22 01:56:21.205  INFO 17092 --- [nio-8080-exec-3] com.zaxxer.hikari.pool.ProxyLeakTask     : Previously reported leaked connection conn0: url=jdbc:h2:mem:testdb user=SA on thread http-nio-8080-exec-3 was returned to the pool (unleaked)

반면에 실제 누수가 된다면 서버로그에서 SQLException 로그와 함께 아래의 로그도 같이 확인하게 될것이다.

[XXXX-XX-XX XX:XX:XX.XXX] [WARN ] [/GET] - c.zaxxer.hikari.pool.ProxyConnection     checkException       : HikariPool-1 - Connection conn0: url=jdbc:h2:mem:testdb user=SA marked as broken because of SQLSTATE(08007), ErrorCode(0)

Related posts