마이크로 서비스와 TIME_WAIT 문제

지난 글에 이어 계속해서 성능 테스트에 대한 이야기 입니다. 전체 성능 테스트에 대해서는 시나리오 작성, 테스트 프로그램, 테스트 수행, 원인 파악 등 실제로 수행한 액션들에 대해서는 별도의 글로 한번 정리하도록 하겠습니다.

마이크로 서비스로 구성된 시스템에서는 서비스간 호출이 많이 발생하는데 이들 서비스간 호출하는데 있어 다양한 프로토콜을 사용할 수 있습니다. 제가 운영하는 서비스에서는 HTTP 기반으로 호출하고 데이터는 JSON 형태로 인터페이스를 하고 있습니다. 마이크로 서비스에서 서비스간 호출에 있어 조심해야 할 사항 중에 하나가 Connection Pool을 사용하지 않고 Socket을 지속적으로 만들고 Close 하는 것입니다.

얼핏 생각하면 Connection Pool을 사용하는 것과 사용하지 않는 것의 차이는 네트워크 연결 비용이 조금 더 들어 처리 속도가 조금 느려 진다는 정도만 생각할 수 있습니다. 저도 이번 테스트를 수행하기 전에 이런 생각을 가지고 있었는데 Connection Pool을 사용하지 않으면 서버 자체에 문제를 줄 수 있다는 것을 알게 되었습니다.

TIME_WAIT

TCP/IP 연결, 종료 시 연결에 대한 여러 상태가 있는데 TIME_WAIT은 Close() 요청을 보낸 후 정상적으로 연결을 끊기 전에 지연된 패킷에 대한 문제 해결 등을 위해 일정 시간 동안 연결을 종료하지 않고 대기하고 있는 상태를 말합니다. 이 문서에서는 이 TIME_WAIT에 대한 자세한 설명은 하지 않겠습니다. 다음 문서에 자세하게 잘 설명되어 있습니다.

• CLOSE_WAIT & TIME_WAIT 최종 분석

문제는 대기 시간이 짧지 않다는 겁니다. OS 또는 버전에 따라 다르지만 제가 사용하는 우분투 환경에서는 60초 인것 같습니다.

모든 네트워크 자원 고갈

클라이언트의 호출을 받은 A 서버가 처리 중에 다른 B 서버의 서비스를 호출할 때 매번 Connection 만들고 Close 하게 되면 TIME_WAIT 상태가 발생하고 60초 지나면 사라지는 것을 반복하게 됩니다.

이 상테에서 60초 이내에 수만개의 Request가 오면 어떻게 될까요? A 서버의 모든 네트워크 포트가 고갈되어 클라이언트는 더 이상 이 A서버로 요청을 보낼 수 없는 상태가 됩니다. 모든 클라이언트가 요청을 못보내는 것이 아니라 일부 클라이언트의 요청은 받을 수 있고, 일부 클라이언트의 요청은 받을 수 없는 상태가 됩니다.

이런 상태는 평소에는 잘 나타나지 않겠지만 갑자기 사용자가 증가하는 경우 발생할 수 있어 어디가 문제인지 잘 파악하기 어려울 수도 있습니다. 클라이언트가 사용자 브라우저 또는 App 이라고 하면 A 서버의 서비스 로그에는 에러 메시지가 남아 있지 않습니다. 브라우저나 App에서 접속을 못하기 때문입니다.

저도 중국의 대규모 할인 행사인 11/11 행사 준비를 위해 성능 테스트 수행 중에 성능 테스트 프로그램(실제 환경에서는 브라우저 또는 App)에서 서버로 접속할 수 없다는 에러 메시지가 나타났고 이를 근거로 해서 원인을 파악할 수 있었습니다.

서버쪽 네트워크 자원은 다음과 같은 명령으로 모니터링을 수행했습니다.

• watch -n 2 "netstat -an | egrep 'ESTABLISHED|TIME_WAIT' | wc -l"

이 명령은 2초마다 네트워크 연결 중에 ESTABLISHED와 TIME_WAIT 상태에 있는 연결 갯수를 보여주는 명령입니다.

Golang HTTP 클라이언트 사용 시 주의

이제 문제는 파악했으니 왜  네트워크 연결을 지속적으로 만들고 Close 하는지를 찾아 보았습니다. 가장 먼저 의심한 것은 A 서버에서 B 서버로 API 호출 시 Connection Pool을 사용에 대한 것이었습니다. 하지만 golang에서 기본으로 제공하는 http client는 connection pool이 내장되어 있습니다. 다음과 같이 http package 에 대해 설명과 함께 예제 코드도 있습니다.

실제 서비스에서 사용하는 코드를 보니 다음과 같이 Default 옵션을 사용하고 있었습니다.

•   client := &http.Client{} resp, err := client.Do(req)

