nGrinder로 성능 테스트 과정에서 발견한 Redis Session 병목

애플리케이션 서버를 개발하고 '나의 서버는 어느 정도의 트래픽을 처리할 수 있을까?'라는 고민을 할 수 있습니다. 하지만 여러 개의 브라우저를 띄워 동시에 요청을 보내는 방법은 한계가 있어 성능 테스트 도구를 이용하는 것이 좋습니다. 그래서 저는 네이버의 nGrinder를 통해 클라우드 환경에 구축해놓은 서버가 얼마만큼의 트래픽을 받을 수 있는지 성능 테스트를 진행했습니다.

---

nGrinder 성능 테스트 스크립트 작성

먼저 nGrinder를 통해 테스트를 하기 위해서는 테스트 시나리오를 짜고 시나리오에 맞는 스크립트 코드를 작성해야 합니다. 저는 사용자의 아이디와 비밀번호를 입력하여 로그인하는 기능을 테스트하고 싶어 다음과 같이 작성하였습니다.

...
class TestRunner {

 	public static final String IP = "10.41.8.33"
	public static final String URL = "http://" + IP + "/users/login";

	public static GTest test
	public static HTTPRequest request
	public static Map<String, Object> params = [:]
	
	static def nvs(def map) {
		def nvs = []
		map.each {
			key, value ->  nvs.add(new NVPair(key, value))
		}
		return nvs as NVPair[]
	}

	@BeforeProcess
	public static void beforeProcess() {
		HTTPRequestControl.setConnectionTimeout(300000)
		test = new GTest(1, IP)
		request = new HTTPRequest()
		params.put("id", "test_id")
		params.put("password", "test_password")
	}
	
	@BeforeThread
	public void beforeThread() {
		test.record(this, "test")
		grinder.statistics.delayReports = true
		grinder.logger.info("before thread.")
	}

	@Test
	public void test() {
		HTTPResponse response = request.POST(URL, nvs(params))
        
		assertThat(response.statusCode, is(200))
	}
}

 

테스트 설정

스크립트 작성이 완료되면 몇 명의 Vuser(가상의 사용자)를 사용할 것인지, 얼마 동안 진행할 것인지, 어떤 스크립트를 사용할 것인지를 선택하여 테스트를 진행할 수 있습니다.

nGrinder 테스트 설정 화면

 

테스트 요청에 대한 WAS의 처리 흐름

1.  id, password를 담은 로그인 요청을 서버가 수신

2. DB 서버에 해당하는 사용자 정보가 존재하는지 확인

3. 존재하면 Redis 서버에 세션 정보와 사용자 정보를 저장

4. 200 상태 코드를 응답으로 반환

 

이렇게 테스트를 진행했을 때 성공적인 흐름대로라면 별문제 없이 트래픽 처리가 이루어져야 합니다.

 

 

테스트 결과

성능 테스트 결과

 

하지만 결과를 보면 TPS의 수치가 올라가다가 갑자기 0으로 뚝 떨어지는 그래프를 확인할 수 있습니다. 동일한 조건으로 여러 번 실행해도 간헐적으로 TPS 수치가 내려가는 현상이 지속되었습니다. 만약 실제 서비스 상황에 이러한 TPS 그래프가 그려지면 사용자 입장에서는 로그인 조차 잘 되지 않는 서비스라고 느낄 수 있는 상황입니다.

 

위의 TPS 그래프는 서버가 트래픽을 처리하는 과정에서 문제가 있다는 의미이고 정확히 어떤 서버에서 발생하는지 확인하기 위해서는 각 서버의 상태를 모니터링할 필요가 있었습니다.

 

 

서버 상태 모니터링

저의 서버는 네이버 클라우드의 Linux CentOS 환경에 설치되어 있고 서버 상태를 확인하기 위해 htop 툴을 사용했습니다.

다시 동일한 테스트를 진행했고 그 결과, 위의 이미지처럼 TPS 수치가 0이 되는 시점에 특정 웹 애플리케이션 서버의 CPU 사용량이 100%가 되고 나머지 서버들은 0%인 현상을 발견할 수 있었습니다. 

 

단순히 모든 서버의 CPU가 적절하게 사용되는 것이 아닌 특정한 서버의 CPU가 100%인 것은 분명한 문제가 있다고 판단을 했고 현상이 발생하는 서버의 상태를 보면 다수의 스레드가 CPU 사용량을 유독 많이 차지하는 것을 확인할 수 있었습니다.

