로그를 통해 우리는 논리적 사고를 할 수 있다 [커넥션 풀 트러블 슈팅 - 3]

https://whxogus215.tistory.com/135

로그를 분석하며 문제를 발견하다 [커넥션 풀 트러블 슈팅 - 2]

지난 포스팅에서 NginX 및 스프링부트의 로그를 바탕으로 원인을 분석하였고, 데이터를 저장하는 과정에서 불필요하게 많은 insert 쿼리가 발생함을 발견하였다. 그러나 IDENTITY 방식으로 ID를 관리하던 엔티티였기에 JPA가 아닌 JDBC를 통해 batchInsert를 적용하기로 하였다.

 

1. JPA와 JDBC를 함께 사용하기

 

우리는 JPA를 사용할 때, 인터페이스만을 선언한 뒤, JpaRepository를 상속받는다. 그러면 스프링 데이터 JPA에서 알아서 구현체를 생성한다. 하지만 이 케이스처럼 JPA와 JDBC를 함께 사용하는, 즉 커스텀된 리포지토리가 함께 필요할 수가 있다. 이럴 때, 사용하는 방식을 소개하겠다.

 

먼저, 커스텀 리포지토리 인터페이스와 그 구현체를 생성한다.

 

이처럼 커스텀 리포지토리 인터페이스를 구현한 클래스는 JdbcTemplat을 주입받는데, 이 때 batchUpdate를 사용하면 batch를 활용하여 쿼리를 보낼 수 있다. BatchPreparedStatementSetter라는 익명 클래스를 활용하여 SQL 쿼리 생성에 필요한 인자 값을 전달하며, 저장할 객체가 담긴 리스트의 크기를 배치 크기로 지정할 수 있다.

 

 

그리고 기존에 사용하던 Repository 인터페이스에서 추가로 생성한 커스텀 인터페이스를 상속받도록 하면 된다.

 

해당 내용은 자바 ORM 표준 JPA 프로그래밍의 12.6 사용자 정의 리포지토리 구현의 내용을 참고하였다.

https://product.kyobobook.co.kr/detail/S000000935744

자바 ORM 표준 JPA 프로그래밍 | 김영한 - 교보문고

 

 

그러면 기존에 사용하던 find~, delete~ 등을 변경하지 않고, 추가로 구현한 saveAll만 적용할 수 있다. 서비스 계층이 추상화(인터페이스)에 의존함으로써 얻을 수 있는 이점이기도 하다.

 

 

jdbctemplate을 사용한 결과, insert 쿼리문이 배치로 실행됨을 로그로 확인할 수 있다.

(해당 옵션은 이전 포스팅에서 언급한 JDBC 관련 디버그 옵션을 활성화하면 된다)

 

2. 정말 insert 쿼리가 하나만 생성되는 걸까?

우리는 위 로그를 통해 jdbctemplate을 활용하여 배치를 활용해 insert 쿼리를 전송함을 확인하였다. 하지만 이는 어플리케이션 쪽에서 날리는 로그이고, 실제 DB에 전달되는 쿼리라고는 단정지을 수 없었다. 정말로 46개의 insert 쿼리가 1개의 insert 쿼리로 단축되는 건지에 대한 의문이 계속 들었고, 프로젝트에서 사용 중이던 MySQL에 전송되는 쿼리를 확인하고 싶었다.

 

MySQL의 로그를 확인하는 방법도 있지만 그보다 더욱 간편한 방법이 있었다.

https://techblog.woowahan.com/2695/

MySQL 환경의 스프링부트에 하이버네이트 배치 설정해 보기 | 우아한형제들 기술블로그

해당 게시글의 내용을 언급하자면 jdbc url에 profileSQL=true을 쿼리 파라미터로 추가하면 실제 MySQL 드라이버에서 전송하는 쿼리를 출력할 수 있다. MySQL 드라이버는 자바 언어로 구현된 어플리케이션이 MySQL과 소통하기 필요한 인터페이스이다. 따라서 여기서 출력하는 쿼리를 통해 나의 궁금증을 해소할 수 있을 것이라 생각했다.

 

