nGrinder Read timed out 오류 해결과정

sieun·2022년 10월 3일

개요

대량의 로그 정보를 조회하는 API에 대해서 부하 테스트를 진행할 때 nGrinder를 사용하였습니다. 이 때, 성능 측정을 목적으로 Vusers을 10이상 늘려 테스트를 하였더니 Read timed out 에러가 발생하였습니다. 이번 글에서는 오류를 어떻게 해결하였는지 그 과정을 기록하였습니다.

문제 발생

Vuser : 10

Vuser : 20

Vuser를 10에서 20으로 늘렸더니 Error도 발생할 뿐만 아니라 중간에 테스트가 강제로 종료되었습니다. nGrinder에서 제공하는 로그를 살펴보니 아래와 같은 에러내용이 적혀있었습니다.

2022-09-27 18:24:16,060 ERROR Read timed out
net.grinder.plugin.http.TimeoutException: Read timed out
	at HTTPClient.BufferedInputStream.fillBuff(BufferedInputStream.java:172)
	at HTTPClient.BufferedInputStream.read(BufferedInputStream.java:110)
	at HTTPClient.StreamDemultiplexor.read(StreamDemultiplexor.java:277)
	at HTTPClient.RespInputStream.read(RespInputStream.java:155)
	at HTTPClient.RespInputStream.read(RespInputStream.java:115)
	at HTTPClient.Response.readResponseHeaders(Response.java:980)
	at HTTPClient.Response.getHeaders(Response.java:698)
	at HTTPClient.Response.getVersion(Response.java:290)
	at HTTPClient.HTTPConnection.sendRequest(HTTPConnection.java:3239)
	at HTTPClient.HTTPConnection.handleRequest(HTTPConnection.java:2883)
	at HTTPClient.HTTPConnection.setupRequest(HTTPConnection.java:2675)
	at HTTPClient.HTTPConnection.Get(HTTPConnection.java:986)
	at net.grinder.plugin.http.HTTPRequest$2.doRequest(HTTPRequest.java:504)
	at net.grinder.plugin.http.HTTPRequest$AbstractRequest.getHTTPResponse(HTTPRequest.java:1276)
	at net.grinder.plugin.http.HTTPRequest.GET(HTTPRequest.java:499)
	at net.grinder.plugin.http.HTTPRequest.GET(HTTPRequest.java:474)
	at net.grinder.plugin.http.HTTPRequest$GET$18.call(Unknown Source)
	at TestRunner.test(mongo.logs.groovy:67)
	at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
	at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
	at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
	at net.grinder.scriptengine.groovy.junit.GrinderRunner.run(GrinderRunner.java:172)
	at net.grinder.scriptengine.groovy.GroovyScriptEngine$GroovyWorkerRunnable.run(GroovyScriptEngine.java:147)
	at net.grinder.engine.process.GrinderThread.run(GrinderThread.java:118)

아래는 명령어 top을 입력한 후의 화면입니다.

사용 가능한 메모리는 109M라 나왔는데, nGrinder 사용자 포럼에서 관리자분이 agent는 4G이상의 실제 메모리와 2G이상의 free 메모리에서만 테스트 되었기 때문에 메모리가 부족해 문제가 생겼을 수도 있다고 하셨습니다.

따라서 첫번째 시도로 메모리를 증설하여보았습니다.

시도1. 메모리 증설

사실 저는 우선적으로 제 로컬에서 ngrinder와 agent를 시범적으로 설치해 실행하였기 때문에 노트북 전원을 껐다 키기만 하였습니다. 하지만 nGrinder에서는 서버를 따로 두고 구성하는 것을 권장하니 참고하시고 메모리를 증설하시면 됩니다.

결과

메모리를 정리하기 전에는 www.naver.com이나 www.google.com같은 일반적인 사이트로 테스트를 실행하여도 오류가 발생하였습니다. 메모리에 공간이 생기니 Vuser가 100이상으로 설정된 부하를 해당 사이트에 던져도 성공적으로 테스트가 완료되었습니다. 하지만 제가 테스트하려는 uri의 경우, 이 전 그대로 read time out 에러가 계속 발생하였습니다.

시간을 조절하는 것이 오류 해결에 도움이 되는 것 같아 관련 답변을 찾아보다가 이 글을 발견하였습니다. 저와 비슷한 상황의 사용자에게 해결책으로 HTTPPluginControl.getConnectinoDefault().timeout의 값을 늘리는 방법을 제시해주셨습니다.

시도2. HTTPPluginControl.getConnectinoDefault().timeout 증가

HTTPPluginControl.getConnectinoDefault().timeout 이란 HTTP 요청 시간초과를 설정하는 것으로, 단위는 밀리초로 되어있습니다.

HTTPPluginControl.getConnectinoDefault().timeout = 51000 , VUser = 100인 경우

Vuser를 100으로 설정한 채로, timeout의 기본값인 6000보다 45000증가시킨 51000으로 설정하였더니 성공적으로 테스트가 완료되었습니다.

HTTPPluginControl.getConnectinoDefault().timeout = 51000 , VUser = 500인 경우

반면, VUser를 500으로 늘려 다시 실행시켜보니 TPS가 없어 중단시켜버렸습니다.

HTTPPluginControl.getConnectinoDefault().timeout = 50000 , VUser = 100인 경우

또한 timeout의 값이 적정선보다 작게 설정하게 되면 error를 많이 발생시키면서 중단되었습니다.

결과

위의 테스트 결과로 보았을 때, VUser의 값을 늘리기 위해서는 HTTPPluginControl.getConnectinoDefault().timeout 의 값도 충분히 늘려주어야 성공적으로 테스트를 수행할 수 있었습니다.

그 외에도 VUser의 수는 일정하게 두고, timeout의 값을 늘려보면 어떤 상관관계가 있을지 알아보았습니다.

HTTPPluginControl.getConnectinoDefault().timeout = 51000 인 경우

HTTPPluginControl.getConnectinoDefault().timeout = 53000 인 경우

HTTPPluginControl.getConnectinoDefault().timeout = 55000 인 경우

timeout의 값이 증가함에 따라 규칙적으로 변화되는 값은 Peak TPS를 제외하곤 딱히 존재하지 않았습니다.

결론

nGrinder maintainer분께서 알려주시길 시스템이 STOP메시지를 보내는 경우의 판단 조건은 다음과 같다고 합니다.

평균 TPS 가 0.001 이하 상태로 60초 이상 지속될 경우
TPS 수치의 반 이상 error가 10초이상 발생하는 경우

이런 경우에 테스트가 중간에 실행을 중단되어버립니다.

저의 경우에는 테스트가 오류난 원인이 사용 가능한 메모리 용량이 부족한 것과, Vuser에 비해 작았던 HTTPPluginControl.getConnectinoDefault().timeout 때문이었습니다.

그 외에도 네트워크의 순간 장애로 인해 agent 커넥션이 끊긴 현상, 장시간동안 테스트를 돌리는 경우 메모리가 증가하는 현상 등의 원인으로 문제가 생길 수 있습니다.

후기

nGrinder에서는 테스트를 진행하면서 발생한 로그들을 제공해주어 무슨 오류인지 알 수는 있지만, 해당 오류의 원인이 방대하여 처음에는 해결책을 찾는데 헤매었습니다. 그러다 nGrinder 사용자 포럼과 nGrinder Github Discussion을 발견하였고, nGrinder 관리자분께서 답변을 많이 해주셔서 도움을 얻었습니다. 만약 테스트 오류의 원인을 찾고 계신다면 이 두 곳을 참고하시면 좋을 것 같습니다.