[P6Spy] p6spy 콘솔에 찍고 로그 파일 저장하기

Spring + JPA 사용 시 JPA 구현체 중 하나인 Hibernate가 제공하는 꿀 기능이 있다

show_sql, format_sql 두 속성인데 sql을 정렬된 상태로 볼 수 있게 해 준다

여기에 logging 하위 속성이 제공하는 BasicBinder까지 사용하면 sql parameter에 무슨 값이 들어가는지 알 수 있다

단 이전 글에서도 언급했듯 기본 제공하는 것을 그대로 쓴다면 큰 단점이 있다

sql 쿼리가 점점 복잡해질수록 가독성이 좋지 못하고 조건이 늘어날수록 어떤 값이 어떤 변수에 붙는지 알기 힘들다

또한 ordinal로 보여주기 때문에 column=value 형식이 아닌 [0]=value 형식으로 보게 된다

[P6Spy] Log4j2, p6spy 적용해보기

 

이전 글에 있는 블로그를 참고하면 어렵지 않게 자신의 프로젝트에도 적용할 수 있을 것이다

초보 때는 콘솔에 찍히는 에러 로그로만 문제를 파악하고 몇 시간 매달려 해결하고 그냥 넘어가기 십상이다

문제 원인과 문제 파악 과정, 해결 과정을 잘 정리해놓지 않으면 비슷한 문제를 또 만나고 다시 한번 시간 날리게 된다

안타깝게도 내가 그랬다 이후로 같은 실수를 반복하지 않기 위해 빡센 문제를 만나면

개인 노션에 대략적인 문제 설명, 나타난 원인, 해결 방법, 참고 블로그 등을 적어놓는다

그렇기 때문에 로그는 운영 상에서만 필수적인 것이 아니라 개발할 때도 필수라 생각한다

 

 

그래서 진행 중인 개인 프로젝트에 AOP를 활용해 로그를 찍는 방식을 도입했는데

하나의 로그 파일에 때려 붓는 방식에서 조금 더 나아가 운영 / 에러 / 쿼리로 세분화하기로 결정했다

운영과 에러는 log4j2.xml 혹은 logback.xml 설정에서

로그 레벨만 바꿔주면 되는 거라 간단히 해결했는데 쿼리가 말썽이다

 

문제는 p6spy에서 로그를 찍어주는 역할을 하는 Appender 3개가 있는데 혼용이 되질 않는다

이것 참 웃기는 문제다

내부 구현을 까보니 appender 설정에 setAppender로 인자 하나만 받도록 되어 있는데

이 부분에서 컬렉션으로 받고 순회하면서 처리했음 되지 않았을까 싶다

소스 파악을 전부 한게 아니기에 뇌피셜이고 하나만 사용해야 하는 뭔가 다른 이유가 있겠지 싶다

다른 이유가 없으면 미친놈이다

com.p6spy.engine.spy.appender.Slf4JLogger	// log.error("blahblah")
com.p6spy.engine.spy.appender.StdoutLogger	// System.out.print("blah")
com.p6spy.engine.spy.appender.FileLogger	// error.log

 

사실 p6spy는 DataSource를 한번 감싸서 쿼리를 훔쳐오는 놈이기 때문에 사용하는 비용이 저렴하지 않다

애초에 개발 / 테스트 단계에서만 사용하라고 만든 거 같은데 그래도 열 받는 건 어쩔 수 없다

로그를 찍으면 파일에 저장이 안 되고, 파일에 저장하면 로그가 찍히지 않는 요상한 일을 한바탕 겪고

간단하게 그냥 내가 파일에 써주기로 결정했다 그래도 이왕 써주는 거 조금 똑똑하게 써줘 보자

 

SQL을 이쁘게 정렬하는 것은 커스텀 클래스인 P6spyPrettySqlFormatter에서 수행한다

따라서 이놈에서 정렬된 SQL을 가져다가 파일 열고 쓰고 닫아주면 끝이다

콘솔 로그, 파일 혼용도 안 되는 놈이 rolling policy 지원할 리 만무하니 파일 롤링도 직접 해주자

난 LocalDate를 사용해 년월일로 분리하기로 결정했다

private static final String QUERY_FILE_NAME = "logs/query/p6spy-%s.log";
private static final DateTimeFormatter FORMATTER = 
  DateTimeFormatter.ofPattern("yyyy-MM-dd HH:mm:ss.SSS");

private String sqlFormat(String sql, String category, String message) {
  if (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);
  }

  String finalSql = sql;
  CompletableFuture.runAsync(() -> {
    File file = new File(String.format(QUERY_FILE_NAME, LocalDate.now()));
    try (BufferedWriter bufferedWriter = new BufferedWriter(new FileWriter(file, true))) {
      bufferedWriter.write(LocalDateTime.now().format(FORMATTER));
      bufferedWriter.write(finalSql.toUpperCase() + "\n");
    } catch (IOException e) {
      log.error("[SUPPORT-ERROR] :: exception {}", e);
    }
  });

  return "\n" + sql.toUpperCase() + message;
}

 

로그 쓰는 과정에 동기적으로 저 놈이 로그를 다 쓸 때까지 blocking 될 필요 없으니

CompletableFuture를 이용한 비동기 방식으로 써주자

QUERY_FILE_NAME에 파일 이름 자유롭게 넣어주고 BufferedWriter 써서 쓰기 성능도 높이고

try-with-resources로 알아서 flush, close 되도록 하면 끝이다

 

sqlFormat 메서드의 인자 중 sql이 우리가 날릴 쿼리고 runAsync()로 비동기 작업 수행 전

값을 한번 복사해서 넣어야 한다고 인텔리제이가 알려주길래 그대로 따랐다

아마 이전 sql에 변경 작업이 수행되었고 앞으로도 변경 가능성이 있으니

비동기 작업 수행 전에 값을 한번 복사해서 작업 중 값이 변하지 않음을 확실히 해주고 수행해야 돼서 그런가 보다

더 엄격한 것을 좋아한다면 final String finalSql = sql; 로 받아주도록 하자, 나도 바꿔놔야겠다

 

여기서 좀 더 세분화한 설정이 필요하다면

1. 타임 아웃 걸어주고

2. CustomExecutorPool 만들어서 거기서 worker thread 땡겨와서 쓰고

3. 에러 처리를 로그만 찍는 게 아니라 커스텀 런타임 에러로 바꿔서 던져주거나 본인만의 에러 처리를 하면 된다

 

또한 p6spy가 개발 단계에서만 사용되도록 강제하려면 P6spyConfig 클래스에 

@Profile("develop")을 붙여서 해당하는 active-profile에서만 작동되도록 간단히 설정할 수 있다