P6Spy 쿼리 로그 출력하기

기존 방식

JPA를 사용하면서, 실제로 수행되는 쿼리를 확인하기 위해 다음과 같은 설정을 사용하고 있었습니다.

# application.yml
spring:
  jpa:
    properties:
      hibernate:
        show_sql: true # SQL 출력
        format_sql: true # 포매터 적용
        use_sql_comments: true # JPQL 출력

logging.level:
  org.hibernate.type: trace # 쿼리 파라미터 출력

위 설정이 적용되면 다음과 같이 JPA 로그가 출력됩니다.

Hibernate:
    /* insert com.raegon.example.jpa.entity.Member
        */ insert
        into
            member
            (id, name, team_id)
        values
            (null, ?, ?)
2021-12-05 13:08:44.891 TRACE 16135 --- [           main] o.h.type.descriptor.sql.BasicBinder      : binding parameter [1] as [VARCHAR] - [member]
2021-12-05 13:08:44.891 TRACE 16135 --- [           main] o.h.type.descriptor.sql.BasicBinder      : binding parameter [2] as [BIGINT] - [1]

쿼리와 함께 바인딩된 파라미터의 타입과 값을 출력해줍니다. 하지만 다음과 같은 문제점이 있습니다.

• 표준 출력을 사용합니다.
• 파라미터가 많아지면 특정 파라미터 ? 에 바인딩 된 값을 확인하기가 어렵습니다.

P6Spy

P6Spy는 기존 코드의 변경 없이 SQL 로그를 출력할 수 있도록 해주는 프레임워크 입니다. 다음 방식 중 한가지를 사용해서 프로젝트에 적용할 수 있습니다.

• DataSource를 사용해서 새로운 P6DataSource 정의합니다.
• JDBC URL 을 jdbc:mysql://host/db/에서 jdbc:p6spy:mysql://host/db 형식으로 변경합니다.
• p6spy-spring-boot-starter를 사용합니다.

이중에서 스타터를 사용해서 설정하는 방법을 알아보겠습니다.

p6spy-spring-boot-starter

스프링 부트 프로젝트의 build.gradle 파일에 다음 의존성을 추가합니다.

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

의존성을 추가해주기만 하면 자동으로 p6spy가 설정되고, 다음과 같이 쿼리 로그가 출력됩니다.

2021-12-05 13:39:02.262  INFO 16493 --- [           main] p6spy                                    : #1638679142262 | took 0ms | statement | connection 4| url jdbc:h2:mem:8b0dd570-e73b-4197-a1b6-60bff2ff4cb6
/* insert com.raegon.example.jpa.entity.Member */ insert into member (id, name, team_id) values (null, ?, ?)
/* insert com.raegon.example.jpa.entity.Member */ insert into member (id, name, team_id) values (null, 'member', 1);

PreparedStatement 와 함께 실제로 수행된 쿼리가 출력되는 것을 확인할 수 있습니다.

프로퍼티 설정

스타터 의존성을 추가하는 것 만으로 쿼리 로그가 출력됩니다. 개발 환경에서는 편리하게 사용할 수 있지만, 운영계에서는 성능에 영향을 줄 수 있습니다. 따라서 기본값을 비활성 상태로 지정하고, 필요할 경우에만 활성 상태로 사용하는 것이 좋습니다.

application.yml에 다음 내용을 추가합니다.

# Disable p6spy
decorator:
  datasource:
    p6spy:
      enable-logging: false

---
# Add p6spy profile
spring:
  profiles: p6spy

decorator:
  datasource:
    p6spy:
      enable-logging: true

• decorator.datasource.p6spy.enable-logging 프로퍼티의 기본값을 false로 지정했습니다.
• p6spy 프로파일을 추가해서 쿼리 로그 출력이 필요할 때 사용할 수 있도록 정의했습니다.

기본 포매터

p6spy는 기본으로 MultiLineFormat 포매터를 사용합니다.

public class MultiLineFormat implements MessageFormattingStrategy {
  @Override
  public String formatMessage(final int connectionId, final String now, final long elapsed, final String category, final String prepared, final String sql, final String url) {
    return "#" + now + " | took " + elapsed + "ms | " + category + " | connection " + connectionId + "| url " + url + "\n" + prepared + "\n" + sql +";";
  }
}

이 포매터를 사용하면 다음과 같은 로그가 출력됩니다.

#1638685190878 | took 0ms | statement | connection 4| url jdbc:h2:mem:6fcd6d10-ff24-49f9-8508-06963d319876
insert into member (id, name, team_id) values (null, ?, ?)
insert into member (id, name, team_id) values (null, 'member', 1);

포매터 정의

MessageFormattingStrategy를 구현해서 취향에 맞는 포매터를 만들어보겠습니다.

@Component  // 1
public class P6SpyFormatter extends JdbcEventListener implements MessageFormattingStrategy {

  @Override // 2
  public void onAfterGetConnection(ConnectionInformation connectionInformation, SQLException e) {
    P6SpyOptions.getActiveInstance().setLogMessageFormat(getClass().getName());
  }

