nGrinder 적용기 - 2

일상 회고록·2024년 3월 25일
JPASpringbootnGrinder
0
post-thumbnail
post-custom-banner

안녕하세요!!

취업 준비로 바쁜 시간을 보내다 오랜만에 돌아왔습니다.

이번 포스팅은 nGrinder 1탄에 이어서 직접 구성한 시나리오를 살펴보고 실제 성능 테스트의 결과를 같이 알아볼까 합니다!

개인적으로 느낄 때 조금 난이도가 있어서 천천히 따라오시면 좋을 것 같습니다. (직접 본인의 프로젝트에 적용해보는 것이 가장 좋겠죠?!)

그럼 시작해 보겠습니다!

1. 시나리오 구성

브릿지 프로젝트는 앞서 설명했듯이 개발자와 디자이너들이 사이드 프로젝트 구인을 용이하게 하기 위한 어플리케이션입니다!

따라서 게시물 전체 조회 및 개별 조회와 유저가 직접 게시물을 작성하는 단계까지 시나리오에 포함시키려고 했습니다.

  1. 유저 토큰 발급 (게시글 조회 혹은 작성 시 토큰 필요)
  2. 게시물 전체 조회
  3. 유저의 관심분야로 필터링 한 후 게시글들 조회
  4. 특정 게시글 조회 및 북마크
  5. 유저가 게시글 작성
  6. 내가 작성한 게시글에 지원한 유저들 조회

최종적으로 위와같이 차례대로 총 6단계 시나리오로 구성했습니다.

테스트인 만큼 유의미한 결과를 얻기 위해서 실제 사용자들이라면 어떻게 사용할까? 를 중점적으로 상상하면서 구성했습니다.

그럼 이제 구성한 시나리오를 통해 스크립트를 작성해볼까요?

2. 스크립트 작성

전 편에서 정말 간단하게 스크립트를 작성했었는데요!

주 사용언어인 Java와 비슷해서 다행히 어렵지 않게 6개의 테스트를 작성할 수 있었습니다!

(여러 에러들을 거치긴 했지만, 처음 사용하는 언어여서 발생하는 작은 에러들이었습니다.)

최종적으로 아래와 같이 스크립트가 완성되었습니다.

import static net.grinder.script.Grinder.grinder
import static org.junit.Assert.*
import static org.hamcrest.Matchers.*
import net.grinder.script.GTest
import net.grinder.script.Grinder
import net.grinder.scriptengine.groovy.junit.GrinderRunner
import net.grinder.scriptengine.groovy.junit.annotation.BeforeProcess
import net.grinder.scriptengine.groovy.junit.annotation.BeforeThread
// import static net.grinder.util.GrinderUtils.* // You can use this if you're using nGrinder after 3.2.3
import org.junit.Before
import org.junit.BeforeClass
import org.junit.Test
import org.junit.runner.RunWith

import org.ngrinder.http.HTTPRequest
import org.ngrinder.http.HTTPRequestControl
import org.ngrinder.http.HTTPResponse
import org.ngrinder.http.cookie.Cookie
import org.ngrinder.http.cookie.CookieManager

@RunWith(GrinderRunner)
class TestRunner {

	public static GTest test00
	public static GTest test01
	public static GTest test02
	public static GTest test03
	public static GTest test04
	public static GTest test05
	public static HTTPRequest request
	public static Map<String, String> headers = [:]
	public static Map<String, Object> params = [:]
	public static List<Cookie> cookies = []

	@BeforeProcess
	public static void beforeProcess() {
		HTTPRequestControl.setConnectionTimeout(300000)
		test00 = new GTest(1, "test00")
		test01 = new GTest(2, "test01")
		test02 = new GTest(3, "test02")
		test03 = new GTest(4, "test03")
		test04 = new GTest(5, "test04")
		test05 = new GTest(6, "test05")
		request = new HTTPRequest()
		grinder.logger.info("before process.")
	}

	@BeforeThread
	public void beforeThread() {
		test00.record(this, "test00")
		test01.record(this, "test01")
		test02.record(this, "test02")
		test03.record(this, "test03")
		test04.record(this, "test04")
		test05.record(this, "test05")
		grinder.statistics.delayReports = true
		grinder.logger.info("before thread.")
	}

