Hibernate Slow Query 감지하기

개요

Hibernate의 slow query를 감지하는 기능을 활성화하는 방법에 대해 알아보겠습니다.

 

더 나아가서 hibernate query에 부가정보를 남겨서 slow query 발생 시 추적에 용이하게 활용할 수 있는 방법에 대해 알아보겠습니다.

 

Slow Query란?

Slow Query는 데이터베이스에서 실행되는 쿼리 중 실행 속도가 느린 쿼리를 의미합니다.

 

일반적으로 데이터베이스 쿼리가 데이터를 가져오거나 업데이트하는 과정에서 시간이 오래 걸리면 데이터베이스의 성능저하로 인해 여러 문제가 발생할 수 있습니다.

 

그러면 얼마나 느려야 slow query로 판단할 수 있을까요?

 

Hibernate Slow Query

org.hibernate.SQL_SLOW = INFO : Hibernate 5.4.5 이상 버전에서 Slow Query 로그레벨 지정
hibernate.session.events.log.LOG_QUERIES_SLOWER_THAN_MS=밀리초 property 를 지정해주면 이 값을 따름.

spring:  
  jpa:
    properties:
      hibernate:        
        session.events.log.LOG_QUERIES_SLOWER_THAN_MS: 5
        
        
logging:
  level:
    org.hibernate.SQL_SLOW: info

 

Spring Boot의 application.yml에 위와 같은 옵션을 주면 Hibernate에서는 5ms 이상의 쿼리들에 대하여 아래와 같이 몇 초가 걸렸는지 어떤 쿼리가 느린지 알려줍니다.

 

org.hibernate.SQL_SLOW                   
: SlowQuery: 7 milliseconds. SQL: 'HikariProxyPreparedStatement@217590872 wrapping prep0: 
select t1_0.id,t1_0.name from test_entity t1_0 where t1_0.id=? {1: UUID 'dfba05cf-f216-43db-af10-2c1432da42f6'}'

 

 

만약 설정이 잘 되지 않는다면 해당 옵션은 AvailableSettings라는 클래스에서 설정되므로 디버깅해 볼 수 있습니다.

AvailableSettings 클래스는 하이버네이트가 가지는 설정들을 모두 나열하고 있습니다.

 

 

Slow Query 부가 정보 남기기

slow query를 남기는 역할은 org.hibernate.engine.jdbc.spi 패키지의 SqlStatementLogger 클래스가 담당하고 있습니다.

	@AllowSysOut
	private void logSlowQuery(Supplier<String> sqlSupplier, long startTimeNanos) {
		if ( logSlowQuery < 1 ) {
			return;
		}
		if ( startTimeNanos <= 0 ) {
			throw new IllegalArgumentException( "startTimeNanos [" + startTimeNanos + "] should be greater than 0" );
		}

		long queryExecutionMillis = TimeUnit.NANOSECONDS.toMillis( System.nanoTime() - startTimeNanos );

		if ( queryExecutionMillis > logSlowQuery ) {
			String logData = "SlowQuery: " + queryExecutionMillis + " milliseconds. SQL: '" + sqlSupplier.get() + "'";
			LOG_SLOW.info( logData );
			if ( logToStdout ) {
				System.out.println( logData );
			}
		}
	}

 

세번째 if문 구절을 살펴보면 지정된 slow query 시간보다 쿼리 실행시간이 큰 경우 sql 문을 남기는 모습을 볼 수 있습니다.

 

slow query가 발생했을 때 더 빠르게 파악하기 위한 부가정보를 남겨보면 어떨까 라는 생각도 할 수 있습니다.

 

부가정보를 위해서는 sql에 주석을 활용해볼 수 있습니다.

 

부가정보의 예로는 어떤 서버에서 호출된 것인지, 어떤 api로부터 호출된 것인지 부가정보를 로그에 담을 수 있습니다.

 

그러면 기존 sql에 정보를 어떻게 하면 넣을 수 있을까요?

 

StatementInspector 활용

Hibernate 5.0 이전에는 Interceptor의 onPrepareStatement로 SQL에 부가정보를 남길 수 있었습니다.

 

하지만 아래 그림과 같이 Hibernate 5.0부터 Interceptor의 onPrepareStatement가 Deprecated되어 StatementInspector를 활용하라고 javaDocs에 명시되어 있습니다.

 

 

주석으로 부가적인 정보를 제공하기 위해 StatementInspector를 정의합니다.

class SQLTrackingStatementInspector: StatementInspector {
    override fun inspect(sql: String): String {
        return "/* inspect test */ $sql"
    }
}

 

이후 정의한 StatementInspector를 session_factory에 등록해주어야 합니다.

spring:  
  jpa:
    properties:
      hibernate:        
        session_factory:
          statement_inspector: com.example.study.hibernate.interceptor.SQLTrackingStatementInspector

 

 

이후 테스트를 수행해보면 쿼리에 부가정보가 남는 모습을 확인할 수 있습니다.

 

실제로 필요한 부가정보는 SqlTrackingStatementInspector를 정의할 때 내부 필드로 변하지 않는 정보를 넣어주거나 MDC에서 값을 꺼내오는 방식으로 쿼리에 부가정보를 넣어줄 수 있습니다.

 

 

 

 

참고자료

https://thorben-janssen.com/hibernate-slow-query-log/

https://docs.jboss.org/hibernate/orm/6.6/introduction/html_single/Hibernate_Introduction.html#basic-configuration-settings

https://docs.jboss.org/hibernate/orm/6.6/javadocs/org/hibernate/cfg/AvailableSettings.html

https://www.baeldung.com/hibernate-interceptor