Post

HikariCP에서 Oracle PreparedStatement cache 활성화하기

Posted Updated
By umbum 11 min read

문제 인식

  

2번째 column이 execution 횟수, 3번째 column이 parse call 횟수

  • 24/11/07 부터 갑자기 특정 쿼리의 parse call이 크게 늘어서 거의 execution 횟수와 동일해졌다.
    • 이 쿼리만 그런 것은 아니고, 다른 쿼리들도 같은 문제가 있었다.
  • 쿼리가 실행 될 때 마다 매번 parse call이 발생하고 있다는 것인데… 11/07에 CP를 DBCP → HikariCP로 변경한 이후로 preparedStatement 또는 cache가 제대로 적용되지 않고 있는 것이 원인으로 보였다.
    1. preparedStatement가 적용되고 있지 않거나
    2. preparedStatement는 적용되고 있지만, cache가 적용되지 않아 매번 parse call 하거나
  • persistence framework로는 mybatis 사용하고 있었다.
  • PreparedStatement란

HikariCP의 preparedStatement cache 설정

  • https://github.com/brettwooldridge/HikariCP?tab=readme-ov-file#statement-cache 참고
  • HikariCP는 CP 레벨에서 preparedStatement cache를 지원하지는 않는다.
  • 그래서 dataSourceProperties 속성으로 driver에 properties를 전달하여 driver, DB level의 cache를 활성화 하는 방식을 사용해야 한다.
  • Oracle JDBC에서 implicit preparedStatement cache는 기본 비활성화 되어 있기 때문에 별도 설정을 통해 활성화 해주어야 한다.

기존 설정 (cache 동작 X)

1
2
3
4
5
6
7
8
9
10

<bean id="dataSourceProps" class="com.zaxxer.hikari.HikariDataSource" destroy-method="close">  
    <property name="driverClassName" value="..."/>  
    <생략>
    <property name="dataSourceProperties">  
        <props>  
            <prop key="implicitCachingEnabled">true</prop>
            <prop key="maxStatements">...</prop>
        </props>  
    </property>  
</bean>
  • 문제 발생 시점의 HikariCP 설정은 위와 같았다.
  • JDBC driver에 preparedStatement cache를 쓰게끔 설정을 잘 넘기고 있는 것 같은데, 적용이 안되고 있는지 확인이 필요했다.
  • 설정 값 출처는 oracle 공홈이라서 (1, 2) 크게 의심하지 않았는데, 결론 부터 얘기하면 이 설정이 잘못된거였다.

로그 확인

01/12 10:14:26 [http-nio-8080-exec-5] [INFO ] (Slf4jSpyLogDelegator.java:518) [connectionOpened] 536. Connection opened  org.springframework.jdbc.datasource.DataSourceUtils.doGetConnection(DataSourceUtils.java:111)
01/12 10:14:26 [http-nio-8080-exec-5] [DEBUG] (Slf4jSpyLogDelegator.java:520) [connectionOpened] open connections:  536 (1)
01/12 10:14:26 [http-nio-8080-exec-5] [DEBUG] (Slf4jSpyLogDelegator.java:167) [methodReturned] 536. Connection.new Connection returned   org.springframework.jdbc.datasource.DataSourceUtils.doGetConnection(DataSourceUtils.java:111)
01/12 10:14:26 [http-nio-8080-exec-5] [DEBUG] (Slf4jSpyLogDelegator.java:167) [methodReturned] 536. Connection.getAutoCommit() returned true  org.mybatis.spring.transaction.SpringManagedTransaction.openConnection(SpringManagedTransaction.java:81)
01/12 10:14:26 [http-nio-8080-exec-5] [DEBUG] (Slf4jSpyLogDelegator.java:167) [methodReturned] 536. PreparedStatement.new PreparedStatement returned   org.apache.ibatis.executor.statement.PreparedStatementHandler.instantiateStatement(PreparedStatementHandler.java:72)
01/12 10:14:26 [http-nio-8080-exec-5] [DEBUG] (Slf4jSpyLogDelegator.java:167) [methodReturned] 536. Connection.prepareStatement(
        SELECT	count(*)
        FROM	re_cncrn_gsw crn,
                re_gsw_info gsw
        WHERE   gsw.GSW_NO = crn.GSW_NO
                and crn.indv_mbr_id = ?) returned net.sf.log4jdbc.PreparedStatementSpy@3d8caad4  org.apache.ibatis.executor.statement.PreparedStatementHandler.instantiateStatement(PreparedStatementHandler.java:72)
