spring / / 2023. 10. 23. 08:33

SQL 로깅 포맷팅을 위한 P6Spy

jpa를 사용할 때 기본적으로 SQL 로그가 표시되지 않는다. 그래서 SQL 출력을 위해 설정을 해주면 표시가 되는데 조금 불편하다. 이를 위해 P6Spy를 사용하면 우리가 원하는 형태로 표시가 되는데 그 내용을 한번 알아보자.

SQL 로그를 찍기위한 테스트 케이스를 작성해보자.

테스트 케이스 작성

@Test
void test() {
    userService.register(new User(1, "홍길동"));

    User user = userService.find(1);
}

userService를 등록하고 조회하는 테스트를 만들고 실행하면 insert와 select가 실행이 될텐데 해당 SQL이 표시되지 않는다.

로그 표시

spring.jpa.show-sql: true를 하면 기본 로그가 표시가 된다.

Hibernate: select userjpo0_.id as id1_0_0_, userjpo0_.name as name2_0_0_ from user_jpo userjpo0_ where userjpo0_.id=?
Hibernate: insert into user_jpo (name, id) values (?, ?)
Hibernate: select userjpo0_.id as id1_0_0_, userjpo0_.name as name2_0_0_ from user_jpo userjpo0_ where userjpo0_.id=?

하지만 show-sql은 콘솔로그라서 로그파일에 생성은 되지 않는데, 로그파일에 생성하려면 logging.level을 설정해주면 된다.

logging:
  level:
    org.hibernate.SQL: debug

이렇게 실행하면 logger에 기록이 된다.

2023-xxxx.002 DEBUG 64914 --- [           main] org.hibernate.SQL                        : select userjpo0_.id as id1_0_0_, userjpo0_.name as name2_0_0_ from user_jpo userjpo0_ where userjpo0_.id=?
2023-xxxx.026 DEBUG 64914 --- [           main] org.hibernate.SQL                        : insert into user_jpo (name, id) values (?, ?)
2023-xxxx.030 DEBUG 64914 --- [           main] org.hibernate.SQL                        : select userjpo0_.id as id1_0_0_, userjpo0_.name as name2_0_0_ from user_jpo userjpo0_ where userjpo0_.id=?

파라미터 표시

위에서 SQL은 표시가 되지만 어떤 데이터가 매핑되는지 정보는 나타나지 않는다.

매핑 파라미터 정보를 표시하려면 아래와 같이 설정하면 된다.

logging:
  level:
    org.hibernate.type: trace

그러면 아래와 같이 매핑 정보도 표시가 된다.

2023-xxxx.743 DEBUG 64983 --- [           main] org.hibernate.SQL                        : select userjpo0_.id as id1_0_0_, userjpo0_.name as name2_0_0_ from user_jpo userjpo0_ where userjpo0_.id=?
2023-xxxx.749 TRACE 64983 --- [           main] o.h.type.descriptor.sql.BasicBinder      : binding parameter [1] as [INTEGER] - [1]
2023-xxxx.767 DEBUG 64983 --- [           main] org.hibernate.SQL                        : insert into user_jpo (name, id) values (?, ?)
2023-xxxx.767 TRACE 64983 --- [           main] o.h.type.descriptor.sql.BasicBinder      : binding parameter [1] as [VARCHAR] - [홍길동]
2023-xxxx.767 TRACE 64983 --- [           main] o.h.type.descriptor.sql.BasicBinder      : binding parameter [2] as [INTEGER] - [1]
2023-xxxx.771 DEBUG 64983 --- [           main] org.hibernate.SQL                        : select userjpo0_.id as id1_0_0_, userjpo0_.name as name2_0_0_ from user_jpo userjpo0_ where userjpo0_.id=?
2023-xxxx.771 TRACE 64983 --- [           main] o.h.type.descriptor.sql.BasicBinder      : binding parameter [1] as [INTEGER] - [1]
2023-xxxx.773 TRACE 64983 --- [           main] o.h.type.descriptor.sql.BasicExtractor   : extracted value ([name2_0_0_] : [VARCHAR]) - [홍길동]

그런데 매핑된 정보를 확인하기가 쉽지가 않다.

