제가 입사하고 나서 맡게된 프로젝트가 하나 있는데, 해당 프로젝트에서 간헐적으로 반년 넘게 속을 썩이던 이슈가 하나 있었고 최근에 그 이슈를 해결했습니다.
해결한 내용에 관해서 간략하게나마 정리를 해보겠습니다.
증상
- 간헐적으로 쓰레드가
Block이 됨
이슈 트래킹
이슈를 설명드리기 전에
Akka에 대해서 조금은 설명을 드리고 넘어가는게 좋을 것 같습니다.해당 프로젝트에서는
Akka라는 프레임워크를 사용하고 있습니다.
Akka는Actor라는 객체를 여러개 만들고, 이렇게 만들어진Actor끼리 서로메세지를 주고 받게 (Actor는 특정메세지를 받으면 특정 로직을 수행) 하면서동시성과비동기를 모두 챙긴 프레임워크라고 이해하시면 될 것 같습니다.그리고
Actor의 로직을 처리하던 쓰레드가Block이 되어버리면 해당Actor의 남아있는 나머지 메세지들도 모두 처리가 되지 않습니다.
- 처음에는 로그를 확인하여, 문제의 범위를 좁히고 코드 디버깅을 통해 문제를 해결하려고 했었습니다.
하지만 관련 로그가 드문드문 남겨져 있었어서 문제를 찾기가 쉽지 않았습니다. - 결국 처음부터 끝까지 코드를 모두 훑어보면서 문제를 찾으려고 했지만, 특별하게 문제가 될만한 부분을 발견하지 못했고 문제의 실마리도 보이지 않았습니다.
- 그러다보니
Actor쓰레드가 간헐적으로 멈추는 것은 순전히Akka프레임워크의 버그라고 생각을 했었습니다.
그래서 재현을 해보고자 Local에서Akka프레임워크를 이용해메세지를 수십만개를 처리하도록 해봤지만 문제는 여전히 발생하지 않았습니다.
(유명한 프레임워크에 이러한 크리티컬 이슈라니, 저의 아주 멍청한 생각이었습니다 😅) - 이슈가 발생하면 어플리케이션 재시작을 통해 문제를 해결한지도 어느새 2달이 넘어가자 해당 이슈도 어떠한 경향성을 보인다는 것을 알 수 가 있었습니다.
- 이슈가 자주 발생하는 특정 시간대가 존재 (주말보다는 평일, 오전 9시 ~ 10시 사이에 주로 발생)
- 해당
Block이슈가 발생하기 전에 Http 통신 관련 Log가 여러번 찍힘
- 저는 여기서 Http 통신 관련 Log가 여러번 찍히는 것에 주목을 했습니다.
- 그래서 Http 통신을 하는 부분의 코드를 집중적으로 확인했습니다.
해당 프로젝트에서는 Apache의 HttpClient 라이브러리를 사용하고 있었는데, Http 통신을 하고 나서 Connection에 대한 close 처리가 제대로 되어있지 않다는 것을 확인할 수 있었습니다.
- 그래서 Http 통신을 하는 부분의 코드를 집중적으로 확인했습니다.
Local Test
- 이슈 트래킹의 마지막에서 HttpClient의 close 관련 문제가 있음을 확인했기 때문에 이를 확인해보고자 close 처리를 하지 않고 HttpClient를 사용하면 어떤 문제가 발생하는지 Local에서 테스트를 해봤습니다.
Http 요청을 할 때마다 새로 HttpClient를 만들어서 사용 → 큰 문제 없음
private HttpResponse executeHttp(HttpGet httpGet) throws IOException {
HttpClient httpClient = HttpClients.createDefault();
HttpResponse response = httpClient.execute(httpGet);
log.info("response: " + response);
return response;
}Http 요청을 할 때 이전에 만들어둔 HttpClient를 그대로 사용 → 문제가 발생
private HttpResponse executeHttp(HttpGet httpGet) throws IOException {
HttpClient httpClient = HttpClients.createDefault();
HttpResponse response = null;
int count = 0;
while (count++ < 5) {
response = httpClient.execute(httpGet);
try {
Thread.sleep(1000); // 1초 대기
} catch (InterruptedException e) {
e.printStackTrace();
}
}
log.info("response: " + response);
return response;
}문제가 발생하는 원인 분석
결론부터 짧게 말씀드리면
HttpClient의 기본 설정은 다음과 같고,HttpClient사용 후Response에 대해서close()를 해주지 않으면 커넥션풀이 고갈나서 커넥션 풀의 최대 커넥션 수를 넘어서는 요청은 무한정 Block 에 빠질 수 있습니다.
HttpClient기본 설정
Default 커넥션 풀 사이즈:2개Default 커넥션 요청 타임아웃:없음 (무제한으로 대기)
-
저희 프로젝트에서 Http 통신을 할 때, 서버로부터
429 (Too Many Request)을 받으면 다시 요청을 하는 로직이 있는데 이 부분에서 close 없이 다시 요청을 했고, 그 때문에 커넥션 풀이 고갈되어 해당 쓰레드가 Block이 되는 이슈가 발생했습니다.- 이 부분을 매 요청마다 response에 대해서 close 하도록 개선하여 문제를 해결했습니다.
private String executeHttp(HttpGet httpGet) throws IOException { int count = 0; while (count++ < 5) { try (CloseableHttpClient httpClient = HttpClients.createDefault()) { CloseableHttpResponse response = httpClient.execute(httpGet); final HttpEntity entity = response.getEntity(); final String body = EntityUtils.toString(entity); EntityUtils.consume(entity); log.info("body: " + body); return body; } catch (IOException e) { log.error("Exception Occurred!!!", e); break; } try { Thread.sleep(1000); // 1초 대기 } catch (InterruptedException e) { e.printStackTrace(); } } return "Error Occurred!!!"; } -
HttpClient 코드 디버깅
Default 커넥션 풀 사이즈설정은 다음 부분에서 확인이 가능합니다.
// PoolingHttpClientConnectionManager.java // 커넥션 풀을 생성할 때, 기본 값을 쓰게 되면 다음과 같습니다.) // new CPool(new InternalConnectionFactory(this.configData, connFactory), 2, 20, timeToLive, timeUnit)에서 // defaultMaxPerRoute: 2, maxTotal: 20 public PoolingHttpClientConnectionManager(HttpClientConnectionOperator httpClientConnectionOperator, HttpConnectionFactory<HttpRoute, ManagedHttpClientConnection> connFactory, long timeToLive, TimeUnit timeUnit) { this.log = LogFactory.getLog(this.getClass()); this.configData = new ConfigData(); this.pool = new CPool(new InternalConnectionFactory(this.configData, connFactory), 2, 20, timeToLive, timeUnit); this.pool.setValidateAfterInactivity(2000); this.connectionOperator = (HttpClientConnectionOperator)Args.notNull(httpClientConnectionOperator, "HttpClientConnectionOperator"); this.isShutDown = new AtomicBoolean(false); }Default 커넥션 요청 타임아웃설정은 다음 부분에서 확인이 가능합니다.-
HttpClient httpClient를 생성할 때HttpClients.createDefault()로 생성 하게 되면
InternalHttpClient객체를 만듭니다. -
해당 객체를 만들때
connectionRequestTimeout (커넥션을 얻을때까지 기다리는 시간)의 값을 -1 (기본값) 으로 만듭니다. (-1이 들어가면 결국 무제한으로 기다립니다.) -
MainClientExec.java에서managedConn = connRequest.get(timeout > 0 ? (*long*)timeout : 0L, TimeUnit.MILLISECONDS);하는 부분이 있는데이 부분을 타고 타고 가보면 결국
PoolingHttpClientConnectionManager의
leaseConnection메서드를 호출하게 되고 여기서 더 타고 타고 가보면AbstractConnPool에서getPoolEntryBlocking을 호출합니다.마지막으로
getPoolEntryBlocking에서*this*.condition.await();를 호출하게 되는데 해당 메서드를 호출하면 해당 쓰레드는 커넥션이 생길때까지 무한정 Block이 됩니다.//MainClientExec.java 의 execute() 메서드 public CloseableHttpResponse execute( HttpRoute route, HttpRequestWrapper request, HttpClientContext context, HttpExecutionAware execAware ) throws IOException, HttpException { // ... 중략 ConnectionRequest connRequest = this.connManager.requestConnection(route, userToken); RequestConfig config = context.getRequestConfig(); HttpClientConnection managedConn; try { int timeout = config.getConnectionRequestTimeout(); managedConn = connRequest.get( //중요한 부분 timeout > 0 ? (long)timeout : 0L, TimeUnit.MILLISECONDS ); } // ... 중략 } //AbstractConnPool.java 의 getPoolEntryBlocking() 메서드 private E getPoolEntryBlocking( T route, Object state, long timeout, TimeUnit timeUnit, Future<E> future ) throws IOException, InterruptedException, ExecutionException, TimeoutException { // ... 중략 try { // ... 중략 if (deadline != null) { success = this.condition.awaitUntil(deadline); } else { this.condition.await(); //중요한 부분 success = true; } // ... 중략 } // ... 중략 }
-
참고 자료