01/12 10:14:26 [http-nio-8080-exec-5] [DEBUG] (Slf4jSpyLogDelegator.java:167) [methodReturned] 536. PreparedStatement.setQueryTimeout(10) returned   org.apache.ibatis.executor.statement.BaseStatementHandler.setStatementTimeout(BaseStatementHandler.java:101)
01/12 10:14:26 [http-nio-8080-exec-5] [DEBUG] (Slf4jSpyLogDelegator.java:167) [methodReturned] 536. PreparedStatement.setString(1, "umbum") returned   org.apache.ibatis.type.StringTypeHandler.setNonNullParameter(StringTypeHandler.java:28)
01/12 10:14:26 [http-nio-8080-exec-5] [INFO ] (Log4JdbcCustomFormatter.java:74) [sqlOccured] SQL=>
        SELECT	count(*)
        FROM	re_cncrn_gsw crn,
                re_gsw_info gsw
        WHERE   gsw.GSW_NO = crn.GSW_NO
                and crn.indv_mbr_id = 'umbum'
01/12 10:14:26 [http-nio-8080-exec-5] [DEBUG] (Slf4jSpyLogDelegator.java:352) [sqlTimingOccured]  org.apache.ibatis.executor.statement.PreparedStatementHandler.query(PreparedStatementHandler.java:56)
536. SELECT count(*) FROM re_cncrn_gsw crn, re_gsw_info gsw WHERE gsw.GSW_NO = crn.GSW_NO and crn.indv_mbr_id = 'umbum'  {executed in 14 msec}
01/12 10:14:26 [http-nio-8080-exec-5] [DEBUG] (Slf4jSpyLogDelegator.java:167) [methodReturned] 536. PreparedStatement.execute() returned true  org.apache.ibatis.executor.statement.PreparedStatementHandler.query(PreparedStatementHandler.java:56)
01/12 10:14:26 [http-nio-8080-exec-5] [DEBUG] (Slf4jSpyLogDelegator.java:167) [methodReturned] 536. ResultSet.new ResultSet returned   org.apache.ibatis.executor.resultset.DefaultResultSetHandler.getFirstResultSet(DefaultResultSetHandler.java:178)
01/12 10:14:26 [http-nio-8080-exec-5] [DEBUG] (Slf4jSpyLogDelegator.java:167) [methodReturned] 536. PreparedStatement.getResultSet() returned net.sf.log4jdbc.ResultSetSpy@2d544b44  org.apache.ibatis.executor.resultset.DefaultResultSetHandler.getFirstResultSet(DefaultResultSetHandler.java:178)
<생략>
01/12 10:14:26 [http-nio-8080-exec-5] [DEBUG] (Slf4jSpyLogDelegator.java:167) [methodReturned] 536. ResultSet.close() returned null  org.apache.ibatis.executor.resultset.DefaultResultSetHandler.closeResultSet(DefaultResultSetHandler.java:213)
01/12 10:14:26 [http-nio-8080-exec-5] [DEBUG] (Slf4jSpyLogDelegator.java:167) [methodReturned] 536. PreparedStatement.getConnection() returned net.sf.log4jdbc.ConnectionSpy@2e91d275  org.apache.ibatis.executor.resultset.DefaultResultSetHandler.getNextResultSet(DefaultResultSetHandler.java:197)
01/12 10:14:26 [http-nio-8080-exec-5] [DEBUG] (Slf4jSpyLogDelegator.java:167) [methodReturned] 536. Connection.getMetaData() returned HikariProxyDatabaseMetaData@1980962681 wrapping oracle.jdbc.driver.OracleDatabaseMetaData@7d0188f3  org.apache.ibatis.executor.resultset.DefaultResultSetHandler.getNextResultSet(DefaultResultSetHandler.java:197)
01/12 10:14:26 [http-nio-8080-exec-5] [DEBUG] (Slf4jSpyLogDelegator.java:167) [methodReturned] 536. PreparedStatement.close() returned   org.apache.ibatis.executor.BaseExecutor.closeStatement(BaseExecutor.java:231)
01/12 10:14:26 [http-nio-8080-exec-5] [INFO ] (Slf4jSpyLogDelegator.java:537) [connectionClosed] 536. Connection closed  org.springframework.jdbc.datasource.DataSourceUtils.doCloseConnection(DataSourceUtils.java:341)
  • 혹시 preparedStatement가 아예 적용이 안되고 있는건가? 싶었는데, 로그를 보니 preparedStatement 자체는 잘 사용하고 있다.
  • 그러면 preparedStatement를 사용하더라도 caching이 되고 있지 않아서 매번 parse call이 발생하고 있는 것 같다.

