JPA Query 로그 출력(feat. 물고기를 주지말고, 물고기 잡는 법좀 알려줘라..)

블로그에 텍스트 복사/붙여넣기를 막은 이유가 있다
내가 정성들여 쓴 IntelliJ 플러그인 25가지 추천 글을 문자 그대로 토씨 하나 안바꾸고 크롤링을 해서 자기 블로그에 그대로 올리는 사람이 있는가하면, 그대로 복붙해서 출처없이 올리는 걸 봤다
그때 충격이었다
 
또한 블로그를 하는 사람들을 무시하는 사람들의 말을 들어보면, 블로그를 한다고 유세떤다, 남의꺼 복붙해서 가져다 쓰는 것이라 말한다
나도 어느정도는 동의한다. 양질<->저질 품질로 따졌을 때 단순히 에러를 해결하는 방법 1줄, 2줄 이정도만 올리는 저질글들이 많다
 
하지만....
시간이 지나감에 따라 21년에 쓴 글이 25년에 될때는 버전 업이 돼서 정답이 아닐지라도 최대한 보는 사람들을 위해서 간단한 프로젝트를 만들어보거나 개인프로젝트에 적용시켜서 테스트를 하고 올리는 분들이 있다
나도 그럴려고 노력하고..!!
어쨌든, 이 JPA 로그 출력이라는 글 하나를 쓰려고 찾아보며 약간 안타까운 마음 반, 나도 앞으로 더 잘해야겠다는 다짐 반으로 주제와 조금 벗어난 이야기를 했다
 

Target

일단 이 글은 JPA with hibernate를 구현체로 사용하는 경우를 다루고 있다
 

Care Points

Persistent Library(DBMS)를 다루게되면 중요하게 봐야할 포인트가 여럿 생긴다
- DB Level: query, query optimization, query order, execution plan, transaction
  - Configuration: collation, timezone, connection pool size, max connections, isolation level, lock mode, commit mode, charset, log setting(slow-query), deadlock timeout
- Application Level: DataSource, Connection Pool, TransactionManager, DataAccessException
- Abstracted Dependent Tool(Library - JPA): Proxy, Entity Mapping, EntityManager, Cache, Fetch Strategy, Batch Size, Open-In-View
 
하지만 대부분의 신입/주니어 개발자들은 yaml파일에서 datasource까지만 신경쓰고 Data JPA를 쓰는법에만 집중한다. querydsl을 써봤고, N+1을 어떻게 해결했고 등등..
공부를 깊게 하면 할수록 실제로 DB에 접속해서 Database, Schema, Table, Authentication/Authorization 설정값들을 보고 조절하는게 필요하다고 많이 느낀다
(대기업이면 DBMS분들이 계셔서 다 관리를 해줄지도..?하지만 그럼에도 알고있어야한다 주의이다)
더 높은 레벨로 가면 권한처리, 샤딩, 파티셔닝, 이중화, 무중단 xx 이런것들이 더 중요해지긴한다
 

Comparison

이 글의 주제는 그 중 간단한 Query로그를 출력해보는 방법에 대해 얘기해보려고 한다
Spring boot 3.x 버전이 나오므로 인해서 바뀐 부분이 매우 많다
하지만 국내의 다수기업들이 아직 2.x 버전을 사용하고 있을수도 있다
간단하게 차이점을 살펴보면...
 
Springboot 2.x.x

• Spring-core: 5.x.x
• Hibernate: 5.x.x

spring boot 2버전대

 
Springboot 3.x.x

• Spring-core: 6.x.x
• Hibernate: 6.x.x

spring boot 3버전대

혹시나 boot버전을 core버전과 헷갈려하는분이 있다면, Spring boot는 AutoConfiguration+Embedded Tomcat을 주 무기로 장착한 설정하기 어려웠던 Spring의 쉬운버전 project의 일종이란 것을 알아두자. core가 중요한 것이다
 

Main Point

Query를 출력하는 방법은 크게 2가지가 있다

1. Console 출력
2. Logger 출력

1번 방법과 2번 방법의 차이를 검색하면 많이 나올텐데
기본적으로 Logger출력을 주로 사용하게 된다
참고로 Logger출력을 사용하면 Level별로 관리, RollingFileAppender(파일 저장), 더 많은정보(Thread, Time), 모니터링 시스템과 연동, 애플리케이션 성능 최적화(I/O 작업 미포함, 비동기) 등 여러 장점이 있다
 
하지만 Query 출력을 위한 1, 2번 모두 설명할 예정이다
 
