앱이 배포된 상태에서 유저의 피드백을 통해 동시성 문제를 발견하고 해결하였다. 처음에는 문제의 원인도 찾기 어려웠는데 문제를 분석해보면서 결국에는 동시성 문제인것을 확인했다. 문제의 원인을 찾아 나간 과정이 흥미로워서 글로 공유 해보려한다.

프로젝트 소개

먼저 문제를 소개하기 앞서 문제가 발생한 프로젝트에 대한 정보를 알아야 이해하기 쉬울 것 같아 프로젝트 소개부터 해보겠다. 현재 그라운드 플립 이라는 프로젝트를 진행중이다. 그라운드 플립은 내가 걸은 영역을 나의 땅으로 만들어 영역을 차지해 나가는 서비스이다.

위 사진 처럼 내가 걸어서 차지한 영역은 초록색으로 표시되고 다른 사람들이 걸어서 차지한 영역들은 빨간색으로 표시된다. 그리고 아무도 밟지 않는 곳이라면 색칠 되지 않는 방식으로 서비스된다.

그리고 현재 내가 소유하고 있는 영역의 개수를 기반으로 랭킹 기능도 제공한다. 내가 1등이라도 다른 사람들이 나의 영역을 밟으면 영역을 빼앗기기 때문에 랭킹이 내려갈 수도 있는 시스템이다.

시스템 구성

위의 정보들을 어떤식으로 저장 하는지 간략하게 설명하겠다. 위 구조를 염두해두고 밑의 글을 읽으면 좋겠다.

영역정보

영역을 우리팀은 pixel 이라 부르기로 정의했다.

MySQL에 저장되며 각 영역마다 고유의 id 인 pixel_id 를 가진다. 그리고 pixel을 소유한 user의 id를 user_id 컬럼에 저장한다.

소유하고 있는 영역의 개수

Redis에서 Sorted Set(정렬 집합) 형태로 저장한다. value 가 user_id 이고 score 가 소유하고 있는 영역의 개수 이다. Sorted Set 을 사용했기에 소유하고 있는 영역의 개수순으로 정렬되어 저장되고 삽입속도도 빠르다.

픽셀 차지 코드

@Transactional
public void occupyPixel(PixelOccupyRequest pixelOccupyRequest) {
	// 땅을 차지 하려는 user id
	Long occupyingUserId = pixelOccupyRequest.getUserId();

	// 차지 하려는 땅을 조회
	Pixel targetPixel = pixelRepository.findByXAndY(pixelOccupyRequest.getX(), pixelOccupyRequest.getY())
		.orElseThrow(() -> new AppException(ErrorCode.PIXEL_NOT_FOUND));

	// 소유하고 있는 픽셀의 개수 추가
	updateRankingOnCache(targetPixel, occupyingUserId);
	//픽셀의 소유주 변경
	targetPixel.updateUserId(occupyingUserId);
}

더 많은 로직이 있지만 이 글에서는 문제와 관련된 코드만 가져왔다.

문제 인식

앱 스토어 출시후 주변지인들을 초대해 서비스 중이었다. 그러다가 영역을 하나 밟을 때마다 현재소유 하고 있는 영역의 개수가 2배씩 올라가는 문제를 발견했다…

확인해보니 프론트 측에서 땅을 차지한다는 요청을 두번 보내는 것을 발견했다. 하지만 나는 백엔드쪽에서 내가 이미 차지한 영역이면 개수가 증가하지 않게 로직을 짜두었다. 그런데 왜 동일한 땅에 대해 개수가 2번 증가하는 것일까?? 혼란스러웠다.

땅을 차지하는 요청을 2번 보낸다면 첫번째 요청에서 땅의 소유주를 나로 바꾸고 차지한 영역의 개수를 증가시킨다. 그리고 두번째 요청에서 땅의 소유주가 나이기 때문에 차지한 영역의 개수를 증가시키지 않아야한다.

