[JPA] 쿼리 로깅에 p6spy multi line 적용하기

JPA 쓰다보면 로깅이 알아보기 힘들게 나오는데 몇가지 설정으로 보기 편하게 할 수 있다.

 

우선 p6spy를 사용하는 것인데, 좋은점은 바인딩 위치에 값을 삽입해준다는 점이다

그래서 쿼리가 다음처럼 나온다.

 

p6spy 사용 전

(hibernate.show_sql 옵션 사용)

select
        subcategor0_.up_category_id as up_cate12_2_1_,
        subcategor0_.id as id1_2_1_,
        subcategor0_.id as id1_2_0_,
        subcategor0_.mod_dt as mod_dt2_2_0_,
        subcategor0_.reg_dt as reg_dt3_2_0_,
        subcategor0_.mod_member as mod_memb4_2_0_,
        subcategor0_.reg_member as reg_memb5_2_0_,
        subcategor0_.mate_show_yn as mate_sho6_2_0_,
        subcategor0_.name as name7_2_0_,
        subcategor0_.ord as ord8_2_0_
    from
        category subcategor0_ 
    where
        subcategor0_.up_category_id in (
            ?, ?, ?, ?, ?
        )

 

 

p6spy 사용 후

gradle에 다음 추가

 

// jpa query logging 
implementation 'com.github.gavlyukovskiy:p6spy-spring-boot-starter:1.7.1'

사용결과 로그

select subcategor0_.up_category_id as up_cate12_2_1_, subcategor0_.id as id1_2_1_, subcategor0_.id as id1_2_0_, subcategor0_.mod_dt as mod_dt2_2_0_, subcategor0_.reg_dt as reg_dt3_2_0_, subcategor0_.mod_member as mod_memb4_2_0_, subcategor0_.reg_member as reg_memb5_2_0_, subcategor0_.mate_show_yn as mate_sho6_2_0_, subcategor0_.name as name7_2_0_, subcategor0_.ord as ord8_2_0_ 
from category subcategor0_ 
where subcategor0_.up_category_id in (1, 12);

 