	@Before
	public void before() {
		request.setHeaders(headers)
		CookieManager.addCookies(cookies)
		grinder.logger.info("before. init headers and cookies")
	}
	
		// 토큰 발급
	@Test
	public void test00() {
		grinder.logger.info("test00")
		String userId = "1"
		params = ["userId" : userId]
		HTTPResponse response = request.GET("http://localhost:8080/token", params)
		String token = response.getBodyText().toString()
		grinder.logger.info(token)
		headers["Authorization"] = "Bearer "+token
		if (response.statusCode == 301 || response.statusCode == 302) {
			grinder.logger.warn("Warning. The response may not be correct. The response code was {}.", response.statusCode)
		} else {
			assertThat(response.statusCode, is(200))
		}
	}
	
	// 모든 프로젝트 조회
	@Test
	public void test01() {
		grinder.logger.info("test01")
		params = ["userId" : "1"]
		
		HTTPResponse response = request.GET("http://localhost:8080/projects/all", params)

		if (response.statusCode == 301 || response.statusCode == 302) {
			grinder.logger.warn("Warning. The response may not be correct. The response code was {}.", response.statusCode)
		} else {
			assertThat(response.statusCode, is(200))
		}
	}
	//분야 필터링
	@Test
	public void test02() {
		grinder.logger.info("test02")
		String part = "\"BACKEND\""
		String body = "{\"part\":"+part+",\n \"skills\":"+["\"SPRINGBOOT\""]+"}"
		grinder.logger.info(body)
		HTTPResponse response = request.POST("http://localhost:8080/projects/category", body.getBytes())

		if (response.statusCode == 301 || response.statusCode == 302) {
			grinder.logger.warn("Warning. The response may not be correct. The response code was {}.", response.statusCode)
		} else {
			assertThat(response.statusCode, is(200))
		}
	}
	
	//특정 프로젝트 조회 및 북마크
	@Test
	public void test03() {
		grinder.logger.info("test03")
		String projectId = "18"
		params = ["userId" : "1", "projectId" : projectId]
		
		HTTPResponse response = request.GET("http://localhost:8080/project/one", params)

		if (response.statusCode == 301 || response.statusCode == 302) {
			grinder.logger.warn("Warning. The response may not be correct. The response code was {}.", response.statusCode)
		} else {
			assertThat(response.statusCode, is(200))
		}
		grinder.logger.info("test03-2")
		request.setHeaders(headers)
		projectId = "14"
		String body = "{\"projectId\":"+projectId+"}"
		HTTPResponse response2 = request.POST("http://localhost:8080/project/scrap", body.getBytes())

		if (response.statusCode == 301 || response.statusCode == 302) {
			grinder.logger.warn("Warning. The response may not be correct. The response code was {}.", response.statusCode)
		} else {
			assertThat(response.statusCode, is(200))
		}
	}
	
	//모집글 작성
	@Test
	public void test04() {
		grinder.logger.info("test04")
		String recruit = "{\"recruitPart\" : \"IOS\""+",\n \"recruitNum\" :"+"2"+", \n \"recruitSkill\" : "+["\"SWIFT\""]+ ",\n \"requirement\" : \"바라는 점\"}"
		String body = "{\"title\": \"project??\""+ ",\n \"overview\":\"소개\""+",\n \"dueDate\":\"2024-05-11T00:00:00\""+ ",\n \"startDate\":"+null+
",\n \"endDate\":"+null+",\n \"recruit\":"+[recruit]+",\n \"tagLimit\":"+["\"회사원\""]+",\n \"meetingWay\" : \"offline\""+",\n \"stage\" : \"구상 중\""+",\n \"userId\" : \"1\"}" 
		grinder.logger.info(body)
		HTTPResponse response = request.POST("http://localhost:8080/project", body.getBytes())

		if (response.statusCode == 301 || response.statusCode == 302) {
			grinder.logger.warn("Warning. The response may not be correct. The response code was {}.", response.statusCode)
		} else {
			assertThat(response.statusCode, is(200))
		}
	}
	
	//지원자 목록 확인
	@Test
	public void test05() {
		grinder.logger.info("test05")
		params = ["projectId" : "90"]
		
		HTTPResponse response = request.GET("http://localhost:8080/projects/apply/users", params)

		if (response.statusCode == 301 || response.statusCode == 302) {
			grinder.logger.warn("Warning. The response may not be correct. The response code was {}.", response.statusCode)
		} else {
			assertThat(response.statusCode, is(200))
		}
	}
}

