Spring Boot 3 + Maven + MyBatis 프로젝트에서 SQL 로그 예쁘게 출력하기(P6Spy 1.10.0)

 

 

 

 

P6Spy를 적용한 이유

Spring Boot로 백엔드 개발을 하면 SQL 로그를 자주 확인하게 된다.

기본 SLF4J debug 설정으로도 SQL 로그 확인이 가능하지만 한 줄로 출력되어 가로로 스크롤하기가 여간 귀찮은 일이 아니었다.

SQL 로그를 여러 줄로 보기 좋게 포맷팅하기 위해 P6Spy를 활용했다.

P6Spy는 애플리케이션의 코드를 변경하지 않고도 데이터베이스 데이터를 원활하게 가로채서 기록할 수 있는 프레임워크이다.

 

개발 환경

Maven : 4.0.0
Spring Boot : 3.4.1
Java : 17
MyBatis : 3.0.4

 

적용하기 위해 구글링을 해봤었지만 이전 버전에서 설치를 했거나 JPA를 사용하여 MyBatis에 적용하기 쉽지가 않았다.

또한 어떤 라이브러리를 쓰는지, 버전마다 적용 방법이 달라서 Spring Boot 3점대 버전+Maven+MyBatis를 사용하는 프로젝트에서 쓸 수 있는 방법을 찾느라 헤맸었다.

 

 

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

결론적으로 위의 spring-boot-data-source-decorator README를 참고하여 적용했다.

 

 

spring-boot-data-source-decorator

spring-boot-data-source-decorator는 JDBC 감시와 로깅을 지원하는 라이브러리로, P6Spy, Datasource Proxy, FlexyPool를 제공한다.

 

1. P6Spy는 애플리케이션의 코드 변경 없이 데이터베이스 데이터를 가로채고 로깅할 수 있도록 지원하는 프레임워크이다. 간편한 설정으로 SQL 실행 로그를 분석할 때 활용할 수 있다.

 

2. Datasource-Proxy는 쿼리나 메서드 실행 전후에 자체 로직을 수행할 수 있게 지원해주는 프록시 프레임워크이다. 기본적으로 쿼리 로깅, 느린 쿼리 감지, 실행 통계 수집, 트레이싱 기능을 제공한다. 필요에 따라 사용자 정의 리스너를 추가할 수 있다.

datasource-proxy User Guide

datasource-proxy의 주요 기능

• 느린 쿼리 감지 및 로깅 : 특정 임계시간을 초과하는 느린 쿼리에 대한 콜백을 추가할 수 있으며, 기본적으로 제공되는 느린 쿼리 로거를 활용할 수 있습니다.
• 연결 ID 부여 : 각 데이터베이스 연결에는 고유한 ID가 부여되며, 해당 ID는 로깅 항목에 포함됩니다.
• 쿼리 실행 통계 수집 : 실행된 쿼리의 총 소요 시간, SELECT/INSERT/UPDATE/DELETE 실행 횟수 등을 수집할 수 있으며, JSON 형식으로 출력이 가능합니다.
• 사용자 정의 로직 삽입 : QueryExecutionListener 및 MethodExecutionListener를 구현하여 쿼리 실행 또는 JDBC API 호출 전후에 원하는 로직을 추가할 수 있습니다.
• 쿼리 및 파라미터 변환 : QueryTransformer 및 ParameterTransformer를 활용하여, 실행 직전에 쿼리 및 파라미터를 변환할 수 있습니다.
• JDBC API 트레이싱 : 연결 획득, PreparedStatement 생성, 파라미터 설정, 쿼리 실행 등의 JDBC API 호출을 가로채어 추적할 수 있습니다.
• 웹 애플리케이션 지원 : ProxyDataSource는 JNDI를 통해 설정할 수 있으며, 웹 요청별로 쿼리 메트릭 정보를 관리할 수도 있습니다. JSP 기반 UI에서는 <dsp:metrics/> 태그를 활용하여 메트릭 데이터를 표시할 수 있습니다.

 

(출처 : datasource-proxy User Guide 번역)

 