해당 스레드들은 Java에서 생성된 스레드이고 CPU를 많이 사용하는 스레드의 PID 또한 확인할 수 있습니다. 이제 jstack 명령어를 활용해 JVM의 스레드 덤프를 획득하고 분석하여 무엇을 하는 스레드인지 확인해 보겠습니다.

 

 

스레드 덤프 분석

https://fastthread.io/

fastthread.io

저는 fastthread.io 사이트를 활용하여 스레드 덤프 분석을 진행하였고, 빨간 박스 안의 스레드를 찾아본 결과 모두 동일한 스택 정보를 가지는 것을 볼 수 있었습니다.

 

스택 정보

...
at org.springframework.data.redis.connection.lettuce.LettuceKeyCommands.pExpire(LettuceKeyCommands.java:394)
at org.springframework.data.redis.connection.DefaultedRedisConnection.pExpire(DefaultedRedisConnection.java:188)
at org.springframework.data.redis.core.RedisTemplate.lambda$expire$8(RedisTemplate.java:796)
at org.springframework.data.redis.core.RedisTemplate$$Lambda$1458/608575278.doInRedis(Unknown Source)
at org.springframework.data.redis.core.RedisTemplate.execute(RedisTemplate.java:222)
at org.springframework.data.redis.core.RedisTemplate.execute(RedisTemplate.java:189)
at org.springframework.data.redis.core.RedisTemplate.expire(RedisTemplate.java:794)
at org.springframework.data.redis.core.DefaultBoundKeyOperations.expire(DefaultBoundKeyOperations.java:53)
at org.springframework.session.data.redis.RedisSessionExpirationPolicy.onExpirationUpdated(RedisSessionExpirationPolicy.java:101)
at org.springframework.session.data.redis.RedisIndexedSessionRepository$RedisSession.saveDelta(RedisIndexedSessionRepository.java:819)
at org.springframework.session.data.redis.RedisIndexedSessionRepository$RedisSession.save(RedisIndexedSessionRepository.java:783)
at org.springframework.session.data.redis.RedisIndexedSessionRepository$RedisSession.access$000(RedisIndexedSessionRepository.java:670)
at org.springframework.session.data.redis.RedisIndexedSessionRepository.save(RedisIndexedSessionRepository.java:398)
at org.springframework.session.data.redis.RedisIndexedSessionRepository.save(RedisIndexedSessionRepository.java:249)
at org.springframework.session.web.http.SessionRepositoryFilter$SessionRepositoryRequestWrapper.commitSession(SessionRepositoryFilter.java:225)
at org.springframework.session.web.http.SessionRepositoryFilter$SessionRepositoryRequestWrapper.access$100(SessionRepositoryFilter.java:192)
at org.springframework.session.web.http.SessionRepositoryFilter.doFilterInternal(SessionRepositoryFilter.java:144)
at org.springframework.session.web.http.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:82)
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
at org.springframework.web.filter.CharacterEncodingFilter.doFilterInternal(CharacterEncodingFilter.java:201)
at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:119)
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:202)
at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:97)
at org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:542)
at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:143)
at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:92)
at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:78)
at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:343)
at org.apache.coyote.http11.Http11Processor.service(Http11Processor.java:374)
at org.apache.coyote.AbstractProcessorLight.process(AbstractProcessorLight.java:65)
at org.apache.coyote.AbstractProtocol$ConnectionHandler.process(AbstractProtocol.java:888)
at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1597)
at org.apache.tomcat.util.net.SocketProcessorBase.run(SocketProcessorBase.java:49)
- locked <0x00000000ffbaa9c0> (a org.apache.tomcat.util.net.NioEndpoint$NioSocketWrapper)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)
at java.lang.Thread.run(Thread.java:748)

스택 정보를 보면 RedisIndexedSessionRepository의 save 메소드를 호출하고 RedisTemplate의 execute를 호출하여 Redis와 통신한다는 것을 알 수 있습니다. 그리고 Expiration 키워드가 자주 등장하는 걸 보니 세션 만료 처리하는 부분이라는 것도 짐작할 수 있습니다.

 

 

결론

모든 정보를 종합해보면 'TPS 수치가 0이 되는 시점에 CPU 사용량의 대부분을 차지하는 스레드가 모두 위의 스택 정보를 가진다면 병목 현상은 WAS에서 Redis Session을 만료 처리하는 과정에서 발생한다.'라는 가설을 세울 수 있습니다.

 

그럼 이 가설이 맞는지 스택 정보를 기반으로 좀 더 상세히 알아보고 왜 발생했는지? 해결하면 병목 현상이 사라지는지?를 통해 가설을 입증해 보도록 하겠습니다. 

 

 

 

다음글

https://liasn.tistory.com/8

Redis Session 병목 해결 및 최적화하기