private void updateRankingOnCache(Pixel targetPixel, Long occupyingUserId) {
	Long originalOwnerUserId = targetPixel.getUserId();
	// 원래 소유주와 소유하려는 사용자의 ID 가 같다면 아무 작업도 하지 않는다.
	if (Objects.equals(originalOwnerUserId, occupyingUserId)) {
		return;
	}

	if (originalOwnerUserId == null) {
		rankingService.increaseCurrentPixelCount(occupyingUserId);
	} else {
		rankingService.updateRankingAfterOccupy(occupyingUserId, originalOwnerUserId);
	}
}

차지한 영역의 개수를 증가시키는 코드를 보면 분명 분기문으로 본인 소유의 땅을 차지하는 경우에는 아무런 작업도 하지 않게 구현했다. 하지만 결과는 2번 증가한다…

문제 재현

여기까지는 화면에 표시된 화면과 DB의 데이터를 보고 오류를 발견했다. 이제부터는 예외 상황이 터지는 조건을 재현 시켜보기로 했다. 재현이 된다면 로그나 디버깅을 찍어 정확한 원인을 발견할 수 있을 것이라고 생각했다.

프론트에서 땅을 밟을 때 요청이 두번오는 것은 프론트 코드를 통해 발견했다. 그렇다면 동시에 여러 요청을 보내보면 동일한 문제가 발생하지 않을까 생각해보았다. 그래서 Jmeter 를 사용하기로 했다!!

Jmeter 는 서버가 제공하는 성능 및 부하를 측정할 수 있는 테스트 도구이다. 여러 스레드를 사용하여 동시에 여러 요청을 보내 성능 및 부하를 측정할 수 있다.

1초동안 스레드 10개

Jmeter 를 사용해 EC2 개발용 서버에 요청들을 보내보았다. 우선 스레드 10개를 사용해 1초 동안 쏴 보았다. 요청은 user id 가 444 이고 1000번 땅을 차지 한다는 요청 10개였다.

실수로 2번 실행해서 jmeter 보고서에 20번 찍혔다.. 😓

차지한 영역을 저장하는 레디스를 확인해보니 4번 증가 했다. 1개가 증가 했어야하는데 4개가 증가했다.

1초동안 스레드 50개

좀더 많이 쏴보았다. 스레드 50개를 사용해 1초 동안 쏴 보았다. 요청은 user id 가 446 이고 1001번 땅을 차지 한다는 요청 50개였다.

이번에도 1개가 증가했어야하는데 10개가 증가했다.

여러번 시도해도 똑같이 1개이상의 점수가 추가되었다. 이 결과들을 보고 확실해졌다. 짧은 시간에 같은 요청이 들어가면 생기는 문제이다 라는 결론이 나왔다. 이제 어떤 상황에서 문제가 발생하는지는 확실해 졌다. 하지만 아직 왜 이런 문제가 생기는지는 찾지 못했다.

로그 찍어서 원인 찾기

원래 흐름

문제의 원인을 찾기 위해 요청을 처리하는 동안의 상태를 로그로 남겨보기로 했다. 먼저 원래 흐름을 보자.

위에서 프로젝트에서 차지하는 영역을 pixel 이라고 표현한다고 소개했었다. pixel을 차지 하는 요청을 서버에 보내면 서버는 DB에서 pixel 정보를 조회한다. 이 pixel 정보에 따라 서버는 다른 로직을 실행한다.

• pixel에 소유주가 없거나 다른 사용자인 경우
  • 내가 그 땅을 차지 하는 경우이니 Redis에 1점을 추가 해주고 DB에도 소유주를 업데이트 해준다.
• pixel에 소유주가 나인 경우
  • 이미 내 소유이므로 소유주를 업데이트 할 필요도 없고 점수를 추가할 필요도 없기 때문에 아무 로직을 실행하지 않고 종료한다.

위 로직을 보면 DB 에 저장되있는 pixel에 상태에 따라 소유한 영역의 개수를 업데이트 하는 것을 알 수있다. 즉 이 로직의 핵심은 DB에 저장되어있는 pixel의 상태라고 판단했다.