간단하게 테스트하기 위해서 kotlin, Spring Data JPA를 사용했다
Entity를 만들고, Repository를 만들고 Springboot에서 EventLister를 활용해 초기 데이터를 넣는 쿼리를 실행했다

초기화

SimpleJpaRepository

논리적인 트랜잭션으로 묶거나 전파를 활용하는 예제는 아니기도하고, 이미 saveAll에 @Transactional이 붙어있기 때문에 달아주지는 않았다(몰랐던 분이 있다면 얻어가시길..!)
 

• Console 출력

spring:
  jpa:
    properties:
      hibernate:
        show_sql: true				# sql 출력
        format_sql: true			# sql 이쁘게 출력(여러줄)
        use_sql_comments: true		# sql 상세출력(어떤엔티티에 들어가는지 등)
        highlight_sql: true			# DDL, DML, DCL 해당/비해당 컬러링

show_sql이 활성화되어있지 않으면 아래의 옵션들은 다 무용지물이 된다

결과

=> 쿼리가 나오지 않았다
 
이제 하나하나 설정을 열어주면서 보여주겠다
 
- show_sql: true

=> 쿼리가 나온다
 
- format_sql: true

=> 쿼리가 여러줄로 이쁘게 나온다
 
- use_sql_comments: true

=> 실제 쿼리 앞부분에 어느 엔티티를 대상으로 한 쿼리인지 패키지명부터 클래스까지 주석으로 표시해준다
 
- highlight_sql: true

=> KEYWORD 부분을 ANSI COLOR를 입혀서 강조해준다
 
위에까지 Spring 3.x.x버전의 테스트였다. 사실 콘솔출력은 메인디쉬가 아니긴 하지만.. 아쉬운 마음에 2.x.x도 테스트해봤다

=> 3버전에서는 insert for라고 나오던게 2버전에서는 insert .. 라고 나온다
아마도 boot3에서 use_sql_comnnect옵션을 활성화하면 insert뒤에 for 키워드가 붙은 이유를 생각해보면... 개발자들이 for가 없으니 insert쿼리가 두번 나간다고 생각했나보다 ㅋㅋ;
그래서 그냥 헷갈리지 말라고 추가한게 아닐까...유추해본다! 아마 맞을듯!
 
참고로 Logger출력은 형태가 아래와 같이

2024-11-15T04:30:33.744+09:00  INFO 15214 --- [           main] boki.BokiLaboratoryApplicationKt         : Started BokiLaboratoryApplicationKt in 2.429 seconds (process running for 2.698)

이렇게 시간/Level/스레드이름/출력패키지.클래스 : 설명 으로 이루어져있다
반면에 [Hibernate]라고 찍힌 부분은 이런 형태가 아닌 것을 볼 수 있다
위에서 설명한 Logger 형태가 아닌 것은, 거의 다 System.out을 사용해 찍는 것이라고 보면 된다
 

• Logger 출력 ✅

이제 Main Dish인 Logger출력을 살펴보겠다
사실 이 Logger에서 Spring boot 2.x와 3.x가 출력되는 위치가 달라졌다(파라미터 바인딩 쪽에서)

 

[ Spring boot 3.x.x ]
먼저 Spring boot 3.x.x의 설정을 살펴보자

logging:
  level:
    org:
      hibernate:
        SQL: DEBUG				# sql 출력
        orm.jdbc.bind: TRACE	# ? <- 파라미터 출력

 

이번에도 위에처럼 실행에 옮겨보자
참고로 콘솔출력은 다 주석으로 해제했다
아! 그리고 너무 간단한 거긴한데.. 로그레벨은
TRACE, DEBUG, INFO, WARN, ERROR, FATAL이 존재한다
TRACE(상세) -> ... -> FATAL(심각)
예를 들어 애플리케이션 로그 레벨을 INFO로 설정 했다면 TRACE, DEBUG 수준의 로그는 보이지 않게 된다
보통 개발환경(local, dev)에서 특정 패키지를 TRACE나 DEBUG로 잡고 개발하고 운영환경(prod, stage)에서는 INFO, WARN정도로 올린다. 왜냐하면 로그를 찍는것도 비용이기때문이다

 
- org.hibernate.SQL: DEBUG

=> 쿼리가 잘 출력됐다
INFO레벨로 수정하면 로그가 보이지 않는다. DEBUG 수준에서 제공되는 쿼리라고 생각하면 된다
그럼 이제 orm.jdbc.bind를 TRACE로 설정해보자
 
- org.hibernate.orm.jdbc.bind: TRACE

=> 어떤 파라미터가 ?에 들어가는지 볼 수 있게 됐다

 

