[Pinit] 통계 갱신의 누락 문제
핀잇 백엔드의 핵심 비즈니스 로직의 구현을 마치고, 간단하게 FE를 구현해 사용해보는 도중 통계가 정상적으로 기록되지 않는 문제를 마주했다.
먼저 문제가 생긴 애플리케이션 로직을 찾아보았다.
orElseGet으로 새로운 통계 객체 생성 후 save() 를 호출해 저장을 수행하고 있었는데, 이 동작에 문제가 생긴 것처럼 보였다.
먼저, 이벤트가 정상적으로 발행되지 않거나, 이에 대한 구독이 이루어지지 않았는지가 의심스러웠다.
그래서 다음과 같이 중단점을 걸고 디버깅을 수행했다.
하지만 그 결과는 아래와 같이 중단점에 잘 도착하는 모습을 확인할 수 있었다.
또한 값 변경도 잘 되는 것을 확인할 수 있었다.
이벤트의 발행/구독에 대한 의심을 걷어낸 나는, 그 다음으로 이루어지는 작업인 SQL에 관심이 생겼다.
그렇게 show sql 옵션을 true 로 설정한 결과, 첫 insert/이후 update 쿼리가 날아가지 않고 있었다.
트랜잭션이 꺼져있나? 라는 의심이 들어, 트랜잭션 동기화 매니저를 이용해 현재 트랜잭션에 대한 정보를 확인해보고자 했다.
- 현재 트랜잭션이 잘 켜져 있는가
- 정상적으로 커밋이 잘 수행되는가
그 결과는 아래와 같았다.
트랜잭션 안인데, 트랜잭션이 없다고?
현재 @TransactionalEventListener(phase = TransactionPhase.AFTER_COMMIT) 이용 중임을 떠올린 나는, 다음과 같은 생각을 했다.
하나의 트랜잭션 컨텍스트 안에서 트랜잭션을 닫고 다시 열 순 없다.
AFTER_COMMIT은 트랜잭션 커밋 후 동작하는 방식이다. 즉 새로운 트랜잭션 컨텍스트를 여는 것을 가정했다.
그런데 트랜잭션이 없다는 것은, 기존 트랜잭션 컨텍스트가 전파된 것으로 보인다.
내가 비동기 처리를 안했었나?
참고: TransactionPhase.AFTER_COMMIT의 동작 방식
기본적으로 스프링의 트랜잭션 컨텍스트는 다음과 같은 상태를 갖는다.
각 상태의 진입 직전과 Transition 직전에 콜백 함수로 기능이 들어가는 것이다.
즉, AFTER_COMMIT 은 COMMITED 이후 콜백 함수로 들어가는 형태이다.
이 상황에서 다시 트랜잭션을 걸려면 NO_TX 상태로 전이가 된 상태여야 한다.
하지만 애초에 우리가 원하던 기능은 위와 같은 상황도 아니었고, 별개의 스레드에서 별개의 트랜잭션 컨텍스트를 갖기를 원하는 상황이었다.
오랜만에 백엔드 코드를 짜느라, @EnableAsync 처리를 깜빡했다는 걸 떠올렸다..
@EnableAsync
스프링의 가장 강력한 이점으로는 어노테이션과 리플렉션을 이용한 간편한 세팅을 들 수 있다.
하지만 어노테이션과 리플렉션 방식은 날것으로 보면 문자열 비교 방식과 크게 다를 바 없어서, 성능에 좋지 않은 영향을 끼친다.
좀 더 구체적으로 이야기하자면, 스프링은 BeanPostProcessor가 @Async가 붙은 메소드들에 대하여 프록시로 감싸는 형태로 반환하는데(이는 AOP의 동작 방식과 유사하다), 매 스프링 컨텍스트 로드시마다 @Async 를 위해 모든 빈을 스캔하는 것은 불필요한 방식이다.
좀 더 소프트웨어 공학적으로 이야기하자면, 서로 책임이 다른 스프링 컨텍스트의 로드 과정과 비동기 작업 등록 작업을 묶어 결합도를 높일 필요가 없다.
이후 jpaRepository.flush() 를 수행한 결과, 정상적으로 쿼리가 날아가는 것을 확인할 수 있었다.
그런데 문제가 있다.
원래 코드를 작성했을 때 기대한 것은 리포지토리에서 자체적으로 insert와 update를 구분하여 동작하길 기대한 것이었는데, update 쿼리가 날아가고 있었다.
실제 JPA의 insert 와 update 의 구분 방식을 확인해보자.
위 코드에서 보듯, entityInformation.isNew()의 결과에 따라, persist(insert) 와 merge(update)로 동작 방식이 달라진다는 것을 알 수 있었다.
즉 isNew의 동작 방식이 중요했기에, 그 구현체들을 살펴보았다.
다양한 구현체들의 new 검증 방식을 볼 수 있었다.
공통적으로 id 값이 null 이면 새로 persist, null 이 아니면 기존 데이터에 merge 하는 형태로 동작한다.
예상한 방식과 크게 다르지 않은데, 왜 문제가 되는걸까?
그래서 다시 확인해보니, 테이블 내에 통계가 생겼다.
아까 @EnableAsync 어노테이션을 붙이면서, JPA 자체는 정상적으로 동작했던 것으로 보인다.
insert 쿼리를 내가 못봤을 뿐, 정상적으로 동작했고, 기록이 여전히 0분 0초여서 헷갈렸던 것일 뿐이었다.
JPA 무죄!
그럼 이제 문제는 다른 곳으로 옮겨갔다.
어째서 프론트의 statistics가 값 갱신이 되지 않는가?
객체 내부에서 갱신도 잘 됐고, 쿼리도 잘 날아가면, DB에 저장도 잘 되어야 하는 것 아닌가?
DB 내에 있는 정보를 다시 한번 확인해보자.
여전히 elapsed time은 0을 가리킨다.
사실 저 값에 문제가 없었다면? 이라는 생각에 GPT에게 다음과 같은 질문을 수행했다.
즉, 위 기록은 시작하자마자 종료한 흔적이고, DB에 저장된 형식은 별 문제가 없었다.
조금 기다린 뒤 통계를 기록한 결과, 다음과 같이 결과가 잘 저장된 것을 확인할 수 있었다.