주석을 달아놓았으니 이해하는데 크게 어렵진 않을 것 같습니다! :)
그럼 이제 진짜 최최종 성능 테스트를 수행해 볼까요?.?

3. 테스트 결과

에이전트는 1명이니 1로 설정해주고, 최대 동시 50명이 해당 시나리오대로 앱을 사용한다고 가정했습니다.
시간은 총 10분으로 설정한 뒤 테스트를 진행했습니다!


설레는 마음으로 테스트한 결과..

MTT(Mean Test Time) - 평균적인 1회 수행 시간
TPS(Transaction Per Second) - 서버가 초당 처리 할 수 있는 요청 개수

평균 테스트 시간이 무려 16초..란 무시무시한 결과와 에러를 배출하며 테스트가 중단되었습니다… …(오열)

아무리 수행되는 테스트가 많더라도 보통 TPS는 1초 미만으로 수행되어야 정상적입니다.

또한 MTT가 0.7초라는 건 성능 개선이 필요하다고 보여지는 결과입니다.


테스트가 수행되면 실제 SpringBoot 서버에서도 로그가 찍히는데요!

에러로 인해 도중에 중단되었기 때문에 에러로그 또한 확인 할 수 있었습니다.

에러는 아래와 같이 총 두가지가 있었습니다.

org.hibernate.StaleStateException: Batch update returned unexpected row count from update [0]; actual row count: 0; expected: 1; statement executed: delete from bookmark where bookmark_id=?
com.mysql.cj.jdbc.exceptions.MySQLTransactionRollbackException: Deadlock found when trying to get lock; try restarting transaction

첫번째 에러는 삭제를 하려고 보니 삭제할 행이 없었다,,이런 내용인 것 같습니다.

두번째 에러는 데드락과 연관된 에러인 것 같은데 데드락 말만 들어보다 실제 로그가 찍힌 걸 보니 신기하기도 하면서 설레(?)였습니다 후후.

한번 하나 씩 분석해 볼까요?

4. 에러 분석

사실 테스트의 목적이 서버의 버그 혹은 에러를 찾기 위함이니 한편으론 테스트가 통과되지 않기를 조금 기대했던거 같습니다.
백엔드의 꽃은 성능 분석과 개선이니까요!

4-1. 첫번째 에러

org.hibernate.StaleStateException: Batch update returned unexpected row count from update [0]; actual row count: 0; expected: 1; statement executed: delete from bookmark where bookmark_id=?

해당 예외를 검색해본 결과 ‘낙관적 락(OptimisticLocking)’ 과 관련된 에러였습니다.

낙관적 락이란 충돌이 거의 발생하지 않을 것이라고 가정하고, 충돌이 발생한 경우 대비하는 방식입니다.


예외 메세지에 따르면 delete 쿼리를 수행했을 때, 예상한 행 수는 `1`이지만 실제로 영향을 받은 행 수는 `0`이라고 나와 있습니다.

즉, 해당 ID를 가진 레코드가 존재하지 않아 삭제 작업이 실패했음을 의미합니다.

왜 이런 에러가 발생했나..곰곰히 생각해보니 제가 구성한 시나리오는 한 명의 유저를 위한 것이고, 작성한 스크립트 또한 정해진 한 명의 유저가 시나리오를 수행하도록 했습니다.

수행한 테스트는 50명의 유저가 동시에 수행하는 상황이기 때문에 한 명이 아닌 적어도 10명 이상의 랜덤 유저로 시나리오를 수행하도록 해주어야 합니다. (현재는 동일한 유저 1명으로 50명이 동작하는 상황)

그렇다보니 동일한 유저의 북마크를 했다 지웠다 하는 과정에서 발생하는 에러였습니다.

해결 방법은 고정적인 유저 역할을 더 늘려주면 될거라 예상합니다!

4-2. 두번째 에러

com.mysql.cj.jdbc.exceptions.MySQLTransactionRollbackException: Deadlock found when trying to get lock; try restarting transaction

두번째는 유명한 데드락에 관한 에러였습니다.

검색해본 결과 정확히 어떤 쿼리에서 데드락이 발생했는지 추적해야 문제를 해결할 수 있었기에

