Trouble Shoot
상황
구현 코드
public Mono<AddToQueueInfo> addToQueue() {
var unixTimestamp = Instant.now().getEpochSecond();
var uuid = UUID.randomUUID();
log.info("ADDING TO QUEUE... timestamp = {}, uuid = {}", unixTimestamp, uuid);
return reactiveRedisTemplate.opsForZSet().add(USER_QUEUE_WAIT_KEY, String.valueOf(uuid), unixTimestamp)
.doOnNext(user -> log.info("UUID : {}, THREAD : {}", uuid, Thread.currentThread().getName()))
.filter(user -> user)
.flatMap(i -> reactiveRedisTemplate.opsForZSet().rank(USER_QUEUE_WAIT_KEY, uuid.toString()))
.map(rank -> {
log.info("USER RANK IN THE WAITING QUEUE, RANK : {}, UUID : {}, THREAD : {}", rank + 1, uuid, Thread.currentThread().getName());
return new AddToQueueInfo(rank + 1, uuid.toString());
});
}테스트 코드
@Test
void addToQueue() throws InterruptedException {
StepVerifier.create(waitService.addToQueue())
.expectNextMatches(info -> info.rank() == 1L && isUUID(info.uuid()))
.verifyComplete();
StepVerifier.create(waitService.addToQueue())
.expectNextMatches(info -> info.rank() == 2L && isUUID(info.uuid()))
.verifyComplete();
}
StepVerifier.create(waitService.addToQueue())
.expectNextMatches(info -> info.rank() == 3L && isUUID(info.uuid()))
.verifyComplete();
}위 테스트 코드는 실패했다. 두 번째의 verifyComplete() 지점이 실패했다. 왜냐하면 info.rank()가 2L이 아니라 1L이 나왔기 때문이다.
왜 그럴까?
앞선 verifyComplete()에서 1L이 rank로 나왔는데, 왜 두 번째의 rank도 똑같이 1L이 나온 것일까?
문제 요약
위 코드는 대기열에 사용자를 추가하는 로직이다.
대기열에 사용자를 추가하고나서, 사용자의 대기 순서를 반환하게 되는데, 그 순서가 연이어서 동일한 값이 나오는 현상이 발생했다.
아래의 사진에서 확인할 수 있다시피, rank가 13인 경우가 두 번 연이어서 출력되었다.
문제 해결 과정
Step 1. 공유된 자원에 동시에 접근하는 동시성 문제 의심
최초에는 이 문제의 발생 원인을 동시성 문제로 생각했다. 구체적으로 설명하자면, 데이터를 redis에 add하고 rank하는 시점이 예상과 달라서 발생되는 동시성 문제라고 생각했다. 그래서 thread id 로그를 출력했고, redis-cli에서도 monitor로 zadd, zrank 명령어의 순서를 확인했다. 하지만 데이터를 add하는 것과 rank하는 순서는 예상대로 출력되었다.
A 데이터 추가 -> A 데이터 순서 반환 -> B 데이터 추가 -> B 데이터 순서 반환
현재 로컬 환경에서 사용하고 있는 redis의 버전은 7.2.4인데, redis는 버전 6부터 네트워크 연결 시, 멀티 스레드 방식으로 동작한다. 하지만 내부 동작을 처리함에는 여전히 단일 스레드로 동작한다. 그래서 이러한 동시성 문제 발생 가능성 자체가 없었다.
그 다음, 애플리케이션 코드도 webflux로 구현되어 있고, 단일 서버만 띄워둔 상태인데다가, 동일한 스레드 내에서 이벤트 루프로 요청이 처리되기 때문에 위와 같은 동시성 문제 발생 가능성을 예측하기 어려웠다.
Step 2. timestamp score
다시 로그에 출력된 값들을 살펴보았다.
timestamp, thread id, uuid 값들을 살펴보았다.
그러다가 문제의 원인을 발견하였다. 동일한 대기열 순서를 반환하고 있는 데이터의 경우, 동일한 timestamp 값을 갖고 있었다. 그리고 timestamp는 sorted set 자료구조를 갖고 있는 대기열에서 score 값으로 사용되고 있었다. score 값이 동일한 데이터가 두 개 이상 들어왔기 때문에, redis의 sorted set 정렬 방식 특성 상, value 값을 사전순으로 재배열하는 과정이 생겼던 것이다.
그렇다면 왜 timestamp가 동일한 경우가 생기게 되었을까?
분명 두 개의 요청은 완전 동일한 때에 보내지 않았다. 그런데 timestamp의 값은 동일하게 기록되었다.
그 원인은 다음과 같다.
기존 코드에서 unixTimestamp 값은 Instant.now().getEpochSecond()로 할당해주었다. 그런데 이것은 초 단위로 값을 생성하기 때문에, 초 기준 비슷한 시기에 요청을 보내는 경우라면 동일한 timestamp 값을 갖게 되었던 것이다.
위 사진에서 보면, 1718940583 즉, unixTimestamp 값은 동일하다. 그런데 대기열에 먼저 들어온 값은 c6472f47-d964-4497-89ea-d01f48105cdd였다. 하지만 그 다음 들어온 값인 47bf196d-9971-44af-8115-54ceec614290이 사전 순으로 더 우선하기 때문에 순서가 자동으로 조정된 것이다.
그래서 결국 중복된 rank가 출력되는 상황이 발생한 것이다.
재정리
결국, 문제는 먼저 들어온 값이 뒤로 밀려나게 된다는 것이다. 다시 말해, 대기열의 순서 공정성이 보장되지 않는다는 것이다. 그리고 이는 timestamp 값이 느슨하게 기록되는 것에서 비롯되었다.
결론 : 초 단위보다 세밀하게 timestamp 값을 생성하고, 관리하는 작업이 필요하다.
문제 해결
기존 코드
var unixTimestamp = Instant.now().getEpochSecond();수정 코드
var unixTimestamp = System.currentTimeMillis();기존 코드의 Instant.now().getEpochSecond()는 초 단위의 타임스탬프를 반환한다. 수정 코드의 System.currentTimeMillis()는 밀리초 단위의 타임스탬프를 반환한다.
--
(추가) System 클래스는 System.out.println() 때 많이 봤지만, 잘 알지 못해서 한번 찾아보았다. println() 메서드 안에 있는 newline() 메서드는 synchronized 키워드가 붙어 있다. 그래서 하나의 임계 영역으로서 메서드 호출 시, 해당 메서드가 잠기게 된다. 그래서 System.out.println()의 경우 로컬 환경에서만 사용하고, 실제 개발 및 운영 환경에서 사용하면 안 된다는 말을 많이 들었던 것이다. currentTimeMillis()도 System의 정적 메서드로 혹시 그런 부분이 있을까봐 찾아봤는데, 문제가 없었다. 단지 주의점은, 컴퓨터 OS의 시간과 실제 UTC 간의 시간 차가 있을 수 있다는 것이다. System.currentTimeMillis()은 OS의 시간을 기준으로 하기 때문이다.
