[Spring] 신규 프로젝트를 위해 사용 해봄직한 Hibernate Logging 옵션 정리

현재 지인 3분과 함께 진행하고 있는 스프링 프로젝트가 있다. 

GitHub - Tiketeer/Tiketeer-BE

프로젝트 초창기 세팅 시 하이버네이트 로그 옵션을 아래처럼 간단하게만 줬었는데, 프로젝트를 진행 함에 있어 디버깅 목적으로 DB 측 로그를 까뒤집을 때 나나 팀원들의 로그 정보에 대한 만족도가 그리 높지 않았다. (정작 필요한 로그가 없다, 로그들이 눈에 안들어온다, 로그들이 너무 많이 찍힌다... 등)

# 기존 application.yml

spring.jpa.show-sql: true

spring.jpa.properties.hibernate.format_sql: true

logging.level.org.hibernate: debug
logging.level.org.hibernate.type.descriptor.sql.BasicBinder: trace

그래서 이를 해소하기 위해 로깅 옵션들을 좀 정리해야겠다고 생각했고, 이를 위해 하이버네이트 로깅 옵션을 리서치한 부분들과 최종적으로 적용한 옵션들을 기록, 공유하기 위해 이 글을 작성하였다.

(적용한 로깅 옵션만 확인하고 싶은 경우, 글의 최하단으로 건너 뛸 것)

로깅 옵션

1. show-sql: true

기존에 사용하던 옵션이다. 

이 옵션을 이용하면 스프링 프로젝트 내에서 Jpa를 통해 DB로 실행될 쿼리들을 아래처럼 로그로 확인할 수 있다.

spring.jpa.show-sql: true 의 결과

개발, 테스트 환경에서 사용해봄직한 옵션으로 JPA가 추상화하는 DB 측 쿼리를 직접적으로 확인할 수 있어 디버깅 시 유용하다.

하지만 실제로 이를 사용하는 것은 권장되지 않는데, 그 이유는 해당 옵션이 프로젝트의 로깅 옵션을 무시한 채 곧바로 표준 출력(Standard Output)을 통해 로그를 출력하기 때문이다.

로그가 곧바로 표준 출력을 통해 출력될 경우 발생할 수 있는 문제는 아래와 같다.

• 출력할 로그를 애플리케이션 실행 컨텍스트에 따라 동적으로 선택하는 것이 힘들다. (로그 레벨)
• 로깅이라는 횡단 관심사에서 발생하는 다양한 요구사항들(ex. 파일 쓰기 정책)을 하나의 구현체(프레임워크)를 통해 제어할 수 없다.

따라서 해당 옵션을 사용하는 것보다 아래 옵션을 사용하는 것이 권장된다.

logging.level.org.hibernate.SQL: {log_level}

공식 문서에 따르면 이들의 동작 방식은 동일하다고 나와있다. 다른 점은, 위 옵션을 사용할 경우 애플리케이션에서 설정한 로거를 이용하여 로그를 출력하게 된다.

단순 쿼리만 출력됐던 것과 달리, 기본 로거의 컨텍스트를 통해 출력되는 모습

 

2. properties.hibernate.format_sql: true

기존에 사용하던 옵션이다.

해당 옵션을 사용할 경우, show-sql를(혹은 이를 대체하는 org.hibernate.SQL 옵션) 통해 출력되는 쿼리들이 보기 좋게 줄바꿈 되어 출력된다.

위에서 보여준 스크린샷들은 사실 이미 이 옵션이 적용된 상태이다. (적용하지 않을 경우 쿼리들이 한줄로 출력된다.)

 

3. properties.hibernate.highlight_sql: true

새롭게 알게 된 옵션이다.

이를 사용할 경우, 출력되는 SQL 쿼리 내 키워드(SELECT, FROM 등)들이 하이라이트(색칠) 표시와 함께 출력된다.

사용했을 때 예시는 아래와 같다.

SQL 내 예약어들에 하이라이트 표시가 된 모습

다만 이 옵션은 IDEA, 콘솔 환경에서는 잘 동작하나, 만약 테스트 결과를 HTML 형태의 리포트로 보게 되면 이 때는 아래처럼 출력되어 되려 가독성이 나빠지는 단점이 있는 것으로 보인다.

JUnit이 생성하는 Html 리포트에서 출력된 모습

 

4. properties.hibernate.generate_statistics: true

새롭게 알게된 옵션이다.

이를 활성화할 시 하나의 트랜잭션에서 실행되는 쿼리들에 대한 간단한 통계들이 아래와 같이 출력된다.

해당 옵션을 활성하려면 추가적으로 아래 옵션을 추가해주어야 한다.

org.hibernate.stat: {log_level}

이 옵션의 장점은 성능 상 병목이 발생하는 지점을 확인하기가 쉽다는 점과, 쓰기 지연을 통한 배치 쿼리가 의도대로 동작하는지 확인하는데 용이하다는 점이다. 

특히 후자의 경우엔, 단순 하이버네이트에서 지원하는 로그로는 실제로 배치 쿼리가 실행되는지 확인하는 것이 쉽지 않은데 이를 사용할 경우 그 문제가 쉽게 해결된다.

 

5. org.hibernate: {log_level}

기존에 사용하던 옵션이다.

해당 옵션을 사용할 경우 하이버네이트에서 발생하는 모든 로그를(로거에서 org.hibernate.~ or o.h.~ 로 출력되는 로그들) DEBUG 레벨로 출력한다. 

이 옵션을 사용할 경우, 기본적으로 로그 창이 굉장히 풍성(?)해진다. 이를 통하면 하이버네이트가 추상화 레이어 이면에서 수행하는 일들이 대부분 출력되어 디버깅에 큰 도움이 되지만, 좀 과하다고 느껴질 수도 있다. 