Connection opened, Connection closed 부분

  • connection을 매번 open, close 하는 것으로 로그가 찍혀있는데, preparedStatement cache의 생명 주기가 connection(session)에 종속된다면, query 날릴 때 마다 conn 열고 닫으면 매번 parse call이 발생 할 것 같다.
  • 하지만 CP를 쓰고 있기 때문에, 매번 open, close 하지는 않을 것 같은데 싶어 디버깅해보았는데
  • 실제로는 CP에서 빌려오고, 반납하는 과정인데 로그가 conn open / close로 찍히는 것 뿐이었다.
    • 이 Connection 객체의 타입은 com.zaxxer.hikari.pool.ProxyConnection 이라서, close 호출 해도 실제로 connection을 닫지 않는다.
    • DataSourceUtils.doGetConnection 부분 : CP에서 conn 빌려온다. (결과적으로 HikariDataSource.getConnection 호출)
    • DataSourceUtils.doCloseConnection 부분 : CP에 conn을 반납한다. (결과적으로 Hikari의 PoolEntry.recycle 호출)
  • 따라서 실제 conn은 CP에서 계속 유지된다. (실제 conn은 CP의 lifetime 설정에 따라 열고 닫는 것이지 query 날릴 때 마다 열고 닫지 않는다.)

PreparedStatement.close 부분

  • connection이 계속 유지되는 것은 확인했는데, 로그에 BaseExecutor.closeStatement 부분도 있다.
  • 여기서 preparedStatement를 닫아버리는건 아닐까? 싶어 디버깅 해보았다.
  • org.apache.ibatis.executor.BaseExecutor 즉 mybatis 단의 객체이고, Executor는 말 그대로 SQL을 execute 하는 역할이다.
  • 아래 3가지 ExecutorType을 지원하며, 아래 설정으로 기본 Executor를 변경 할 수 있다.
1
2
3
4
5

<setting name="defaultExecutorType" value="SIMPLE"/>

- ExecutorType.SIMPLE: 기본값. 구문 실행마다 새로운 PreparedStatement객체를 생성
- ExecutorType.REUSE : PreparedStatement 객체를 재사용 (캐싱)
- ExecutorType.BATCH : 모든 update구문을 배치처리하고 중간에 select 가 실행될 경우 필요하다면 경계를 표시

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17

public class ReuseExecutor extends BaseExecutor {
    private final Map<String, Statement> statementMap = new HashMap<String, Statement>();
    // key는 SQL문 (select name from tbl where id = ?)
    
