PessimisticLockException 원인 파악하고 해결하기

현상

 

점심을 먹고 가볍게 산책을 하고 있는데.. RDB와 연결된 서버에서 헤비 트래잭션이 발생했다.

*/userBehavior API는 사용자 행위를 추적하는 기능으로 "어떤 사용자가 어떤 행위를 했다"의 정보를 저장하는 단순한 기능이다. 그런데 이렇게 간단한 기능이 50초 이상 여러 번 수행된 흔적이 보였다. 게다가 Select도 아닌 insert query에서 발생했다.

 

원인

원인 분석

우선 트랜잭션 히트맵을 확인했다. 문제가 발생한 13:00 ~ 13:10 구간으로 조회했더니 헤비 트랜잭션이 조회되긴하지만 별다른 근거를 찾지 못했다. 

 

다음으로 로그를 확인했다. 로그 트렌드 페이지는 선택한 Key-Value 쌍으로 로그를 검색해서 "분 당 로그 수"의 추이를 확인하고 원본 로그까지 확인할 수 있는 페이지이다. 아래의 사진에서는 문제가 발생한 13:00 ~ 13:10 시간에 문제가 된 서버 이름(oname)으로 로그를 검색했을 때 조회된 로그이다. PessimisticLockException과 TransactionException이 발생한 것을 확인할 수 있다.

 

다음으로 DB 모니터링을 확인했다. Lock Tree가 발생한 것이 관측되었고, DB Pool이 말라 버린 것도 확인할 수 있었다.

 

그리고 SQL 통계 페이지에서 문제가 발생한 10분 구간에서 호출된 SQL을 확인했더니 DELETE  query가 수행되었다.

분명히 트랜잭션에서는 Insert 쿼리가 발생했었는데 Delete Query가 관측된다. 히트맵에서 확인했던 Insert 쿼리가 발생한 트랜잭션은 직접적인 원인이 아니고 피해를 받은 트랜잭션일 가능성이 생겼다. 사용자 행위 정보가 삭제되는 로직이 있는지 담당자 연우님께 확인해보니 새벽 4시에 수행되는 배치잡이 있다고 들었다. 문제가 발생한 13시와 딱 9시간 차이라서 TimeZone 문제일 것이라는 추정이 들었다.  코드를 확인해보니 TimeZone 설정이 누락되었다.  

@Scheduled의 설명을 확인해보면 zone을 지정하지 않으면 서버의 로컬 시간이 사용된다고 되어 있다.  문제가 발생한 서버는 서울 리전이고 서울 리전 서버는 UTC로 지정되어 있으므로, 서버 시간 기준으로 04시에 수행되면 브라우저 시간 기준으로는 13시에 수행된다. 

깊게 이해하기

전체적인 큰 그림이 그려졌으니 다시 한 번 검토해보자. 먼저 Scheduler가 의도하지 않은 시간에 동작했다. (TimeZone 지정의 오류) 그래서 문제가 발생한 10분 구간에서 호출된 SQL을 확인했더니 DELETE query가 수행되었다. (오래된 정보를 삭제하는 배치 잡이 수행됨) 이 과정에서 Lock Tree가 발생한 것이 관측되었다. 

https://docs.whatap.io/postgresql/analysis-lock-and-deadlock

아래의 사진을 확인하면 첫 번째 Delete 쿼리가 Lock holder이고, 두 번째 Delete 쿼리가 Lock Waiter이다. 

히트맵에서 Insert를 수행하는 트랜잭션이 오랫동안 수행된 것은 Delete 쿼리의 경합에 의해서 Lock Tree가 발생하고 이 과정에서 DB Pool이 말라버렸기 때문이다. Delete 쿼리가 가해자이고 Insert 쿼리는 피해자이다. 

 

그러면 애초에 PessimisticLockingFailureException이 왜 발생했을까? 사용자 행위를 담당하는 서버가 Scale-Out 되어있었고 여러 개의 서버에서 동시에 같은 Row를 삭제하려고 했기 때문이다. 위 락트리 정보에서도 서로 다른 host에서 같은 query가 수행된 것을 볼 수 있다.

 

이런 문제를 제일 간단하게 처리하려면 특정 서버에서만 스케줄러를 활성화할 수 있지만, 이렇게 되면 어떤 서버에 어떤 설정을 넣어야하는지 계속 챙겨야하고 Scale Out의 목적에서 벗어나는 것 같다. 좀 더 안전하게 처리하려면 중앙에서 관리되는 락을 사용하는 방법이 있다. 락을 담당할 객체를 생성하고 이 객체를 조회할 때 @Lock(LockModeType.PESSIMISTIC_WRITE)을 사용한다면 좀 더 우-아하게 하나의 서버에서만 스케줄러가 동작함을 보장할 수 있다. 

대응

아래의 코드는 다음의 수정 사항이 반영된 모습이다.

1. zone = "Asia/Seoul" 추가
2. 스케줄러 비활성화 옵션 추가 (scheduler_delete_old_behaviors)
3. 중앙 집중화된 락 객체 적용 (schedulerLockService)