아 비상이다 비상... 에러가 이틀째 찾고 있다. 사실 해결방법은 찾았는데 왜 그런지 모르겠어서 이틀째 찾고 있는데 자료가 별로 없다..
그래서 지금 다 로그 찍어서 보는 중.. 그랬더니 아주 난리다 난리
분산락 관련해서는 프로젝트 적용을 위해 블로그에 이미 기록을 했다
https://haebing.tistory.com/99
문제상황
나는 동시성 문제를 분산락 Redisson을 이용해서 해결하려고 하고 있다. 그래서 분산락 관련된 AOP클래스를 만들고 joinPoint.proceed()는 따로 트랜젝션으로 시작하게 하기 위해
propagation = Propagation.REQUIRES_NEW
로 따로 클래스를 분리해두고 부모 커밋해야 다른 스레드가 이용할 수 있게 해놨다.
그니까 순서대로 얘기하자면 aop 시작 -> 분산락 적용된 메소드 트랜젝션 시작 -> 분산락 트랜젝선 종료 -> aop 종료
일단 문제점 1. insert가 2번된다
-> 나는 예약을 하는 서비스라 한 날짜에 한 사람만 예약이 가능한 상황이라 딱 1번만 insert가 되어야하는데 2,3,4,5 어째든 여러번 insert되는 경우가 뜬다
문제점 2. lock에 대해서 정확히 걸리지 않는다.
내가 이해한 aop와 트랜젝션은
aop 시작 -> 분산락 걸린 트랜젝션 시작 -> 분산락 걸린 트랜젝션 종료 -> aop 종료다.
즉 한 쓰레드가 저 과정을 다 거친후에 다른 쓰레드가 lock을 획득하고 진행 가능하다. 근데 로그를 보면 아주 가관이다.
2023-12-02T01:24:49.428+09:00 DEBUG 1832 --- [ool-4-thread-12] o.s.orm.jpa.JpaTransactionManager : Creating new transaction with name [com.project.dogwalker.reserve.service.ReserveServiceImpl.reserveService]: PROPAGATION_REQUIRED,ISOLATION_DEFAULT
2023-12-02T01:24:49.429+09:00 TRACE 1832 --- [pool-4-thread-5] o.s.t.i.TransactionInterceptor : Getting transaction for [com.project.dogwalker.reserve.service.ReserveServiceImpl.reserveService]
2023-12-02T01:24:49.429+09:00 DEBUG 1832 --- [ool-4-thread-12] o.s.orm.jpa.JpaTransactionManager : Opened new EntityManager [SessionImpl(1565654762<open>)] for JPA transaction
2023-12-02T01:24:49.428+09:00 DEBUG 1832 --- [pool-4-thread-6] o.s.orm.jpa.JpaTransactionManager : Opened new EntityManager [SessionImpl(1465083820<open>)] for JPA transaction
2023-12-02T01:24:49.429+09:00 DEBUG 1832 --- [ool-4-thread-17] o.s.orm.jpa.JpaTransactionManager : Creating new transaction with name [com.project.dogwalker.reserve.service.ReserveServiceImpl.reserveService]: PROPAGATION_REQUIRED,ISOLATION_DEFAULT
2023-12-02T01:24:49.428+09:00 DEBUG 1832 --- [ool-4-thread-13] o.s.orm.jpa.JpaTransactionManager : Opened new EntityManager [SessionImpl(1297603577<open>)] for JPA transaction
2023-12-02T01:24:49.430+09:00 DEBUG 1832 --- [ool-4-thread-17] o.s.orm.jpa.JpaTransactionManager : Opened new EntityManager [SessionImpl(1019272060<open>)] for JPA transaction
2023-12-02T01:24:49.430+09:00 DEBUG 1832 --- [ool-4-thread-18] o.s.orm.jpa.JpaTransactionManager : Creating new transaction with name [com.project
일단 여러 스레드가 트랜젝션을 시작한다.. 이러면 안된는데...거기다가 lock획득이 진행되고 되야하지 않나..?
문제점 3. lock을 획득하지 않은채로 분산락 걸린 메서드를 실행한다.
2023-12-02T01:24:54.540+09:00 INFO 1832 --- [ool-4-thread-20] c.p.d.aop.distribute.DistributedLockAop : redis lock start
2023-12-02T01:24:54.463+09:00 INFO 1832 --- [ool-4-thread-12] c.p.d.r.service.ReserveServiceImpl : reserve service start
로그를 일부만 발췌한거지만 스레드 12는 lock을 획득한후 분산락 걸린 메서들 실행할 수 있는데 로그를 찾아봤느데 redis lock start라는 로그가 없다.. 다른 스레드가 시작한 로그만 있을뿐..
아 아주 총체적 문제점들이네???
그래서 생각한게 트랜젝션 문제들 같은데..? 라는 생각이 확 들었다.
나의 해결책
사실 아직 왜 저렇게 트랜젝션이 꼬이는지 이유를 찾지 못했지만 해결책은
내가 분산락이 걸린 메서드(서비스쪽)에 @Transactional을 뺐더니 트랜젝션들이 아주 순차적으로 잘 실행된다
2023-12-02T01:38:14.827+09:00 INFO 1894 --- [ool-4-thread-30] c.p.d.aop.distribute.DistributedLockAop : redis lock start
2023-12-02T01:38:14.827+09:00 DEBUG 1894 --- [ool-4-thread-30] o.s.orm.jpa.JpaTransactionManager : Creating new transaction with name [com.project.dogwalker.aop.distribute.AopForTransaction.proceed]: PROPAGATION_REQUIRES_NEW,ISOLATION_DEFAULT
2023-12-02T01:38:14.827+09:00 DEBUG 1894 --- [ool-4-thread-30] o.s.orm.jpa.JpaTransactionManager : Opened new EntityManager [SessionImpl(1605953943<open>)] for JPA transaction
2023-12-02T01:38:14.827+09:00 DEBUG 1894 --- [ool-4-thread-30] o.s.orm.jpa.JpaTransactionManager : Exposing JPA transaction as JDBC [org.springframework.orm.jpa.vendor.HibernateJpaDialect$HibernateConnectionHandle@6ab04b0e]
2023-12-02T01:38:14.827+09:00 TRACE 1894 --- [ool-4-thread-30] o.s.t.i.TransactionInterceptor : Getting transaction for [com.project.dogwalker.aop.distribute.AopForTransaction.proceed]
2023-12-02T01:38:14.828+09:00 INFO 1894 --- [ool-4-thread-30] c.p.d.r.service.ReserveServiceImpl : reserve service start
2023-12-02T01:38:14.828+09:00 INFO 1894 --- [ool-4-thread-30] c.p.d.r.service.ReserveServiceImpl : reserve exist start
2023-12-02T01:38:14.828+09:00 TRACE 1894 --- [ool-4-thread-30] o.s.t.i.TransactionInterceptor : No need to create transaction for [org.springframework.data.jpa.repository.support.SimpleJpaRepository.findByWalkerUserIdAndServiceDate]: This method is not transactional.
2023-12-02T01:38:14.884+09:00 DEBUG 1894 --- [ool-4-thread-30] org.hibernate.SQL :
2023-12-02T01:38:14.886+09:00 INFO 1894 --- [ool-4-thread-30] c.p.d.r.service.ReserveServiceImpl : reserve exist end
2023-12-02T01:38:14.886+09:00 TRACE 1894 --- [ool-4-thread-30] o.s.t.i.TransactionInterceptor : No need to create transaction for [org.springframework.data.jpa.repository.support.SimpleJpaRepository.findByUserEmailAndUserRole]: This method is not transactional.
2023-12-02T01:38:14.887+09:00 DEBUG 1894 --- [ool-4-thread-30] org.hibernate.SQL
2023-12-02T01:38:14.901+09:00 DEBUG 1894 --- [ool-4-thread-30] o.s.orm.jpa.JpaTransactionManager : Closing JPA EntityManager [SessionImpl(1605953943<open>)] after transaction
2023-12-02T01:38:14.902+09:00 INFO 1894 --- [ool-4-thread-30] c.p.d.aop.distribute.DistributedLockAop : redis unlock
lock을 획득한 스레드 30이 순차적으로 잘 실행 하고 있는 걸 볼 수 있다.
lock을 획득해도 이미 예약이 있는 스레드들 경우에도 순차적으로 잘 실행되고 있다
2023-12-02T01:38:14.903+09:00 INFO 1894 --- [ool-4-thread-39] c.p.d.aop.distribute.DistributedLockAop : redis lock start
2023-12-02T01:38:14.903+09:00 DEBUG 1894 --- [ool-4-thread-39] o.s.orm.jpa.JpaTransactionManager : Creating new transaction with name [com.project.dogwalker.aop.distribute.AopForTransaction.proceed]: PROPAGATION_REQUIRES_NEW,ISOLATION_DEFAULT
2023-12-02T01:38:14.903+09:00 DEBUG 1894 --- [ool-4-thread-39] o.s.orm.jpa.JpaTransactionManager : Opened new EntityManager [SessionImpl(1761827908<open>)] for JPA transaction
2023-12-02T01:38:14.904+09:00 DEBUG 1894 --- [ool-4-thread-39] o.s.orm.jpa.JpaTransactionManager : Exposing JPA transaction as JDBC [org.springframework.orm.jpa.vendor.HibernateJpaDialect$HibernateConnectionHandle@6d3cd5bc]
2023-12-02T01:38:14.904+09:00 TRACE 1894 --- [ool-4-thread-39] o.s.t.i.TransactionInterceptor : Getting transaction for [com.project.dogwalker.aop.distribute.AopForTransaction.proceed]
2023-12-02T01:38:14.904+09:00 INFO 1894 --- [ool-4-thread-39] c.p.d.r.service.ReserveServiceImpl : reserve service start
2023-12-02T01:38:14.904+09:00 INFO 1894 --- [ool-4-thread-39] c.p.d.r.service.ReserveServiceImpl : reserve exist start
2023-12-02T01:38:14.904+09:00 TRACE 1894 --- [ool-4-thread-39] o.s.t.i.TransactionInterceptor : No need to create transaction for [org.springframework.data.jpa.repository.support.SimpleJpaRepository.findByWalkerUserIdAndServiceDate]: This method is not transactional.
2023-12-02T01:38:14.904+09:00 DEBUG 1894 --- [ool-4-thread-39] org.hibernate.SQL :
2023-12-02T01:38:14.910+09:00 INFO 1894 --- [ool-4-thread-39] c.p.d.r.service.ReserveServiceImpl : reserve exist true
2023-12-02T01:38:14.911+09:00 TRACE 1894 --- [ool-4-thread-39] o.s.t.i.TransactionInterceptor : Completing transaction for [com.project.dogwalker.aop.distribute.AopForTransaction.proceed] after exception: com.project.dogwalker.exception.reserve.ReserveAlreadyException
2023-12-02T01:38:14.911+09:00 DEBUG 1894 --- [ool-4-thread-39] o.s.orm.jpa.JpaTransactionManager : Initiating transaction rollback
2023-12-02T01:38:14.911+09:00 DEBUG 1894 --- [ool-4-thread-39] o.s.orm.jpa.JpaTransactionManager : Rolling back JPA transaction on EntityManager [SessionImpl(1761827908<open>)]
2023-12-02T01:38:14.911+09:00 DEBUG 1894 --- [ool-4-thread-39] o.s.orm.jpa.JpaTransactionManager : Closing JPA EntityManager [SessionImpl(1761827908<open>)] after transaction
2023-12-02T01:38:14.912+09:00 INFO 1894 --- [ool-4-thread-39] c.p.d.aop.distribute.DistributedLockAop : redis unlock
아 모르겠다... 멘토님께...질문을
하루종일 찾아보다가 모르겠어서 멘토님께 질문드렸다. 왜 그런지 모르겠다고..
멘토님이 답변을 주셨다
이렇게 되어있군요..! 요러면 제대로 동작하지 않을 수 있습니다.
이유는 현재 붙여주신 것이 @DistributedLock과 동일한 레벨에 있기 때문에
DistributedLock의 해제와 transaction이 한데 묶여버립니다.
즉 distributed lock이 해제가 되고 transaction이 끝나는 형태가 되기때문에 이때 db insert가 발생하게 되어요.
그래서 중복된 데이터 save가 생깁니다.
@Transactional을 DistributedLock보다 작게 잡아주시면 될것 같아요.
이미 aopTransaction으로 tx를 잡아주셨기때문에 별도로 잡아주지 않으셔도 될것 같습니다.
역으시 트랜젝션 문제...
멘토님 말씀을 분석해보면 결국 aop의 트랜젝션과 service에 붙인 트랜젝션이 동일한 레벨에 있기 때문에 그렇다는 것같다
동일한 레벨??이게 무슨말이람??뭔가 몸으로는 체감되는 느낌인데 머리로는 이해안됨..
찾아보니 동일한 레벨이란 동일한 격리수준이라는 뜻이다.
뭐? 격리수준은 또 뭔데??
동시에 db에 접근할때 그 접근을 어떻게 제외할지 에 대한 설정이다.
즉 동시에 여러 트랜젝션이 처리될때, 특정 트랜젝셔이 다른 트랜젝션이 변경한 데이터를 볼 수 있도록 허용할지 말지를 결정하는 것
(트랜젝션 격리수준은 인터넷 찾아보면 많으니 모르시면 검색해보세유)
조금더 깊게 들어가보자면
이부분은 프록시에 대해 더 공부해야하지만 aop분산락과 @Transactional서비스 이렇게 되면 각각 프록시 객체가 생성된다.
여기서 문제가 만약 내가 해당 서비스 쪽 메서드를 호출하면 aop분산락 프록시가 호출될것이라고 생각하지만 아니다..
사실 명확한 순서를 모른다. 앞서 말했다 싶이 동일한 레벨에 있기떄문에 호출순서가 명확하지 않다.
그래서 앞서 aop 프록시가 먼저 호출될 수도 있고 서비스 쪽 트래젝션이 먼저 호출될 수 있기때문에
insert가 두번되는 현상, lock을 얻지도 않았는데 서비스 메서드를 수행하는 현상등이 발생한 것이다.
아 이게 맞는 말인것같다. 내 스스로 납득되었다. 그래서 aop쪽에 @Order(1)과 같이 순서를 매겨주면 서비스쪽에 트랜젝션 어노테이션이 있어도 aop가 먼저 실행되어 정상적인 결과가 나온다.
어렵다 어려워... 처음으로 트랜젝션 관련 문제를 만나서..아..?아..?아..? 이러다가 멘토님의 도움으로 힌트를 얻고 트랜젝서-> 프록시 -> 트랜젝션 순서?? 이렇게 공부하다보니 나온결론. 아 짜릿해
'프로젝트 > 개인 프로젝트(2023.11.13-2023.12.18)' 카테고리의 다른 글
| [개인프로젝트] CascadeType 미설정 오류 (0) | 2023.12.17 |
|---|---|
| [개인프로젝트] JPA OneToOne N+1 문제 (1) | 2023.12.17 |
| [개인프로젝트] Redis 역직렬화 문제 (0) | 2023.12.16 |
| Elastic Search 프로젝트에 적용하기 (0) | 2023.12.16 |
| [개인프로젝트] @FeignClient 파라미터 오류 (1) | 2023.11.22 |
