shirohoo
795
2021-05-28 22:26:05 작성 2021-05-31 00:12:06 수정됨
6
997

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







안녕하세요.

주니어 서버개발자입니다.

JPA를 주로 사용하는데 간혹 N+1문제로 인해 대량의 쿼리가 발생합니다.

이때 가독성 문제로 쿼리 튜닝하기가 곤란한 경우가 생겨 이를 개선하기 위한 작업을 해봤습니다.


Mybatis를 쓰건 JPA를 쓰건 JdbcTemplate을 쓰건 혼용해서 쓰건 JDBC기반의 기술이라면

모든 쿼리포맷이 통합되어 출력되기 때문에 매우 유용하다고 생각됩니다.


이 글이 많은분들께 도움이 되길 바랍니다.


개인 블로그에 작성한 글을 그대로 가져왔으며,

주니어 개발자라 틀린 부분이 있을 수 있으니 가급적 비판적인 견해로 봐주세요.




🚫 주의!


  • 굉장히 비싼 자원을 사용하므로 운영 환경에선 절대 사용하지 말 것을 권장 드립니다.




✅ 개발 환경

모든 소스코드가 보고싶으시다면 GitHub🎁 를 참고해주세요.

  • Java 11
  • Gradle 7.0.2
  • Spring-Boot 2.5.0
  • Spring-Data-JPA
  • H2 Database
  • p6spy 1.7.1




✅ 필수 설정


//build.gradle
implementation 'com.github.gavlyukovskiy:p6spy-spring-boot-starter:1.7.1'


//application.yaml
decorator:
  datasource:
    p6spy:
      enable-logging: true


운영환경이라 이 기능을 사용하고 싶지 않다면, 운영환경 profile에 위의 enable-logging을 false로 지정해주면 된다.




JPA를 쓰다 보면 예상 밖의 쿼리가 발생하는 경우가 굉장히 많다.

스프링에는 쿼리를 파악하기 좋게 해주는 라이브러리로 p6spy가 있는데,

기본값으로 사용할 경우 단순히 파라미터 바인딩만 보여주는 수준으로 생각보다 가독성이 좋지 않다.


큰 문제점은 쿼리가 한번 발생하면 파라미터가 바인딩되지 않은 원본 쿼리와

파라미터를 바인딩한 후의 쿼리, 총 두 개의 쿼리가 나란히 출력되기 때문이다.


이처럼 간단한 쿼리의 경우는 그럭저럭 괜찮을 수 있으나,

통계성 쿼리 같이 복잡하고 수십 줄 이상되는 빅 쿼리가 두 개 연달아 나오면 굉장히 혼란스럽다.

심지어 두개의 쿼리 중 한개는 물음표가 가득 할 것이다.


이런 문제를 개선하기 위해 p6spy를 커스터마이징했다.




📕 p6spy는 대략 다음과 같은 과정을 거쳐 쿼리를 캡처한다.


1. DataSource를 래핑하여 프락시를 만든다.

2. 쿼리가 발생하여 JDBC가 ResultSet을 반환하면 이를 만들어둔 프락시로 가로챈다.

3. 내부적으로 ResultSet의 정보를 분석하고 p6spy의 옵션을 적용해준다.

4. Slf4j를 사용해 로깅한다.




처음 p6spy가 초기화 될 때 쿼리를 포매팅하는 객체를 지정하는데 Default 객체가 MultiLineFormat이다.

public class P6SpyProperties {
   
    private boolean enableLogging = true;
  
    private boolean multiline = true;
   
    private P6SpyLogging logging = P6SpyLogging.SLF4J;
   
    private String logFile = "spy.log";

    private String logFormat;
}


private boolean multiline = true이며

private String logFormat = null이다.


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");
            }
        }


위 조건으로 인해 CustomLogMessageFormat이 아닌 MultiLineFormat으로 타고 들어간다.

이후 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 +";";
  }
  
}



이러한 결과가 나타난다.


