[Spring Boot] P6Spy 쿼리 로깅

[JPA] N+1 문제 발생 지점 찾아 해결하기

이전 글에서 application.yml의 logging 설정을 통해 SQL 쿼리에 바인딩되는 파라미터 값을 확인할 수 있었다.

spring:
  jpa:
    show-sql: true
    properties:
      hibernate:
        format_sql: true

logging:
  level:
    org:
      hibernate:
        SQL: debug
        type.descriptor.sql: trace
    org.hibernate.orm.jdbc.bind: trace

logging을 통한 Hibernate 로그 설정은 이처럼 application.yml 파일에서 간단하게 설정할 수 있지만 로그를 직관적으로 확인하기 불편하다는 단점이 있다.

 

P6Spy란?

P6Spy는 기존 애플리케이션 코드를 변경하지 않고도 데이터베이스의 데이터를 가로채 로그를 남길 수 있는 프레임워크이다.

사용자의 DataSource를 P6SpyDataSource가 감싸고, JDBC 요청이 발생할 때마다 P6Spy가 프록시로 감싸 해당 정보를 분석하고 로그를 남기는 방식으로 작동한다.

 

SpringBoot 3.x.x 부터는 자동 설정(auto-configuration) 방식이 변화해 데이터 소스의 꾸미기(decorating) 작업을 위해 'gavlyukovskiy/spring-boot-data-source-decorator'와 같은 별도의 프로젝트를 활용한다. 따라서 기존처럼 P6Spy를 직접 프로젝트에 적용하는 방식이 아닌, gavlyukovskiy 프로젝트를 통해 더 체계적으로 P6Spy를 설정할 수 있게 되었다.

 

P6Spy 구성

🫧 자동 구성 (start 사용 ⭕️)

build.gradle에 p6spy starter 의존성을 추가해준다.

dependencies {
    implementation 'com.github.gavlyukovskiy:p6spy-spring-boot-starter:1.9.0'
}

 

🫧 수동 구성 (start 사용 ❌)

보다 세밀한 설정이나 커스터마이징이 필요할 경우, p6spy starter 의존성을 추가하지 않고 p6spy를 수동으로 추가하여 커스텀 설정을 구현할 수 있다.

dependencies {
    implementation 'p6spy:p6spy:3.9.1'
    implementation 'com.github.gavlyukovskiy:datasource-decorator-spring-boot-autoconfigure:1.9.2'
}

build.gradle에 p6spy 라이브러리 의존성을 추가해준다.

이 의존성은 P6Spy 라이브러리와, 스프링 부트와 P6Spy 간의 자동 구성을 지원하는 라이브러리를 제공한다.

 

프로젝트의 resources 폴더 하위에 위와 같은 폴더 구조를 만든 후 org.springframework.boot.autoconfigure.AutoConfiguration.imports 이름의 파일을 만들어 아래 내용을 입력해준다.

com.github.gavlyukovskiy.boot.jdbc.decorator.DataSourceDecoratorAutoConfiguration

 

이 파일은 스프링 부트가 DataSourceDecoratorAutoConfiguration 클래스를 찾아 자동으로 로드하도록 지시한다.

 

DataSourceDecoratorAutoConfiguration 클래스는 스프링 부트 애플리케이션의 데이터 소스를 자동으로 P6Spy 객체로 감싸는 역할을 한다. 이로 인해, 데이터베이스와의 상호작용은 P6Spy에 의해 로깅되고 추적되며, 이 모든 과정은 사용자가 코드를 직접 수정하지 않아도 자동으로 처리된다.

 

설정 완료

P6Spy를 설정한 후 테스트해보면, SQL 쿼리에서 ? 대신 실제 인자값이 표시되며, 쿼리가 한 줄로 출력되는 것을 확인할 수 있다.