관련 명령어로 MySQL 쿼리 히스토리를 볼 수 있었습니다.

DeadRock이란? - 서로 트랙젝션에 걸린 잠금(락)이 풀리기를 무한히 기다리는 상황


- ** (1) TRANSACTION:
TRANSACTION 945750, ACTIVE 0 sec starting index read
mysql tables in use 1, locked 1
LOCK WAIT 7 lock struct(s), heap size 1128, 3 row lock(s), undo log entries 1
MySQL thread id 12533, OS thread handle 6190854144, query id 1095511 localhost 127.0.0.1 bridge-project updating
update project set bookmark_num=-1, due_date='2024-05-25 23:59:59', end_date=null, meeting_way='offline', overview='개요', stage='디자인', start_date=null, title='프로젝트 제목14', upload_time='2024-03-05 23:59:59', user_id=1 where project_id=14
- ** (1) HOLDS THE LOCK(S):
RECORD LOCKS space id 35173 page no 6 n bits 216 index PRIMARY of table `bridge`.`project` trx id 945750 lock mode S locks rec but not gap
Record lock, heap no 15 PHYSICAL RECORD: n_fields 13; compact format; info bits 0
0: len 8; hex 800000000000000e; asc ;;
1: len 6; hex 0000000e6e4b; asc nK;;
2: len 7; hex 0200000156060c; asc V ;;
3: len 4; hex 7ffffffe; asc ;;
4: len 8; hex 99b3737efb000000; asc s~ ;;
5: SQL NULL;
6: len 7; hex 6f66666c696e65; asc offline;;
7: len 6; hex eab09cec9a94; asc ;;
8: len 9; hex eb9494ec9e90ec9db8; asc ;;
9: SQL NULL;
10: len 21; hex ed9484eba19ceca09ded8ab820eca09cebaaa93134; asc 14;;
11: len 8; hex 99b2cb7efb000000; asc ~ ;;
12: len 8; hex 8000000000000001; asc ;;
- ** (1) WAITING FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 35173 page no 6 n bits 216 index PRIMARY of table `bridge`.`project` trx id 945750 lock_mode X locks rec but not gap waiting
Record lock, heap no 15 PHYSICAL RECORD: n_fields 13; compact format; info bits 0
0: len 8; hex 800000000000000e; asc ;;
1: len 6; hex 0000000e6e4b; asc nK;;
2: len 7; hex 0200000156060c; asc V ;;
3: len 4; hex 7ffffffe; asc ;;
4: len 8; hex 99b3737efb000000; asc s~ ;;
5: SQL NULL;
6: len 7; hex 6f66666c696e65; asc offline;;
7: len 6; hex eab09cec9a94; asc ;;
8: len 9; hex eb9494ec9e90ec9db8; asc ;;
9: SQL NULL;
10: len 21; hex ed9484eba19ceca09ded8ab820eca09cebaaa93134; asc 14;;
11: len 8; hex 99b2cb7efb000000; asc ~ ;;
12: len 8; hex 8000000000000001; asc ;;

---