    public List<BatchResult> doFlushStatements(boolean isRollback) throws SQLException {
        Iterator i$ = this.statementMap.values().iterator();

        while(i$.hasNext()) {
            Statement stmt = (Statement)i$.next();
            this.closeStatement(stmt);
        }

        this.statementMap.clear();
        return Collections.emptyList();
    }
    <생략>
}
  • ReuseExecutor에서 statementMap으로 캐싱을 하고 있지만, 이건 DB level의 preparedStatement cache와는 전혀 무관하다.
    • ReuseExecutor를 사용하더라도, DB에서 캐싱이 되고 있지 않다면 쿼리를 날릴 때 마다 parse call이 발생한다.
  • 이건 단순히 app 단에서 Statement 객체를 Map에 담아 재활용 하는 개념이다. (mybatis 레벨에서 지원하는 객체에 대한 캐시)
  • 그래서 여기서 cache를 flush하든, statement를 닫든, DB level의 preparedStatement cache에는 영향을 주지 않는다. 이는 별개의 개념이다.

[!warning] mybatis 레벨의 preparedStatement cache가 과연 의미가 있나 싶다.
ojdbc를 살펴보니, 어차피 DB 단의 cache가 켜져있으면 JDBC driver 단에서 LRUStatementCache 라는 구조체를 유지하고 여기서 캐싱해서 객체 반환하고 있다.
즉 DB driver단에서 이미 하고 있기 때문에 mybatis 단에서 굳이 이중으로 할 필요가 없어보인다.
반대로 DB 단의 cache가 꺼져있으면, 어차피 mybatis에서 캐시한다고 해도 parse call은 매번 발생한다. 따라서 DB 단의 cache가 켜져 있든 꺼져 있든… mybatis의 ReuseExecutor가 성능에는 별로 도움이 되지 않을 것 같다.

그렇다면 앱단에서 DB 단의 preparedStatement cache가 적용되고 있는지 알 수 있나?

  • 로그의 connection, preparedStatement 부분을 살펴보았지만, 이는 모두 앱단 설정에 관련된 내용이고, DB 레벨에서 cache가 적용되고 있는지를 판단 할 수 있는 로그는 없었다.
  • 그렇다면 어떻게 알아낼 수 있을까? ⇒ 1. 쿼리와 2. 디버깅

parse call 횟수를 찍어 볼 수 있는 쿼리

  • :1 placeholder가 들어가 있는 것 보니 query는 제대로 preparedStatement로 전달되고 있다.
1
2
3
4
5
6
7
8
9
10
11
12
13

SELECT sql_id, sql_text, parse_calls, executions  
FROM v$sql  
WHERE parse_calls > 0  
AND sql_id = '6sqg1g48j3uzg'  
ORDER BY parse_calls DESC;

---
SQL_TEXT
SELECT	count(*)
FROM	re_cncrn_gsw crn,
        re_gsw_info gsw
WHERE   gsw.GSW_NO = crn.GSW_NO
        and crn.indv_mbr_id = :1

디버깅

  • 실제 connection 객체(oracle.jdbc.driver)에서 실제로 statementCache와 implicitStatementCacheSize 확인
  • null, 0 인 것을 보니 cache 적용이 안되고 있다.

올바른 설정

  • 디버깅 해보니, DataSource instance가 OracleDataSource가 아니라, DriverDataSource 인 것을 발견
  • implicitCachingEnabled, maxStatements는 OracleDataSource에 적용되는 설정이라, key를 DriverDataSource에 맞게 바꿔주어야 한다.
1
2
3
4
5
6
7
8
9

<bean id="dataSourceProps" class="com.zaxxer.hikari.HikariDataSource" destroy-method="close">  
    <property name="driverClassName" value="..."/>  
    <생략>
    <property name="dataSourceProperties">  
        <props>  
            <prop key="oracle.jdbc.implicitStatementCacheSize">50</prop>
        </props>  
    </property>  
</bean>

preparedStatement cache가 제대로 활성화 된 모습

이후 v$sql 테이블에서 parse call, execution 횟수 조회해보면 cache가 제대로 적용되고 있음을 확인 할 수 있다.

Java Stack, Persistence
This post is licensed under CC BY 4.0 by the author.