Spring boot, JPA 환경에서의 더 좋은 쿼리 로깅 하기

최근에 Spring boot를 활용한 프로젝트를 보면 MyBatis(SQL Mapper)보다 JPA(ORM)/Hibernate/Spring data jpa를 사용하는 사례가 더 많은 것 같다.

• JPA, Hibernate, Spring data jpa를 모르는 분은 구글에서 찾아보길 바란다. 이후에는 JPA라고 약칭하겠다.

 

Query Logging

JPA/Hibernate를 사용하면 Query를 직접 작성해 활용하는 것이 아니기에 어떤 Query들이 구성되고 사용되고 있는지 확인하기 어려울 때가 있다.

그래서 이를 로깅 (Logging)을 통해 확인할 수 있도록 지원하고 있다.

 

근데 많이 알려진 방법이 좋지 않을 뿐더러 쿼리 결과도 정확히 나오지 않아 다른 방법을 제시하고자 한다.

일단 많이 알려진 방법대로 설정해보자.

 

application property 설정

Spring data jpa를 사용한다면, 아래와 같은 application property를 설정한다.

# application.properties
spring.jpa.show-sql=true

 

위 property 설정은 hibernate.show_sql property를 활성화시킨다.

• HibernateJpaVendorAdapter.java#L154

if (isShowSql()) {
    jpaProperties.put(AvailableSettings.SHOW_SQL, "true");
}

 

위 사항들을 설정하게 되면 JPA를 통해 쿼리가 나가게 될 때 아래와 비슷한 형태의 로그를 볼 수 있다.

Hibernate: 
    select
        server0_.service_id as server_1_0_0_,
        server0_.created_at as created_2_0_0_,
        server0_.is_deleted as is_delet3_0_0_,
        server0_.updated_at as updated_4_0_0_,
        server0_.author_id as author_11_0_0_
    from
        server server0_ 
    where
        server0_.service_id=? 

 

반응형

 

 

문제

위 방법/결과를 보았을 때, 뭐가 문제일까?

 

1. System.out.println의 사용

위 방식대로 활용하면 logging library를 통해 로깅되는 것이 아닌 System.out.println로 로깅된다.

• SqlStatementLogger.java#L130

무조건 System.out.println으로 로깅하는 것이 잘못된 것은 아니지만, 로그에 시스템 정보가 포함되지 않는 등의 단점으로 보통 사용하지 않는다.

 

2. 쿼리에 사용된 파라미터

쿼리에 사용된 파라미터는 로깅되지 않는다.

즉, PreparedStatement 형태의 쿼리만 로깅될 뿐, 어떠한 파라미터가 해당 쿼리에 바인드 되어 활용되었는지는 알 수 없다.

위 문제들을 해결하기 위해 다른 방법들을 소개하겠다.

 

 

 

 

다른 로깅 방법

hibernate application logging level 설정하기

간단하게는 hibernate의 logging level을 설정하는 것만으로도 해결할 수 있다.

 

아래처럼 application logging을 설정하자.

# application.properties
logging.level.org.hibernate.SQL=debug
logging.level.org.hibernate.type.descriptor.sql=trace

 

그러면 아래와 같은 로그가 출력될 것이다.

2022-11-20 23:45:51.428 DEBUG 84438 --- [nio-8080-exec-1] org.hibernate.SQL                        : 
    select
        server0_.service_id as server_1_0_0_,
        server0_.created_at as created_2_0_0_,
        server0_.is_deleted as is_delet3_0_0_,
        server0_.updated_at as updated_4_0_0_,
        server0_.author_id as author_11_0_0_
    from
        server server0_ 
    where
        server0_.service_id=? 
2022-11-20 23:45:51.509 TRACE 84438 --- [nio-8080-exec-1] o.h.type.descriptor.sql.BasicBinder      : binding parameter [1] as [BIGINT] - [133]

System.out.println으로 출력되지 않기도 하고, 바인드 된 파라미터에 대한 정보도 로깅되는 것을 확인할 수 있다.

 

하지만 이 방법 또한 단점이 존재한다.

• batch를 활용하는 경우, 메서드가 호출되는 순간이 아닌 준비 단계에서 로깅된다. 그렇기에 데이터베이스에 실제로 얼마나 쿼리가 전달되는지 확인할 수 없다.
• org.hibernate.type.descriptor.sql를 통해 바인드 된 파라미터가 로깅될 수 있는 것인데, 모든 타입의 변수가 로깅될 수 있는 것은 아니다. Hibernete core types에 해당하지 않는 타입은 제대로 동작하지 않는다.

 

 

Datasource-proxy 사용하기

Datasource-proxy는 JDBC execute listener를 지원하는 JDBC logging framework이다.

이를 활용해 Listener를 bean으로 등록해 모든 쿼리에 대한 결과를 로깅할 수 있다.

 

직접 Bean으로 등록할 수 있지만 이를 설정해놓은 의존성(Spring Boot DataSource Decorator)을 추가하는 것만으로도 적용할 수 있다.

# gradle
implementation("com.github.gavlyukovskiy:datasource-proxy-spring-boot-starter:${version}")

# maven
<dependency>
    <groupId>com.github.gavlyukovskiy</groupId>
    <artifactId>datasource-proxy-spring-boot-starter</artifactId>
    <version>${version}</version>
</dependency>

 

해당 프레임워크에 대한 로깅 레벨을 설정하자.

logging.level.net.ttddyy.dsproxy.listener=debug

 

이를 적용하면 아래와 같은 로깅 결과를 얻을 수 있다.

2022-11-20 23:59:43.171 DEBUG 84597 --- [nio-8080-exec-1] n.t.d.l.l.SLF4JQueryLoggingListener      : 
Name:dataSource, Connection:10, Time:15, Success:True
Type:Prepared, Batch:False, QuerySize:1, BatchSize:0
Query:["select server0_.server_id as server_1_0_0_, server0_.created_at as created_2_0_0_, server0_.is_deleted as is_delet3_0_0_, server0_.updated_at as updated_4_0_0_, server0_.author_id as author_11_0_0_ from server server0_ where server0_.server_id=?"]
Params:[(133)]

로깅 결과에서 볼 수 있다시피 datasource에 대한 상세 정보, batch/query 사이즈 유무, 쿼리, 파라미터 값 등을 상세하게 확인할 수 있다.

 

 

 

결론

이렇게 여러 방법을 알아보았다.

사실 production(상용) 서비스에서는 쿼리 결과를 다 로깅하는 것은 불가능하기 때문에 staging 이하 환경에서 활용될 테지만, 더 효율적이고 많은 정보를 제공하는 방식을 활용하는 편이 좋을 것이라고 생각한다.

 

만약 의존성 추가에 대한 위험부담이 없는 상황이라면, 맨 마지막 방법이 상세한 정보를 로깅할 수 있어 좋은 방법일 것 같다는 생각이 든다.

개인 개발자의 의존성 추가가 불안하다면, 직접 dataproxy를 bean으로 활용하거나 hibernate의 logging level을 변경해 활용하는 방법이 대안일 것이다.

 

 

References

• https://vladmihalcea.com/the-best-way-to-log-jdbc-statements/
• https://github.com/jdbc-observations/datasource-proxy
• https://github.com/gavlyukovskiy/spring-boot-data-source-decorator