애플리케이션이 실제로 어떤 SQL 을 보내는지, 바인딩 값이 무엇인지, 얼마나 걸렸는지를 코드 수정 없이 보고 싶을 때가 있다. ORM 이 만들어 내는 쿼리나 상용 패키지의 내부 쿼리가 특히 그렇다. JDBC 계층에 프록시를 끼우면 드라이버와 애플리케이션 사이를 지나는 모든 호출을 가로챌 수 있다.
| 방식 | 끼우는 지점 | 특징 |
|---|---|---|
| P6Spy | 드라이버를 감싼다 | 가장 널리 쓴다. 설정 파일 기반이라 재배포 없이 조정할 수 있다 |
| log4jdbc | 드라이버를 감싼다 | 설정이 단순하다. 원 프로젝트는 오래전에 멈췄고 포크가 여럿이다 |
| datasource-proxy | DataSource 를 감싼다 | 코드로 설정한다. Spring Boot 에서 세밀한 제어가 가능하다 |
드라이버를 바꿀 수 있으면 P6Spy 가 무난하다. 드라이버 교체가 불가능하고 DataSource 를 코드에서 만들 수 있으면 datasource-proxy 를 쓴다.
접속 정보 두 군데만 바꾼다.
드라이버: com.p6spy.engine.spy.P6SpyDriver
URL: jdbc:p6spy:postgresql://dbhost:5432/appdb
클래스패스 루트에 spy.properties 를 둔다.
# 실제 드라이버
driverlist=org.postgresql.Driver
# SLF4J 로 내보낸다
appender=com.p6spy.engine.spy.appender.Slf4JLogger
# 한 줄 포맷. 실행 시간(ms)과 바인딩이 채워진 SQL 을 남긴다
logMessageFormat=com.p6spy.engine.spy.appender.CustomLineFormat
customLogMessageFormat=%(executionTime)ms | %(category) | %(sqlSingleLine)
# 느린 쿼리만 남기기
filter=true
outagedetection=true
outagedetectioninterval=2
%(sql) 은 물음표가 남은 원본, %(sqlSingleLine) 은 바인딩 값이 채워진 형태다. 바인딩 값이 채워진다는 것은 곧 개인정보와 토큰이 로그에 남는다는 뜻이므로 운영에서는 신중해야 한다.
DataSource proxy = ProxyDataSourceBuilder
.create(realDataSource)
.name("appds")
.logQueryBySlf4j(SLF4JLogLevel.DEBUG)
.multiline()
.build();
느린 쿼리만 남기려면 다음을 쓴다.
.logSlowQueryBySlf4j(1, TimeUnit.SECONDS, SLF4JLogLevel.WARN)
배치 실행 정보와 커넥션 획득 시간까지 볼 수 있어 커넥션 풀 고갈을 진단할 때 유용하다.
전량 로깅은 TPS 가 조금만 높아도 로그가 폭증하고 디스크와 I/O 를 잡아먹는다. 기본은 느린 쿼리만 남기고, 필요할 때 한시적으로 전량으로 올렸다가 되돌린다.
로거를 비동기로 둔다. 동기 파일 어펜더는 디스크가 느려질 때 애플리케이션 스레드를 그대로 붙잡는다.
배치 INSERT 는 건마다 한 줄씩 남아 순식간에 수만 줄이 된다. 배치는 요약만 남기도록 필터를 건다.
바인딩 값 로깅은 개인정보 노출 경로다. 마스킹이 불가능하면 운영에서는 끄고 %(sql) 만 남긴다.
프록시를 거치면 커넥션마다 래핑 객체가 하나 더 생긴다. 드라이버 고유 기능을 쓰려고 unwrap() 을 호출하는 코드가 있으면 동작을 확인해야 한다.
서버 쪽 로깅으로 충분한 경우도 많다. 애플리케이션을 건드리지 않아도 되고 실제 실행 시간을 서버 관점에서 본다.
# PostgreSQL. 1초 이상 걸린 문장만 기록
log_min_duration_statement = 1000
-- MySQL. 느린 쿼리 로그
SET GLOBAL slow_query_log = ON;
SET GLOBAL long_query_time = 1;
애플리케이션 관점의 호출 흐름이 필요 없다면 이쪽이 부담이 적다.