p6spy 적용 배경

ORM 인 JPA (Hibernate) 는 DB 테이블을 객체에 맞게 패러다임을 변화시켜 유용한 기능을 제공합니다.

덕분에 객체지향 프레임워크를 이용하는 백엔드 개발자들은 Hibernate 를 통해 좋은 DX를 제공받습니다.

그 중 하나는 런타임중에 발생한 쿼리를 확인하는 것입니다.

스프링에서는 간단한 세팅을 통해서 실제로 행해지는 쿼리를 로그로 확인하는 기능이 있습니다.

아래 방식으로 설정시 binding paramter 를 이용한 JPQL 문법으로 쓰여진 쿼리문을 확인할 수 있습니다.

spring:
  jpa:
    properties.hibernate:
      show_sql: true
      format_sql: true

또한 아래 옵션을 추가시 hibernate 가 쿼리를 수행할때 binding paramter 에 삽입된 값들을 하나하나 확인할 수도 있습니다.

logging.level:
  org.hibernate:
    type.descriptor.sql: info

위 방식으로도 유용하지만, Spring 과 Hibernate 의 로그 방식에는 결국 아래와 같은 단점이 있습니다.

  1. dynamic query 에 binding 되는 parameter 확인은 되지만 Full Query 로 보여주지 않습니다. 쿼리를 위한 로그가 번잡해집니다.
  2. JPQL 문법으로 표현됩니다.

이러한 단점들을 커버할 수 있는 좋은 방법 중 하나가 p6spy 라고 하는 라이브러리를 적용하는 것이다.

p6spy 란?

기존 어플리케이션에 코드의 변화 없이 SQL 로그를 남기는 데이터베이스 프레임워크입니다.

https://github.com/p6spy/p6spy

한 훌륭한 라이브러리 개발자께서 p6spy의 Spring Boot 버전도 마련해주셨습니다.

https://github.com/gavlyukovskiy/spring-boot-data-source-decorator

README 를 참고하여 빠르게 설정이 가능합니다.

implementation("com.github.gavlyukovskiy:p6spy-spring-boot-starter:${version}")
decorator:
  datasource:
    p6spy:
      enable-logging: true
      tracing.include-parameter-values: true

p6spy + Sleuth 연동

가이드를 읽던 중 확인해보니 최근에 p6spy 가 sleuth 에 녹아들었다는 것을 발견했습니다. 공식 가이드에서 앞선 gavlyukovskiy 의 spring-boot-data-source-decorator 패키지를 포팅했다고 소개합니다. 공교롭게도 저는 sleuth 사용자이므로 해당 가이드를 참고하여 Sleuth 랑 연동하는 것이 좀 더 공식적인 p6spy 사용 방법이라고 판단하였습니다.

p6spy 를 의존성 리스트에 추가하고

//    implementation 'com.github.gavlyukovskiy:p6spy-spring-boot-starter:1.8.1'
implementation 'p6spy:p6spy:3.9.1'

설정을 통해 쿼리를 로깅할 수 있었네요.

spring:
  sleuth:
    jdbc:
      p6spy:
        enable-logging: true

로그에서 쿼리 전문, 소모된 시간, connection 정보 등을 모두 확인할 수가 있었습니다. 개발시에 매우 유용할 듯 합니다.

[2023-07-03 14:47:02.344][INFO ][http-nio-8080-exec-4] p6spy - #1688363222344 | took 9ms | statement | connection 60| url jdbc:mysql://localhost:3306/monolith
select storeinfo0_.id * ...

아래 옵션을 참고하면 여러 설정이 가능합니다.

최종적으로 사용하는 옵션은 다음과 같습니다.

개발시에만 디버깅 용도로 쿼리를 로그를 확인하고, 실제 상황에서는 굳이 쿼리를 로그로 남기지는 않습니다.

spring:
  sleuth:
    jdbc:
      p6spy.enable-logging: true
---
spring:
	profiles.active: prod
	sleuth:
    jdbc:
      p6spy.enable-logging: false

결과는 아래와 같이 binding parameter 를 ? 로 분리한 것과 binding parameter 를 붙인 것 두개의 쿼리를 모두 출력해줍니다.

[2023-07-03 14:52:05.545][INFO ][http-nio-8080-exec-7] p6spy - #1688363525545 | took 81ms | statement | connection 89| url jdbc:mysql://localhost:3306/monolith
select distinct productinf0_.id ...
select distinct productinf0_.id ...
[2023-07-03 14:52:05.580][INFO ][http-nio-8080-exec-6] p6spy - #1688363525579 | took 236ms | statement | connection 91| url jdbc:mysql://localhost:3306/monolith
select storeinfo0_.id as ...
select storeinfo0_.id as ...

Custom logger 를 이용해서 query 를 여러줄로 표현할 수도 있을 것 같습니다만, 로그의 가독성을 위해 이정도면 충분한 것 같습니다.

이제 오랜 시간이 걸리는 쿼리를 확인할 수 있게 되었습니다.