따라서 profileSQL=true와 위 글에서 언급한 로거 및 쿼리 길이를 설정하고, 실제 MySQL 드라이버에서 전송하는 쿼리를 확인해보았다.

 

결과는...?

 

옆에 MySQL이라고 표시되어 있으므로, 이는 MySQL 드라이버에서 출력하는 로그이다. 그림에서 알 수 있듯이, 여전히 insert 쿼리를 Row 개수만큼 생성하고 있다. 이를 통해, 배운 점은 다음과 같다.

1. 끝까지 의심해볼 것. 성능 개선의 목적이 실제 DB에 전송되는 쿼리 개수를 줄이기 위함이었으므로 어플리케이션 단에서 출력하는 로그 이외에도 실제 DB 쪽에서 출력하는 로그까지 확인해야 하는 것이 맞다. 나의 방법이 옳은 것인지에 대해 계속 검증하고 의심해봐야 한다.
2. 해당 옵션을 통해 실제 사용되는 커넥션 ID도 확인할 수 있다. 사실 맨 처음에는 리포지토리 메서드 호출에 사용되는 커넥션의 ID를 확인하기 위해 AOP로 로그를 찍는 등 별 수고를 다했었지만 결국 실패했었다. 하지만 해당 옵션을 통해 MySQL 드라이버에서 출력하는 로그로 실제 사용되는 커넥션이 같은 커넥션을 사용하고 있는지 아닌지를 확인할 수 있었다.

해당 포스팅을 참고한 결과, JDBC의 경우 rewriteBatchedStatements=true 옵션을 활성화 해야 batch 쿼리를 지원한다. 그리고 해당 옵션을 쿼리 파라미터로 추가하였고, 다시 테스트했을 때 성공적으로 쿼리가 하나만 생성됨을 확인할 수 있었다.

 

하나의 insert 쿼리에서 values 뒤에 여러 Row들이 묶여져 있다.

 

3. 메서드 성능 비교

개선 전

개선 후

 

메서드 실행 시간은 0.195초에서 0.159초로 0.036초 단축됐다. 추가하는 데이터가 100개도 되지 않기에 미비한 성능 차이를 알 수 있다. 하지만 커넥션을 통해 DB에 전송되는 쿼리문은 46개에서 1개로 단축되었기 때문에 DB I/O를 줄이는 것에 더 의의가 있다고 할 수 있다.

 

4. 이번에 알게 된 Git 꿀팁

1. Git에서 -는 이전 브랜치를 의미한다. 따라서 두 개의 브랜치를 번갈아 사용할 일이 있을 경우, git switch 브랜치명이 아니라 git switch -를 입력하면 이전 브랜치로 쉽게 이동할 수 있다.
2. 특정 브랜치에서 작성한 코드를 반영하지 않고, 다른 브랜치로 넘어가 코드를 적용시키고 싶다면? 즉, A에서 작성한 코드를 커밋하지 않고 B에다가 옮기고 싶을 수가 있다. 필자는 develop 브랜치에서의 실행시간 측정 코드를 그대로 트정 브랜치에 옮기고 싶었다. 이 때, git stash를 통해 내부 저장소에 변경 사항을 저장할 수 있다. 그리고 특정 브랜치로 넘어와서 git stash apply를 하면 해당 코드가 바로 적용된다. (물론, 같은 위치의 코드를 변경한다는 가정하에)
   • 이외에도 다른 브랜치로 옮길 때, 변경사항을 커밋하지 않으면 옮기지 못하는데 이 때도 stash를 사용할 수 있다.
     git stash로 잠시 저장한 다음에 브랜치를 옮긴 후, git stash drop을 통해 제거하면 된다. (물론, 컨트롤 + Z를 몇 번 눌러서 되돌릴 수도 있긴 하다.

 

문제를 해결하기 위해 디버그 옵션을 활성화하여 평소에 많이 보지 못했던 여러 종류의 로그들을 확인할 수 있었다. 이 과정을 통해 운영 환경에서 적절한 로그를 남기는 것의 중요성도 알게 되었고, 로그를 통해 좀 더 문제를 논리적으로 접근하고, 분석할 수 있었다.