[Spring Boot] 스프링부트 JDBC logging 파헤치기 (로그설정, 로그레벨, JPA 쿼리)

#application.properties
logging.level.org.springframework.jdbc.core=TRACE

#application.yml
logging:
  level:
    root: INFO
    org.springframework: DEBUG
    com.myproject: INFO

위 처럼 설정을 하면 JDBC에 관련한 로그를 확인 할 수 있다.

어떤 원리로 로그를 보여주는지, 왜 JPA의 쿼리를 로그로 보여주는지에 대해 궁금해져서 JDBC 로그에 대해 파헤쳐 보기로했다.

 

JDBC(Java Database Connectivity) logging은 어떻게 동작할까?

로그 생성 과정

1. 로깅 요청 발생 : 애플리케이션 실행 중 org.springframework.jdbc.core 패키지 또는 그 하위 패키지의 클래스에서 로그를 생성하는 요청이 발생한다. 예를 들어, JdbcTemplate가 SQL 쿼리를 실행할 때, 해당 쿼리 정보, 실행 시간, 실행 결과 등의 로그를 생성할 수 있다.

로깅발생 예시)

JdbcTemplate jdbcTemplate = new JdbcTemplate(dataSource);
jdbcTemplate.query("SELECT * FROM users", new RowMapper<User>() {
    @Override
    public User mapRow(ResultSet rs, int rowNum) throws SQLException {
        // 결과 처리
    }
});

위 코드에서 jdbcTemplate.query 메서드를 호출하면, 내부적으로 다음과 같은 로그가 생성될 수 있다.

SQL 쿼리 실행 전: "Executing query: SELECT * FROM users"
SQL 쿼리 실행 후: "Query executed in 10 ms"

2. 레벨 체크 : 로깅 시스템은 해당 로그 요청의 레벨을 확인하고, 설정된 로그 레벨과 비교한다.

3. 로그 기록 여부 결정 : 설정된 로그 레벨보다 낮은 레벨의 로그 요청은 무시된다. 예를 들어, 로그 레벨이 DEBUG로 설정되어 있을 경우, TRACE 레벨의 로그는 무시되고, DEBUG 이상의 로그만 기록된다.

4. 로그 시스템에 전달 : 필터링된 로그는 스프링 프레임워크가 사용하는 로깅 시스템(SLF4J, Log4j 등)으로 전달된다. 로깅 시스템은 이 로그를 적절한 출력 장치(콘솔, 파일, 네트워크 등)에 기록한다.

5. 로그 출력 : 설정된 레벨 이상의 로그는 콘솔, 파일, 또는 다른 로그 저장소에 기록된다.

 

로그 레벨 종류

1. TRACE: 로그의 가장 상세한 수준, 소프트웨어의 각 단계와 세부 동작을 로그로 보여준다.
2. DEBUG: 일반적인 디버깅 정보를 기록한다.
3. INFO: 중요한 이벤트나 상태 정보를 기록한다.
4. WARN: 경고나 잠재적 문제를 나타냄, 예상치 못한 상황이나 잠재적 오류를 방지한다.
5. ERROR: 심각한 오류나 예외 상황을 나타냄, 기능 실패나 문제 해결 정보를 제공한다.
6. FATAL: 매우 심각한 오류를 나타냄
7. OFF: 로깅을 완전히 비활성화

레벨을 설정했을때 그 레벨의 하위 레벨의 로그를 모두 포함한다.

예를들어 INFO로 설정했을때 INFO, WARN, ERROR, FATAL의 로그를 모두 보여준다.

 

로그의 구성을 알아보자

2023-11-17 13:23:06.689 TRACE 58135 --- [main] o.s.jdbc.core.StatementCreatorUtils      : Setting SQL statement parameter value: column index 1, parameter value [1], value class [java.lang.Long], SQL type -5
2023-11-17 13:23:06.689 TRACE 58135 --- [main] o.s.jdbc.core.StatementCreatorUtils      : Setting SQL statement parameter value: column index 2, parameter value [NAGnUXHgZAekDivTIczL], value class [java.lang.String], SQL type 12
2023-11-17 13:23:06.689 TRACE 58135 --- [main] o.s.jdbc.core.StatementCreatorUtils      : Setting SQL statement parameter value: column index 3, parameter value [1998-12-07], value class [java.time.LocalDate], SQL type 91
2023-11-17 13:23:06.689 TRACE 58135 --- [main] o.s.jdbc.core.StatementCreatorUtils      : Setting SQL statement parameter value: column index 4, parameter value [2010-03-21T21:26:46.470010644], value class [java.time.LocalDateTime], SQL type 93
2023-11-17 13:23:06.689 TRACE 58135 --- [main] o.s.jdbc.core.StatementCreatorUtils      : Setting SQL statement parameter value: column index 1, parameter value [1], value class [java.lang.Long], SQL type -5

위 로그는 jpa 프로젝트에서 어떤 insert문을 호출했을때 나온 로그이다.

이 로그를 분석해보자

1. 타임스탬프: 2023-11-17 13:23:06.689는 로그가 기록된 정확한 시간을 나타낸다.
2. 로그 레벨: TRACE는 위에서 설명한 로그 레벨을 나타난다.
3. 프로세스 ID: 58135는 이 로그를 생성한 애플리케이션의 프로세스 ID를 나타낸다.
4. 스레드 정보: [main]은 로그가 기록된 스레드의 이름이다.
5. 클래스명: o.s.jdbc.core.StatementCreatorUtils는 로그를 생성하는 클래스의 이름이다. 
6. 메시지:
컬럼 인덱스: column index 1, 2, 3, 4 등은 SQL 쿼리 내의 각 파라미터의 위치(인덱스)
파라미터 값: parameter value [값]은 해당 위치에 설정된 실제 파라미터의 값
값 클래스: value class [자바 클래스 타입]은 파라미터 값의 자바 데이터 타입 ex)java.lang.Long, java.lang.String, java.time.LocalDate 등
SQL 타입: SQL type [숫자]는 해당 파라미터의 SQL 데이터 타입을 나타내는 번호 ex) 93 : 'timestamp'

 

왜 JDBC 로깅이 JPA 쿼리도 보여주는걸까?

단순히 데이터베이스 관련 로그니까 보여주겠지 했는데 좀 더 자세히 알고 싶어졌다.

JPA (Java Persistence API)는 데이터베이스 작업을 위한 표준 Java API이다. 하지만 JPA 자체는 구현체가 아니라 인터페이스 집합에 불과하므로 실제로 데이터베이스 작업을 수행하기 위해서는 JPA의 인터페이스를 구현한 구현체(예: Hibernate, EclipseLink, OpenJPA 등)가 필요하다. 이러한 구현체들은 내부적으로 JDBC (Java Database Connectivity)를 사용하여 실제 데이터베이스 작업을 수행한다.

이게 무슨뜻일까? JPA 자체는 구현이 아닌 고수준의 인터페이스일 뿐이다. 규칙세트 일 뿐이고 이 규칙을 따르는 각각의 구현체들 (Hibernate같은)은 이 규칙에 따라서 실제 데이터 베이스 작업을 한다.

그런데 이러한 실제 데이터베이스 작업을 수행하기 위해 이 구현체들은 JDBC API를 사용한다.

예를 들어 Hibernate 는Session.save(Object) 또는 Session.find(Class, ID) 같은 메서드는 내부적으로 JDBC의 Connection, PreparedStatement, ResultSet 등을 사용하여 SQL 쿼리를 실행하고 결과를 처리한다.

따라서 JDBC 로깅에 JPA 쿼리가 찍히는것 처럼 보여지는 것이다.