3. FlexyPool은 기존 커넥션 풀(HikariCP, DBCP 등)에 동적 크기 조정과 메트릭 수집 기능을 추가하는 라이브러리다. 대부분의 커넥션 풀은 동적 구성 전략이 제한적이지만, FlexyPool을 활용하면 실시간으로 풀 크기를 조정할 수 있어 트래픽이 급증했을 때 커넥션 풀을 자동으로 확장해주는 등 리소스 관리를 지원한다. 커넥션 풀 크기 동적 조정 및 성능 모니터링을 할 때 활용할 수 있다. 라이브러리를 제공해주는 사이트의 설명에 따르면 메트릭 기반 분석을 통해 병목 현상을 사전에 감지하고 최적화할 수 있다고 한다.

 

실시간 모니터링 및 메트릭 수집

• 동시 접속 커넥션 히스토그램
• 커넥션 요청 횟수 히스토그램
• 커넥션 획득 시간 히스토그램
• 커넥션 임대 시간(Lease Time) 히스토그램
• 최대 풀 크기 히스토그램
• 총 커넥션 획득 시간 히스토그램
• 초과 풀 크기(Overgrow Pool Size) 히스토그램
• 재시도 횟수 히스토그램

 

(출처 : FlexyPool README 번역)

FlexyPool을 사용해야 하는 이유

• 애플리케이션의 부하를 효과적으로 관리
  • 트래픽 급증 시 커넥션 풀을 자동으로 확장하여 서비스 안정성을 유지할 수 있음
  • 특정 임계값을 초과하는 느린 쿼리를 감지하고 분석 가능
• 메트릭 기반 성능 분석 가능
  • 실행 중인 데이터베이스 커넥션을 실시간으로 모니터링하여 병목 현상 감지
  • Dropwizard Metrics 패키지와 통합 가능
• 기존 커넥션 풀과 손쉽게 연동
  • 단순한 설정 변경만으로 HikariCP, Apache DBCP, C3P0 등과 통합 가능
  • JMX를 통한 모니터링 지원

(출처 : FlexyPool README 번역)

실제 적용 사례

• Etuovi.com (핀란드 최대 부동산 포털)
  • 2014년부터 FlexyPool을 프로덕션 환경에서 사용하며, 일시적인 트래픽 증가를 효과적으로 처리
  • 프런트엔드부터 백엔드 서비스까지 전반적인 인프라에 적용
• Scentbird (미국 향수 구독 서비스)
  • HikariCP와 함께 FlexyPool을 적용하여 성능 테스트 후 프로덕션 도입
  • 빠르고 안정적인 데이터베이스 연결 관리가 가능해졌으며, 전체적인 성능이 개선됨

(출처 : FlexyPool README 번역)

 

라이브러리 선택 기준

SQL 실행 로그가 필요할 때 → P6Spy

코드 변경 없이 쉽게 적용 가능해서 단순 SQL 로깅 및 분석에 적합하다.

 

 

JDBC API 호출을 가로채서 추가 로직을 적용하고 싶을 때 → datasource-proxy

트랜잭션 로깅, JDBC 메서드 추적, SQL 변환 기능 필요할 때 유용하다.

 

 

커넥션 풀을 동적으로 조정해야 할 때 → FlexyPool

트래픽 급증 시 풀 크기를 자동으로 확장해야 하거나 메트릭 기반 커넥션 모니터링을 활용할 수 있다.

애플리케이션의 요구사항에 따라 적절한 라이브러리를 선택하거나 조합해서 사용하면 강력한 기능을 적용할 수 있다.

 

 

P6Spy 적용하기

나는 쿼리를 가독성 있게 여러 줄로 출력하기 + 이 쿼리가 어디서 실행됐는지 등 정보를 출력하기를 원했기 때문에 설정이 간편한 P6Spy를 적용했다. 버전은 Spring Boot 3 애플리케이션과 호환되는 P6Spy 1.10.0을 사용했다.

 

 

트러블 슈팅

P6Spy 적용하면서 지피티의 답변은 혼선만 가중시켰다. 아직 P6Spy 1.10.0 버전을 잘 모르는 것 같았다. Spring Boot 3점대 버전에서는 적용이 안 되었던 것을 기록해보자면,

 

application.yml → ❌

spring:
  datasource:
    driver-class-name: com.p6spy.engine.spy.P6SpyDriver
    url: jdbc:p6spy:${DB_URL}
		...

 

 

