application.yaml 설정- org.hibernate.sql 작동 안함

 

로거를 통한 쿼리문 로깅을 위해 logging.level.org.hibernate.sql: debug 를 application.yaml에 작성해주었으나 제대로 작동하지 않는 것을 발견하였다. 

해결책부터 말하자면 logging.level.org.hibernate.SQL: debug 와 같이 'sql'을 'SQL'로 작성해주면 된다.

 

탐색

jpa:
    properties:
      hibernate:
        dialect: org.hibernate.dialect.MySQL8Dialect
        show_sql: true #A
        format_sql: true
        use_sql_comments: true
        hbm2ddl:
          auto: create
        default_batch_fetch_size: 1000

logging:
  level:
    org.hibernate.sql: debug #B

 

spring.jpa.properties.hibernate.show_sql: true 옵션을 A, logging.level.org.hibernate.sql: debug 옵션을 B라고 하자.

하이버네이트가 실행하는 쿼리들이 A는 system.out으로, B는 logger로 출력이된다.

 

다음은 aplication.yaml에 A, B 둘 다 설정 시 보이는 하이버네이트 실행 SQL이다.

Hibernate: 
    select
        next_val as id_val 
    from
        hello_seq for update
Hibernate: 
    update
        hello_seq 
    set
        next_val= ? 
    where
        next_val=?
Hibernate: 
    /* insert for
        study.querydsl.entity.Hello */insert 
    into
        hello (id) 
    values
        (?)
Hibernate: 
    /* select
        h 
    from
        Hello h */ select
            h1_0.id 
        from
            hello h1_0

 

정상적인 결과였다면 A, B 설정을 해줬으므로 똑같은 하이버네이트 실행 SQL문이 중복되어 보이는게 맞다. 확인 결과 A 옵션만 정상적으로 동작하고 B 옵션이 동작하지 않았다.

 

참고로 spring.jpa.properties.hibernate.show_sql: true 옵션은 하이버네이트 실행 SQL문을 시스템 출력하고 logging.level.org.hibernate.sql: debug 옵션은 logger를 통해 출력한다. 따라서 spring.jpa.properties.hibernate.show_sql: true은 끄고 logging.level.org.hibernate.sql: debug 옵션을 사용하는 것이 좋다.

원인

나의 경우 logging.level.org.hibernate.sql: debug 옵션은 왜 동작하지 않았을까?

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

🔼실행결과 쿼리문 확인 불가

logging:
  level:
    org.hibernate.SQL: debug
    org.hibernate.type: trace

🔼실행결과 정상적으로 출력된 쿼리문 확인

 

org.hibernate.SQL이 아닌 debug org.hibernate.sql을 작성했던 것이 문제였다.

내가 설정한 org.hibernate.sql은 패키지였다.

 

 

이걸 선택해야했었다.(애초에 대문자로 작성하자.)

 

둘이 다르다는건 알겠는데 구체적으로 뭐가 다른지 궁금증이 생겨서 여기저기 돌아댕겨봤다.

🔎 org.hibernate.sql

https://docs.jboss.org/hibernate/orm/3.5/api/org/hibernate/sql/package-summary.html

org.hibernate.sql (Hibernate JavaDocs)

🔎 org.hibernate.SQL

LoggingApplicationListener class에 다음과 같은 코드가 있다.

LoggingApplicationListener class는 애플리케이션 부팅과 같은 상황에서 기본 로깅 설정을 해주는 친구인 것 같다.(로깅 시스템 초기화)

여기서 org.hibernate.SQL을 DEFAULT_GROUP_LOGGERS에 추가해놓은 건 기본 설정 차 추가해준 것으로 짐작했다.

 DEFAULT_GROUP_LOGGERS에 org.hibernate.SQL을 추가해줌으로써 이 패키지에 속한 로거들의 로그 설정을 편리하게 관리할 수 있게된다. 

 

해결

따라서 logging.level.org.hibernate.sql에서 org.hibernate.sql은 패키지가 아닌 로깅 그룹에 속한 org.hibernate.SQL으로 설정해주어야한다.

 

logging.level.org.hibernate.SQL: debug

https://docs.spring.io/spring-boot/docs/3.1.7/reference/html/application-properties.html#appendix.application-properties

 

 : logging.level.* 형식을 통해 org.hibernate.SQL에 대한 로깅 레벨을 debug로 설정

 

 

추가

https://sematext.com/blog/logging-levels/

Logging Levels: What They Are & How to Choose Them - Sematext

로깅 레벨이란?

 

https://www.inflearn.com/questions/1032603/p6spy-%ED%8F%AC%EB%A7%B7-%EC%84%A4%EC%A0%95-%EA%B3%B5%EC%9C%A0%ED%95%A9%EB%8B%88%EB%8B%A4

P6Spy 포맷 설정 공유합니다. - 인프런

위 링크에서 알려준대로 코드를 추가하면 아래와 같은 예쁜 결과를 받아 볼 수 있다.

 

2024-01-09T16:20:27.321+09:00  INFO 113856 --- [    Test worker] p6spy                                    : 
Execute DML : 

    select
        next_val as id_val 
    from
        hello_seq for update

Execution Time: 13 ms
----------------------------------------------------------------------------------------------------
2024-01-09T16:20:27.324+09:00  INFO 113856 --- [    Test worker] p6spy                                    : 
Execute DML : 

    update
        hello_seq 
    set
        next_val= 51 
    where
        next_val=1

Execution Time: 1 ms
----------------------------------------------------------------------------------------------------
2024-01-09T16:20:27.338+09:00  INFO 113856 --- [    Test worker] p6spy                                    : 
Execute Command : 

	commit

----------------------------------------------------------------------------------------------------
2024-01-09T16:20:27.665+09:00  INFO 113856 --- [    Test worker] p6spy                                    : 
Execute DML : 

    /* insert for
        study.querydsl.entity.Hello */insert 
    into
        hello (id) 
    values
        (1)

Execution Time: 1 ms
----------------------------------------------------------------------------------------------------
2024-01-09T16:20:27.698+09:00  INFO 113856 --- [    Test worker] p6spy                                    : 
Execute DML : 

    /* select
        h 
    from
        Hello h */ select
            h1_0.id 
        from
            hello h1_0

Execution Time: 0 ms
----------------------------------------------------------------------------------------------------
2024-01-09T16:20:27.752+09:00  INFO 113856 --- [    Test worker] p6spy                                    : 
Execute Command : 

	rollback

----------------------------------------------------------------------------------------------------