문제는 이게 1줄로 나온다는 점이다(위의 from 과 where 의 줄바꿈은 내가 보기편하게 하기위해 임의로 수정한 것이다.

 

그래서 살펴보니 view를 커스텀할 수 있는 있다는걸 알았다.(multi line 설정 가능)

문제는 별도구현을 해야한다는 것 정도...

 

일단 p6spy를 살펴보자.

p6spy 은 다음의 설정을 참고한다.

package com.github.gavlyukovskiy.boot.jdbc.decorator.p6spy;

@Getter
@Setter
public class P6SpyProperties {

    /**
     * Enables logging JDBC events.
     *
     * @see P6LogFactory
     */
    private boolean enableLogging = true;
    /**
     * Enables multiline output.
     */
    private boolean multiline = true;
    /**
     * Logging to use for logging queries.
     */
    private P6SpyLogging logging = P6SpyLogging.SLF4J;
    /**
     * Name of log file to use (only for logging=file).
     */
    private String logFile = "spy.log";
    /**
     * Custom log format.
     */
    private String logFormat;

    public enum P6SpyLogging {
        SYSOUT,
        SLF4J,
        FILE
    }
}

 

이 설정파일을 기본으로 P6SpyConfiguration.java 를 읽는데 init() 메서드를 통해 위 설정파일을 읽는다.

@ConditionalOnClass(P6DataSource.class)
public class P6SpyConfiguration {
...
    @PostConstruct
    public void init() {
        P6SpyProperties p6spy = dataSourceDecoratorProperties.getP6spy();
...

 

아래 파일을 실행하면서 P6SpyProperties 를 호출한다.

@Getter
@Setter
@ConfigurationProperties(prefix = "decorator.datasource")
public class DataSourceDecoratorProperties {
...
    @NestedConfigurationProperty
    private P6SpyProperties p6spy = new P6SpyProperties();

 

P6SpyConfiguration.java 파일을 보면 중간에 다음과 같은 설정이 있다

...
        if (!initialP6SpyOptions.containsKey("logMessageFormat")) {
            if (p6spy.getLogFormat() != null) {
                System.setProperty("p6spy.config.logMessageFormat", "com.p6spy.engine.spy.appender.CustomLineFormat");
                System.setProperty("p6spy.config.customLogMessageFormat", p6spy.getLogFormat());
            }
            else if (p6spy.isMultiline()) {
                System.setProperty("p6spy.config.logMessageFormat", "com.p6spy.engine.spy.appender.MultiLineFormat");
            }
        }
...

 

기본 설정이 multiline 이므로 해당설정을 실행하게 될 것인데, 왜 멀티라인으로 보여지지 않을까? 그 이유는 저 클래스에 있다.

 

com.p6spy.engine.spy.appender.MultiLineFormat 이 위치를 따라가 파일을 열어보면 아래와 같은 파일이 있는데,해당파일만 보면 별다른 Line 구분 처리를 하고있지 않다

/**
 * P6Spy
 *
 * Copyright (C) 2002 - 2019 P6Spy
 *
 * Licensed under the Apache License, Version 2.0 (the "License");
 * you may not use this file except in compliance with the License.
 * You may obtain a copy of the License at
 *
 *      http://www.apache.org/licenses/LICENSE-2.0
 *
 * Unless required by applicable law or agreed to in writing, software
 * distributed under the License is distributed on an "AS IS" BASIS,
 * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
 * See the License for the specific language governing permissions and
 * limitations under the License.
 */
package com.p6spy.engine.spy.appender;

/**
 * @author Quinton McCombs 
 * @since 09/2013
 */
public class MultiLineFormat implements MessageFormattingStrategy {

  /**
   * Formats a log message for the logging module
   *
   * @param connectionId the id of the connection
   * @param now          the current ime expressing in milliseconds
   * @param elapsed      the time in milliseconds that the operation took to complete
   * @param category     the category of the operation
   * @param prepared     the SQL statement with all bind variables replaced with actual values
   * @param sql          the sql statement executed
   * @param url          the database url where the sql statement executed
   * @return the formatted log message
   */
  @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 +";";
  }
}

 

 

때문에 이 내용을 실 구현체로 생성, 변경하면 된다

MessageFormattingStrategy 를 상속하여 다음과같이 구현한다

public class CustomP6spySqlFormat implements MessageFormattingStrategy {
    @Override
    public String formatMessage(int connectionId, String now, long elapsed, String category, String prepared, String sql, String url) {
        sql = formatSql(category, sql);
        return now + "|" + elapsed + "ms|" + category + "|connection " + connectionId + "|" + sql;
    }

    private String formatSql(String category,String sql) {
        if(sql ==null || sql.trim().equals("")) return sql;

        // Only format Statement, distinguish DDL And DML
        if (Category.STATEMENT.getName().equals(category)) {
            String tmpsql = sql.trim().toLowerCase(Locale.ROOT);
            if(tmpsql.startsWith("create") || tmpsql.startsWith("alter") || tmpsql.startsWith("comment")) {
                sql = FormatStyle.DDL.getFormatter().format(sql);
            }else {
                sql = FormatStyle.BASIC.getFormatter().format(sql);
            }
        }

        return sql;
    }
}

 

Override 한 메서드의 파라미터중에 prepared 의 경우 바인딩 되기 전 쿼리정보가 있다(제외해도 무방하여 여기서는 제외했다)

예를들어 다음과 같은 것이다

select subcategor0_.up_category_id as up_cate12_2_1_, subcategor0_.id as id1_2_1_, subcategor0_.id as id1_2_0_, subcategor0_.mod_dt as mod_dt2_2_0_, subcategor0_.reg_dt as reg_dt3_2_0_, subcategor0_.mod_member as mod_memb4_2_0_, subcategor0_.reg_member as reg_memb5_2_0_, subcategor0_.mate_show_yn as mate_sho6_2_0_, subcategor0_.name as name7_2_0_, subcategor0_.ord as ord8_2_0_
from category subcategor0_ 
where subcategor0_.up_category_id in (?, ?)

 

SQL안에 있는게 바인딩 적용된 쿼리이고, 해당 쿼리를 formatSql 메서드를 통해 재구성하여 리턴한 것이다.

 

위에 생성한 파일을 스프링 프로젝트가 실행될때 등록할 수 있도록 한다

/**
 * query multi line custom configure
 */
@Configuration
public class P6spyLogMessageFormatConfiguration {
    @PostConstruct
    public void setLogMessageFormat() {
        P6SpyOptions.getActiveInstance().setLogMessageFormat(CustomP6spySqlFormat.class.getName());
    }
}

 

이제 실행하면 다음과 같이 포멧팅되어 나온다

2021-11-04 08:39:33.818  INFO 2755 --- [io-10040-exec-2] p6spy                                    : 1635982773817|3ms|statement|connection 7|
    select
        subcategor0_.up_category_id as up_cate12_2_1_,
        subcategor0_.id as id1_2_1_,
        subcategor0_.id as id1_2_0_,
        subcategor0_.mod_dt as mod_dt2_2_0_,
        subcategor0_.reg_dt as reg_dt3_2_0_,
        subcategor0_.mod_member as mod_memb4_2_0_,
        subcategor0_.reg_member as reg_memb5_2_0_,
        subcategor0_.mate_show_yn as mate_sho6_2_0_,
        subcategor0_.name as name7_2_0_,
        subcategor0_.ord as ord8_2_0_
    from
        category subcategor0_ 
    where
        subcategor0_.up_category_id in (
            2, 6, 7, 8, 13
        )

 

 

 

추가1)

JPA를 사용하다보면 어디에서 호출한 것인지 알기 힘든데 인터넷에 좋은 사례가 있어 공유

- 호출한 Stack을 콘솔에 노출

public class CustomP6spySqlFormat implements MessageFormattingStrategy {
    // 표기에 허용되지 않는 filter
    private List<String> DENIED_FILTER = Arrays.asList("Test1"
            , this.getClass().getSimpleName());
    // 표기에 허용되는 filter
    private String ALLOW_FILTER = "com.test";

    @Override
    public String formatMessage(int connectionId, String now, long elapsed, String category, String prepared, String sql, String url) {
        sql = formatSql(category, sql);
        if(sql.trim().isEmpty()) { // sql 이 없다면 출력하지 않아도 됨
            return "";
        }
        // stack 을 구성하는 Format을 만든다
        return sql + createStack(connectionId, elapsed);
    }

...
    // stack 콘솔 표기
    private String createStack(int connectionId, long elapsed) {
        Stack<String> callStack = new Stack<>();
        StackTraceElement[] stackTrace = new Throwable().getStackTrace();

        for (StackTraceElement stackTraceElement : stackTrace) {
            String trace = stackTraceElement.toString();

            // trace 항목을 보고 내게 맞는 것만 필터
            if(trace.startsWith(ALLOW_FILTER) && !filterDenied(trace)) {
                callStack.push(trace);
            }
        }

        StringBuffer sb = new StringBuffer();
        int order = 1;
        while (callStack.size() != 0) {
            sb.append("\n\t\t" + (order++) + "." + callStack.pop());
        }

        return new StringBuffer().append("\n\n\tConnection ID:").append(connectionId)
                .append(" | Excution Time:").append(elapsed).append(" ms\n")
                .append("\n\tExcution Time:").append(elapsed).append(" ms\n")
                .append("\n\tCall Stack :").append(sb).append("\n")
                .append("\n--------------------------------------")
                .toString();
    }

 

콘솔 결과

Trace 에 있는 경우 클릭하면 해당 파일로 이동도 된다.

2021-11-04 10:16:50.793  INFO 9137 --- [io-10040-exec-2] p6spy                                    : 
     select
        subcategor0_.up_category_id as up_cate12_2_1_,
        subcategor0_.id as id1_2_1_,
        subcategor0_.id as id1_2_0_,
        subcategor0_.mod_dt as mod_dt2_2_0_,
        subcategor0_.reg_dt as reg_dt3_2_0_,
        subcategor0_.mod_member as mod_memb4_2_0_,
        subcategor0_.reg_member as reg_memb5_2_0_,
        subcategor0_.mate_show_yn as mate_sho6_2_0_,
        subcategor0_.name as name7_2_0_,
        subcategor0_.ord as ord8_2_0_
    from
        category subcategor0_ 
    where
        subcategor0_.up_category_id in (
            1, 12
        )|

	Connection ID:7
	Excution Time:4 ms

	Call Stack :
		1. com.test.web.lecture.LectureController.getLectureCategory(LectureController.java:30)
		2. com.test.infrastructure.fo.lecture.LectureReaderImpl$$EnhancerBySpringCGLIB$$2984ac1a.getAllLectureInCategory(<generated>)

 

 

 

끝

 

참조:

https://jessyt.tistory.com/27#recentEntries

Spring Data JPA, Querydsl 로깅처리. p6spy pretty하게 설정하기

https://hch4102.tistory.com/147

쿼리 튜닝을 편하게! p6spy 개조하기

https://www.sentinelone.com/blog/java-stack-trace-understanding/

Java Stack Trace: Understanding It and Using It to Debug | Scalyr