  @Override // 3
  public String formatMessage(int connectionId, String now, long elapsed, String category, String prepared, String sql, String url) {
    StringBuilder sb = new StringBuilder();
    sb.append(category).append(" ").append(elapsed).append("ms");
    if (StringUtils.hasText(sql)) {
      sb.append(highlight(format(sql)));
    }
    return sb.toString();
  }

  private String format(String sql) {
    if (isDDL(sql)) {
      return FormatStyle.DDL.getFormatter().format(sql);
    } else if (isBasic(sql)) {
      return FormatStyle.BASIC.getFormatter().format(sql);
    }
    return sql;
  }

  private String highlight(String sql) {
    return FormatStyle.HIGHLIGHT.getFormatter().format(sql);
  }

  private boolean isDDL(String sql) {
    return sql.startsWith("create") || sql.startsWith("alter") || sql.startsWith("comment");
  }

  private boolean isBasic(String sql) {
    return sql.startsWith("select") || sql.startsWith("insert") || sql.startsWith("update") || sql.startsWith("delete");
  }

}

이 포매터는 다음과 같은 방식으로 작동합니다.

• 1: JdbcEventListener를 상속받고 @Component를 사용해서 빈으로 등록합니다.
• 2: onAfterGetConnection 메소드를 오버라이드해서 P6SpyFormatter를 등록합니다.
• 3: formatMessage 메소드를 오버라이드해서 로그를 생성합니다.

새로운 포매터를 적용하면 다음과 같이 로그가 출력됩니다.

쿼리가 여러줄로 표시되고, 하이라이트 기능이 적용되서 가독성이 좋아졌습니다.

@DataJpaTest

@SpringBootTest 대신 @DataJpaTest를 사용해서 JPA 관련 테스트를 실행하면, p6spy-spring-boot-starter의 자동 설정이 적용되지 않아서 쿼리 로그가 출력되지 않습니다.

이를 해결하기 위해서 다음과 같이 @EnableQueryLog 어노테이션을 정의했습니다.

@Target(ElementType.TYPE)
@Retention(RetentionPolicy.RUNTIME)
@ImportAutoConfiguration(DataSourceDecoratorAutoConfiguration.class) // 1
@Import(P6SpyFormatter.class) // 2
@TestPropertySource(properties = {
    "logging.level.org.springframework.test.context=ERROR"
}) // 3
public @interface EnableQueryLog {

  @PropertyMapping("spring.jpa.show-sql") // 4
  boolean showSql() default false;

  @PropertyMapping("decorator.datasource.p6spy.enable-logging") // 5
  boolean enableLogging() default true;

}

• 1: DataSourceDecoratorAutoConfiguration을 import 해서 자동 설정이 적용되도록 합니다.
• 2: P6SpyFormatter를 import 해서 위에서 정의한 포매터를 사용합니다.
• 3: 선택사항. 테스트 컨텍스트의 로그 레벨을 ERROR로 정의해서 트랜잭션 관련 로그를 출력하지 않도록 설정합니다.
• 4: @DataJpaTest를 사용하면 spring.jpa.show-sql 프로퍼티를 true로 설정합니다. 이 값을 false로 변경합니다.
• 5: p6spy 로그 출력을 활성 상태로 변경합니다.

테스트 코드에서 다음과 같이 사용합니다.

@DataJpaTest
@EnableQueryLog
public class MemberTest {

  @Autowired
  TestEntityManager em;

  @Test
  public void test() {
    // Given
    Team team = Team.builder().name("team").build();
    Member member = Member.builder().name("member").team(team).build();
    em.persistAndFlush(team);
    em.persistAndFlush(member);
    em.clear();

    // When
    Member findMember = em.find(Member.class, member.getId());

    // Then
    assertThat(findMember.getName()).isEqualTo("member");
    assertThat(findMember.getTeam().getMembers()).containsExactly(findMember);
  }

}

요약

이번 글에서는 다음과 같은 내용을 알아보았습니다.

• build.gradle에 p6spy-spring-boot-starter 의존성을 추가하면 자동으로 p6spy가 설정됩니다.
• decorator.datasource.p6spy.enable-logging 프로퍼티의 기본값을 false로 지정합니다.
• MessageFormattingStrategy를 구현해서 로그가 출력되는 방식을 바꿀 수 있습니다.
• JdbcEventListener를 상속받은 빈을 등록해서, 커넥션이 생성되는 시점에 포매터를 등록할 수 있습니다.
• @DataJpaTest에서 로그를 출력하기 위해 @EnableQueryLog 어노테이션 정의했습니다.

예제 코드는 Github 저장소에서 확인하실 수 있습니다.

참고

• https://p6spy.readthedocs.io/en/latest/index.html
• https://github.com/gavlyukovskiy/spring-boot-data-source-decorator#p6spy
• https://backtony.github.io/spring/2021-08-13-spring-log-1/