특별한 문제는 없어 보이지만 "golang http TIME_WAIT" 라는 키워드로 검색을 해보면 잘못 사용할 경우 문제가 된다는 것을 알 수 있습니다.

DefaultMaxIdleConnsPerHost 옵션

다음 문서는 golang을 이용하여  HTTP 요청에 대한 성능 테스트 프로그램을 만들었는데 성능 테스트 프로그램 자체에 TIME_WAIT 문제가 발생하여 해결한 내용입니다.

• Tuning the Go HTTP Client Settings for Load Testing

내용을 요약하면

• golang의 http client는 connection pool을 사용하고 있으며 여러가지 옵션( Transport)을 이용하여 connection 설정을 할 수 있다.
• Pool 관련 주요 설정 값은 MaxIdleConns, MaxIdleConnsPerHost 값인데 기본 값은 100, 2로 설정되어 있다.
• Pool이 생성되면 요청이 계속해서 들어 오면 MaxIdleConns 옵션에 따라 100개까지 만들지만 MaxIdleConnsPerHost 옵션에 따라 생성된 Connection 중 2개만 남기고 나머지는 모두 Close 하게 된다.

즉 Connection pool의 갯수는 100개 이지만 Host 당 사용 가능한 갯수가 2개이기 때문에 지속적으로 Connection 생성, Close를 반속하면서 TIME_WAIT이 증가하게 된다는 것입니다.

MaxIdleConnsPerHost 값을 부하 상황에 맞게 적절하게 설정한 후 다시 테스트를 수행하였지만 여전히 TIME_WAIT이 증가하였습니다.

Connection 객체는 하나만 생성해야함

golang의 transport.go 소스 코드 유심히 살펴보니 다음과 같은 주석이 있었습니다.

1
2
// Transports should be reused instead of created as needed.
// Transports are safe for concurrent use by multiple goroutines.

즉, Transport는 재사용되니 매번 만들지 말라는 경고 입니다. 그리고 소스 코드를 보니 모든 요청에 대해 http.Client 를 계속 생성하고 있었습니다. 즉 위에서 설정한 MaxIdleConns, MaxIdleConnsPerHost 갯수 만큼 계속 만들어 지고 있었습니다.

다음과 같이 코드를 수정하여 최초 한번만 생성하고 이를 재사용하는 방식으로 개선한 다음 테스트를 수행하니 더 이상 TIME_WAIT 문제가 발생하지 않았습니다.

1
2
3
4
5
6
7
8
9
10
11
12
13
var defaultClient *http.Client
func init() {
  defaultTransportPointer, ok := http.DefaultTransport.(*http.Transport)
  if !ok {
    panic(fmt.Sprintf("defaultRoundTripper not an *http.Transport"))
  }
  defaultTransport := *defaultTransportPointer // dereference it to get a copy of the struct that the pointer points to
  defaultTransport.MaxIdleConns = 100
  defaultTransport.MaxIdleConnsPerHost = 100
  defaultClient = &http.Client{Transport: &defaultTransport}
}
// 실제 사용하는 코드에서는 다음과 같이 호출
resp, err := defaultClient.Do(httpReq)

Java Apache HttpClient 사용시 주의

DB 및 서버에 대한 튜닝을 모두 마치고 성능 테스트를 수행하니 성능테스트 Driver에서 다시 동일한 TIME_WAIT 문제가 발생하였습니다.

1
2
3
4
5
6
7
8
9
10
11
12
java.net.NoRouteToHostException: Cannot assign requested address (Address not available)
  at java.net.PlainSocketImpl.socketConnect(Native Method) ~[na:1.8.0_121]
  at java.net.AbstractPlainSocketImpl.doConnect(AbstractPlainSocketImpl.java:350) ~[na:1.8.0_121]
  at java.net.AbstractPlainSocketImpl.connectToAddress(AbstractPlainSocketImpl.java:206) ~[na:1.8.0_121]
  at java.net.AbstractPlainSocketImpl.connect(AbstractPlainSocketImpl.java:188) ~[na:1.8.0_121]
  at java.net.SocksSocketImpl.connect(SocksSocketImpl.java:392) ~[na:1.8.0_121]
  at java.net.Socket.connect(Socket.java:589) ~[na:1.8.0_121]
  at org.apache.http.conn.socket.PlainConnectionSocketFactory.connectSocket(PlainConnectionSocketFactory.java:75) ~[httpclient-4.5.3.jar!/:4.5.3]
  at org.apache.http.impl.conn.DefaultHttpClientConnectionOperator.connect(DefaultHttpClientConnectionOperator.java:142) ~[httpclient-4.5.3.jar!/:4.5.3]
  at org.apache.http.impl.conn.PoolingHttpClientConnectionManager.connect(PoolingHttpClientConnectionManager.java:359) ~[httpclient-4.5.3.jar!/:4.5.3]
  at org.apache.http.impl.execchain.MainClientExec.establishRoute(MainClientExec.java:381) ~[httpclient-4.5.3.jar!/:4.5.3]
  at org.apache.http.impl.execchain.MainClientExec.execute(MainClientExec.java:237) ~[httpclient-4.5.3.jar!/:4.5.3]