- (2) TRANSACTION:
TRANSACTION 945748, ACTIVE 0 sec starting index read
mysql tables in use 1, locked 1
LOCK WAIT 7 lock struct(s), heap size 1128, 3 row lock(s), undo log entries 1
MySQL thread id 12542, OS thread handle 6214250496, query id 1095513 localhost 127.0.0.1 bridge-project updating
update project set bookmark_num=-1, due_date='2024-05-25 23:59:59', end_date=null, meeting_way='offline', overview='개요', stage='디자인', start_date=null, title='프로젝트 제목14', upload_time='2024-03-05 23:59:59', user_id=1 where project_id=14
- ** (2) HOLDS THE LOCK(S):
RECORD LOCKS space id 35173 page no 6 n bits 216 index PRIMARY of table `bridge`.`project` trx id 945748 lock mode S locks rec but not gap
Record lock, heap no 15 PHYSICAL RECORD: n_fields 13; compact format; info bits 0
0: len 8; hex 800000000000000e; asc ;;
1: len 6; hex 0000000e6e4b; asc nK;;
2: len 7; hex 0200000156060c; asc V ;;
3: len 4; hex 7ffffffe; asc ;;
4: len 8; hex 99b3737efb000000; asc s~ ;;
5: SQL NULL;
6: len 7; hex 6f66666c696e65; asc offline;;
7: len 6; hex eab09cec9a94; asc ;;
8: len 9; hex eb9494ec9e90ec9db8; asc ;;
9: SQL NULL;
10: len 21; hex ed9484eba19ceca09ded8ab820eca09cebaaa93134; asc 14;;
11: len 8; hex 99b2cb7efb000000; asc ~ ;;
12: len 8; hex 8000000000000001; asc ;;
- ** (2) WAITING FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 35173 page no 6 n bits 216 index PRIMARY of table `bridge`.`project` trx id 945748 lock_mode X locks rec but not gap waiting
Record lock, heap no 15 PHYSICAL RECORD: n_fields 13; compact format; info bits 0
0: len 8; hex 800000000000000e; asc ;;
1: len 6; hex 0000000e6e4b; asc nK;;
2: len 7; hex 0200000156060c; asc V ;;
3: len 4; hex 7ffffffe; asc ;;
4: len 8; hex 99b3737efb000000; asc s~ ;;
5: SQL NULL;
6: len 7; hex 6f66666c696e65; asc offline;;
7: len 6; hex eab09cec9a94; asc ;;
8: len 9; hex eb9494ec9e90ec9db8; asc ;;
9: SQL NULL;
10: len 21; hex ed9484eba19ceca09ded8ab820eca09cebaaa93134; asc 14;;
11: len 8; hex 99b2cb7efb000000; asc ~ ;;
12: len 8; hex 8000000000000001; asc ;;
- ** WE ROLL BACK TRANSACTION (2)

조금 복잡해 보이지만 하나씩 차근차근 살펴보도록 하겠습니다.

현재 두개의 트렌잭션(945750, 945748)이 데드락 상태인 걸 확인 할 수 있습니다.

먼저 1번 트랜젝션의 경우

  • project 테이블의 bookmark_num=-1, due_date='2024-05-25 23:59:59', end_date=null, meeting_way='offline', overview='개요', stage='디자인', start_date=null, title='프로젝트 제목14', upload_time='2024-03-05 23:59:59', user_id=1 를 수정하려고 레코드 락인 S락을 보유 중인 걸 알 수 있습니다.
  • 하지만 수정을 위해선 S락을 먼저 보유하고 X락이 필요합니다.
  • 따라서 1번 트랜젝션은 해당 게시물에 대해 X락의 Grant를 대기하고 있는 상황입니다.

2번 트랜젝션의 경우
  • 마찬가지로 동일한 project 테이블의 bookmark_num=-1, due_date='2024-05-25 23:59:59', end_date=null, meeting_way='offline', overview='개요', stage='디자인', start_date=null, title='프로젝트 제목14', upload_time='2024-03-05 23:59:59', user_id=1 를 수정하려고 레코드 락인 S락을 보유 중인 상황입니다.
  • 즉, 2번 트랜젝션 또한 동일한 게시물의 X락 Grant를 대기하고 있는 상황입니다.

정리해보자면 현재 두개의 트랜젝션이 동일한 게시물에 대해서 수정을 하려고 하는 상황입니다.

수정을 위해선 S락을 먼저 보유한 후 X락을 보유해야 하지만 양쪽에서 락이 풀리기를 대기하고 있는 상황인 것이죠!

따라서 마지막 문장을 보면 최종적으로 2번 트랜젝션 롤백한 것을 알 수 있습니다.

해당 예외 역시 첫번째 예외와 마찬가지로 동일한 프로젝트를 동일한 사람이 동시에 북마크 수정을 여러번 요청하다보니 생긴 데드락 문제였습니다.

결론적으로 두가지 예외 모두 시나리오 구성이 잘못되어 발생한 에러였습니다!

이렇게해서 실제로 시나리오를 구성한 뒤 성능 테스트까지 진행해봤습니다.
뭔가 또 새로운 세계로 들어온 것 같은 느낌이 드는 것 같습니다!
다음 포스트에서는 시나리오와 스크립트를 수정한 뒤 성능 개선 과정을 담아보도록 하겠습니다😏
긴 글 읽어주셔서 감사합니다!!

profile
일상 회고록
하고 싶은 것들이 많은 개발자입니다
이전 포스트

nGrinder 적용기 - 1

다음 포스트

캐시란 무엇일까

post-custom-banner

0개의 댓글