[JVM] JDBC 쿼리 및 메서드 실행 로깅

1. JDBC 쿼리 로그 활성화

애플리케이션이 실행하는 SQL 쿼리와 그 실행 시간을 로그로 기록하려면, JVM 옵션에서 로그 레벨을 설정해야 한다. 아래는 이를 설정하는 방법이다:

-Dlogging.level.jdbc.sqlonly=off       # SQL 쿼리만 로깅하지 않음
-Dlogging.level.jdbc.sqltiming=info    # SQL 쿼리 실행 시간을 info 레벨로 로깅
-Dlogging.level.jdbc.resultsettable=info  # 쿼리 결과를 info 레벨로 로깅
-Dlogging.level.jdbc.audit=off         # JDBC audit 로그 비활성화
-Dlogging.level.jdbc.resultset=info    # JDBC 결과 셋을 로깅
-Dlogging.level.jdbc.connection=off    # JDBC 연결 로그 비활성화

이 설정을 적용하면, 애플리케이션이 실행하는 SQL 쿼리와 그 실행 시간이 로그에 기록된다. 또한, 쿼리 결과도 로그를 통해 확인할 수 있다.
 

2. Spring Datasource URL 설정

-Dspring.datasource.url=jdbc:log4jdbc:mariadb://DB-IP:3306/rorodb

 
 

3. 메서드 실행 로그 설정

특정 메서드가 언제 실행되는지 확인하기 위해서는, 패키지의 로그 레벨을 trace로 설정해야 한다. 예를 들어, 다음과 같이 설정할 수 있다:

-Dlogging.level.io.playce.roro=trace

• 실행되기 전에 “--> 메소드명”
• 실행되고 나서 ”<-- 메소드명”

2023-05-23 09:36:02.389 xec-3 TRACE .api.config.MethodTraceLogging:39 - --> io.playce.roro.api.domain.inventory.service.InventoryService.getInventoryCount
2023-05-23 09:36:02.390 xec-3 TRACE .api.config.MethodTraceLogging:45 - <-- io.playce.roro.api.domain.inventory.service.InventoryService.getInventoryCount

이 로그를 통해 메서드가 언제 호출되고, 언제 종료되는지 명확하게 파악할 수 있다.
 

4. 로그 조합 및 확인

이제 쿼리와 메서드 실행 로그를 함께 확인할 수 있다. 다중 스레드 환경에서는 특정 스레드의 로그만 필터링하면, 특정 메서드 실행과 관련된 쿼리 로그를 명확하게 확인할 수 있다. 예를 들어, 아래와 같은 로그가 출력될 수 있다.

2023-05-23 09:36:02.389 xec-3 TRACE .api.config.MethodTraceLogging:39   - --> io.playce.roro.api.domain.inventory.service.InventoryService.getInventoryCount
2023-05-23 09:36:02.390 xec-3  INFO                 jdbc.sqltiming:373  - select max(a.`count`) as `count`
             , max(a.discovered_count) as discovered_count
             , 'SVR' as inventory_type_code
        from (
          select count(1) as `count`
               , -1 as discovered_count
            from inventory_master im
           where im.delete_yn = 'N'
             and im.project_id = 1
             and im.inventory_type_code = 'SVR'
           union all
          select -1 as `count`
               , count(1) as discovered_count
            from discovered_instance_master dim
           where dim.delete_yn = 'N'
             and dim.possession_inventory_id is null
             and dim.project_id = 1
             and dim.inventory_type_code = 'SVR'
        ) a
 {executed in 1 msec}
2023-05-23 09:36:02.390 xec-3  INFO            jdbc.resultsettable:610  -
|------|-----------------|--------------------|
|count |discovered_count |inventory_type_code |
|------|-----------------|--------------------|
|6     |2                |SVR                 |
|------|-----------------|--------------------|
2023-05-23 09:36:02.390 xec-3 TRACE .api.config.MethodTraceLogging:45   - <-- io.playce.roro.api.domain.inventory.service.InventoryService.getInventoryCount