tcpdump를 활용한 타임아웃 분석
시스템 엔지니어의 주요 업무 중 하나는 애플리케이션에서 발생하는 타임아웃의 원인 분석입니다. 특히 요즘처럼 서비스들 간에 API를 통해서 연동을 하는 경우에는 타임아웃이 더욱 빈번하게 발생할 수 있고 빈번하게 발생하는 타임아웃은 결국 서비스의 품질에 영향을 줄 수 있습니다.
또한 타임아웃의 원인은 애플리케이션 자체의 성능적인 문제, OS의 설정 문제, 네트워크 문제 등등 여러 가지가 있을 수 있습니다. 그래서 애플리케이션에서 타임아웃이 발생했을 때 tcpdump를 통해서 네트워크 레벨부터 문제 분석을 시작하는 것은 좋은 방법 중에 하나입니다. 우선 문제의 원인이 어디에 있는지부터 찾아보고 해당하지 않는 것들을 하나씩 지우다 보면 진짜 원인을 찾을 수 있기 때문입니다.
그럼 어떤 경우들이 있는지 살펴 보겠습니다.
실제로 응답을 늦게 준 경우
첫 번째로 살펴볼 tcpdump의 내용은 아래와 같습니다.
tcpdump 결과 #1파란색으로 표시된 89618번째 패킷과 89619번째 패킷을 보면 요청과 응답이 바로 확인이 됩니다. 89618을 통해서 보낸 GET 요청에 대해서 89619를 통해서 200 OK 응답을 받은 것을 확인할 수 있습니다. 하지만 빨간색으로 표시된 89626번째 패킷을 보면 POST를 통해서 요청을 보냈지만 89787번째 패킷을 통해 응답을 받았음을 알 수 있습니다. 두 패킷 사이의 시간차는 약 5초. 그리고 중간에 89717번째 패킷을 보면 POST 요청을 보내고 약 3초의 시간이 흐른 뒤에 클라이언트에서 먼저 FIN을 보내서 세션 끊기를 유도하고 있음을 볼 수 있습니다. 이는 애플리케이션의 타임아웃이 3초이기 때문에 발생한 자연스러운 현상입니다. 하지만 서버로부터 그에 대한 FIN, ACK를 받지 못했기 때문에 89717 번째 패킷을 계속해서 재전송하는 것을 확인할 수 있습니다. 그리고 89787 번째 패킷을 보면 해당 서비스가 응답을 주긴 주었다는 것을 볼 수 있습니다. 5초나 소요되었지만요.
이를 통해 이번 타임아웃의 원인은 내부에 있는 것이 아니고, 연동하는 시스템에서 응답을 주는데 오랜 시간이 소요되었기 때문임을 알 수 있습니다.
실제로 연동하는 시스템의 nginx request time을 확인해 보니 5초 이상이 소요된 요청이 확인되었습니다.
Idle timeout 에 의해 연결이 강제 종료되는 경우
두 번째로 살펴볼 tcpdump는 아래와 같습니다.
tcpdump 결과 #2파란색으로 표시된 1767번째 패킷과 1768번째 패킷을 살펴보면 1767번 패킷을 통해 보낸 GET 요청을 1768번 패킷에서 200 OK 응답으로 받은 것을 확인할 수 있습니다. 그런데, 빨간색으로 표시된 1908번 패킷을 보면 GET 요청을 보냈으나 응답은커녕 1909번 패킷을 통해 FIN을 받았음을 알 수 있습니다. 요청을 보냈는데 그에 대한 응답은 오지 않고 오히려 연결을 끊겠다는 FIN 패킷을 받고 있는 겁니다. 왜일까요? 마지막으로 GET 요청을 보냈던 1767번 패킷과 1908번 패킷 사이의 시간 차이를 한 번 볼까요? 약 133초 정도의 시간차가 있습니다. 마지막으로 GET 요청을 보내고 133여 초 후에 새로운 GET 요청을 보낸 겁니다. 그런데 왜 응답이 오지 않고 FIN이 와버렸을까요? 이 문제의 원인은 LB (Load Balancer)의 Idle timeout 때문이었습니다. LB의 Idle timeout은 120초로 설정되어 있었는데, 그 시간이 넘었기 때문에 GET 요청을 백엔드의 서버로 전달하지 않고 FIN을 통해서 연결을 끊은 것입니다.
LB의 Idle timeout은 120초이지만 그렇다고 딱 120초에 끊어지진 않습니다. 내부적으로 타이머를 확인하는 백그라운드 스레드의 주기에 따라 그 시간은 유동적으로 변할 수 있습니다.
LB의 Idle timeout으로 인한 애플리케이션 타임아웃결국 원인은 요청 간의 시간차가 LB의 Idle timeout 이상으로 발생하기 때문에 발생한 것입니다.
이럴 경우에는 GET 요청을 할 때 Connection:close와 같은 형태의 헤더를 통해서 연결을 유지하지 않고 끊도록 해서 해결할 수 있습니다. 오히려 Keepalive를 통해서 연결을 유지하려는 동작이 타임아웃을 만들어내는 원인이 된 것입니다.
패킷의 생성이 늦어지는 경우
마지막으로 살펴볼 tcpdump는 아래와 같습니다.
tcpdump 결과 #3이번 이슈의 타임아웃 메시지는 아래와 같았습니다.
[WARN] - from application in application-akka.actor.default-dispatcher-3 XXX is too slow [ElpasedTime: 10864 ms]
연동하는 시스템 중 하나인 XXX라는 시스템으로의 요청에 대한 소요 시간이 10초가 넘었다는 메시지였습니다. 한데 패킷을 보면 16605번 패킷과 16698번 패킷 사이의 시간 차이가 약 10초 정도 납니다. 이 이야기는 XXX로 향하는 패킷 자체가 생성되는데 10초가 소요되었다는 이야기입니다. 즉, 네트워크적으로 뭔가 문제가 있는 것이 아니고 서버 내부적으로 어떤 이유에 의해서 10초 동안 패킷을 생성하지 못했다는 이야기가 됩니다. 그래서 이럴 경우에는 애플리케이션 내부에서 뭔가 응답 지연을 일으킬 만한 문제가 있는지를 살펴봐야 합니다.
실제로 이 이슈는 Full-GC가 비정상적으로 10여 초 정도 발생해서 생긴 이슈였습니다.
JVM은 Full-GC가 발생할 때 모든 스레드를 멈추게 하고 GC를 위한 스레드만 동작하게 하는데 이 현상을 Stop-The-World 현상이라고 합니다. 즉, 비정상적인 Full-GC에 의해 모든 스레드가 멈춰 버렸고 이는 XXX 시스템으로 요청하는 스레드까지 멈추게 했기 때문에 네트워크적으로 시간이 소요되지 않았음에도 불구하고 10초 넘는 응답 시간을 보인다는 메시지를 찍었습니다.
마치며
지금까지 우리는 세 가지의 tcpdump 예제를 통해서 애플리케이션의 타임아웃 원인을 분석해 봤습니다. 애플리케이션에서의 메시지는 타임아웃이라는 하나의 메시지이지만 내용을 살펴보면 원인은 전부 달랐으며 그에 따라 해결 방법도 모두 다릅니다. 첫 번째 경우는 연동하는 시스템의 문제, 두 번째 경우는 의도치 않게 긴 시간 유휴 상태로 남게 된 커넥션의 문제, 세 번째 경우는 비정상적인 Full-GC로 인한 문제였습니다. 하지만 이 경우들 모두 tcpdump에서부터 분석을 시작하여 원인을 찾을 수 있었습니다.
이렇게 어디서부터 원인 파악을 시작해야 할지 모르는 타임아웃 문제의 경우 tcpdump부터 시작해서 추적하면 그 원인을 좀 더 빠르게 찾을 수 있습니다. 지금 이 순간에도 많은 문제와 싸우고 있을 시스템 엔지니어 분들에게 이 글이 도움이 되었으면 좋겠습니다. 감사합니다.
ps. 역시 이번 글에도 제일 마지막엔 셀프 책 광고를.. ㅋㅋ
http://www.yes24.com/24/goods/44376723?scode=032&OzSrank=3