select p1_0.id,b1_0.id,b1_0.created_at,b1_0.modified_at,b1_0.name,p1_0.created_at,p1_0.is_deleted,p1_0.modified_at,p1_0.name,p1_0.price from product p1_0 join brand b1_0 on b1_0.id=p1_0.brand_id where (p1_0.is_deleted = false) order by p1_0.created_at desc offset 0 rows fetch first 21 rows only;

 

 

SQL 쿼리 포맷팅

가독성을 위해 포맷 설정파일을 추가해 한 줄로 출력되는 SQL 쿼리를 포맷팅해준다.

@Configuration
public class P6SpyConfig implements MessageFormattingStrategy, ChaewsstoreConfig {

    @PostConstruct
    public void setLogMessageFormat() {
        P6SpyOptions.getActiveInstance().setLogMessageFormat(this.getClass().getName());
    }

    @Override
    public String formatMessage(int connectionId, String now, long elapsed, String category,
        String prepared, String sql, String url) {
        return String.format("[%s] | %d ms | %s", category, elapsed, formatSql(category, sql));
    }

    private String formatSql (String category, String sql){
        if (sql != null && !sql.trim().isEmpty() && Category.STATEMENT.getName()
            .equals(category)) {
            String trimmedSQL = sql.trim().toLowerCase(Locale.ROOT);
            if (trimmedSQL.startsWith("create") || trimmedSQL.startsWith("alter")
                || trimmedSQL.startsWith("comment")) {
                sql = FormatStyle.DDL.getFormatter().format(sql);
            } else {
                sql = FormatStyle.BASIC.getFormatter().format(sql);
            }
            return sql;
        }
        return sql;
    }
}

• 포맷 설정(setLogMessageFormat 메서드)
  • P6Spy의 로그 메세지 포맷을 현재 클래스 이름인 P6SpyConfig로 설정해 로그 메세지를 해당 클래스의 포맷 방식으로 출력한다.
• SQL 포맷팅(formatMessage 메서드)
  • SQL 쿼리 형식을 지정한 포맷에 맞게 변환하여 출력한다.
• SQL 포맷 로직(formatSql 메서드)
  • SQL 쿼리를 검사하여, 쿼리가 비어있지 않고 Category.STATEMENT 카테고리에 해당하는 경우 SQL 쿼리를 DDL쿼리와 일반 쿼리를 구분하여 포맷한다.

 

+ 호출 스택 트레이스

위 설정에서 쿼리를 호출한 코드를 추적할 수 있는 호출 스택 트레이스를 추가한 코드이다.

트레이스의 파일 이름을 클릭하면 해당하는 파일로 이동도 가능하다.

@Configuration
public class P6SpyConfig implements MessageFormattingStrategy, ChaewsstoreConfig {

    @PostConstruct
    public void setLogMessageFormat() {
        P6SpyOptions.getActiveInstance().setLogMessageFormat(this.getClass().getName());
    }

    @Override
    public String formatMessage(int connectionId, String now, long elapsed, String category,
        String prepared, String sql, String url) {
        return String.format("[%s] | %d ms | %s", category, elapsed,
            formatSql(category, sql));
    }

    private String stackTrace() {
        return Stream.of(new Throwable().getStackTrace())
            .filter(t -> t.toString().startsWith("com.chaewsstore") && !t.toString().contains(
                ClassUtils.getUserClass(this).getName()))
            .map(StackTraceElement::toString)
            .collect(Collectors.joining("\n"));
    }

    private String formatSql(String category, String sql) {
        if (sql != null && !sql.trim().isEmpty() && Category.STATEMENT.getName().equals(category)) {
            String trimmedSql = sql.trim().toLowerCase(Locale.ROOT);
            return stackTrace() + (trimmedSql.startsWith("create") || trimmedSql.startsWith("alter")
                || trimmedSql.startsWith("comment")
                ? FormatStyle.DDL.getFormatter().format(sql)
                : FormatStyle.BASIC.getFormatter().format(sql));
        }
        return sql;
    }
}

 

 

📚 참고

[Spring Boot JPA] P6Spy 활용해 쿼리 로그 확인하기