요즘 회사에서 API Server 성능 최적화 작업을 진행하느라 정신이 없는 하루하루를 보내고 있다.
그래도 정신 차리고 하루 날 잡아서 업무 하며 알게 된 내용들을 정리를 해보고자 한다.
성능 최적화 작업을 시작하게 되고 제일 먼저 진행한 업무는 WAS와 DB 간 통신 관련의 개선이었는데
우리는 API Server로 Spring Boot + JPA 를 사용하고 있고
DB는 저장되는 데이터 특성에 맞춰서
1. Postgresql
2. Elastic Search
3. Cortex
4. Redis
이렇게 총 네 가지를 사용하고 있다.
이 중에 오늘은 Postgresql 쪽을 정리해보고자 한다.
JDBC 라는 단어를 들어보신 적이 있다.
Java를 기반으로 웹서비스를 개발하시는 분이라면 무조건 들어봤을 단어인데,
JDBC는 Java Database Connetivity의 줄임말로 자바에서 데이터베이스에 접속할 수 있도록 하는 자바 API 다.
보통 데이터베이스에서 자료를 쿼리 하거나 업데이트하는 방법을 제공한다.
이 JDBC를 각 데이터베이스에 맞춰 드라이버를 설치 후 그냥 사용해도 무방하지만,
실제 운영되는 서비스나 동접이 상당한 서비스들은 JDBC (HikariCP) 들을
그 서비스 특성에 맞춰 적절하게 수정하고 튜닝해주어야 한다.
(안그러면 서버가 펑 터진다. 어떻게 알게되었냐고? 나도 알고 싶지 않았다...)
설정 적용 법을 알아보기 전에 현재 나는 어떤 방식으로 사용하는지 확인해 보자.
spring:
datasource:
url: jdbc:log4jdbc:postgresql://postgres:5432/postgresdb
hikari:
maximum-pool-size: 20
idle-time-out: 60000되게 일부 설정값만 사용하고 있었고, 이 값들에 대한 적절한 근거가 없었는데,
JDBC (HikariCP)를 분석해 보면서 적절한 튜닝 값들을 알아보고자 한다.
네이버 기술 블로그를 읽으면서 와! 싶었던 이미지다.
WAS와 DBMS 통신에는 Timeout Layer가 존재하는데, 총 3 영역으로 나뉘게 된다.
1. Transaction Timeout (default = -1)
Application 레벨의 Timeout 값으로 전체 Statement를 수행하는 데
시간을 허용할 수 있는 최대 시간 값을 설정한다.
서비스마다 다르겠지만 보통 Transaction이라 하면 일련적 기능의 단위를 뜻하곤 하는데
StatementTimeout x N(Statement 수행 수) + α(가비지 컬렉션 및 기타)
라고 생각하면 될 것 같다.
설정은
@Transactional(timeout = 10)
---------------------------------
spring:
transaction:
default-timeout: 10첫 번째 방식처럼 @Transactional Annotation을 통해 필드 값으로 설정해 줄 수 있고 (지역변수 단위 s)
application 설정 파일에 설정해줄 수도 있다. (전역 변수 단위 s)
물론 둘 다 적용이 되어있다면 지역변수가 전역 변수를 오버라이딩 한다!
2. Statement Timeout (default = 0)
Query Timeout 이라고도 부르며 하나의 Query가 실행되는 시간을 허용할 수 있는 최대 시간 값을 설정한다.
기본적으로 JDBC Query에는 제한 시간이 없기 때문에 Query가 Thread를 무제한으로 Block 하여 Hang이 걸릴 위험이 있다고 한다
요즘 개발 환경에서는 개발자가 직접 Statement Timeout 값을 Java 코드로 직접 수정하는 일은 드물다고는 한다.
요즘엔 Query 관련된 Framework 레벨에서 해결해주기도 한다.
저는 Spring Data JPA 를 사용 중이기에 적용 법을 확인해보았다.
@QueryHints(value = @QueryHint(name = "javax.persistence.query.timeout", value = "10"))
------------------------------------------------------------------------------------------
spring:
jpa:
properties:
javax:
persistence:
query:
timeout: 10Transaction Timeout과 마찬가지로 Annotation을 이용하는 방식과 application 설정 파일 방식 두 가지가 있고
오버 라이딩 방식과 단위도 모두 동일하다!
3. Socket Timeout (default = 30m)
DBMS가 비정상으로 종료되었거나 네트워크 장애가 발생했을 때 필요한 값이다.
JDBC는 Socket 방식으로 데이터베이스와 통신을 하는데, 이 구조상 네트워크 장애를 감지할 수가 없는데
즉, Application 에서는 DBMS와의 연결 끊김을 알 수 없기 때문에 무한정 기다리게 되어 성능 저하를 야기시키게 된다.
이 값은 JDBC 드라이버마다 적용 방식이 다르다.
url="jdbc:postgresql://127.0.0.1:5432/onbbp? connectionTimeout=2&socketTimeout=2"JDBC 드라이버를 설정할 때 쿼리스트링 방식으로 값을 추가해주면 된다.
참고로 Socket Timeout 값은 Statement Timeout 값보다 크게 잡아야 하는데 이는 Socket Timeout 값이 Statement Timeout 값보다 작으면, SocketTimeout 값이 먼저 작동하기 때문에 Statement Timeout 값은 의미가 없게 되어 동작하지 않기 때문이다.
제가 사용 중인 postgresdb 의 설정값들은 다음과 같은 쿼리로 확인할 수 있다.
select name, setting, source, sourcefile, sourceline
from pg_settings
where name like '%time%';
다음과 같이 Statement Timeout 값은 비교대상이 있는데,
Socket Timeout 값은 어떤 값과 비교해야 하는지 애매해서 조금 더 분석이 필요할 것 같다.
다음으로 JDBC의 Connection Pooling 기능을 담당하는 HikariCP에 설정값에 대해서 알아보자.
HikariCP는 각종 설정 값을 제공하는데, application 설정 파일을 통해 적용할 수 있다.
| 설정명 | 기본값 | 설명 |
| connection-timeout | 30000ms | - connection pool 에서 connection을 얻을 때 최대 대기 시간 - 대기 시간 내에 connection을 얻지 못하면 Exception이 발생 |
| maximum-pool-size | 10 | - 유휴 상태와 사용 중인 connection을 포함해서 허용하는 최대 connection 수 - pool 이 해당 크기에 도달했는데 유휴 connection이 없으면 connection-timeout이 날 때까지 Blocking |
| minimum-idle | 10 | - pool에서 유지해줄 유휴 상태의 connection의 최소 개수 - hikariCP github에 최적의 성능과 응답성을 요구한다면 설정을 하지 않을 것을 권고 |
| idle-timeout | 600000ms | - pool에서 유휴 상태로 유지시킬 최대 시간의 최대 시간을 설정 - 이 값은 minimum-idle 값이 maximum-pool-size 값보다 작은 경우에만 동작 |
| max-lifetime | 1800000ms | - connection의 최대 유지 시간 - max-lifetime 설정 값으로 0으로 설정하면 무한 lifetime이 적용되고, idle-timeout 값이 설정되어 있다면 max-lifetime이 미적용 |
| auto-commit | true | - connection pool의 auto commit 여부를 설정 |
대부분의 값은 각자 개발하는 애플리케이션 특성과 비즈니스 로직에 맞춰서 설정해줘야 하지만
auto-commit 에 대해서는 성능 개선을 진행한 문서를 보면 대부분 동일한 방법으로 진행을 하길래 이를 정리해보고자 한다.
결론부터 말하자면 hikariCP auto-commit 값은 false로 설정하자
부가설명을 하자면
hikariCP auto-commit 은 false로 하고, Hibernate provider_disables_autocommit 은 true로 해야 한다.
위와 같이 설정하면 Hibernate 내에 불필요한 로직이 생략되기 때문에 성능을 향상시키기 때문인데
좀 더 자세히 알아보자.
일단, jdbc auto-commit 값은 쿼리문이 수행되었을 때 변경사항을 데이터베이스에 즉시 반영할지의 여부를 결정하는 값이다.
하지만 다들 아시다시피 서비스 특성에 맞춰 여러 쿼리가 하나의 트랜잭션으로 묶이는 경우가 있다.
그렇다면 해당 서비스의 일련의 과정이 성공적으로 마무리되어야만 commit 처리를 해줘야 하는데,
그렇기 때문에 매 쿼리마다 auto-commit 에 따라 처리를 해버리면 Transaction 의 일관성 및 적합성의 유지가 힘들다.
그래서 Hibernate 의 흐름은 다음과 같은데,
1. 트랜잭션 전으로 setAutoCommit(false)
2. n개의 쿼리 수행
.
.
3. 트랜잭션 후로 setAutoCommit(true)
4. Commit 또는 Rollback 을 수행
즉, 트랜잭션 전/후로 setAutoCommit 이라는 행위를 하게 되는데 내부 소스코드를 확인해보면
실제 데이터베이스에 쿼리를 날리기 때문에 성능에 영향을 끼치게 된다.
public void setAutoCommit(boolean autoCommit) throws SQLException {
if (autoCommit == getAutoCommit()) return;
try (Statement stmt = createStatement()) {
stateFlag |= ConnectionState.STATE_AUTOCOMMIT;
stmt.executeUpdate("set autocommit=" + ((autoCommit) ? "1" : "0"));
}
}초기에 auto commit 을 false로 변경할 때, 기존으로 설정된 값과 동일하면 바로 리턴되는 로직이기 때문에
하위에 쿼리를 날리는 로직을 생략할 수 있다!
두 번째로 볼 값은 max-lifetime 값으로 connection의 유지기간의 값이다.
제가 프로젝트에 해당 값을 직접 설정해보고 테스트를 해본 결과를 공유해 드리고자 한다.
저는 postgresdb 의 설정값은 따로 변경하지 않고 기본값을 사용 중인 상태이다.
설정값을 변경하면서 보니 postgresdb 에서 커넥션을 유지하는 시간은 10분! 인걸 알게되었다.
(맞나?)
밑에 로그를 확인해보자.
1. max-lifetime 값을 10분보다 큰 값으로 설정했을 때
2022-04-27 16:54:15.107 WARN [api-server,,,] 7580 --- [TaskScheduler-1] com.zaxxer.hikari.pool.PoolBase : HikariPool-1 - Failed to validate connection org.postgresql.jdbc.PgConnection@2232223a (This connection has been closed.). Possibly consider using a shorter maxLifetime value.
2022-04-27 16:54:15.108 DEBUG [api-server,,,] 7580 --- [nnection closer] com.zaxxer.hikari.pool.PoolBase : HikariPool-1 - Closing connection org.postgresql.jdbc.PgConnection@2232223a: (connection is dead)2. max-lifetime 값을 10분보다 작은 값으로 설정 했을 때
2022-04-27 16:42:20.756 DEBUG [api-server,,,] 17076 --- [nnection closer] com.zaxxer.hikari.pool.PoolBase : HikariPool-1 - Closing connection org.postgresql.jdbc.PgConnection@44b29205: (connection has passed maxLifetime)
1번의 경우에는
'(This connection has been closed.). Possibly consider using a shorter maxLifetime value.'
라는 로그가 눈에 띄는데,
대충 읽어봐도 이미 connection이 닫힌 상태라고 maxLifetime의 값을 더 작게 설정하는 것을 고려해보라고 하는거 같다.
즉, 데이터베이스 측에서는 이미 connection을 종료시켰는데,
WAS에서는 계속 connection을 들고 있었던 거다.
그에 비해서 2번의 경우는
'connection has passed maxLifetime'
라고 찍히며 정상적으로 connection이 종료되는 것을 볼 수 있다.
또 내가 파악한 부분은
2022-04-27 16:42:20.756 DEBUG [api-server,,,] 17076 --- [nnection closer] com.zaxxer.hikari.pool.PoolBase : HikariPool-1 - Closing connection org.postgresql.jdbc.PgConnection@44b29205: (connection has passed maxLifetime)
2022-04-27 16:42:20.784 DEBUG [api-server,,,] 17076 --- [onnection adder] com.zaxxer.hikari.pool.HikariPool : HikariPool-1 - Added connection org.postgresql.jdbc.PgConnection@13d5847a2번의 경우처럼 성공적으로 connection이 종료되면 idle 정책에 맞춰서 바로 connection을 생성한다.
하나의 connection이 정상 종료되면 바로 생성을 하는거다.
하지만 1번의 경우에서는
2022-04-27 16:54:15.107 WARN [api-server,,,] 7580 --- [TaskScheduler-1] com.zaxxer.hikari.pool.PoolBase : HikariPool-1 - Failed to validate connection org.postgresql.jdbc.PgConnection@2232223a (This connection has been closed.). Possibly consider using a shorter maxLifetime value.
2022-04-27 16:54:15.108 DEBUG [api-server,,,] 7580 --- [nnection closer] com.zaxxer.hikari.pool.PoolBase : HikariPool-1 - Closing connection org.postgresql.jdbc.PgConnection@2232223a: (connection is dead)
2022-04-27 16:54:15.108 WARN [api-server,,,] 7580 --- [TaskScheduler-1] com.zaxxer.hikari.pool.PoolBase : HikariPool-1 - Failed to validate connection org.postgresql.jdbc.PgConnection@402819e6 (This connection has been closed.). Possibly consider using a shorter maxLifetime value.
2022-04-27 16:54:15.109 DEBUG [api-server,,,] 7580 --- [nnection closer] com.zaxxer.hikari.pool.PoolBase : HikariPool-1 - Closing connection org.postgresql.jdbc.PgConnection@402819e6: (connection is dead)
2022-04-27 16:54:15.110 WARN [api-server,,,] 7580 --- [TaskScheduler-1] com.zaxxer.hikari.pool.PoolBase : HikariPool-1 - Failed to validate connection org.postgresql.jdbc.PgConnection@4eefff93 (This connection has been closed.). Possibly consider using a shorter maxLifetime value.
2022-04-27 16:54:15.110 DEBUG [api-server,,,] 7580 --- [nnection closer] com.zaxxer.hikari.pool.PoolBase : HikariPool-1 - Closing connection org.postgresql.jdbc.PgConnection@4eefff93: (connection is dead)
2022-04-27 16:54:15.111 WARN [api-server,,,] 7580 --- [TaskScheduler-1] com.zaxxer.hikari.pool.PoolBase : HikariPool-1 - Failed to validate connection org.postgresql.jdbc.PgConnection@4ad07296 (This connection has been closed.). Possibly consider using a shorter maxLifetime value.
2022-04-27 16:54:15.111 DEBUG [api-server,,,] 7580 --- [nnection closer] com.zaxxer.hikari.pool.PoolBase : HikariPool-1 - Closing connection org.postgresql.jdbc.PgConnection@4ad07296: (connection is dead)
2022-04-27 16:54:15.112 WARN [api-server,,,] 7580 --- [TaskScheduler-1] com.zaxxer.hikari.pool.PoolBase : HikariPool-1 - Failed to validate connection org.postgresql.jdbc.PgConnection@fd2f5a8 (This connection has been closed.). Possibly consider using a shorter maxLifetime value.
2022-04-27 16:54:15.112 DEBUG [api-server,,,] 7580 --- [nnection closer] com.zaxxer.hikari.pool.PoolBase : HikariPool-1 - Closing connection org.postgresql.jdbc.PgConnection@fd2f5a8: (connection is dead)
2022-04-27 16:54:15.112 WARN [api-server,,,] 7580 --- [TaskScheduler-1] com.zaxxer.hikari.pool.PoolBase : HikariPool-1 - Failed to validate connection org.postgresql.jdbc.PgConnection@fb53a9d (This connection has been closed.). Possibly consider using a shorter maxLifetime value.
2022-04-27 16:54:15.112 DEBUG [api-server,,,] 7580 --- [nnection closer] com.zaxxer.hikari.pool.PoolBase : HikariPool-1 - Closing connection org.postgresql.jdbc.PgConnection@fb53a9d: (connection is dead)
2022-04-27 16:54:15.113 WARN [api-server,,,] 7580 --- [TaskScheduler-1] com.zaxxer.hikari.pool.PoolBase : HikariPool-1 - Failed to validate connection org.postgresql.jdbc.PgConnection@3e975f9f (This connection has been closed.). Possibly consider using a shorter maxLifetime value.
2022-04-27 16:54:15.113 DEBUG [api-server,,,] 7580 --- [nnection closer] com.zaxxer.hikari.pool.PoolBase : HikariPool-1 - Closing connection org.postgresql.jdbc.PgConnection@3e975f9f: (connection is dead)
2022-04-27 16:54:15.113 WARN [api-server,,,] 7580 --- [TaskScheduler-1] com.zaxxer.hikari.pool.PoolBase : HikariPool-1 - Failed to validate connection org.postgresql.jdbc.PgConnection@771ace19 (This connection has been closed.). Possibly consider using a shorter maxLifetime value.
2022-04-27 16:54:15.113 DEBUG [api-server,,,] 7580 --- [nnection closer] com.zaxxer.hikari.pool.PoolBase : HikariPool-1 - Closing connection org.postgresql.jdbc.PgConnection@771ace19: (connection is dead)
2022-04-27 16:54:15.114 WARN [api-server,,,] 7580 --- [TaskScheduler-1] com.zaxxer.hikari.pool.PoolBase : HikariPool-1 - Failed to validate connection org.postgresql.jdbc.PgConnection@6ffd0ae7 (This connection has been closed.). Possibly consider using a shorter maxLifetime value.
2022-04-27 16:54:15.114 DEBUG [api-server,,,] 7580 --- [nnection closer] com.zaxxer.hikari.pool.PoolBase : HikariPool-1 - Closing connection org.postgresql.jdbc.PgConnection@6ffd0ae7: (connection is dead)
2022-04-27 16:54:15.115 WARN [api-server,,,] 7580 --- [TaskScheduler-1] com.zaxxer.hikari.pool.PoolBase : HikariPool-1 - Failed to validate connection org.postgresql.jdbc.PgConnection@49baa457 (This connection has been closed.). Possibly consider using a shorter maxLifetime value.
2022-04-27 16:54:15.115 DEBUG [api-server,,,] 7580 --- [nnection closer] com.zaxxer.hikari.pool.PoolBase : HikariPool-1 - Closing connection org.postgresql.jdbc.PgConnection@49baa457: (connection is dead)
2022-04-27 16:54:15.115 WARN [api-server,,,] 7580 --- [TaskScheduler-1] com.zaxxer.hikari.pool.PoolBase : HikariPool-1 - Failed to validate connection org.postgresql.jdbc.PgConnection@4dd57158 (This connection has been closed.). Possibly consider using a shorter maxLifetime value.
2022-04-27 16:54:15.115 DEBUG [api-server,,,] 7580 --- [nnection closer] com.zaxxer.hikari.pool.PoolBase : HikariPool-1 - Closing connection org.postgresql.jdbc.PgConnection@4dd57158: (connection is dead)
2022-04-27 16:54:15.116 WARN [api-server,,,] 7580 --- [TaskScheduler-1] com.zaxxer.hikari.pool.PoolBase : HikariPool-1 - Failed to validate connection org.postgresql.jdbc.PgConnection@6c1e04fd (This connection has been closed.). Possibly consider using a shorter maxLifetime value.
2022-04-27 16:54:15.116 DEBUG [api-server,,,] 7580 --- [nnection closer] com.zaxxer.hikari.pool.PoolBase : HikariPool-1 - Closing connection org.postgresql.jdbc.PgConnection@6c1e04fd: (connection is dead)
2022-04-27 16:54:15.117 WARN [api-server,,,] 7580 --- [TaskScheduler-1] com.zaxxer.hikari.pool.PoolBase : HikariPool-1 - Failed to validate connection org.postgresql.jdbc.PgConnection@6bb391ab (This connection has been closed.). Possibly consider using a shorter maxLifetime value.
2022-04-27 16:54:15.117 DEBUG [api-server,,,] 7580 --- [nnection closer] com.zaxxer.hikari.pool.PoolBase : HikariPool-1 - Closing connection org.postgresql.jdbc.PgConnection@6bb391ab: (connection is dead)
2022-04-27 16:54:15.117 WARN [api-server,,,] 7580 --- [TaskScheduler-1] com.zaxxer.hikari.pool.PoolBase : HikariPool-1 - Failed to validate connection org.postgresql.jdbc.PgConnection@77371896 (This connection has been closed.). Possibly consider using a shorter maxLifetime value.
2022-04-27 16:54:15.117 DEBUG [api-server,,,] 7580 --- [nnection closer] com.zaxxer.hikari.pool.PoolBase : HikariPool-1 - Closing connection org.postgresql.jdbc.PgConnection@77371896: (connection is dead)
2022-04-27 16:54:15.118 WARN [api-server,,,] 7580 --- [TaskScheduler-1] com.zaxxer.hikari.pool.PoolBase : HikariPool-1 - Failed to validate connection org.postgresql.jdbc.PgConnection@dab2fa9 (This connection has been closed.). Possibly consider using a shorter maxLifetime value.
2022-04-27 16:54:15.118 DEBUG [api-server,,,] 7580 --- [nnection closer] com.zaxxer.hikari.pool.PoolBase : HikariPool-1 - Closing connection org.postgresql.jdbc.PgConnection@dab2fa9: (connection is dead)
2022-04-27 16:54:15.118 WARN [api-server,,,] 7580 --- [TaskScheduler-1] com.zaxxer.hikari.pool.PoolBase : HikariPool-1 - Failed to validate connection org.postgresql.jdbc.PgConnection@7a62c97e (This connection has been closed.). Possibly consider using a shorter maxLifetime value.
2022-04-27 16:54:15.119 DEBUG [api-server,,,] 7580 --- [nnection closer] com.zaxxer.hikari.pool.PoolBase : HikariPool-1 - Closing connection org.postgresql.jdbc.PgConnection@7a62c97e: (connection is dead)
2022-04-27 16:54:15.119 WARN [api-server,,,] 7580 --- [TaskScheduler-1] com.zaxxer.hikari.pool.PoolBase : HikariPool-1 - Failed to validate connection org.postgresql.jdbc.PgConnection@355e9d0c (This connection has been closed.). Possibly consider using a shorter maxLifetime value.
2022-04-27 16:54:15.119 DEBUG [api-server,,,] 7580 --- [nnection closer] com.zaxxer.hikari.pool.PoolBase : HikariPool-1 - Closing connection org.postgresql.jdbc.PgConnection@355e9d0c: (connection is dead)
2022-04-27 16:54:15.120 WARN [api-server,,,] 7580 --- [TaskScheduler-1] com.zaxxer.hikari.pool.PoolBase : HikariPool-1 - Failed to validate connection org.postgresql.jdbc.PgConnection@53f2710e (This connection has been closed.). Possibly consider using a shorter maxLifetime value.
2022-04-27 16:54:15.120 DEBUG [api-server,,,] 7580 --- [nnection closer] com.zaxxer.hikari.pool.PoolBase : HikariPool-1 - Closing connection org.postgresql.jdbc.PgConnection@53f2710e: (connection is dead)
2022-04-27 16:54:15.120 WARN [api-server,,,] 7580 --- [TaskScheduler-1] com.zaxxer.hikari.pool.PoolBase : HikariPool-1 - Failed to validate connection org.postgresql.jdbc.PgConnection@7f0dabe (This connection has been closed.). Possibly consider using a shorter maxLifetime value.
2022-04-27 16:54:15.120 DEBUG [api-server,,,] 7580 --- [nnection closer] com.zaxxer.hikari.pool.PoolBase : HikariPool-1 - Closing connection org.postgresql.jdbc.PgConnection@7f0dabe: (connection is dead)
2022-04-27 16:54:15.122 WARN [api-server,,,] 7580 --- [TaskScheduler-1] com.zaxxer.hikari.pool.PoolBase : HikariPool-1 - Failed to validate connection org.postgresql.jdbc.PgConnection@6bb5ca07 (This connection has been closed.). Possibly consider using a shorter maxLifetime value.
2022-04-27 16:54:15.122 DEBUG [api-server,,,] 7580 --- [nnection closer] com.zaxxer.hikari.pool.PoolBase : HikariPool-1 - Closing connection org.postgresql.jdbc.PgConnection@6bb5ca07: (connection is dead)
2022-04-27 16:54:15.134 DEBUG [api-server,,,] 7580 --- [onnection adder] com.zaxxer.hikari.pool.HikariPool : HikariPool-1 - Added connection org.postgresql.jdbc.PgConnection@1e739061
2022-04-27 16:54:15.148 DEBUG [api-server,,,] 7580 --- [onnection adder] com.zaxxer.hikari.pool.HikariPool : HikariPool-1 - Added connection org.postgresql.jdbc.PgConnection@10b47ddf
2022-04-27 16:54:15.149 DEBUG [api-server,,,] 7580 --- [onnection adder] com.zaxxer.hikari.pool.HikariPool : HikariPool-1 - After adding stats (total=2, active=0, idle=2, waiting=0)
2022-04-27 16:54:15.173 DEBUG [api-server,,,] 7580 --- [onnection adder] com.zaxxer.hikari.pool.HikariPool : HikariPool-1 - Added connection org.postgresql.jdbc.PgConnection@148bfb11
2022-04-27 16:54:15.173 DEBUG [api-server,,,] 7580 --- [onnection adder] com.zaxxer.hikari.pool.HikariPool : HikariPool-1 - After adding stats (total=3, active=0, idle=3, waiting=0)
2022-04-27 16:54:15.202 INFO [api-server,,,] 7580 --- [xecutorLoop-1-3] i.l.core.protocol.ConnectionWatchdog : Reconnecting, last destination was /146.56.145.199:6379
2022-04-27 16:54:15.211 INFO [api-server,,,] 7580 --- [ioEventLoop-8-3] i.l.core.protocol.ReconnectionHandler : Reconnected to 146.56.145.199:6379
2022-04-27 16:54:15.228 DEBUG [api-server,,,] 7580 --- [onnection adder] com.zaxxer.hikari.pool.HikariPool : HikariPool-1 - Added connection org.postgresql.jdbc.PgConnection@518977e4
2022-04-27 16:54:15.228 DEBUG [api-server,,,] 7580 --- [onnection adder] com.zaxxer.hikari.pool.HikariPool : HikariPool-1 - After adding stats (total=4, active=0, idle=4, waiting=0)
2022-04-27 16:54:15.266 DEBUG [api-server,,,] 7580 --- [onnection adder] com.zaxxer.hikari.pool.HikariPool : HikariPool-1 - Added connection org.postgresql.jdbc.PgConnection@537b152c
2022-04-27 16:54:15.266 DEBUG [api-server,,,] 7580 --- [onnection adder] com.zaxxer.hikari.pool.HikariPool : HikariPool-1 - After adding stats (total=5, active=0, idle=5, waiting=0)
2022-04-27 16:54:15.495 INFO [api-server,,,] 7580 --- [TaskScheduler-1] .c.a.s.k.s.CassandraDataCacheServiceImpl : Read from Elastic. 1mCache / getKubeJsonContextLastOne / fJX6gknlAeNbAxI3duMzpG / 2022-04-27T07:54:06Z
2022-04-27 16:54:15.511 DEBUG [api-server,,,] 7580 --- [onnection adder] com.zaxxer.hikari.pool.HikariPool : HikariPool-1 - Added connection org.postgresql.jdbc.PgConnection@6092c019
2022-04-27 16:54:15.511 DEBUG [api-server,,,] 7580 --- [onnection adder] com.zaxxer.hikari.pool.HikariPool : HikariPool-1 - After adding stats (total=6, active=0, idle=6, waiting=0)
2022-04-27 16:54:15.527 DEBUG [api-server,,,] 7580 --- [onnection adder] com.zaxxer.hikari.pool.HikariPool : HikariPool-1 - Added connection org.postgresql.jdbc.PgConnection@2b8afc69
2022-04-27 16:54:15.527 DEBUG [api-server,,,] 7580 --- [onnection adder] com.zaxxer.hikari.pool.HikariPool : HikariPool-1 - After adding stats (total=7, active=0, idle=7, waiting=0)
2022-04-27 16:54:15.540 DEBUG [api-server,,,] 7580 --- [onnection adder] com.zaxxer.hikari.pool.HikariPool : HikariPool-1 - Added connection org.postgresql.jdbc.PgConnection@31a688ab
2022-04-27 16:54:15.540 DEBUG [api-server,,,] 7580 --- [onnection adder] com.zaxxer.hikari.pool.HikariPool : HikariPool-1 - After adding stats (total=8, active=0, idle=8, waiting=0)
2022-04-27 16:54:15.566 DEBUG [api-server,,,] 7580 --- [onnection adder] com.zaxxer.hikari.pool.HikariPool : HikariPool-1 - Added connection org.postgresql.jdbc.PgConnection@3aff39c6
2022-04-27 16:54:15.566 DEBUG [api-server,,,] 7580 --- [onnection adder] com.zaxxer.hikari.pool.HikariPool : HikariPool-1 - After adding stats (total=9, active=0, idle=9, waiting=0)
2022-04-27 16:54:15.638 DEBUG [api-server,,,] 7580 --- [onnection adder] com.zaxxer.hikari.pool.HikariPool : HikariPool-1 - Added connection org.postgresql.jdbc.PgConnection@4c1ba488
2022-04-27 16:54:15.638 DEBUG [api-server,,,] 7580 --- [onnection adder] com.zaxxer.hikari.pool.HikariPool : HikariPool-1 - After adding stats (total=10, active=0, idle=10, waiting=0)
2022-04-27 16:54:15.652 DEBUG [api-server,,,] 7580 --- [onnection adder] com.zaxxer.hikari.pool.HikariPool : HikariPool-1 - Added connection org.postgresql.jdbc.PgConnection@308e70d6
2022-04-27 16:54:15.652 DEBUG [api-server,,,] 7580 --- [onnection adder] com.zaxxer.hikari.pool.HikariPool : HikariPool-1 - After adding stats (total=11, active=0, idle=11, waiting=0)
2022-04-27 16:54:15.666 DEBUG [api-server,,,] 7580 --- [onnection adder] com.zaxxer.hikari.pool.HikariPool : HikariPool-1 - Added connection org.postgresql.jdbc.PgConnection@35e855bc
2022-04-27 16:54:15.666 DEBUG [api-server,,,] 7580 --- [onnection adder] com.zaxxer.hikari.pool.HikariPool : HikariPool-1 - After adding stats (total=12, active=0, idle=12, waiting=0)
2022-04-27 16:54:15.687 DEBUG [api-server,,,] 7580 --- [onnection adder] com.zaxxer.hikari.pool.HikariPool : HikariPool-1 - Added connection org.postgresql.jdbc.PgConnection@761a6bce
2022-04-27 16:54:15.687 DEBUG [api-server,,,] 7580 --- [onnection adder] com.zaxxer.hikari.pool.HikariPool : HikariPool-1 - After adding stats (total=13, active=0, idle=13, waiting=0)
2022-04-27 16:54:15.733 DEBUG [api-server,,,] 7580 --- [onnection adder] com.zaxxer.hikari.pool.HikariPool : HikariPool-1 - Added connection org.postgresql.jdbc.PgConnection@67b4ae61
2022-04-27 16:54:15.733 DEBUG [api-server,,,] 7580 --- [onnection adder] com.zaxxer.hikari.pool.HikariPool : HikariPool-1 - After adding stats (total=14, active=0, idle=14, waiting=0)
2022-04-27 16:54:15.775 DEBUG [api-server,,,] 7580 --- [onnection adder] com.zaxxer.hikari.pool.HikariPool : HikariPool-1 - Added connection org.postgresql.jdbc.PgConnection@247f6a81
2022-04-27 16:54:15.775 DEBUG [api-server,,,] 7580 --- [onnection adder] com.zaxxer.hikari.pool.HikariPool : HikariPool-1 - After adding stats (total=15, active=0, idle=15, waiting=0)
2022-04-27 16:54:15.830 DEBUG [api-server,,,] 7580 --- [onnection adder] com.zaxxer.hikari.pool.HikariPool : HikariPool-1 - Added connection org.postgresql.jdbc.PgConnection@534d8e07
2022-04-27 16:54:15.830 DEBUG [api-server,,,] 7580 --- [onnection adder] com.zaxxer.hikari.pool.HikariPool : HikariPool-1 - After adding stats (total=16, active=0, idle=16, waiting=0)
2022-04-27 16:54:15.881 DEBUG [api-server,,,] 7580 --- [onnection adder] com.zaxxer.hikari.pool.HikariPool : HikariPool-1 - Added connection org.postgresql.jdbc.PgConnection@762ccbbb
2022-04-27 16:54:15.881 DEBUG [api-server,,,] 7580 --- [onnection adder] com.zaxxer.hikari.pool.HikariPool : HikariPool-1 - After adding stats (total=17, active=0, idle=17, waiting=0)
2022-04-27 16:54:16.094 INFO [api-server,,,] 7580 --- [TaskScheduler-1] .c.a.s.k.s.CassandraDataCacheServiceImpl : Read from Elastic. 1mCache / getKubeJsonContextLastOne / 5sznUu5z49IasTL9dN-6fx / 2022-04-27T07:54:08Z
2022-04-27 16:54:16.149 DEBUG [api-server,,,] 7580 --- [onnection adder] com.zaxxer.hikari.pool.HikariPool : HikariPool-1 - Added connection org.postgresql.jdbc.PgConnection@3429b4b9
2022-04-27 16:54:16.149 DEBUG [api-server,,,] 7580 --- [onnection adder] com.zaxxer.hikari.pool.HikariPool : HikariPool-1 - After adding stats (total=18, active=0, idle=18, waiting=0)
2022-04-27 16:54:16.176 DEBUG [api-server,,,] 7580 --- [onnection adder] com.zaxxer.hikari.pool.HikariPool : HikariPool-1 - Added connection org.postgresql.jdbc.PgConnection@6b5dfbdf
2022-04-27 16:54:16.176 DEBUG [api-server,,,] 7580 --- [onnection adder] com.zaxxer.hikari.pool.HikariPool : HikariPool-1 - After adding stats (total=19, active=0, idle=19, waiting=0)
2022-04-27 16:54:16.197 DEBUG [api-server,,,] 7580 --- [onnection adder] com.zaxxer.hikari.pool.HikariPool : HikariPool-1 - Added connection org.postgresql.jdbc.PgConnection@54df7d05
2022-04-27 16:54:16.197 DEBUG [api-server,,,] 7580 --- [onnection adder] com.zaxxer.hikari.pool.HikariPool : HikariPool-1 - After adding stats (total=20, active=0, idle=20, waiting=0)connection 이 이미 종료되었다는 로그와 함께 connection이 생성되지 않고
모든 connection의 상태 체크가 이루어진 후 일괄적으로 connection을 다시 생성한다!
되게 드물고, 짧은 시간에 만들어지기 때문에 이런 일은 없겠지만,
찰나의 순간(connection이 없을 때?)에 connection이 필요한 경우가 생기면 어떻게 될까?
를 생각하게 되는 로직인 것 같다.
사실 jdbc는 취직 전부터 사용하였지만,
지금처럼 최적화 방안이나 분석을 해본건 처음인 거 같다.
이 부분이 정말 어려운 게 사실 정해진 답이 없고 장단점이 모두 있기 때문에 내가 개발하고자 하는 서비스 특성에 맞춰서
설정해야 해서 참 애매한 거 같다.
하지만 모든 값에는 근거가 있어야 한다는 것! 그 부분을 알게 되어 좋은 시간이었던거 같다!
그럼 안녕!
'Programing > Spring' 카테고리의 다른 글
| Spring 양방향 Dependency Injection (0) | 2022.05.29 |
|---|---|
| Rest 통신 기반의 CRUD Transaction 처리 해보기 (AOP, Generic) (3) | 2022.05.23 |
| WAS (Spring Boot) - DB 성능 개선과 최적화 (2) - RestTemplate (0) | 2022.05.14 |
| Spring Security Provider Customizing 하기 (2) (0) | 2022.04.01 |
| Spring Security Provider Customizing 하기 (1) (0) | 2022.04.01 |