[ Spring boot 2.x.x ]
스프링부트 2버전대의 설정도 안보면 아쉬울 것 같다
아직도 오래된 블로그에서 제공하는 정보를 찾을 수 있다
또는 3버전을 사용하는 최신 블로그에서 부트2버전대의 로그 설정을 가져다 올리고 하이버네이트에서 제공을 하지 않는다고 한다..ㅎ

logging:
  level:
    org:
      hibernate:
        SQL: DEBUG					# sql 출력
        type.descriptor.sql: TRACE	# ? <- 파라미터 출력

부트 3점대 버전과 다른 점은 파라미터 바인딩을 보기 위한 패키지명이다
테스트해보자

- org.hibernate.SQL: DEBUG

=> 쿼리가 잘 출력됐다
 
- org.hibernate.type.descriptor.sql: TRACE

=> 어떤 파라미터가 ?에 들어가는지 볼 수 있게 됐다
3버전대랑 비교해보면 출력 형태가 조금 바뀐 것을 볼 수 있다. 3버전은 <-로 뭔가 대입된다는 느낌이 확 들고, 파라미터 순서와 타입을 (순서:타입)으로 그룹화한 모양새다
 

• 3rd library

p6spy
현재 공부하거나 작업하는 프로젝트에서는 사용하고 있지 않아서 잘 모르지만 3점대에서는 많이 바뀌었다고 본 것 같다
개인적으로 이렇게 외부 라이브러리를 주렁주렁 쓰는걸 좋아하진 않는다
순수하게 스프링부트만 해도 이미 꽤 무거운 의존성들을 갖고 있고, 옵션을 잘 살펴보면 굳이 오픈소스를 갖다 안써도 충분히 프로젝트는 돌아가기 때문이다
하지만 2021년에 만든 기존에 2점대 버전의 springboot 프로젝트에서는 적용했던 적이 있어서, 사용결과만 보여주겠다

  

How To Eat

고기를 단순히 먹는게 아닌, 고기를 잡는 법을 직접 알아야 한다
어느 블로그에 보면 콘솔과 로깅 둘다 쓰면서 파라미터를 확인한다던지..; 짬뽕글들이 많다
단순히 남의껏을 베끼기만 하고, 탐구해볼 생각은 없는걸까..ㅎ
 
어쨌든 이렇게 버전이 올라가면서 로그가 나오는 패키지가 달라진다면 개발자는 어떻게 대응해야 할까...?
답은 최상단 패키지의 로그레벨을 낮게 잡고 내가 원하는 로그를 내고 있는 패키지를 한정짓고, 그 패키지의 레벨만 낮게 설정하면 된다
말이 어려웠지만.... 사진으로 보면

찾았다 요놈

이렇게 hibernate를 TRACE 로그레벨로 실행해보면 애플리케이션 로그가 미친듯이 뜬다
그 중에서 grep이나 find를 사용해서 'binding parameter'를 검색해보면 된다

log에서 이놈을 출력해주는 패키지.클래스를 찾아보면 org.hibernate.orm.jdbc.bind 인 것을 볼 수 있다!!
그럼 최종적으로 다시 로그레벨을 원상복구 시켜줘서 나의 관심사가 아닌 것들까지 TRACE 레벨로 나오는 것을 막자

굿

 
위의 내용을 활용해서 boot 2버전대의 binding되는 파라미터를 출력하는 클래스도 알 수 있었다
결론적으로 type.descriptor.sql.BasicBinder: TRACE 로 설정해줬어도 파라미터가 나오는 것을 찾을 수 있었다

boot 2버전대 binding paramter 찾는법

문제는 이렇게 찾고 해결하는 것이다
자바 버전, 스프링 버전, 라이브러리 버전, 코틀린 등등은 계~속 업데이트 된다
요상한 블로그의 결론, 오래된 블로그의 결론.. 이런거에 휘둘리지 말고 이렇게 코어를 찾는 연습을 해보자
사실 간단하게 패키지 단위로 로그레벨을 바꿔가며 보는 기본적인 디버깅 방법이었다
아마 중고수분들은 다 아는내용이라 심드렁하셨을듯..!!
 
로거도 더 살펴보면 최적화할 수 있고 재밌는 내용이 많다
성능 - Sync, AsyncAppender, AsyncLogger
압축 - 단일 파일로 쌓다가 특정 크기 이상이 되면 압축
 
오랜만에 조금 길게 개발관련 글 써봤다! 간단한 거고, 신입과 주니어때부터 이미 알고있던 거였지만 다시 정리해보니 좋다.. 지금은 새벽5시ㅎㅎ
그럼 굿나잇!