그래서 SQL 로그를 좀 더 쉽게 확인할 수 있도록 나온 것이 P6Spy이다. (https://github.com/p6spy/p6spy)

P6Spy

P6Spy는 일반적으로 애플리케이션 서버에 설치하여 클래스패스에 jar를 두고 드라이버와 JDBC connection정보를 수정하기만 하면 사용이 가능하다.

또 다른 방법은 Spring Boot에 자동 구성을 추가함으로써 P6Spy를 적용하는 것이 가능하다.

p6spy-spring-boot-starter는 P6Spy와 데이터베이스 모니터링 라이브러리를 통합하는 repository이다. 이 라이브러리 덕분에 P6Spy는 jar를 추가하는 것만으로 충분하다.

<dependency>
    <groupId>com.github.gavlyukovskiy</groupId>
    <artifactId>p6spy-spring-boot-starter</artifactId>
    <version>1.9.0</version>
 </dependency>

그리고 spy.properties라는 파일을 resources 폴더에 추가하자.

appender=com.p6spy.engine.spy.appender.FileLogger
logfile=database.log
append=true
logMessageFormat=com.p6spy.engine.spy.appender.CustomLineFormat
customLogMessageFormat=%(currentTime)|%(executionTime)|%(category)|%(sqlSingleLine)

여기서는 database.log라는 파일에 로깅이 되도록 설정을 했다.

그러면 database.log에 아래와 같이 SQL 로그가 남는다.

1698014880394|0|statement|drop table if exists user_jpo CASCADE 
1698014880395|0|statement|create table user_jpo (id integer not null, name varchar(255), primary key (id))
1698014880941|4|statement|select userjpo0_.id as id1_0_0_, userjpo0_.name as name2_0_0_ from user_jpo userjpo0_ where userjpo0_.id=1
1698014880956|0|statement|insert into user_jpo (name, id) values ('홍길동', 1)
1698014880957|0|commit|
1698014880960|0|statement|select userjpo0_.id as id1_0_0_, userjpo0_.name as name2_0_0_ from user_jpo userjpo0_ where userjpo0_.id=1
1698014880963|0|commit|

다른 appender를 설정할 수도 있다.

# Slf4j appender
appender=com.p6spy.engine.spy.appender.Slf4JLogger
# Stdout appender
appender=com.p6spy.engine.spy.appender.StdoutLogger

하지만 SQL 포맷팅이 되지 않는 문제가 생긴다.

그래서 SQL 포맷팅을 위한 설정을 해주자.

SQL 포맷팅을 위한 formatter 클래스를 추가하고

public class P6spyPrettySqlFormatter implements MessageFormattingStrategy {

    @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) {
        String formattedSql = formatSql(category, sql);
        return formatLog(elapsed, category, formattedSql);
    }

    private String formatSql(String category, String sql) {
        if (hasText(sql) && isStatement(category)) {
            String trimmedSQL = trim(sql);
            if (isDdl(trimmedSQL)) {
                return FormatStyle.DDL.getFormatter().format(sql);
            }
            return FormatStyle.BASIC.getFormatter().format(sql); // maybe DML
        }
        return sql;
    }

    private static boolean isDdl(String trimmedSQL) {
        return trimmedSQL.startsWith("create") || trimmedSQL.startsWith("alter") || trimmedSQL.startsWith("comment");
    }

    private static String trim(String sql) {
        return sql.trim().toLowerCase(Locale.ROOT);
    }

    private static boolean isStatement(String category) {
        return Category.STATEMENT.getName().equals(category);
    }

    private String formatLog(long elapsed, String category, String formattedSql) {
        return String.format("[%s] | %d ms | %s", category, elapsed, formatSql(category, formattedSql));
    }
}

이를 @Configuration에 추가하자.

@Configuration
public class P6spyConfig {
    @PostConstruct
    public void setLogMessageFormat() {
        P6SpyOptions.getActiveInstance().setLogMessageFormat(P6spyPrettySqlFormatter.class.getName());
    }
}

그러면 아래와 같이 SQL 로그에 포맷팅되어 로그가 남는다.

2023-10-23 08:28:01.025  INFO 66756 --- [           main] p6spy                                    : [statement] | 4 ms | 
    select
        userjpo0_.id as id1_0_0_,
        userjpo0_.name as name2_0_0_      
    from
        user_jpo userjpo0_      
    where
        userjpo0_.id=1
2023-10-23 08:28:01.040  INFO 66756 --- [           main] p6spy                                    : [statement] | 0 ms | 
    insert      
    into
        user_jpo
        (name, id)      
    values
        ('홍길동', 1)
2023-10-23 08:28:01.041  INFO 66756 --- [           main] p6spy                                    : [commit] | 0 ms | 
2023-10-23 08:28:01.044  INFO 66756 --- [           main] p6spy                                    : [statement] | 0 ms | 
    select
        userjpo0_.id as id1_0_0_,
        userjpo0_.name as name2_0_0_      
    from
        user_jpo userjpo0_      
    where
        userjpo0_.id=1
2023-10-23 08:28:01.047  INFO 66756 --- [           main] p6spy                                    : [commit] | 0 ms |

다시 정리

  1. P6Spy의존성 추가
  2. spy.properties 추가
    • appender=com.p6spy.engine.spy.appender.Slf4JLogger로 설정
  3. Formatter 적용을 위한 P6spyPrettySqlFormatter를 @Configuration에 추가

이렇게 하면 sql 로깅을 위해 application.yml에 추가한 설정이 필요없게 된다.

참고

https://www.baeldung.com/java-p6spy-intercept-sql-logging

https://github.com/p6spy/p6spy

https://progress0407.tistory.com/146

반응형
저작자표시
  • 네이버 블로그 공유
  • 네이버 밴드 공유
  • 페이스북 공유
  • 카카오스토리 공유
spring 관련 글
글 더보기

티스토리툴바