코드를 보면 알겠지만, 원하는 포맷으로 확장하기 위해서 포매터를 직접 구현하여 지정해주면 된다.


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


설정 클래스를 생성하여 새로운 LogFormatter를 지정해준 후 구현에 들어간다.


public class P6spyPrettySqlFormatter 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 null;
    }
    
}


MessageFormattingStrategy를 구현한다.

이름 그대로 메시지 포매팅 전략이다.

기본적으로 SingleLineFormatCustomLineFormatMultiLineFormat이 구현돼있으며

CustomLineFormat은 이름때문에 약간 헷갈리는데 사용자가 커스터마이징 할 포매터가 아니고,

SingleLineFormat을 약간 더 손본 포매터다. 그러므로 이녀석을 쓰면 안되고 직접 구현해야한다.

아래는 CustomLineFormat의 전체 코드이다. 참고바람.

public class CustomLineFormat implements MessageFormattingStrategy {

  private static final MessageFormattingStrategy FALLBACK_FORMATTING_STRATEGY = new SingleLineFormat();

  public static final String CONNECTION_ID = "%(connectionId)";
  public static final String CURRENT_TIME = "%(currentTime)";
  public static final String EXECUTION_TIME = "%(executionTime)";
  public static final String CATEGORY = "%(category)";
  public static final String EFFECTIVE_SQL = "%(effectiveSql)";
  public static final String EFFECTIVE_SQL_SINGLELINE = "%(effectiveSqlSingleLine)";
  public static final String SQL = "%(sql)";
  public static final String SQL_SINGLE_LINE = "%(sqlSingleLine)";
  public static final String URL = "%(url)";

