[Spring Boot 3] JPA SQL 파라미터 로그 보기 (P6Spy 적용)

Spring Boot 3와 JPA를 사용하는 프로젝트에서
실제로 실행되는 SQL 쿼리와 파라미터 값을 확인하기 위해 P6Spy를 적용했다.

Hibernate의 기본 SQL 로그는 파라미터 값이 `?`로만 출력돼서
실제 어떤 값이 바인딩되는지 확인하기 어렵다.

P6Spy를 사용하면 별도의 코드 변경 없이도
실행되는 SQL과 파라미터를 함께 로그로 확인할 수 있다.

이 글에서는 Spring Boot 3 환경에서 P6Spy를 적용하는 방법과,
기존 방식과 달라진 설정 포인트를 정리한다. 

P6spy 적용 이유 

- P6Spy를 사용하는 주된 이유는 스프링 부트와 JPA를 사용하는 프로젝트에서 SQL 쿼리를 정확하고 효과적으로 로깅하고 추적하기 위해서이다. P6Spy는 아래의 3가지 상황에서 사용된다.

1. 쿼리 확인

JPA는 매우 편리하지만 개발자가 직접 쿼리를 작성하지 않기 때문에 실제 어떤 쿼리가 실행되는지 확인하기 어렵다. p6Spy를 사용하면 이러한 쿼리를 눈으로 직접 확인할 수 있다. 특히 의도한 대로 작동하지 않을 때나 N+1 문제가 발생했는지 확인이 필요할 때 유용하다​​. 

2. 프록시를 통한 로깅

P6Spy는 기존 어플리케이션의 코드를 변경하지 않고도 데이터베이스의 데이터를 가로채고 로그를 남길 수 있는 프레임워크다. 사용자의 DataSource를 P6SpyDataSource가 감싸고, JDBC 요청이 발생할 때마다 P6Spy가 프록시로 래핑하여 해당 정보를 분석하고 로그를 남기는 방식으로 작동한다. 

3. 외부 라이브러리 장점

P6Spy는 JPA나 Hibernate에서 제공하는 SQL 로깅 기능 대신 사용할 수 있는 오픈 소스, 무료 라이브러리로, Java 어플리케이션에서 SQL 로그를 가로채는데 유용하다. 이는 다양한 방법으로 애플리케이션에 통합할 수 있으며, 스프링 부트 어플리케이션에서 P6Spy를 사용하는 예제를 통해 주요 구성 옵션을 볼 수 있다.

 

>> 내가 P6spy를 적용시키는 이유는 사실 JPA를 공부하면서 SQL문을 보기위해 P6spy를 써왔었는데, 프로젝트를 진행하면서 로깅할 때 쓰려고 알아보니 여러 종류의 라이브러리들이 있었다. Logback, Log4j2 등 다양하게 있었지만, 그 중에 익숙했던 P6spy를 사용하려고 보니까 위의 장점들이 보였고, 사용법도 제일 간편해서 좋았다.

 

적용 전에...

- Springboot 3부터 적용방법이 변경된 이유

: 스프링 부트 3에서 P6Spy 적용 방법이 바뀐 건 스프링 부트의 자동 설정(auto-configuration) 방식이 변화했기 때문이다. 스프링 부트 3에서는 데이터 소스를 꾸미는(decorating) 작업을 위해 특별한 프로젝트인 'gavlyukovskiy/spring-boot-data-source-decorator'를 사용한다. 

이 프로젝트는 P6Spy 같은 데이터 소스 데코레이터를 쉽게 통합할 수 있게 해주는 역할을 하는데, 이는 스프링 부트가 점점 더 유연하고 다양한 설정 옵션을 제공하기 위한 진화의 일부이다. 기존 방식에서는 P6Spy를 직접 프로젝트에 적용했지만, 스프링 부트 3에서는 이 별도 프로젝트를 통해 좀 더 체계적으로 P6Spy를 설정하게 된다.

 

- gavlyukovskiy는 뭘까?

gavlyukovskiy 라는 단어가 무엇을 의미하는지 엄청 궁금했다. 분명히 누군가의 이름 같은데 이게 스프링이 직접 지원하는 무언가 폴더 같은 것인지 아니면 누군가가 본인의 이름을 넣은 채로 만들어서 배포하고 있는 것인지를 알아봤다.

 

: gavlyukovskiy/spring-boot-data-source-decorator는 스프링에서 만들어서 배포한것이 아니라 개인 개발자인 gavlyukovskiy가 만든 오픈 소스 프로젝트다. 이 프로젝트는 스프링 부트 애플리케이션에서 P6Spy, datasource-proxy, FlexyPool 등과의 통합을 쉽게 할 수 있도록 도와준다. 

스프링 부트의 설정을 통해 이 데코레이터들을 활성화하고 구성할 수 있어서, 스프링 부트 3 어플리케이션에서 SQL 쿼리 로깅 및 데이터베이스 연결 모니터링을 효과적으로 수행할 수 있게 한다. 

스프링 부트의 클래스패스에 이 스타터를 추가하기만 하면, 사용자 정의 또는 자동 구성된 데이터 소스가 적절한 데이터 소스 프록시 제공자로 자동 래핑되면서, 데이터베이스 작업을 세밀하게 추적하고 관리할 수 있게 되는 것이다.

 