org.h2.Driver를 사용하면 P6Spy가 SQL을 감싸지 못해 바인딩된 값이 적용되지 않습니다.

라고 해서 위의 설정을 했었는데 어느 외국 사이트에서 Spring Boot 3점대 버전부터는 P6SpyDriver를 사용하지 않고 각 벤더사의 JDBC driver를 사용해도 된다고 해서 기존 설정으로 바꾼 후 잘 실행이 됐다.

 

 

application.yml → ✅

spring:
  datasource:
    driver-class-name: org.h2.Driver
    url: jdbc:h2:${DB_URL}
		...

 

 

참고) sleuth는 deprecated됨.

https://docs.spring.io/spring-cloud-sleuth/docs/3.1.0/reference/html/integrations.html#sleuth-jdbc-integration

Spring Cloud Sleuth customization

 

최종적으로 적용한 설정

 

pom.xml

    <!-- https://mvnrepository.com/artifact/com.github.gavlyukovskiy/p6spy-spring-boot-starter -->
    <dependency>
        <groupId>com.github.gavlyukovskiy</groupId>
        <artifactId>p6spy-spring-boot-starter</artifactId>
        <version>1.10.0</version>
    </dependency>

 

resources/spy.properties

# SLF4J 사용해서 로그 출력
appender=com.p6spy.engine.spy.appender.Slf4JLogger

# 커스텀 포맷 사용
logMessageFormat=com.p6spy.engine.spy.appender.CustomLineFormat

# 로그 메세지 포맷
customLogMessageFormat=%(sql) | execution time %(executionTime) ms

# [선택] commit, rollback 로그 제거
excludecategories=commit,rollback

 

바인딩된 SQL만 깔끔하게 출력하는 게 P6Spy를 적용한 목적이었기에 customLogMessageFormat을 사용해서 로그 메세지를 원하는대로 설정했다.

 

P6Spy는 기본적으로 바인딩되지 않은 원본 SQL(?가 포함된 JDBC PreparedStatement)과 바인딩된 값이 적용된 SQL(실제 실행된 SQL)을 출력한다.

 

%(sql) : 멀티라인 출력, 실행된 SQL 출력 → 바인딩된 값이 적용된 SQL

 

 

application.yml

logging:
  level:
    com.p6spy.engine.spy.P6SpyDriver: INFO

 

실행 결과

2025-02-07T13:13:31.307+09:00  INFO 31308 --- [nio-8090-exec-2] p6spy                                    : 
----------------------------------------------------
Query Type: statement | Execution Time: 3 ms | Connection: 1
JDBC URL: jdbc:h2:file:./data/testdb | Method: %(method) | Thread: %(thread)
Executed From: %(class)#%(line)
----------------------------------------------------
/* TodoMapper, searchTodo" */
        SELECT
               ID
             , TITLE
             , OWNER
             , PRIORITY
             , STATUS
             , DUE_DATE
             , CREATED_AT
             , UPDATED_AT
          FROM TODO
         WHERE 1 = 1
         
           AND TITLE LIKE '%' || '%%프로젝트%%' || '%'
         
         
           AND DUE_DATE >= '2025-02-01T00:00'
         
         
      ORDER BY DUE_DATE DESC
----------------------------------------------------

 

다음과 같이 잘 출력해준다.

 

spy.properties는 개행이 되지 않아 커스텀한 포맷을 적용하기가 불편하여 따로 P6SpyConfigLoader를 만들어서 ApplicationListener를 이용해 자동 설정하는 방식으로 사용했다.

 

txt 파일에서 개행 포함된 SQL 로그 형식을 읽어오고 런타임에 동적으로 설정을 변경해서 Spring Boot 실행 시 자동으로 적용되게 했다.

----------------------------------------------------
Query Type: %(category) | Execution Time: %(executionTime) ms | Connection: %(connectionId)
JDBC URL: %(url) | Method: %(method) | Thread: %(thread)
Executed From: %(class)#%(line)
----------------------------------------------------
%(sql)
----------------------------------------------------

 

쿼리 가독성을 위해 색상을 변경하는 방법과 더 자세한 내용은 다음 포스팅에서 계속될 예정이다.