  /**
   * 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) {

    String customLogMessageFormat = P6SpyOptions.getActiveInstance().getCustomLogMessageFormat();

    if (customLogMessageFormat == null) {
      // Someone forgot to configure customLogMessageFormat: fall back to built-in
      return FALLBACK_FORMATTING_STRATEGY.formatMessage(connectionId, now, elapsed, category, prepared, sql, url);
    }

    return customLogMessageFormat
      .replaceAll(Pattern.quote(CONNECTION_ID), Integer.toString(connectionId))
      .replaceAll(Pattern.quote(CURRENT_TIME), now)
      .replaceAll(Pattern.quote(EXECUTION_TIME), Long.toString(elapsed))
      .replaceAll(Pattern.quote(CATEGORY), category)
      .replaceAll(Pattern.quote(EFFECTIVE_SQL), Matcher.quoteReplacement(prepared))
      .replaceAll(Pattern.quote(EFFECTIVE_SQL_SINGLELINE), Matcher.quoteReplacement(P6Util.singleLine(prepared)))
      .replaceAll(Pattern.quote(SQL), Matcher.quoteReplacement(sql))
      .replaceAll(Pattern.quote(SQL_SINGLE_LINE), Matcher.quoteReplacement(P6Util.singleLine(sql)))
      .replaceAll(Pattern.quote(URL), url);
  }


쿼리가 정확히 어떤 경로를 타고 발생했는지 추적하여 기록해줄 것이다.


StackTraceElement[] stackTrace = new Throwable().getStackTrace();
    for(StackTraceElement stackTraceElement : stackTrace) {
        System.out.println(stackTraceElement);
    }


Throwable을 호출하여 stack trace를 쭉 뽑아보면


io.p6spy.formatter.P6spyPrettySqlFormatter.formatMessage(P6spyPrettySqlFormatter.java:15)
com.p6spy.engine.spy.appender.Slf4JLogger.logSQL(Slf4JLogger.java:50)
com.p6spy.engine.common.P6LogQuery.doLog(P6LogQuery.java:121)
com.p6spy.engine.common.P6LogQuery.doLogElapsed(P6LogQuery.java:91)
com.p6spy.engine.common.P6LogQuery.logElapsed(P6LogQuery.java:203)
com.p6spy.engine.logging.LoggingEventListener.logElapsed(LoggingEventListener.java:107)
com.p6spy.engine.logging.LoggingEventListener.onAfterCommit(LoggingEventListener.java:54)
com.p6spy.engine.event.CompoundJdbcEventListener.onAfterCommit(CompoundJdbcEventListener.java:285)
com.p6spy.engine.wrapper.ConnectionWrapper.commit(ConnectionWrapper.java:172)
org.hibernate.resource.jdbc.internal.AbstractLogicalConnectionImplementor.commit(AbstractLogicalConnectionImplementor.java:86)
org.hibernate.resource.transaction.backend.jdbc.internal.JdbcResourceLocalTransactionCoordinatorImpl$TransactionDriverControlImpl.commit(JdbcResourceLocalTransactionCoordinatorImpl.java:282)
org.hibernate.engine.transaction.internal.TransactionImpl.commit(TransactionImpl.java:101)
org.springframework.orm.jpa.JpaTransactionManager.doCommit(JpaTransactionManager.java:562)
org.springframework.transaction.support.AbstractPlatformTransactionManager.processCommit(AbstractPlatformTransactionManager.java:743)
org.springframework.transaction.support.AbstractPlatformTransactionManager.commit(AbstractPlatformTransactionManager.java:711)
org.springframework.transaction.interceptor.TransactionAspectSupport.commitTransactionAfterReturning(TransactionAspectSupport.java:654)
org.springframework.transaction.interceptor.TransactionAspectSupport.invokeWithinTransaction(TransactionAspectSupport.java:407)
org.springframework.transaction.interceptor.TransactionInterceptor.invoke(TransactionInterceptor.java:119)
org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:186)
org.springframework.dao.support.PersistenceExceptionTranslationInterceptor.invoke(PersistenceExceptionTranslationInterceptor.java:137)
org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:186)
org.springframework.data.jpa.repository.support.CrudMethodMetadataPostProcessor$CrudMethodMetadataPopulatingMethodInterceptor.invoke(CrudMethodMetadataPostProcessor.java:174)
org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:186)
org.springframework.aop.interceptor.ExposeInvocationInterceptor.invoke(ExposeInvocationInterceptor.java:97)
org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:186)
org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:215)
com.sun.proxy.$Proxy88.save(Unknown Source)
io.p6spy.controller.MainController.run(MainController.java:35)
java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
java.base/java.lang.reflect.Method.invoke(Method.java:566)
org.springframework.web.method.support.InvocableHandlerMethod.doInvoke(InvocableHandlerMethod.java:197)
org.springframework.web.method.support.InvocableHandlerMethod.invokeForRequest(InvocableHandlerMethod.java:141)
org.springframework.web.servlet.mvc.method.annotation.ServletInvocableHandlerMethod.invokeAndHandle(ServletInvocableHandlerMethod.java:106)
org.springframework.web.servlet.mvc.method.annotation.RequestMappingHandlerAdapter.invokeHandlerMethod(RequestMappingHandlerAdapter.java:894)
org.springframework.web.servlet.mvc.method.annotation.RequestMappingHandlerAdapter.handleInternal(RequestMappingHandlerAdapter.java:808)
org.springframework.web.servlet.mvc.method.AbstractHandlerMethodAdapter.handle(AbstractHandlerMethodAdapter.java:87)
org.springframework.web.servlet.DispatcherServlet.doDispatch(DispatcherServlet.java:1063)
org.springframework.web.servlet.DispatcherServlet.doService(DispatcherServlet.java:963)
org.springframework.web.servlet.FrameworkServlet.processRequest(FrameworkServlet.java:1006)
org.springframework.web.servlet.FrameworkServlet.doPost(FrameworkServlet.java:909)
javax.servlet.http.HttpServlet.service(HttpServlet.java:652)
org.springframework.web.servlet.FrameworkServlet.service(FrameworkServlet.java:883)
javax.servlet.http.HttpServlet.service(HttpServlet.java:733)
org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:227)
org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:162)
org.apache.tomcat.websocket.server.WsFilter.doFilter(WsFilter.java:53)
org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:189)
org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:162)
org.springframework.web.filter.RequestContextFilter.doFilterInternal(RequestContextFilter.java:100)
org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:119)
org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:189)
org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:162)
org.springframework.web.filter.FormContentFilter.doFilterInternal(FormContentFilter.java:93)
org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:119)
org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:189)
org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:162)
org.springframework.web.filter.CharacterEncodingFilter.doFilterInternal(CharacterEncodingFilter.java:201)
org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:119)
org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:189)
org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:162)
org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:202)
org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:97)
org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:542)
org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:143)
org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:92)
org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:78)
org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:357)
org.apache.coyote.http11.Http11Processor.service(Http11Processor.java:374)
org.apache.coyote.AbstractProcessorLight.process(AbstractProcessorLight.java:65)
org.apache.coyote.AbstractProtocol$ConnectionHandler.process(AbstractProtocol.java:893)
org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1707)
org.apache.tomcat.util.net.SocketProcessorBase.run(SocketProcessorBase.java:49)
java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128)
java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)
java.base/java.lang.Thread.run(Thread.java:834)
2021-05-28 21:31:46.316  INFO 2820 --- [nio-8080-exec-2] p6spy                                    : 


Throwable이 호출된 시점까지의 모든 경로가 출력된다.

여기서 필요한 부분만 추출하면 되는데, 원하는 trace에서 공통점을 찾을 수 있다.

바로 문자열의 시작점이 main 패키지의 경로라는 것이다.

따라서 아래와 같이 코드를 작성해준다면...


for(StackTraceElement stackTraceElement : stackTrace) {
        if(stackTraceElement.toString().startsWith("io.p6spy")) {
            System.out.println(stackTraceElement);
        }
    }



이러한 로그를 얻을 수 있다.

이 로그를 보고 알 수 있는 것은

MainController의 run 메서드가 호출됐고 이후 call_1~call_3 메서드가 연쇄 호출되며 쿼리가 발생했다는 것이다.


MainControlelr의 코드를 보자.


@Controller
@RequiredArgsConstructor
public class MainController {
    
    private final StudentRepository studentRepository;
    private final SchoolRepository schoolRepository;
    
    @GetMapping("/")
    public String index() {
        return "index";
    }
    
    @ResponseBody
    @PostMapping("/matriculation")
    public void run(MatriculationRequest matriculationRequest) {
        Student student = matriculationRequest.getStudent();
        School school = schoolRepository.findByName(matriculationRequest.getSchoolName());
        if(school == null) {
            school = schoolRepository.save(createSchool());
        }
        school.matriculation(student);
        call_1(student);
    }
    
    private School createSchool() {
        return School.builder()
                     .name("용산초")
                     .build();
    }
    
    private void call_1(Student student) {
        call_2(student);
    }
    
    private void call_2(Student student) {
        call_3(student);
    }
    
    private void call_3(Student student) {
        studentRepository.save(student);
    }
    
}



StackTraceElement[] stackTrace = new Throwable().getStackTrace();
    for(StackTraceElement stackTraceElement : stackTrace) {
            if(stackTraceElement.toString().startsWith("io.p6spy") && !stackTraceElement.toString().contains("P6spyPrettySqlFormatter")) {
                System.out.println(stackTraceElement);
            }
        }


여기서 P6spyPrettySqlFormatter의 trace는 필요 없기 때문에 필터링 해 준다.



원하는 결과만 나온다.


이제 이 로그를 더 보기 편하게 역순으로 뒤집어줄 것이다.

Stack을 활용할 것인데, 추출되는 trace를 순서대로 Stack에 push 하고, 다시 pop 하면 역순으로 뒤집힐 것이다.


@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) {
    Stack<String> callStack = new Stack<>();
    StackTraceElement[] stackTrace = new Throwable().getStackTrace();
    for(StackTraceElement stackTraceElement : stackTrace) {
        String trace = stackTraceElement.toString();
        if(trace.startsWith("io.p6spy") && !trace.contains("P6spyPrettySqlFormatter")) {
            callStack.push(trace);
        }
    }
    
    StringBuilder callStackBuilder = new StringBuilder();
    int order = 1;
    while(callStack.size() != 0) {
        callStackBuilder.append("\n\t\t" + (order++) + ". " + callStack.pop());
    }
    return null;
}



쿼리가 발생한 지점과 클릭하면 즉시 이동할 수 있는 포탈(🤗)이 생성됐다.

이제 SQL을 보기 좋게 포매팅 할 것이다.

formatMessage 메서드에 이런저런 파라미터가 많이 들어오는데

이에 대한 자세한 내용은 p6spy docs를 보면 하기와 같다. 


Params:
connectionId – the id of the connection
now – the current ime expressing in milliseconds
elapsed – the time in milliseconds that the operation took to complete
category – the category of the operation
prepared – the SQL statement with all bind variables replaced with actual values
sql – the sql statement executed
url – the database url where the sql statement executed


이 파라미터들을 적당히 버무려 준다.


public class P6spyPrettySqlFormatter 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) {
        Stack<String> callStack = new Stack<>();
        StackTraceElement[] stackTrace = new Throwable().getStackTrace();

        for(int i = 0; stackTrace.length; i++) {
String trace = stackTrace.toString();
if(trace.startsWith("io.p6spy") && !trace.contains("P6spyPrettySqlFormatter")) { callStack.push(trace); } } StringBuilder callStackBuilder = new StringBuilder(); int order = 1; while(callStack.size() != 0) { callStackBuilder.append("\n\t\t" + (order++) + ". " + callStack.pop()); } String message = new StringBuilder().append("\n\n\tConnection ID: ").append(connectionId) .append("\n\tExecution Time: ").append(elapsed).append(" ms\n") .append("\n\tCall Stack (number 1 is entry point): ").append(callStackBuilder).append("\n") .append("\n----------------------------------------------------------------------------------------------------") .toString(); return sqlFormat(sql, category, message); } private String sqlFormat(String sql, String category, String message) { if(sql.trim() == null || sql.trim().isEmpty()) { return ""; } if(Category.STATEMENT.getName().equals(category)) { String s = sql.trim().toLowerCase(Locale.ROOT); if(s.startsWith("create") || s.startsWith("alter") || s.startsWith("comment")) { sql = FormatStyle.DDL .getFormatter() .format(sql); } else { sql = FormatStyle.BASIC .getFormatter() .format(sql); } } return new StringBuilder().append("\n") .append(sql.toUpperCase()) .append(message) .toString(); } }




1
  • 댓글 6

  • 공부는 습관
    724
    2021-05-29 09:45:52
    좋은 글 감사합니다.
  • 제타건담
    7k
    2021-05-31 16:18:58

    내용에 대한걸 깊게 읽기 전에 궁금한게 있어서 먼저 질문을 드려봅니다..

    일단 쓰신 글을 읽어보니 java에서 SQL 처리할때 SQL문을 보여주는 로그 기능을 하는걸로 이해했는데요..

    근데 사실 이 기능으로 가장 널리 쓰이는게 log4jdbc 가 있는데..

    이걸 쓰는 이유..에 대한 언급이 없으셔서 질문을 드리게 됐습니다..

    구글에서 검색해보니 2013년도 업데이트 이후로는 전혀 업데이트 된 것이 없어서 이걸 쓴다는 글도 보긴 했습니다만..

    그 이유로도 좀 설득이 와닿지는 않더라구요..

    누군가는 너무 오래전 라이브러리라 보안에 문제가 있을 가능성이 있다..라고 말하실수도 있겠습니다만..

    그래서 이걸 쓰시는 이유를 여쭤봐도 될까요..?

    단순히 선택의 문제인건지..아니면 log4jdbc의 단점이 있어서 이걸 쓰시는건지..그걸 알고 싶어서 글을 남겨봅니다..

  • shirohoo
    795
    2021-05-31 16:31:55 작성 2021-05-31 16:58:58 수정됨

    제타건담

    죄송하지만 제가 개발공부 한 기간이 일년이 채 되지 않아서 말씀하시는 바를 정확히 잘 모르겠습니다.


    이렇게 쓰는 이유라고 한다면 spring-boot은 로깅인터페이스로 slf4j를 두고 logback을 기본 구현체로 쓰고있습니다.

    근데 이 상태로 쿼리를 로깅하면 쿼리 가독성이 엄청 안좋게 나옵니다.


    insert into student (student_id, age, name, school_id) values (null, ?, ?, ?)


    대략 이런식인데 파라미터가 제대로 바인딩됐는지도 안보입니다.

    그래서 쿼리를 쌔벼서(?) 좀더 보기좋게 해주는 라이브러리로 p6spy가 있는데 이녀석을 쓰면 이렇게 나옵니다.


    insert into student (student_id, age, name, school_id) values (null, ?, ?, ?)
    insert into student (student_id, age, name, school_id) values (null, 11, '용용이', 1)

    아무런 가공을 거치지 않은 원본쿼리와, 파라미터가 바인딩 된 쿼리로 두개를 보여줍니다.

    실제 발생한 쿼리는 한번이고요.

    어떤 로직에서 발생한 쿼리인지도 직접 찾아야 합니다.

    이런 상황에 JPA를 사용하다보니 N+1문제가 간혹 생겨서 쿼리가 의도치않게 대량으로 나가는 경우가 있고, 이럴 경우 소위 말하는 노가다를 해야되더라구요.


    그래서 쿼리에 파라미터가 어떻게 바인딩됐고 어떤 경로를 타고 발생했고,

    몇번의 쿼리가 발생했는지, 얼마의 시간이 걸렸는지를 한눈에 파악할 수 있으면 좋겠다 싶어서 했습니다.


    단순히 개발환경에서 좀 더 도움을 주는정도의 효과를 바랬습니다.

  • 제타건담
    7k
    2021-06-01 03:49:48 작성 2021-06-01 03:50:48 수정됨

    아..제 얘기는 단순한 질문입니다..

    원래 SQL 로그 보는 기능으로 자주 사용하는 라이브러리가 기존에 log4jdbc-log4j2 라는게 있어요..

    그것도 마찬가지로 SQL문을 보여주고 파라미터 값까지 넣어주는데다가 보기 좋게까지 해주는 기능이 있거든요..

    그리고 이것또한 Spring과 Spring Boot에서 사용가능합니다..

    JPA에서도 가능한것이 원래 이 쿼리 보여주는 기능은 Java Connection 객체를 통해 호출되는 SQL문을 가져오는 것이기 때문에 JPA나 Mybatis나 Java Connection을 이용하는 것에는 변함이 없거든요..

    만약 p6spy가 JPQL을 출력해준다면 그건 얘기가 달라지기는 하겠지만 올리신 글에서는 그런 내용은 보이지는 않더라구요..


    근데 log4jdbc-log4j2를 안쓰시고 p6spy 라는 라이브러리를 사용하시길래..

    log4jdbc-log4j2보다 p6spy가 어떤 점에서 좋은 것이 있는지..혹시 아시면 답을 부탁드리려 질문을 한겁니다..

    p6spy가 log4jdbc-log4j2보다 성능적인 차원에서 나은 부분이 있어서 이걸 하신건지..

    아니면 그냥 단순한 취향으로서의 라이브러리 선택차원에서 하신건지..


    log4jdbc-log4j2와 관련해서는 여기를 클릭하시면 아실수 있으실겁니다..

    말씀하신 p6spy와 같은 기능을 해요..

    링크된 글에서는 신나고..란 값을 입력받아서 파라미터 값으로 활용했을꺼라 생각합니다..

    설마 하드코딩으로 신나고..를 했을리는 없겠죠..쿼리 구조를 보면 문자열 연결 연산자를 사용했기 때문에 그 부분은 파라미터 처리를 했을꺼라 생각합니다..

  • shirohoo
    795
    2021-06-01 09:25:48 작성 2021-06-01 12:48:19 수정됨

    제타건담 

    아 이해했습니다.

    딱히 이유가 있어서 사용한건 아니었습니다.

    단지 스프링부트를 배우면서 자연스럽게 접한게 p6spy-spring-boot-starter였기 때문인 듯 합니다.


    관련 문서들을 훑어보면서 아래와 같은 점을 파악했습니다

    1. 2013년 이후로 업데이트가 없는듯 합니다

    2. logback으로 대체된것으로 판단됩니다

    3. 설정이 좀 번거로운 느낌이 있어보입니다.

    4. 단순 쿼리를 기록하기 위해 slf4j xml에 의존성이 들어가는게 걸립니다.


    log4jdbc-log4j2를 제가 써본적이 없어서 어떤 장점들이 있는지는 솔직히 말씀드려서 모르겠습니다.

    jpql을 직접 출력해준다는게 어떤 의미인지는 잘 모르겠습니다만 p6spy를 쓰는 이유라고 한다면 몇가지 꼽아볼 수 있을 것 같습니다.

    1.확장성이 좋다

     - 저는 현재 slf4j 구현체로 logback을 이용하고 있습니다. logback은 kafka와 연동돼있고 logback은 순수하게 모든 데이터 스트림을 기록하는데만 이용되고 있습니다. p6spy와 logback은 별도의 영역에서 동작하고 있고, p6spy는 개발환경에서 쿼리의 기록에만 집중적으로 이용되고 있습니다. (제 개발환경 이야기입니다). 

    운영과 개발환경을 명확하게 구분지어가며 쉽게 전환하여 이용하고 있습니다.


     - 본문 글의 포매터는 하이버네이트의 포매터를 사용하여 확장했습니다.. 


    Hibernate: 
        insert 
        into
            TABLE
            (COLUMN_1, COLUMN_2) 
        values
            (?, ?)



    2.설정이 간편하다


    //application.yaml
    decorator:
      datasource:
        p6spy:
          enable-logging: true


     - 본문 글 위 설정도 사실 기본값으로 설정돼있는 것이라 생략해도 되는 것인데, 스프링 프로파일을 이용해 운영과 개발환영을 나누기 위해 명시적으로 선언해둔 것일 뿐입니다.

    p6spy를 사용하기 위해 해야 할 작업은 사실상 build.gradle이나 pom.xml에 의존성을 설정하는것 하나가 끝입니다.


    속도의 차이 같은것은 따로 벤치마킹을 해봐야 정확하게 알 것 같습니다.

    한번 살펴봐야 겠습니다. 좋은 의문이 생기게 해주셔서 감사합니다.





  • 제타건담
    7k
    2021-06-02 17:35:25

    비동기 작업이 없으시면 상관은 없는데요..

    만약 비동기 작업이 있게 되면 log4j2가 더 나은 선택이 될 수 있습니다..

    여기를 보시면 log4j, logback, log4j2에 대한 간력한 설명이 있습니다..

    영문이긴 합니다만..여기를 가시면 apache log4j2 홈피에 언급된 내용도 있습니다..관심 있으시면 한번 보세요..

    log4j, logback, log4j2 모두 log 라이브러리이고 이걸 이용해서 SQL을 출력하는 의미로다가 log4jdbc-log4j2 라 한거거든요..

    즉 사용되는 log 라이브러리는 log4j2 입니다..

    그리고 설정 역시 application.properties 파일에서 로그레벨 설정하는 것을 그대로 사용할 수 있습니다..
    (별도 파일이 필요 없어요)

    남은 하나 걸리는건 2013년 이후로의 업데이트가 없다는거..이게 걸리긴 걸리죠..ㅎㅎ..

    왜냐면 보안과 관련된 문제가 생길 가능성이 있어서..

    저로서는 같은 기능을 하는 새로운 라이브러리를 알게 되어서 좋네요..

  • 로그인을 하시면 댓글을 등록할 수 있습니다.