그래서 나는 DB에서 조회해온 pixel의 상태를 로그를 찍어보면 문제의 원인을 찾을 수 있을 것이라고 생각해서 pixel의 소유주의 id에 대한 로그를 찍는 코드를 추가했다. 그 후 다시 Jemter 를 사용해 요청을 보냈다.

결과는 첫 10개 요청에서 DB에서 조회한 pixel의 소유주에 대한 값이 null 로 찍혔다. 내가 의도한 대로라면 첫 요청만 null 이고 나머지 요청들에 대한 소유자 값은 null 이 아닌 소유주의 id 가 들어있어야 했다.

서버에서 초반에 업데이트된 값을 읽지 못하고 업데이트 전의 값을 읽는 것이 로그를 통해 확실 해졌다.

원인 분석

위 결과를 보자마다 옛날에 들은 동시성 문제가 생각이 났다. 그리고 생각해보니 스프링 부트는 요청당 하나의 스레드를 할당해 요청을 처리한다. 그렇기에 동시에 여러 요청이 오면 여러 스레드가 할당되어 동시에 로직을 처리할 것이다. (동시에 처리되는 것 처럼 보이는 것이지만..) 이 개념이 생각나니 모든 문제가 맞아 떨어졌다.

먼저 들어온 스레드에서 pixel을 조회하고 작업을 실행하고 소유주의 상태를 업데이트 하는 것이 끝나기 전에, 다른 스레드가 DB 에서 업데이트 되기전의 pixel 정보를 조회해서 생기는 문제인것이다!! 좀 더 이해하기 쉽게 그림으로 알아보자.

간단하게 거의 동시에 동일한 2개의 요청이 왔다고 가정해보자. 위 그림처럼 스프링은 2개의 스레드를 사용해서 요청을 처리 할 것이다. 편의를 위해 시간은 1ms, 2ms .. 로 가정했다. 실제 시간은 아니다.

1ms

• 1ms 일때 스레드1 은 DB에 데이터를 조회하여 메모리에 가지고 있는다. 이때 DB에 user_id 가 null 이므로 소유주가 없는 상태로 조회된다.
• 스레드2 는 이제 요청을 받았다.

2ms

• 스레드1 는 픽셀에 소유주가 null 이므로 Redis에 1을 추가 한다.
• 스레드1 에서 아직 DB에 소유주를 업데이트 하는 요청을 보내지 않았기에 스레드2 에서는 업데이트 되지 않은 user_id 가 null 인 정보를 조회하여 메모리에 갖게 된다.

여기서 문제가 터진다. 스레드1이 업데이트를 하지 않았는데 스레드2에서 조회를 하게 되니 원래 의도했던 대로 동작하지 않는 것이다.

3ms

• 3ms 가 되서야 스레드1 은 DB에 소유주 업데이트 쿼리를 날린다.
  • 이때 스레드2가 데이터를 읽어서 처리해야 정상적으로 동작한다.
• 스레드2 입장에서는 픽셀 소유주가 null인 정보를 조회했으니 Redis에 1을 추가해서 총 점수가 2가 된다.

4ms

• 스레드1 은 응답을 한다
• 스레드2 는 다시 한번 DB에 소유주 업데이트 쿼리를 날린다. 같은 정보여서 바뀌진 않는다.

즉, 여러 스레드들이 동시에 변경되지 않은 같은 데이터를 참조하면서 생기는 동시성 문제 였던 것이다.

멘토님들께 말로만 듣던 동시성 문제를 내가 직접 경험해볼 줄은 몰랐다. 하지만 직접 경험해보니 반갑기도 하고 막막하기도 했던 것 같다. 코드 레벨에서는 문제점을 찾을 수 없고 내부 동작 원리까지 파악해야만 찾을 수 있는 문제였다.

이제 문제의 원인을 확실히 알았으니까 문제를 해결해야된다. 해결하는 과정은 글이 너무 길어져서 다음 글에서 다루어 보겠다.