아래는 해당 옵션을 켠 뒤 간단한 테스트 코드를 실행했을 때 출력되는 로그의 대략적인 수를 세본 것이다.

이 옵션을 활성화하는 것 만으로, 테스트 메서드 4개짜리 테스트에서 약 2000여건의 로그가 출력된다.

 

6. org.hibernate.SQL: {log_level}

새롭게 알게된 옵션이다.

해당 옵션은 위에서 이미 언급한 1. show-sql: true 옵션과 동일한 로그를 출력한다. 다만 이 경우엔 애플리케이션 내 설정된 로거를 활용하니 되도록이면 이 옵션을 사용하자.

 

7. org.hibernate.type.descriptor.sql.BasicBinder: {log_level}

기존에 사용하던 옵션이다.

해당 옵션의 역할은 출력되는 SQL 로그에 실제로 어떤 값들이 바인딩되고 있는지 함께 출력하는 역할이다. 이 옵션을 활성화할 경우 디버깅에 큰 도움이 될 수 있다.

하지만 이번 기회에 확인한 결과, 이상하게도 우리 프로젝트에서는 동작하지 않았다. 그 이유는 하이버네이트 5.X 버전에서 Deprecated 되었기 때문.... (현재 프로젝트의 하이버네이트 버전은 6.X)

따라서 해당 옵션 대신 아래의 옵션을 활용할 수 있다.

org.hibernate.orm.jdbc.bind: {log_level}

이를 사용할 경우, 아래처럼 쿼리가 출력된 이후에 곧바로 어떤 파라미터들이 실제로 바인딩 되는지 확인이 가능하다.

좀 잘리긴 했으나, 쿼리 로그 이후에 어떤 값들이 파라미터 자리에 바인딩 되었는지 출력되는 모습

 

8. org.hibernate.orm.jdbc.bind: {log_level}

새롭게 알게된 옵션.

하이버네이트 6버전 이상에서 쿼리 파라미터를 출력하기 위해서는 해당 옵션을 사용해야 한다.

바로 직전 7.org.hibernate.type.descriptor.sql.BasicBinder 챕터에서 이미 설명하였으므로 이하 생략.

 

9. org.hibernate.SQL_SLOW

새롭게 알게된 옵션.

하이버네이트 5.4.5 버전 이상부터 사용할 수 있으며, 이 옵션을 활성화할 경우 애플리케이션에서 실행된 느린 쿼리가 로그에 출력된다.

이 옵션을 추가하기 위해서는 아래 옵션에 대한 추가가 필수적이다.

spring.jpa.properties.hibernate.session.events.log.LOG_QUERIES_SLOWER_THAN_MS: {느린 쿼리 판단 기준 ms}

이 옵션에서 설정한 ms를 초과하는 쿼리에 대해서만 로그가 출력된다. 이 때 실행 시간을 측정하는 기준은 실제 쿼리가 실행된 시간 만을 측정.

 

결론 (실제 적용 로깅 옵션)

1. Test 용 (본문에서 다룬 내용들만 작성)

# application.yml

spring:
  jpa:
    properties:
      hibernate:
        format_sql: true
        generate_statistics: true
        session.events.log.LOG_QUERIES_SLOWER_THAN_MS: 300
        ...
logging:
  level:
    org.hibernate.SQL: DEBUG
    org.hibernate.orm.jdbc.bind: TRACE
    org.hibernate.SQL_SLOW: INFO
    org.hibernate.stat: DEBUG
    ...

테스트에 활용할 설정 파일은 위와 같이 구성해주었다. 쉬운 디버깅을 위해 거의 모든 로깅을 활성화 하였으나 아래 두개의 옵션은 비활성화했다.

• org.hibernate: {log_level}
• properties.hibernate.highlight_sql: true

그 이유는, 우선 전자의 옵션은 디버깅 시 크게 활용하지 않는 로그들도 너무 많이 찍힌다는 단점이 있었다. 팀원들과의 디버깅 과정을 돌이켜보면, 해당 옵션을 통해 출력되는 로그들보다는 실제 어떤 쿼리와 어떤 파라미터로 쿼리가 실행되는지와 또한 org.springframework.orm, org.springframework.tracsaction 옵션을 통한 로그들에 더 많이 의존하였기 때문에 이를 과감히 삭제하였다.

또한 sql 하이라이팅 옵션은 Html 리포트에서 가독성을 너무나 떨어뜨리는 문제 때문에 테스트 환경에서는 추가하지 않았다.

 

2. Dev 용

# application.yml

spring:
  jpa:
    properties:
      hibernate:
        format_sql: true
        highlight_sql: true
        generate_statistics: true
        session.events.log.LOG_QUERIES_SLOWER_THAN_MS: 300
        ...
logging:
  level:
    org.hibernate.SQL: DEBUG
    org.hibernate.orm.jdbc.bind: TRACE
    org.hibernate.SQL_SLOW: INFO
    org.hibernate.stat: DEBUG
    ...

개발 환경용 설정은 위와 같이 해주었다. 테스트 용 설정에서 highlight_sql 옵션 만을 추가해주었다.

 

3. Prod 용

# application.yml

logging:
  level:
    org.hibernate: ERROR
    ...

아직 프로덕션 환경을 구성하지는 않았으나, 구성하게 된다면 위와 같이 구성할 것 같다.

실제 환경에서는 꼭 필요한 로그만을 출력해야하기 때문에 하이버네이트 내에서 발생하는 에러 이상의 로그들만 출력하는 것이 타당하다고 생각했다.

 

References

Logging Guide for Hibernate 4, 5 & 6 - Use the right config for dev and prod

Hibernate ORM 6.1.7.Final User Guide