P6spy 적용

적용 전, 기본으로 제공되는 hibernate의 로그를 먼저 적용해보자.

 

개발환경 : Spring boot 3.3.2(gradle, jdk 17) / 데이터베이스 : PostgreSQL

 

<application.xml>

spring:
  datasource:
    url: jdbc:postgresql://localhost:5432/(MyDB)
    username: (MyUserName)
    password: (MyPassword)
    driver-class-name: org.postgresql.Driver
  jpa:
    hibernate:
      ddl-auto: update
    show-sql: true
    properties:
      hibernate:
        format_sql: true

Test RestAPI를 만들어서 실행시켜보았다.

SQL 쿼리에서 파라미터 값이 ?로 보여서 어떤값이 들어가는지 확인이 불가능하다.

이 값들을 보기 위해 p6spy를 적용시켜보자.

최대한 간단하게 작성해보겠다.

 

1. 라이브러리 의존성 설정

<build.gradle>

// p6spy - show query parameters
implementation 'com.github.gavlyukovskiy:p6spy-spring-boot-starter:1.9.2'

위의 코드를 써서 의존성 설정을 한다.

(Mac : Cammand + Shift + I / Window : Ctrl + Shift + O 였나...?)

 

해당 라이브러리 버전은 여기에서 확인해서 넣으면된다.

 

2. yml 설정

<application.yml>

spring:
  datasource:
    ...
  jpa:
    ...

decorator:
  datasource:
    p6spy:
      enable-logging: true

제일 아래에 decorator.datasource.p6spy.enable-logging: true 를 작성해주자.

p6spy의 로깅을 사용한다는 의미이며, 디폴트가 true이긴 하지만 유지보수성을 위해 명시해주도록 한다.

위의 hibernate 설정 코드에서 이어서 작성하면된다.

 

* 주의: 개발 환경에서만 사용하고 운영 환경에서는 false로 수정해서 끄도록 하자.

 

3. spy.properties 설정

이것은 p6spy의 내부 설정을 위한 파일이다. 다음 경로에 파일명 그대로 생성해주자.

 

경로 : (myProject)/src/main/resources/spy.properties

 

<spy.properties>

appender=com.p6spy.engine.spy.appender.Slf4JLogger
logMessageFormat=com.p6spy.engine.spy.appender.CustomLineFormat
customLogMessageFormat= %(currentTime) | %(category) | %(executionTime) ms | %(sql)

customLogMessageFormat에서 내가 출력하고자 하는 플레이스홀더를 적으면 거기에 해당하는 값들이 나온다. 플레이스홀더는 버전마다 달라서 확인해보고 사용하면 된다.

아래는 혹시 몰라서 chatGPT한테 물어본 내용을 적어두겠다. (안되는게 있을 수 있음)

• %(connectionId): 쿼리를 실행한 JDBC 커넥션의 ID를 출력
• %(currentTime): 쿼리가 실행된 현재 날짜와 시간을 출력 (형식은 dateformat 설정에 따라 변경 가능)
• %(category): 쿼리의 카테고리 출력. 예: statement, resultset, commit, rollback 등
• %(effectiveSql): 실제로 실행된 SQL 쿼리 출력. 파라미터가 바인딩된 최종 쿼리
• %(sql): 원본 SQL 쿼리 출력. 파라미터 바인딩 전의 SQL
• %(url): JDBC URL 출력. 데이터베이스 연결 정보 제공
• %(method): 쿼리를 실행한 JDBC 메소드 출력. 예: executeQuery, executeUpdate
• %(batch): 배치 쿼리일 경우 실행된 쿼리 개수 출력
• %(thread): 쿼리를 실행한 스레드 이름 출력
• %(username): 데이터베이스에 연결된 사용자 이름 출력

 

이렇게 설정하고 출력하면 다음과 같이 나온다.

근데... p6spy가 기본적으로 currentTime을 밀리초 단위의 타임스탬프로 처리하기 때문에 숫자로 나온다.

날짜 양식을 포맷하려면 아래처럼 마지막에 다음과 같이 넣어주면 된다.

appender=com.p6spy.engine.spy.appender.Slf4JLogger
logMessageFormat=com.p6spy.engine.spy.appender.CustomLineFormat
customLogMessageFormat= %(currentTime) | %(category) | %(executionTime) ms | %(sql)
dateformat=yyyy-MM-dd HH:mm:ss

추가하고 실행해보자.

날짜도 잘 나오고, sql 쿼리를 확인해보면 값들도 잘 들어가서 출력된다.

 

Tips.

그대로 따라오다보면 hibernate의 sql 쿼리도 같이 중복으로 출력될 것이다. 

그건 application.yml에서 spring.jpa.show-sql: true를 false로 바꾸거나 지우면 된다.

 

 

---

다 하고 보니까 sql 쿼리가 한줄로 나오는 것도 불편하다.

위의 hibernate에서 제공해주는 format처럼 보기 쉽게 적용시켜 보고싶다.

그리고 로그를 파일로도 남겨보고, 로그 레벨 설정하는 법까지 알아보고싶다.

해당 내용은 다음 포스팅에서 하겠다.