테스트 Driver는 Java로 개발하였는데 이 코드도 Golang의 위에서의 문제를 그대로 가지고 있었습니다.

Connection Pool  사용

테스트 Driver에서도 API URL 호출을 할때 Connection Pool을 재사용하지 않고 내트워크 연결을 만들고 해제하는 것을 반복하게 되면 짧은 시간내에 너무 많은 TIME_WAIT 상태가 발생하게 되어 결과적으로는 네트워크 연결을 만들 수 없는 상황이 발생하게 됩니다. 따라서 테스트 Driver로 Connection Pool을 사용해야 합니다. Apache HttpClient의 버전이 여러 종류이고 버전별로 사용방법이 많이 달라서 이것저것 시도를 해보았는데 다음과 같은 코드로 구현하였습니다.

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
public static void main(String[] args) {
  PoolingHttpClientConnectionManager connManager = new PoolingHttpClientConnectionManager();
  connManager.setMaxTotal(500);
  connManager.setDefaultMaxPerRoute(100);
  // 이 httpClient 객체를 모든 Thread가 같이 사용
  CloseableHttpClient httpClient = HttpClients.custom().setConnectionManager(connManager).build();
  for(...) {
    (new TestThread(httpClient)).start();
  }
}
class TestThread extends Thread {
  public void run() {
  @Override
  public void run() {
    HttpHost targetHost = new HttpHost("server01", 8080);
    while (!stop.get()) {
      CloseableHttpResponse response = null;
      try {
        HttpPost httpPost = new HttpPost("/test");
        response = httpClient.execute(targetHost, httpPost);
        if (!String.valueOf(response.getStatusLine().getStatusCode()).startsWith("2")) {
          HttpEntity entity = response.getEntity();
          String responseString = EntityUtils.toString(entity, "UTF-8");
          LOG.error("Call Error: " + response.getStatusLine().getStatusCode() + " ==> " + responseString);
          this.testStatistics.failed(System.currentTimeMillis() - calledAt);
        } else {
          this.testStatistics.addTestResult(System.currentTimeMillis() - calledAt);
        }
      } finally {
        if (response != null) {
          response.close();
        }
      }
    }
  }
}

Response의 내용을 모두 처리하지 않음

위와 같이 구현하면 정상적으로 CLOSE 된다고 생각했지만 여전히 동일한 문제가 발생하였습니다. 다른 방식으로 구현해도 동일한 문제였습니다. 여러 삽질중에 다음 부분이 문제인 것을 확인하였습니다.

1
2
3
4
5
6
7
8
9
response = httpClient.execute(targetHost, httpGet);
if (!String.valueOf(response.getStatusLine().getStatusCode()).startsWith("2")) {
  HttpEntity entity = response.getEntity();
  String responseString = EntityUtils.toString(entity, "UTF-8");
  LOG.error("API call Error: " + response.getStatusLine().getStatusCode() + " ==> " + responseString);
  this.testStatistics.failed(System.currentTimeMillis() - calledAt);
} else {
  this.testStatistics.addTestResult(System.currentTimeMillis() - calledAt);
}

위 코드를 보면 성공시에는 아무런 처리를 하지 않고 실패 시에는 Response의 내용을 출력하도록 되어 있습니다. 몇가지 문서를 확인해보니 response.close() 호출한다고 해서 connection pool에 반환되지 않는 다는 것을 알았습니다.

• https://stackoverflow.com/questions/4775618/httpclient-4-0-1-how-to-release-connection If you want to re-use the connection then you must consume content stream completely after every use as follows : EntityUtils.consume(response.getEntity())

즉 response의 있는 모든 컨텐츠의 내용을 처리해야만 connection을 재사용 가능합니다. Golang에도 이와 비슷한 메소드를 제공하고 있습니다.

• io.Copy(ioutil.Discard, con)

결론

이번 테스트 과정을 진행하면서 느낀 것은

• 눈에 보이는 것이 전부가 아니고 시스템은 우리가 생각하는 것과 전혀 다른 상황으로 운영되고 있을 수도 있다.
• 부하 상황에서는 전혀 다른 현상이 발생할 수 있다.
• 하나의 잘못된 코드가 전체 시스템을 망칠 수 있다.
• golang을 사용할 때는 소스 코드의 주석을 잘 살펴보자.
• golang 사용함에 있어 마음 가짐이 Java 초창기 혼돈의 시기와 같은 마음가짐이라야 할 것 같다. 중요 사항들은 하나하나 꼼꼼히 체크해야 할 듯