개요
기존 사용하던 Tracer 솔루션의 지연이 발생했지만 정확한 원인 분석이 되지 않고 있었다.
사용자가 많이 몰리는 시간대에만 발생했고, 당시의 Andriod APP 로그는 아래와 같다. (구현체는 OkHttpClient 사용)
• java.net.SocketTimeoutException: failed to connect to host.name.co.kr/xxx.xxx.xxx.xxx (port xxxx) from /xxx.xxx.xxx.xxx (port xxxx) after 5000ms
• /TRACERAPI/inputQueue.do (5217ms)
• /TRACERAPI/inputQueue.do (4041ms)
• SocketTimeoutException: failed to connect to host.name.co.kr/xxx.xxx.xxx.xxx (port xxxx) from /xxx.xxx.xxx.xxx (port xxxx) after 5000ms이를 보고 단순히 Tracer 의 응답이 느려 SocketTimeoutException 이 발생했다고 생각할 수 있지만,
부하테스트를 여러 번 수행해보며 여러 오류를 겪어본 입장에서는 failed to connect to 의 힌트가 Tracer 서버에 연결하는 과정에서 발생한 것으로 추측했다.
이 글에서는 특정 상황의 발생 시점을 파악하고 보다 상세한 원인을 분석하기 위해 직접 재현해본 과정을 공유한다.
분석을 위해 방대한 자료를 찾아보았는데, 아쉽게도 유용하고 정확한 정보는 많지 않았으며 허위 자료들도 다수 발견되었다.
따라서 직접 Linux, Android 네이티브 코드를 분석하며 상황을 재현해야 했고, 이 과정에서 상당한 시간이 소요되었다.
이러한 어려움을 겪을 다른 개발자들이 시간을 절약하는 데 도움이 되기를 바라며, 직접 확인하고 분석한 내용을 공유한다.
참고로, 해당 Tracer 는 Tomcat 을 내장 서버로 둔 Spring Application 이었고,
나는 사내 자체 구축하는 신규 프로젝트에도 Tomcat 을 내장 서버로 둔 Spring Application 을 사용해 재현해보고자 한다.
이론
결론부터 말하자면, SpringBoot 에서 내장 Tomcat 사용 시 아래 설정값에 따라
- server.tomcat.max-connections
- server.tomcat.accept-count
Kernel 단에서 'listen queue of a socket overflowed', 'SYNs to LISTEN sockets dropped' 이 발생해 연결을 맺지 못할 수 있다.
우선 java.net.SocketTimeoutException: failed to connect to ... 는 왜 발생할까?
failed to connect to ... 키워드로 서버에 연결을 실패한 것을 확인할 수 있다.
일반적으로 OkHttp 와 같은 HttpClient 구현체들은 ConnectTimeout, ReadTimeout 등의 설정을 할 수 있다.
그리고 통상적으로 아는 개념으로는
Connection Timeout 은 3-way-handshake 가 완료되기 전에 발생한다.
Connection 을 맺지 못하는 경우는 일반적으로 아래와 같은 상황들이 있다.
| 원인 | 설명 |
|---|---|
| DNS 확인 실패 | 클라이언트가 서버의 호스트 이름을 IP 주소로 확인할 수 없음. |
| 네트워크 연결 문제 | 일반적인 네트워크 중단 또는 통신을 방해하는 라우팅 문제. |
| 방화벽 제한 | TCP 연결 시도를 차단하는 방화벽. |
| 잘못된 서버 주소/포트 | 클라이언트가 잘못된 엔드포인트에 연결하려고 시도. |
| IPv4/IPv6 문제 | 어느 IP 프로토콜에든 문제가 있어 연결을 방해함. |
| 프록시 문제 | 구성된 프록시 서버의 문제. |
| TLS/SSL Handshake 실패 | 보안 연결 설정 중 실패 (연결 오류로 나타날 수 있음). |
| 실패한 3-Way Handshake | TCP 연결 설정 과정 중 하나 이상의 단계 실패. |
| 서버 Accept Queue 포화 | 서버가 연결 요청으로 압도되어 새 연결을 수락할 수 없음. |
| 프록시 문제 | 구성된 프록시 서버의 문제. |
| TLS/SSL Handshake 실패 | 보안 연결 설정 중 실패 (연결 오류로 나타날 수 있음). |
| 실패한 3-Way Handshake | TCP 연결 설정 과정 중 하나 이상의 단계 실패. |
| 서버 Accept Queue 포화 | 서버가 연결 요청으로 압도되어 새 연결을 수락할 수 없음. |
다만 평소에 잘 되던 것이 사용자가 몰릴 때에만 발생하는 것이라, 네트워크 자체 문제는 아닌 것으로 추측했다.
또한 운영에서의 네트워크 대역폭은 10Gbps 또는 100Gbps로 매우 큰 대역폭을 가지고 있었다.
네트워크 문제도 아니라고 가정하면, 왜 클라이언트에서 3-way-handshake는 완료되었는데 Conncetion 을 맺지 못한다고 나올까?
(failed to connecto to ...)
Linux Kernel 단의 문제인 것일까? 과연 Application 단과는 연관이 없는 것일까?
여러가지 가능성을 생각해 보았지만, 예전에 여러 번 수행한 부하테스트 경험 상 가장 유력한 것은 Server - Application 단의 병목으로 인해 Server - Kernel 단의 3-way-handshake 과정에서 발생하는 것이었다.
그래서 Tracer 가 띄워져 있는 물리 서버의 아래 Metric들을 운영팀에 요청해보았다.
listen queue of a socket overflowed
SYNs to LISTEN sockets dropped
이는 netstat -s | grep -i "listen" 와 같은 명령어로 출력이 가능하다.
각각 의미하는 바는 아래와 같다.
listen queue of a socket overflowed: Accept Queue 가 가득 찬 상태에서 연결 요청이 들어왔을 때 발생SYNs to LISTEN sockets dropped: SYN Queue 가 가득 찬 상태에서 연결 요청이 들어왔을 때 발생
# netstat -s | grep -i "listen"
# 1.
2063660 times the listen queue of a socket overflowed
2245967 SYNs to LISTEN sockets dropped
# 2.
1611204 times the listen queue of a socket overflowed
1621418 SYNs to LISTEN sockets dropped
# 3.
1703204 times the listen queue of a socket overflowed
1703256 SYNs to LISTEN sockets dropped
# 4.
1592389 times the listen queue of a socket overflowed
1592447 SYNs to LISTEN sockets dropped이것만 안다고 문제가 해결되지는 않는다. 아래 그린 3-way-handshake 과정을 살펴보자.
- Server - bind() : 서버의 초기 설정 과정. 서버의 소켓에 특정 로컬 주소를 할당한다.
- Server - listen() : 서버의 소켓을 LISTEN 상태로 만들어서, 연결 요청을 받을 준비를 한다.
- Client - connect() : 클라이언트의 소켓을 생성하고, 서버의 주소로 연결 요청을 한다.
이 때 SYN 패킷을 보내고 SYN_SENT 상태로 저장한다. - Server : 연결 요청을 받아, 새로운 소켓을 생성하여 연결을 수락한다.
이 때 SYN 패킷을 읽어 SYN_RECV 상태로 저장하며,
SYN Queue 에 넣고,
SYN + ACK 패킷을 응답한다. - Client : SYN + ACK 패킷을 받고, SYN 패킷을 ESTABLISHED 상태로 저장한다.
이 때 ACK 패킷을 보낸다. - Server : ACK 패킷을 읽어 ESTABLISHED 상태로 저장한다.
이 때 3-way-handshake 가 완료되었다고 인식해, Accept Queue 에 넣는다. - 이제 Server 의 Application 단에서 Accept Queue 으로부터 소켓을 빼와서 로직을 수행한다.
이 내용을 알고 보니 무언가 이상한 점이 보인다.
각각의 Metric 들은 Accept Queue, SYN Queue 가 가득 찼을 때 발생한다고 했는데,
listen queue of a socket overflowed, SYNs to LISTEN sockets dropped 의 발생 수가 거의 동일하다.
사실 Linux Kernel 의 구조는 버전에 따라 다르기도 하고, 매우 복잡해 SYNs to LISTEN sockets dropped 는 매우 다양한 상황에서 발생할 수 있다.
특히, Accept Queue 가 가득찼을 때 SYN 패킷이 인입되는 경우에도 SYN Drop이 발생할 수 있다.
아래 리눅스 코드를 까보자. (Linux Github 참고)
Linux-Github-tcp_ipv4.c
Linux-Github-tcp.h
// net/ipv4/tcp_ipv4.c
...
/*
* The three way handshake has completed - we got a valid synack -
* now create the new socket.
*/
struct sock *tcp_v4_syn_recv_sock(const struct sock *sk, struct sk_buff *skb,
struct request_sock *req,
struct dst_entry *dst,
struct request_sock *req_unhash,
bool *own_req)
{
struct inet_request_sock *ireq;
bool found_dup_sk = false;
struct inet_sock *newinet;
struct tcp_sock *newtp;
struct sock *newsk;
#ifdef CONFIG_TCP_MD5SIG
const union tcp_md5_addr *addr;
struct tcp_md5sig_key *key;
int l3index;
#endif
struct ip_options_rcu *inet_opt;
if (sk_acceptq_is_full(sk))
goto exit_overflow;
newsk = tcp_create_openreq_child(sk, req, skb);
if (!newsk)
goto exit_nonewsk;
newsk->sk_gso_type = SKB_GSO_TCPV4;
inet_sk_rx_dst_set(newsk, skb);
newtp = tcp_sk(newsk);
newinet = inet_sk(newsk);
ireq = inet_rsk(req);
inet_opt = rcu_dereference(ireq->ireq_opt);
RCU_INIT_POINTER(newinet->inet_opt, inet_opt);
newinet->mc_index = inet_iif(skb);
newinet->mc_ttl = ip_hdr(skb)->ttl;
newinet->rcv_tos = ip_hdr(skb)->tos;
inet_csk(newsk)->icsk_ext_hdr_len = 0;
if (inet_opt)
inet_csk(newsk)->icsk_ext_hdr_len = inet_opt->opt.optlen;
atomic_set(&newinet->inet_id, get_random_u16());
if (READ_ONCE(sock_net(sk)->ipv4.sysctl_tcp_reflect_tos))
newinet->tos = tcp_rsk(req)->syn_tos & ~INET_ECN_MASK;
if (!dst) {
dst = inet_csk_route_child_sock(sk, newsk, req);
if (!dst)
goto put_and_exit;
} else {
/* syncookie case : see end of cookie_v4_check() */
}
sk_setup_caps(newsk, dst);
tcp_ca_openreq_child(newsk, dst);
tcp_sync_mss(newsk, dst_mtu(dst));
newtp->advmss = tcp_mss_clamp(tcp_sk(sk), dst_metric_advmss(dst));
tcp_initialize_rcv_mss(newsk);
#ifdef CONFIG_TCP_MD5SIG
l3index = l3mdev_master_ifindex_by_index(sock_net(sk), ireq->ir_iif);
/* Copy over the MD5 key from the original socket */
addr = (union tcp_md5_addr *)&newinet->inet_daddr;
key = tcp_md5_do_lookup(sk, l3index, addr, AF_INET);
if (key && !tcp_rsk_used_ao(req)) {
if (tcp_md5_key_copy(newsk, addr, AF_INET, 32, l3index, key))
goto put_and_exit;
sk_gso_disable(newsk);
}
#endif
#ifdef CONFIG_TCP_AO
if (tcp_ao_copy_all_matching(sk, newsk, req, skb, AF_INET))
goto put_and_exit;
#endif
if (__inet_inherit_port(sk, newsk) < 0)
goto put_and_exit;
*own_req = inet_ehash_nolisten(newsk, req_to_sk(req_unhash),
&found_dup_sk);
if (likely(*own_req)) {
tcp_move_syn(newtp, req);
ireq->ireq_opt = NULL;
} else {
newinet->inet_opt = NULL;
if (!req_unhash && found_dup_sk) {
bh_unlock_sock(newsk);
sock_put(newsk);
newsk = NULL;
}
}
return newsk;
exit_overflow:
NET_INC_STATS(sock_net(sk), LINUX_MIB_LISTENOVERFLOWS);
exit_nonewsk:
dst_release(dst);
exit:
tcp_listendrop(sk);
return NULL;
put_and_exit:
newinet->inet_opt = NULL;
inet_csk_prepare_forced_close(newsk);
tcp_done(newsk);
goto exit;
}
EXPORT_IPV6_MOD(tcp_v4_syn_recv_sock);
...
// include/net/tcp.h
...
static inline void tcp_listendrop(const struct sock *sk)
{
atomic_inc(&((struct sock *)sk)->sk_drops);
__NET_INC_STATS(sock_net(sk), LINUX_MIB_LISTENDROPS);
}
...
net/ipv4/tcp_ipv4.c 에서의 tcp_v4_syn_recv_sock 를 보면 metric 들을 어떻게 증가시키는지 확인할 수 있다.
if (sk_acceptq_is_full(sk))
goto exit_overflow; // Accept Queue 에서 Overflow 가 발생하면
exit_overflow:
NET_INC_STATS(sock_net(sk), LINUX_MIB_LISTENOVERFLOWS); // LINUX_MIB_LISTENOVERFLOWS, 즉 listen queue overflow 를 증가시킨다.
exit_nonewsk:
dst_release(dst);
exit:
tcp_listendrop(sk); // tcp_listendrop 를 수행한다.static inline void tcp_listendrop(const struct sock *sk)
{
atomic_inc(&((struct sock *)sk)->sk_drops);
__NET_INC_STATS(sock_net(sk), LINUX_MIB_LISTENDROPS); // LINUX_MIB_LISTENDROPS, 즉 SYNs to LISTEN sockets dropped 를 증가시킨다.
}그에 대한 증명을 맨 아래 테스트 결과로부터 확인할 수 있다.
테스트 결과에서는 listen queue of a socket overflowed, SYNs to LISTEN sockets dropped 값이 동일하게 출력된다.
그러면 어떻게 해결해야 하는가? 아래 TCP 요청이 Tomcat 에 어떻게 들어가는지 확인해보자.
1. Client 로부터 SYN 패킷이 들어오면 Kernel은 SYN + ACK 를 응답하며 SYN Queue 에 추가된다.
이 때, SYN Queue 의 사이즈는 통상적으로 net.ipv4.tcp_max_syn_backlog 값으로 결정되는 것으로 알려져 있으나,
실제로는 Linux Kernel 2.6.20 까지만 유효했던 개념이고 이제는 net.ipv4.tcp_max_syn_backlog 말고도 여러 요인에 의해 값이 결정된다. (OS 별로, 버전 별로 다름)
2. Client 가 ACK 패킷 보내면 Kernel은 Accept Queue 에 소켓을 담는다.
Accept Queue 의 사이즈는 net.core.somaxconn 으로 관리된다.
(각 listen 포트에 대한 기본값은 통상적으로 4096이다.)
다만 Application 단에서 각각의 포트에 Accept Queue 크기를 다르게 설정할 수 있다.
Accept Queue 에 들어온 것들은 일반적으로 3-way-handshake 가 완료된 것이라고 본다.
3. Tomcat 의 Acceptor 쓰레드는 Kernel 의 Accept Queue 에 있는 소켓을 가져와 Tomcat 내부의 Poller Event Queue 에 넣는다.
Tomcat 의 acceptCount 프로퍼티 값이 Tomcat 이 listen 하는 포트의 Accept Queue 크기를 결정한다.
(default : 100)
4. Poller 쓰레드는 Poller Event Queue 에 있는 소켓을 가져와 Non-Blocking 하게 Worker Thread 에 할당한다.
Tomcat 이 Non-Blocking 하다는 의미는 여기에서 나온다.
기존 BIO (Blocking IO) Connector 는 하나의 소켓에 하나의 Worker Thread 가 할당되는데,
NIO (Non-Blocking IO) Connector 는 하나의 소켓에 여러 개의 Worker Thread 가 할당된다.
Tomcat 내에서 Worker Thread + Poller 가 담당할 수 있는 최대 소켓 수는 maxConnections 값으로 관리된다.
(default : 8192)
그러면 NIO Tomcat 에서 연결을 수용할 수 있는 크기인 maxConnections 값을 늘리는 것이 3-way-handshake 오류가 발생하지 않게 하는 가장 효율적인 방법이라고 생각한다.
AcceptCount 값을 조정하는 것은 개인적으로 아래와 같은 이유로 추천하지 않는다.
- Application 단에서는 본인이 사용하는 Accept Queue 는 특정 포트에 대해 size를 지정할 수 있다.
- Linux Kernel 단에서는 특정 포트만 지정하는 것이 아니라 모든 포트에 대해 Accept Queue size 를 지정한다.
- Application 단에서 지정한 Accpet Queue size / Linux Kernel 단에서 지정한 Accept Queue size 중 작은 값으로 적용된다.
- 그래서 Application 단에서만 Accpet Queue size 값을 늘린다고 근본적으로는 해결이 되지 않으며,
- 그렇다고 Linux Kernel 단에서도 전체 포트에 대해 Queue size 를 늘리는 것은 모양새가 조금 이상하다.
- 물론 OS 에 따라 Linux Kernel 단의 기본 Accept Queue size (somaxconn) 값이 1024 또는 4096 정도로 적당히 큰 값이 존재하니 이 정도 선까지는 Application 단의 Accept Queue size 값을 늘리는 것이 효과적일 수 있다.
물론, worker thread 단에서 병목 발생과 동시에 TCP 요청이 계속 인입되면 maxConnections 큐도 가득찰 가능성이 높아진다.
이러할 경우에는 maxConnections 수를 늘리는 것보다 인스턴스 수를 늘리는 것이 효율적이다.
아래는 위 내용과는 무관하지만 Springboot 내장 서버로 선택 가능한 Tomcat, Undertow, Netty에 대한 비교이다.
이번에 신규로 개발하는 Tracer 대체 프로젝트는 SpringBoot MVC + Tomcat 을 사용한 것에 대해 의문을 가질 수 있어 미리 작성한다.
성능만으로 보면 WebFlux + Netty 가 가장 좋을 것 같지만,
- 실제로 짧은 기간 내에 개발에 참여한 모든 인원들이 Reactive Programming 에 대해 정확히 숙지하고 있어야 하며, 이를 지키지 못할 시 오히려 성능이 떨어지는 현상이 발생할 수 있다.
- 또한 디버깅이 어렵고 기존 사내 공통 라이브러리로 사용하던 모든 것들을 전부 새로 작성해야 되는 불편함이 존재한다.
- 따라서 시간이 여유있고 모든 개발 구성원들이 학습에 대한 의지가 있는 경우에 적용해야 된다는 것이 내 판단이다.
그래서 이번 프로젝트에서는 SpringBoot MVC + Tomcat 에 더해 Virtual Thread + Kotlin coroutine 을 적극 사용한다.
- Virtual Thread 는 기존 무거운 Platform Thread 에서 벗어나 JVM 단에서 관리되는 매우 경량 쓰레드이다.
- Kotlin coroutine 은 비동기 프로그래밍을 위한 효율적인 방법이다.
- 기존 MVC 개념을 유지해 개발에 대한 학습 곡선이 크지 않다.
- Webflux + Netty 에 비해 성능이 뒤쳐지지 않는, 가볍고 빠른 비동기 프로그래밍을 효율적으로 적용할 수 있다.
- Undertow 는 RedHat 에서 만든 오픈소스로, 현재 Virtual Thread 를 지원하지 않는다. (SpringBoot Github - Undertow Virtual Thread Memory Leak 이슈)
Virtual Thread + Kotlin coroutine 에 대한 내용은 차후 다른 곳에 상세히 작성할 예정이다.
참고: Tomcat 이 Non-Blocking 하다는 의미
아주 예전의 Tomcat 이 아니라면 NIO 방식을 지원한다.
구분 BIO (Blocking I/O) NIO (Non-blocking I/O) 연결 처리 방식 연결당 하나의 Worker Thread 할당 및 점유 Poller가 다수의 연결 관리, 이벤트 발생 시 Worker Thread 활용 Worker Thread 연결의 전체 생명주기 동안 블로킹될 수 있음 I/O 이벤트 발생 시 작업 처리에만 사용, 블로킹 최소화 동시 연결 수 스레드 수에 강하게 비례하여 제한적 적은 수의 스레드로 더 많은 동시 연결 처리 가능 자원 효율성 유휴 연결도 스레드 점유하여 자원 낭비 발생 유휴 연결은 스레드 점유하지 않아 자원 효율적 확장성 동시 연결 증가 시 스레드 증가 부담 큼 적은 스레드로 확장성이 우수함 주요 컴포넌트 Acceptor, Worker Thread Pool Acceptor, Poller (Selector), Worker Thread Pool
참고 : Springboot 내장 Tomcat, Undertow, Netty 비교
특징 NIO Tomcat (Spring MVC와 함께) Undertow (Spring MVC와 함께) Netty (Spring WebFlux와 함께) 주요 사용 패러다임 전통적 Servlet (블로킹 API), Spring MVC Servlet (블로킹 API), Spring MVC 리액티브 프로그래밍, Spring WebFlux 기반 I/O 모델 Java NIO (Selector) XNIO (Java NIO 추상화) Java NIO, 네이티브 전송 (epoll, kqueue 등) I/O 스레드 Acceptor (연결 수락), Poller (I/O 이벤트 감지) XNIO I/O 스레드 (연결 수락 및 I/O 이벤트 감지) Netty Boss EventLoop (연결 수락), Netty Worker EventLoop (I/O 이벤트, 논블로킹 로직 실행) 애플리케이션 로직 실행 스레드 별도 Worker 스레드 풀 (server.tomcat.threads.max) 에서 Servlet/Controller 실행 (블로킹 가능) 별도 Worker 스레드 풀 (server.undertow.threads.worker) 에서 Servlet/Controller 실행 (블로킹 가능) 기본적으로 Worker EventLoop 스레드에서 논블로킹 로직 실행. 블로킹 작업은 Schedulers로 별도 스레드 풀에 위임 필수. 이벤트 루프 방식 부분적 (Poller는 이벤트 기반, 요청 처리는 스레드 풀) I/O 스레드는 이벤트 루프. 요청 처리는 MVC의 경우 워커 스레드로 위임. 강력하고 명확한 이벤트 루프 (EventLoop 자체가 이벤트 루프) 블로킹 코드 처리 Worker 스레드가 블로킹됨. 풀 소진 시 요청 대기. Worker 스레드가 블로킹됨 (MVC). 풀 소진 시 요청 대기. EventLoop 스레드에서 블로킹 절대 금지. Schedulers로 위임. 요청 처리 효율성 다수 동시 요청 시 스레드 증가, 컨텍스트 스위칭 비용 발생 가능 Tomcat 대비 경량, 잠재적으로 더 나은 성능 (MVC). 높은 수준의 성능 및 확장성, 논블로킹 최적화, 리소스 효율 극대화 개발 복잡도 상대적으로 낮음 (전통적 블로킹 모델) MVC 사용 시 Tomcat과 유사. WebFlux 시 Netty와 유사. 높음 (논블로킹, 비동기 패러다임, Netty 내부 구조 이해 필요, 디버깅 어려움)
SocketTimeoutException: failed to connect to ... 재현
이제 에러 현상을 이해하기 위한 사전지식을 설명했으니,
SocketTimeoutException: failed to connect to ... 발생을 재현해보자.
Android 환경에서 수행한다.
앱에서 OkhttpClient 를 사용한 것이 확인되어,
Native Java 인터페이스 환경에서 수행해 보았지만 동일한 에러 로그가 출력되지 않았다.
그래서 실제 Android 에뮬레이터를 띄우고 테스트를 수행했다.
- 실제 앱: 안드로이드 OS 환경에서 실행되며, 안드로이드 시스템의 네트워킹 API와 libcore 같은 저수준 라이브러리를 활용한다. 특히 com.android.okhttp를 사용한다면 더욱 그렇다.
- Native Java : JVM 환경에서 실행되며, 실제 네트워크 통신은 JVM의 표준 네트워킹 기능을 사용한다.
okhttp3 라이브러리는 이러한 JVM 환경에 맞게 동작한다.
AndroidManifest.xml
<?xml version="1.0" encoding="utf-8"?>
<manifest xmlns:android="http://schemas.android.com/apk/res/android"
xmlns:tools="http://schemas.android.com/tools">
<uses-permission android:name="android.permission.INTERNET" />
<uses-permission android:name="android.permission.ACCESS_NETWORK_STATE" />
<application
...
android:usesCleartextTraffic="true"
>
</application>
build.gradle.kts
...
android {
compileSdk = 35
defaultConfig {
...
minSdk = 35
targetSdk = 35
}
...
compileOptions {
sourceCompatibility = JavaVersion.VERSION_11
targetCompatibility = JavaVersion.VERSION_11
}
kotlinOptions {
jvmTarget = "11"
}
testOptions {
unitTests {
isIncludeAndroidResources = true
}
}
}
dependencies {
...
implementation("com.squareup.okhttp3:okhttp:4.14.1")
// kotlin coroutine 필요에 따라 구성
// Android 진영에서는 아직 JDK21 의 Virtual Thread 를 지원하지 않음에 참고.
// implementation("org.jetbrains.kotlinx:kotlinx-coroutines-core:1.8.1")
// implementation("org.jetbrains.kotlinx:kotlinx-coroutines-test:1.8.1")
}
아래 Andriod Kotlin 코드로 재현하고 증명하고자 한다.
환경은 아래와 같다.
- Kotlin, Kotlin coroutine
- Android 에뮬레이터는 가상 라우터 뒤에서 실행되기 때문에, localhost 가 아닌 10.0.2.2 로 접근한다.
- OkHttpClient
- ConnectTimeout : 5초
- ReadTimeout : 60초
- Device API version : 35
SocketTimeoutException 재현 코드
@RunWith(AndroidJUnit4::class)
class ExampleInstrumentedTest {
companion object {
private const val TAG = "SINGLE_CALL_TEST"
}
private fun createTrafficRequestBodyJson(): String {
return """
{
...
}
""".trimIndent()
}
private suspend fun performHttpRequest(client: OkHttpClient, url: String, jsonBody: String): Response {
return withContext(Dispatchers.IO) {
val mediaType = "application/json; charset=utf-8".toMediaType()
val requestBody = jsonBody.toRequestBody(mediaType)
val request = Request.Builder()
.url(url)
.post(requestBody)
.build()
client.newCall(request).execute()
}
}
private suspend fun processSingleUserRequest(
client: OkHttpClient,
url: String,
requestJson: String,
userId: Int,
successCounter: AtomicInteger,
failureCounter: AtomicInteger
) {
val startTime = System.currentTimeMillis()
try {
val response = performHttpRequest(client, url, requestJson)
val endTime = System.currentTimeMillis()
val elapsedTime = endTime - startTime
response.use {
if (it.isSuccessful) {
successCounter.incrementAndGet()
Log.i(TAG, "유저 $userId, 호출 성공: ${it.code}, 시간: ${elapsedTime}ms")
} else {
failureCounter.incrementAndGet()
Log.e(TAG, "유저 $userId, 호출 실패: ${it.code} ${it.body?.string()}, 시간: ${elapsedTime}ms")
}
}
} catch (e: Exception) {
val endTime = System.currentTimeMillis()
val elapsedTime = endTime - startTime
failureCounter.incrementAndGet()
Log.e(TAG, "유저 $userId, 예외 발생: ${e.message}, 시간: ${elapsedTime}ms", e)
}
}
@Test
fun singleCallTest_PerUser_With_Coroutines() {
runBlocking {
val concurrentUsers = 1
val targetUrl = "http://172.20.188.27:21000/test" // wsl private ip
// val targetUrl = "http://10.0.2.2:21000/test
val requestJson = createTrafficRequestBodyJson()
Log.i(TAG, "단일 호출 테스트 시작: 동시 유저=$concurrentUsers, URL=$targetUrl")
val client = OkHttpClient.Builder()
.connectTimeout(1, TimeUnit.SECONDS)
.readTimeout(60, TimeUnit.SECONDS)
.build()
val successCount = AtomicInteger(0)
val failureCount = AtomicInteger(0)
val userJobs = List(concurrentUsers) { userId ->
launch {
Log.d(TAG, "유저 $userId 시작 (단일 호출)")
processSingleUserRequest(
client,
targetUrl,
requestJson,
userId,
successCount,
failureCount
)
Log.d(TAG, "유저 $userId 단일 호출 완료")
}
}
userJobs.joinAll()
Log.d(TAG, "모든 유저 작업 완료")
val finalSuccessCount = successCount.get()
val finalFailureCount = failureCount.get()
val totalCalls = finalSuccessCount + finalFailureCount
Log.i(TAG, "---------- 테스트 결과 ----------")
Log.i(TAG, "총 유저 수: $concurrentUsers")
Log.i(TAG, "총 요청 수 (유저당 1회): $totalCalls")
Log.i(TAG, "성공: $finalSuccessCount")
Log.i(TAG, "실패: $finalFailureCount")
Log.i(TAG, "-----------------------------")
}
}
}
그리고 부하를 받는 Spring Boot 의 내장 Tomcat 의 properties 는 아래와 같이 설정했다.
Tomcat properties
server.tomcat.max-connections=1 (default : 8192)
server.tomcat.accept-count=1 (default : 100)API 응답시간 : 1초
이 조건에서 동시에 호출하는 유저 수를 변경해보면서, 어떠한 현상이 발생하는지 확인하고자 한다.
아래는 동시 호출 유저 수 : 1 로 설정한 결과이다.
// 동시 호출 유저 수 : 1
05-17 04:27:42.098 28865 28880 D SINGLE_CALL_TEST: 유저 0 시작 (단일 호출)
05-17 04:27:43.178 28865 28880 I SINGLE_CALL_TEST: 유저 0, 호출 성공: 200, 시간: 1080ms
05-17 04:27:43.179 28865 28880 D SINGLE_CALL_TEST: 유저 0 단일 호출 완료
05-17 04:27:43.182 28865 28880 D SINGLE_CALL_TEST: 모든 유저 작업 완료
05-17 04:27:43.182 28865 28880 I SINGLE_CALL_TEST: ---------- 테스트 결과 ----------
05-17 04:27:43.182 28865 28880 I SINGLE_CALL_TEST: 총 유저 수: 1
05-17 04:27:43.182 28865 28880 I SINGLE_CALL_TEST: 총 요청 수 (유저당 1회): 1
05-17 04:27:43.182 28865 28880 I SINGLE_CALL_TEST: 성공: 1
05-17 04:27:43.182 28865 28880 I SINGLE_CALL_TEST: 실패: 0
05-17 04:27:43.182 28865 28880 I SINGLE_CALL_TEST: -----------------------------병목이 발생하지 않아 정상적으로 1초만에 응답받은 모습이다.
그러면 이 때 발생하는 TCP 패킷을 Wireshark 로 분석해보자.
- Client -> Server : SYN (TCP 연결 시작, 3-way-handshake 시작)
- Server -> Client : SYN-ACK (TCP 연결 수락)
- Client -> Server : ACK (TCP 연결 완료, 3-way-handshake 완료)
- Client -> Server : HTTP Request
- Server -> Client : ACK (위 Request 에 대해 데이터를 잘 받았다는 의미)
- Server -> Client : PSH, ACK (PSH : 수신 측에 데이터를 즉시 상위 애플리케이션으로 전달하라는 의미)
- Server -> Client : HTTP Response
- Client -> Server : ACK (위 Response 에 대해 데이터를 잘 받았다는 의미)
- Client -> Server : FIN, ACK (클라이언트 -> 서버 연결 종료 요청, TCP Connection Teardown, 4-way-handshake)
- Server -> Client : FIN, ACK (서버가 FIN 요청을 수락(ACK)하고, 자신도 연결 종료(FIN)를 요청)
- Client -> Server : ACK (클라리언트가 서버의 FIN 에 대해 ACK 를 보내며 연결 정상 종료.)
이로써 TCP 연결이 어떻게 이루어지는지 한 바퀴를 확인해보았다.
그러면 동시 유저 수를 2로 늘려보자.
동시 호출 유저 수 : 2
05-17 04:54:01.525 29208 29225 I SINGLE_CALL_TEST: 유저 1, 호출 성공: 200, 시간: 1163ms
05-17 04:54:01.525 29208 29225 D SINGLE_CALL_TEST: 유저 1 단일 호출 완료
05-17 04:54:22.547 29208 29225 I SINGLE_CALL_TEST: 유저 0, 호출 성공: 200, 시간: 22195ms
05-17 04:54:22.547 29208 29225 D SINGLE_CALL_TEST: 유저 0 단일 호출 완료
05-17 04:54:22.549 29208 29225 D SINGLE_CALL_TEST: 모든 유저 작업 완료
05-17 04:54:22.549 29208 29225 I SINGLE_CALL_TEST: ---------- 테스트 결과 ----------
05-17 04:54:22.549 29208 29225 I SINGLE_CALL_TEST: 총 유저 수: 2
05-17 04:54:22.549 29208 29225 I SINGLE_CALL_TEST: 총 요청 수 (유저당 1회): 2
05-17 04:54:22.549 29208 29225 I SINGLE_CALL_TEST: 성공: 2
05-17 04:54:22.549 29208 29225 I SINGLE_CALL_TEST: 실패: 0
05-17 04:54:22.549 29208 29225 I SINGLE_CALL_TEST: -----------------------------결과가 약간 이상하다.
유저 1이 1초만에 응답을 받았는데, 유저 2는 22초가 소요되었다.
Tomcat 에서 설정한 프로퍼티는 아래를 의미한다.
- max-connections : Tomcat 내부적으로 동시에 처리할 수 있는 최대 연결 수 (설정값 : 1)
- accept-count : Tomcat 에서 최대로 처리할 수 없어서 Kenral 단에서 기다리고 있는 (Accept Queue) 의 최대 개수 (설정값 : 1)
wireshark 에서는 유저 1의 Client 임시 port 가 54878, 유저 2의 Client 임시 port 가 54879 로 확인된다.
유저 1과 유저 2의 SYN 요청이 동시에 인입되었고, 둘 다 3-way-handshake 가 완료되었다.
유저 1의 요청이 1초만에 끝났으면, 유저 2의 요청도 1초를 기다렸다가 API 내부 로직인 1초 수행한 총 2초만에 수행되어야 하지 않는가?
다만 Tomcat 에는 내부적으로 HTTP 1.1 이상부터는 Keep-alive 속성이 존재한다.
이는 유저 1의 요청이 완료되었더라도, 기본값인 20초 동안 연결을 유지할 수 있도록 하는 것이다.
그러므로 유저 2의 요청은 1초 + 20초 동안 기다렸다가 1초를 소요한 총 22초만에 응답을 받게 된다.
참고 : 여기서 ConnectTimeout : 5초인데 ConnectTimeout 이 나지 않은 것은 이미 3-way-handshake 가 완료되었기 때문이다.
그러므로 ReadTimeout 설정인 최대 60초까지 계속 대기하게 된다.
이를 증명해보이기 위해 동시 호출 유저 수 : 2, 각 유저 별 호출 수 : 2 로 설정한 상태에서 수행해보자.
05-17 05:21:25.559 29649 29663 I SINGLE_CALL_TEST: 유저 1, 호출 성공: 200, 시간: 1155ms
05-17 05:21:25.560 29649 29663 D SINGLE_CALL_TEST: 유저 1 시작 (단일 호출)
05-17 05:21:26.569 29649 29663 I SINGLE_CALL_TEST: 유저 1, 호출 성공: 200, 시간: 1009ms
05-17 05:21:26.570 29649 29663 D SINGLE_CALL_TEST: 유저 1 단일 호출 완료
05-17 05:21:47.597 29649 29663 I SINGLE_CALL_TEST: 유저 0, 호출 성공: 200, 시간: 23202ms
05-17 05:21:47.598 29649 29663 D SINGLE_CALL_TEST: 유저 0 시작 (단일 호출)
05-17 05:21:48.607 29649 29663 I SINGLE_CALL_TEST: 유저 0, 호출 성공: 200, 시간: 1009ms
05-17 05:21:48.607 29649 29663 D SINGLE_CALL_TEST: 유저 0 단일 호출 완료
05-17 05:21:48.609 29649 29663 D SINGLE_CALL_TEST: 모든 유저 작업 완료
05-17 05:21:48.609 29649 29663 I SINGLE_CALL_TEST: ---------- 테스트 결과 ----------
05-17 05:21:48.609 29649 29663 I SINGLE_CALL_TEST: 총 유저 수: 2
05-17 05:21:48.609 29649 29663 I SINGLE_CALL_TEST: 총 요청 수 (유저당 1회): 4
05-17 05:21:48.609 29649 29663 I SINGLE_CALL_TEST: 성공: 4
05-17 05:21:48.609 29649 29663 I SINGLE_CALL_TEST: 실패: 0
05-17 05:21:48.609 29649 29663 I SINGLE_CALL_TEST: -----------------------------예상이 맞았다.
한 번 연결된 요청은 20초 동안 유지되어, Tomcat 의 connection 수를 차지한다.
이는 아래와 같이 분석된다.
- 유저 1_1 요청 : 1초
- 유저 2_1 요청 : 유저 1 의 연결이 끝날때까지 대기
- 유저 1_2 요청 : 1초
- 유저 2_1 요청 : 1_2 의 요청이 끝난 후 20초 대기 후 1초 수행 = 1초 + 1초 + 20초 + 1초 = 23초
- 유저 2_2 요청 : 유저 2가 이미 연결되어있으므로 1초만에 수행
이제는 동시 호출 유저 수 : 3 로 수행해보자.
여기서부터는 동시에 3명을 wireshark 로 한 번에 보기 힘드므로, 각 유저별로 나누어서 보자.
05-17 05:32:15.621 30000 30014 D SINGLE_CALL_TEST: 유저 0 시작 (단일 호출)
05-17 05:32:15.631 30000 30014 D SINGLE_CALL_TEST: 유저 1 시작 (단일 호출)
05-17 05:32:15.633 30000 30014 D SINGLE_CALL_TEST: 유저 2 시작 (단일 호출)
05-17 05:32:16.749 30000 30014 I SINGLE_CALL_TEST: 유저 2, 호출 성공: 200, 시간: 1116ms
05-17 05:32:16.750 30000 30014 D SINGLE_CALL_TEST: 유저 2 단일 호출 완료
05-17 05:32:37.763 30000 30014 I SINGLE_CALL_TEST: 유저 1, 호출 성공: 200, 시간: 22130ms
05-17 05:32:37.763 30000 30014 D SINGLE_CALL_TEST: 유저 1 단일 호출 완료
05-17 05:32:58.790 30000 30014 I SINGLE_CALL_TEST: 유저 0, 호출 성공: 200, 시간: 43169ms
05-17 05:32:58.791 30000 30014 D SINGLE_CALL_TEST: 유저 0 단일 호출 완료
05-17 05:32:58.793 30000 30014 D SINGLE_CALL_TEST: 모든 유저 작업 완료
05-17 05:32:58.793 30000 30014 I SINGLE_CALL_TEST: ---------- 테스트 결과 ----------
05-17 05:32:58.793 30000 30014 I SINGLE_CALL_TEST: 총 유저 수: 3
05-17 05:32:58.793 30000 30014 I SINGLE_CALL_TEST: 총 요청 수 (유저당 1회): 3
05-17 05:32:58.793 30000 30014 I SINGLE_CALL_TEST: 성공: 3
05-17 05:32:58.793 30000 30014 I SINGLE_CALL_TEST: 실패: 0
05-17 05:32:58.793 30000 30014 I SINGLE_CALL_TEST: -----------------------------Every 1.0s: netstat -s | grep -i "listen"
0 times the listen queue of a socket overflowed
0 SYNs to LISTEN sockets dropped여기서도 무언가 이상한 점이 보인다.
동시 요청은 Tomcat 의 maxConnection 의 1 + AcceptCount 의 1 이므로, 2개만 허용하는 것으로 설정했는데, kernel 단의 overflow 가 발생하지 않았다.
아주 중요한 내용은 아니지만, Linux Kernel 단의 Accpet Queue 는 비교값 연산자가 > 가 아닌 >= 으로 설정되어 있어 최대값 + 1개까지 Accpept Queue 에 허용된다.
아래 Linux Kernel 함수를 보면, Accept Queue 최대값을 1로 설정했을 때
이미 Accept Queue 가 가득 찬 (1) 상태에서 새로 Accept Queue 인입 요청을 위해 해당 메서드를 수행해도 가득 차지 않음 으로 판단하기 때문에 인입이 허용된다.
다만 왜 이렇게 구현했는지는 이해할 수는 없다.
// sk_ack_backlog: 현재 Accept Queue에 대기 중인 연결 수.
// sk_max_ack_backlog: listen() 시스템 콜의 backlog 파라미터와 net.core.somaxconn 중 작은 값으로 설정된 최대 큐 크기.
// accept queue 가 가득찼는지 판단하는 리눅스 Kernel 메서드
static inline bool sk_acceptq_is_full(const struct sock *sk) {
return READ_ONCE(sk->sk_ack_backlog) > READ_ONCE(sk->sk_max_ack_backlog);
}그 부분을 제외하면 예상한대로 이전 요청의 Keep-Alive 의 유지가 끊기고 나서 다음 요청이 인입되게 동작한다.
이제는 동시 호출 유저 수 : 4 로 수행해보자.
여기서부터는 overflow 가 발생할 것으로 예상된다.
Every 1.0s: netstat -s | grep -i "listen"
5 times the listen queue of a socket overflowed
5 SYNs to LISTEN sockets dropped05-17 06:18:55.451 30475 30490 D SINGLE_CALL_TEST: 유저 0 시작 (단일 호출)
05-17 06:18:55.456 30475 30490 D SINGLE_CALL_TEST: 유저 1 시작 (단일 호출)
05-17 06:18:55.458 30475 30490 D SINGLE_CALL_TEST: 유저 2 시작 (단일 호출)
05-17 06:18:55.461 30475 30490 D SINGLE_CALL_TEST: 유저 3 시작 (단일 호출)
05-17 06:18:56.564 30475 30490 E SINGLE_CALL_TEST: 유저 0, 예외 발생: failed to connect to /172.20.188.27 (port 21000) from /10.0.2.16 (port 36122) after 1000ms, 시간: 1107ms
05-17 06:18:56.564 30475 30490 E SINGLE_CALL_TEST: java.net.SocketTimeoutException: failed to connect to /172.20.188.27 (port 21000) from /10.0.2.16 (port 36122) after 1000ms
05-17 06:18:56.564 30475 30490 E SINGLE_CALL_TEST: at libcore.io.IoBridge.connectErrno(IoBridge.java:235)
05-17 06:18:56.564 30475 30490 E SINGLE_CALL_TEST: at libcore.io.IoBridge.connect(IoBridge.java:179)
05-17 06:18:56.564 30475 30490 E SINGLE_CALL_TEST: at java.net.PlainSocketImpl.socketConnect(PlainSocketImpl.java:142)
05-17 06:18:56.564 30475 30490 E SINGLE_CALL_TEST: at java.net.AbstractPlainSocketImpl.doConnect(AbstractPlainSocketImpl.java:390)
05-17 06:18:56.564 30475 30490 E SINGLE_CALL_TEST: at java.net.AbstractPlainSocketImpl.connectToAddress(AbstractPlainSocketImpl.java:230)
05-17 06:18:56.564 30475 30490 E SINGLE_CALL_TEST: at java.net.AbstractPlainSocketImpl.connect(AbstractPlainSocketImpl.java:212)
05-17 06:18:56.564 30475 30490 E SINGLE_CALL_TEST: at java.net.SocksSocketImpl.connect(SocksSocketImpl.java:436)
05-17 06:18:56.564 30475 30490 E SINGLE_CALL_TEST: at java.net.Socket.connect(Socket.java:646)
05-17 06:18:56.564 30475 30490 E SINGLE_CALL_TEST: at okhttp3.internal.platform.Platform.connectSocket(Platform.kt:128)
05-17 06:18:56.564 30475 30490 E SINGLE_CALL_TEST: at okhttp3.internal.connection.RealConnection.connectSocket(RealConnection.kt:295)
05-17 06:18:56.564 30475 30490 E SINGLE_CALL_TEST: at okhttp3.internal.connection.RealConnection.connect(RealConnection.kt:207)
05-17 06:18:56.564 30475 30490 E SINGLE_CALL_TEST: at okhttp3.internal.connection.ExchangeFinder.findConnection(ExchangeFinder.kt:226)
05-17 06:18:56.564 30475 30490 E SINGLE_CALL_TEST: at okhttp3.internal.connection.ExchangeFinder.findHealthyConnection(ExchangeFinder.kt:106)
05-17 06:18:56.564 30475 30490 E SINGLE_CALL_TEST: at okhttp3.internal.connection.ExchangeFinder.find(ExchangeFinder.kt:74)
05-17 06:18:56.564 30475 30490 E SINGLE_CALL_TEST: at okhttp3.internal.connection.RealCall.initExchange$okhttp(RealCall.kt:255)
05-17 06:18:56.564 30475 30490 E SINGLE_CALL_TEST: at okhttp3.internal.connection.ConnectInterceptor.intercept(ConnectInterceptor.kt:32)
05-17 06:18:56.564 30475 30490 E SINGLE_CALL_TEST: at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.kt:109)
05-17 06:18:56.564 30475 30490 E SINGLE_CALL_TEST: at okhttp3.internal.cache.CacheInterceptor.intercept(CacheInterceptor.kt:95)
05-17 06:18:56.564 30475 30490 E SINGLE_CALL_TEST: at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.kt:109)
05-17 06:18:56.564 30475 30490 E SINGLE_CALL_TEST: at okhttp3.internal.http.BridgeInterceptor.intercept(BridgeInterceptor.kt:83)
05-17 06:18:56.564 30475 30490 E SINGLE_CALL_TEST: at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.kt:109)
05-17 06:18:56.564 30475 30490 E SINGLE_CALL_TEST: at okhttp3.internal.http.RetryAndFollowUpInterceptor.intercept(RetryAndFollowUpInterceptor.kt:76)
05-17 06:18:56.564 30475 30490 E SINGLE_CALL_TEST: at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.kt:109)
05-17 06:18:56.564 30475 30490 E SINGLE_CALL_TEST: at okhttp3.internal.connection.RealCall.getResponseWithInterceptorChain$okhttp(RealCall.kt:201)
05-17 06:18:56.564 30475 30490 E SINGLE_CALL_TEST: at okhttp3.internal.connection.RealCall.execute(RealCall.kt:154)
05-17 06:18:56.564 30475 30490 E SINGLE_CALL_TEST: at com.example.myapplication.ExampleInstrumentedTest$performHttpRequest$2.invokeSuspend(ExampleInstrumentedTest.kt:61)
05-17 06:18:56.564 30475 30490 E SINGLE_CALL_TEST: at kotlin.coroutines.jvm.internal.BaseContinuationImpl.resumeWith(ContinuationImpl.kt:33)
05-17 06:18:56.564 30475 30490 E SINGLE_CALL_TEST: at kotlinx.coroutines.DispatchedTask.run(DispatchedTask.kt:104)
05-17 06:18:56.564 30475 30490 E SINGLE_CALL_TEST: at kotlinx.coroutines.internal.LimitedDispatcher$Worker.run(LimitedDispatcher.kt:111)
05-17 06:18:56.564 30475 30490 E SINGLE_CALL_TEST: at kotlinx.coroutines.scheduling.TaskImpl.run(Tasks.kt:99)
05-17 06:18:56.564 30475 30490 E SINGLE_CALL_TEST: at kotlinx.coroutines.scheduling.CoroutineScheduler.runSafely(CoroutineScheduler.kt:584)
05-17 06:18:56.564 30475 30490 E SINGLE_CALL_TEST: at kotlinx.coroutines.scheduling.CoroutineScheduler$Worker.executeTask(CoroutineScheduler.kt:811)
05-17 06:18:56.564 30475 30490 E SINGLE_CALL_TEST: at kotlinx.coroutines.scheduling.CoroutineScheduler$Worker.runWorker(CoroutineScheduler.kt:715)
05-17 06:18:56.564 30475 30490 E SINGLE_CALL_TEST: at kotlinx.coroutines.scheduling.CoroutineScheduler$Worker.run(CoroutineScheduler.kt:702)
05-17 06:18:56.564 30475 30490 D SINGLE_CALL_TEST: 유저 0 단일 호출 완료
05-17 06:18:56.652 30475 30490 I SINGLE_CALL_TEST: 유저 2, 호출 성공: 200, 시간: 1191ms
05-17 06:18:56.653 30475 30490 D SINGLE_CALL_TEST: 유저 2 단일 호출 완료
05-17 06:19:17.675 30475 30490 I SINGLE_CALL_TEST: 유저 3, 호출 성공: 200, 시간: 22214ms
05-17 06:19:17.675 30475 30490 D SINGLE_CALL_TEST: 유저 3 단일 호출 완료
05-17 06:19:38.702 30475 30490 I SINGLE_CALL_TEST: 유저 1, 호출 성공: 200, 시간: 43245ms
05-17 06:19:38.702 30475 30490 D SINGLE_CALL_TEST: 유저 1 단일 호출 완료
05-17 06:19:38.703 30475 30490 D SINGLE_CALL_TEST: 모든 유저 작업 완료
05-17 06:19:38.703 30475 30490 I SINGLE_CALL_TEST: ---------- 테스트 결과 ----------
05-17 06:19:38.703 30475 30490 I SINGLE_CALL_TEST: 총 유저 수: 4
05-17 06:19:38.703 30475 30490 I SINGLE_CALL_TEST: 총 요청 수 (유저당 1회): 4
05-17 06:19:38.703 30475 30490 I SINGLE_CALL_TEST: 성공: 3
05-17 06:19:38.703 30475 30490 I SINGLE_CALL_TEST: 실패: 1
05-17 06:19:38.703 30475 30490 I SINGLE_CALL_TEST: -----------------------------예상대로 listen queue(Accept Queue) overflow 가 발생했고, 이로 인해 운영 상 발생한
SocketTimeoutException: failed to connect to 가 재현되었다.
다만 요청은 1번만 실패했는데 listen queue overflow 는 왜 5번이 발생한 것일까?
wireshark 패킷부터 분석해보자. 오류가 발생한 유저 (임시 Client 63719 포트)
1. Client -> Server : SYN (TCP 연결 시작, 3-way-handshake 시작)
2. Server : Accept Queue 가 가득 차 SYN 패킷을 Drop 한다.
3. Client : SYN 패킷을 보냈는데도 응답이 오지 않아, Retransmission Timeout(RTO) 가 발생한다.
4. Client -> Server : 다시 SYN 패킷을 보낸다. 이 때, 이전 SYN 패킷 요청시간 보다 1초 뒤에 보낸다.
5. Server : Accept Queue 가 가득 차 SYN 패킷을 Drop 한다.
6. Client : SYN 패킷을 보냈는데도 응답이 오지 않아, Retransmission Timeout(RTO) 가 발생한다.
7. Client -> Server : 다시 SYN 패킷을 보낸다. 이 때, 이전 SYN 패킷 요청시간 보다 2초 뒤에 보낸다.
8. Server : Accept Queue 가 가득 차 SYN 패킷을 Drop 한다.
9. Client : SYN 패킷을 보냈는데도 응답이 오지 않아, Retransmission Timeout(RTO) 가 발생한다.
10. Client -> Server : 다시 SYN 패킷을 보낸다. 이 때, 이전 SYN 패킷 요청시간 보다 4초 뒤에 보낸다.
11. Server : Accept Queue 가 가득 차 SYN 패킷을 Drop 한다.
12. Client : SYN 패킷을 보냈는데도 응답이 오지 않아, Retransmission Timeout(RTO) 가 발생한다.
13. Client -> Server : 다시 SYN 패킷을 보낸다. 이 때, 이전 SYN 패킷 요청시간 보다 8초 뒤에 보낸다.
14. Server : Accept Queue 가 가득 차 SYN 패킷을 Drop 한다.
Retransmission Timeout(RTO) 는 무엇일까?
Client 가 Server 에 최초 3-way-handshake를 수행하기 위해 SYN 패킷을 보냈는데,
정상적인 응답을 받지 못한 경우를 의미한다.
이 때 특정 주기마다 SYN 패킷을 재전송하는데, 이 주기는 min 1s 부터 * 2 를 하며 재수행한다. (backoff, 지수 증가 형식)
재수행 횟수는 Client 가 지정하고 OS 별로 기본값이 다르며, Linux 기준 net.ipv4.tcp_syn_retries 값으로 변경 가능하다.
# syn retry 설정값 조회
sysctl net.ipv4.tcp_syn_retries
# syn retry 설정값 적용
# /etc/sysctl.conf
net.ipv4.tcp_syn_retries=?
# 반영
sudo sysctl -p참고 : net.ipv4.tcp_abort_on_overflow 값에 따라 서버가 바로 RST (거부) 패킷을 보낼 수도 있다.
이 값은 1일 때, Accept Queue 가 가득 차는 순간 RST 패킷을 보내 Client 가 재시도 하지 않게 한다.
0일 때에는 별다른 응답을 보내지 않아 Client 는 RTO 로 인한 SYN 패킷 재전송을 임계점까지 계속한다.
대체로 기본값은 0이다.
추가로 failed to connect to ... after 1000ms 에서 1000ms 는 RTO 와는 관계없이 okHttpClient 의 ConnectTimeout 값이 적용된 것이다.
ConnectTimeout = 5초로 설정 시 에러 로그도 5000ms 로 표시된 것이 확인된다.
참고 차 Andriod 에서 언제 SocktTimeoutException 을 발생시키는지 DeCompile한 Andriod Native 코드를 아래 첨부한다.
이는 소켓 프로그래밍을 위한 학습에 도움이 되므로 한 번쯤은 읽어보는 것을 추천한다.
아래 코드를 이해한다면, 위에서 발생한 SocketTimeoutException: failed to connecto to ... 뿐만 아니라,
ConnectTimouet 을 매우 길게 잡아놓았을 때, RTO 의 retry 횟수가 임계점까지 도달한 경우는 어느 에러가 발생하는지도 이해할 수 있다.
시간이 된다면 언제 Blocking / Non-Blocking 되는지도 살펴보면 더 좋을 듯 하다.
package libcore.io;
...
@SystemApi(client = MODULE_LIBRARIES)
public final class IoBridge {
private IoBridge() {
}
public static int available(FileDescriptor fd) throws IOException {
try {
int available = Libcore.os.ioctlInt(fd, FIONREAD);
if (available < 0) {
available = 0;
}
return available;
} catch (ErrnoException errnoException) {
if (errnoException.errno == ENOTTY) {
return 0;
}
throw errnoException.rethrowAsIOException();
}
}
/**
* connect가 SYN 패킷을 전송하기 전에 bind 수행
* 소켓(파일 디스크립터 fd)에 로컬 IP 주소와 포트 번호를 할당한다.
* 이 작업은 전적으로 로컬 시스템 내에서 이루어지며, 네트워크 패킷을 발생시키지 않는다.
* 소켓이 '어떤 로컬 주소와 포트를 사용할 것인가'를 결정하는 단계이다.
*/
public static void bind(FileDescriptor fd, InetAddress address, int port) throws SocketException {
if (address instanceof Inet6Address) {
Inet6Address inet6Address = (Inet6Address) address;
if (inet6Address.getScopeId() == 0 && inet6Address.isLinkLocalAddress()) {
NetworkInterface nif = NetworkInterface.getByInetAddress(address);
if (nif == null) {
throw new SocketException("Can't bind to a link-local address without a scope id: " + address);
}
try {
address = Inet6Address.getByAddress(address.getHostName(), address.getAddress(), nif.getIndex());
} catch (UnknownHostException ex) {
throw new AssertionError(ex);
}
}
}
try {
Libcore.os.bind(fd, address, port);
} catch (ErrnoException errnoException) {
if (errnoException.errno == EADDRINUSE || errnoException.errno == EADDRNOTAVAIL ||
errnoException.errno == EPERM || errnoException.errno == EACCES) {
throw new BindException(errnoException.getMessage(), errnoException);
} else {
throw new SocketException(errnoException.getMessage(), errnoException);
}
}
}
/**
* 실제 SYN 패킷을 전송하기 위한 connect 메서드
* SocketTimeoutException 발생 시 로직을 강조한다.
*/
public static void connect(FileDescriptor fd, InetAddress inetAddress, int port) throws SocketException {
try {
IoBridge.connect(fd, inetAddress, port, 0);
} catch (SocketTimeoutException ex) {
throw new AssertionError(ex);
}
}
/**
* 위 connect 에서 내부 호출되는 메서드
* 여러 Exception 로직에 대한 분기를 담당한다.
*/
public static void connect(FileDescriptor fd, InetAddress inetAddress, int port, int timeoutMs) throws SocketException, SocketTimeoutException {
try {
connectErrno(fd, inetAddress, port, timeoutMs);
} catch (ErrnoException errnoException) {
if (errnoException.errno == EHOSTUNREACH) {
throw new NoRouteToHostException("Host unreachable");
}
if (errnoException.errno == EADDRNOTAVAIL) {
throw new NoRouteToHostException("Address not available");
}
throw new ConnectException(createMessageForException(fd, inetAddress, port, timeoutMs,
errnoException), errnoException);
} catch (SocketException ex) {
throw ex;
} catch (SocketTimeoutException ex) {
throw ex;
} catch (IOException ex) {
throw new SocketException(ex);
}
}
/**
* 위 connect 에서 호출되는 connectErrorno 메서드
* timeout이 없는 경우, OS 의 기본 connect 콜을 직접 호출하며 blocking 하게 동작한다.
* timeout이 있는 경우, Socket 을 Non-Blocking 모드로 전환하고, SYN 패킷을 전송한다.
* 연결이 즉시 가능하다면 다시 Blocking 모드로 전환하고 리턴한다.
* 연결이 즉시 불가능할 때, EINPROGRESS (Operation now in progress) 상태라면 연결 과정이 백그라운드에서 시작되었음을 의미하므로 던지지 않고 이후 로직을 수행한다.
* 남은 timeout 시간을 계산해 0 이하라면 SocketTimeoutException 을 발생시키며 에러메시지를 별도로 작성한다.
* 이 때 남은 timeout 시간을 계산하는 것은 polling 방식으로 isConnected 를 통해 이루어진다.
* 연결이 완료되면 다시 Blocking 모드로 전환한다.
*/
private static void connectErrno(FileDescriptor fd, InetAddress inetAddress, int port, int timeoutMs) throws ErrnoException, IOException {
if (timeoutMs <= 0) {
Libcore.os.connect(fd, inetAddress, port);
return;
}
IoUtils.setBlocking(fd, false);
long finishTimeNanos = System.nanoTime() + TimeUnit.MILLISECONDS.toNanos(timeoutMs);
try {
Libcore.os.connect(fd, inetAddress, port);
IoUtils.setBlocking(fd, true);
return;
} catch (ErrnoException errnoException) {
if (errnoException.errno != EINPROGRESS) {
throw errnoException;
}
}
int remainingTimeoutMs;
do {
remainingTimeoutMs =
(int) TimeUnit.NANOSECONDS.toMillis(finishTimeNanos - System.nanoTime());
if (remainingTimeoutMs <= 0) {
throw new SocketTimeoutException(
createMessageForException(fd, inetAddress, port, timeoutMs, null));
}
} while (!IoBridge.isConnected(fd, inetAddress, port, timeoutMs, remainingTimeoutMs));
IoUtils.setBlocking(fd, true);
}
/**
* SocketTimeoutException 발생 시 에러메시지를 작성.
* failed to connect to ... 에러 메시지는 여기서 나온 것임을 확인할 수 있다.
*/
private static String createMessageForException(FileDescriptor fd, InetAddress inetAddress,
int port, int timeoutMs, Exception causeOrNull) {
InetSocketAddress localAddress = null;
try {
localAddress = getLocalInetSocketAddress(fd);
} catch (SocketException ignored) {
}
StringBuilder sb = new StringBuilder("failed to connect")
.append(" to ")
.append(inetAddress)
.append(" (port ")
.append(port)
.append(")");
if (localAddress != null) {
sb.append(" from ")
.append(localAddress.getAddress())
.append(" (port ")
.append(localAddress.getPort())
.append(")");
}
if (timeoutMs > 0) {
sb.append(" after ")
.append(timeoutMs)
.append("ms");
}
if (causeOrNull != null) {
sb.append(": ")
.append(causeOrNull.getMessage());
}
return sb.toString();
}
...
/**
* 실제 연결이 성공했는지 (ACK 응답을 받았는지) 확인
* poll 시스템 콜에 전달할 file descriptor (소켓) 과 timeout 을 전달해, Non-Blocking 하게 소켓의 상태 변화를 감시한다.
* poll 시스템콜의 반환값 rc
* rc == 0 : timeout, 소켓의 상태 변화가 없었음을 의미한다. false 리턴 후 다시 while 문으로 시도 시 전체
* timeoutMs 시간이 초과되면 SocketTimeoutException 발생
* rc > 0 : 연결 성공, write() 가 가능한 상태가 되었음을 의미한다.
* 이후 socket 이 쓰기 가능한 상태가 되었더라도, 실제 연결이 성공했는지 검증한다.
* connectError : 0 (오류 없음), != 0 (오류 발생)
* 위 단계에서 연결 상태가 성공적이지 않은 경우, file descriptor 가 유효한지 않은지 (다른 Thread 에서 닫혔는지 등) 검증한다.
* 이후 에러 원인이 ETIMEDOUT 임을 확인해 SocketTimeoutException 을 던진다.
* (rc == 0 과는 다름. 시스템 레벨의 timeout, 예시로 RTO 가 여러 번 발생해 시스템이 더 이상 재시도하지 않겠다 판단하는 등..)
* 이 외의 경우에는 모두 ConnectException 으로 처리한다.
*
*/
@UnsupportedAppUsage
public static boolean isConnected(FileDescriptor fd, InetAddress inetAddress, int port,
int timeoutMs, int remainingTimeoutMs) throws IOException {
ErrnoException cause;
try {
StructPollfd[] pollFds = new StructPollfd[] { new StructPollfd() };
pollFds[0].fd = fd;
pollFds[0].events = (short) POLLOUT;
int rc = Libcore.os.poll(pollFds, remainingTimeoutMs);
if (rc == 0) {
return false; // Timeout.
}
int connectError = Libcore.os.getsockoptInt(fd, SOL_SOCKET, SO_ERROR);
if (connectError == 0) {
return true; // Success!
}
throw new ErrnoException("isConnected", connectError); // The connect(2) failed.
} catch (ErrnoException errnoException) {
if (!fd.valid()) {
throw new SocketException("Socket closed");
}
cause = errnoException;
}
String detail = createMessageForException(fd, inetAddress, port, timeoutMs, cause);
if (cause.errno == ETIMEDOUT) {
SocketTimeoutException e = new SocketTimeoutException(detail);
e.initCause(cause);
throw e;
}
throw new ConnectException(detail, cause);
}
...
}이 이론대로라면, Accept Queue 가 가득찬 상태에서 N 개의 요청이 인입되면 5*N 번의 listen queue overflow 및 SYN drop 현상이 발생할 것이다.
한 번만 더 검증해보자.
이번에는 동시 호출 유저 수 : 103 으로 설정해 3명이 Accept Queue 를 가득 채우고,
나머지 100명이 overflow 되는 요청을 보내고 각각 4번의 retry 를 수행해 5 * 100 번의 overflow 및 SYN drop 현상이 발생할 것이다.
05-17 08:23:29.341 31525 31539 D SINGLE_CALL_TEST: 모든 유저 작업 완료
05-17 08:23:29.341 31525 31539 I SINGLE_CALL_TEST: ---------- 테스트 결과 ----------
05-17 08:23:29.341 31525 31539 I SINGLE_CALL_TEST: 총 유저 수: 103
05-17 08:23:29.341 31525 31539 I SINGLE_CALL_TEST: 총 요청 수 (유저당 1회): 103
05-17 08:23:29.341 31525 31539 I SINGLE_CALL_TEST: 성공: 3
05-17 08:23:29.341 31525 31539 I SINGLE_CALL_TEST: 실패: 100
05-17 08:23:29.341 31525 31539 I SINGLE_CALL_TEST: -----------------------------Every 1.0s: netstat -s | grep -i "listen"
500 times the listen queue of a socket overflowed
500 SYNs to LISTEN sockets dropped이론대로 맞아 떨어짐이 확인된다.
그러면 운영 상에서 listen queue overflow 가 발생한 횟수로 얼마만큼의 Client 입장에서 얼마만큼의 API 요청이 실패했는지 역산이 가능하다.
# 1.
2063660 times the listen queue of a socket overflowed
2245967 SYNs to LISTEN sockets dropped
# 2.
1611204 times the listen queue of a socket overflowed
1621418 SYNs to LISTEN sockets dropped
# 3.
1703204 times the listen queue of a socket overflowed
1703256 SYNs to LISTEN sockets dropped
# 4.
1592389 times the listen queue of a socket overflowed
1592447 SYNs to LISTEN sockets dropped앞서 언급한 운영 상의 metric 들을 보았을 떄, 2063660 + 1611204 + 1703204 + 1592389 = 6,568,459 라는 overflow 횟수가 확인된다.
또한 APP 의 OkhttpClient 의 ConnectTimeout 은 5초로 설정되어 있다.
overflow가 발생 가능한 경우의 수를 살펴보자.
- Client 가 SYN 패킷을 보냈는데 ACK 응답을 받지 못한 경우, RTO 가 발생할 수 있다.
- RTO 가 발생할 경우, 최초 SYN 패킷 전송 시점으로부터
1초 뒤 SYN 패킷을 재전송한다.- 이 때 다시 ACK 응답을 받지 못한 경우, 위 SYN 재전송 시점으로부터
2초 뒤 SYN 패킷을 재전송한다.- 이 때 다시 ACK 응답을 받지 못한 경우, 위 SYN 재전송 시점으로부터
4초 뒤 SYN 패킷을 재전송하려는데,
이미 SYN 재전송 시점이 ConnectTimeout(5초)을 초과한 상태이므로, ConnectTimeout 이 발생한다.
하지만Exception 이 발생해도 Client 는 SYN 패킷을 재전송하므로 overflow 에는 집계가 된다.- 이 때 다시 ACK 응답을 받지 못한 경우, 위 SYN 재전송 시점으로부터
8초 뒤 SYN 패킷을 재전송한다. - 또는 ACK 응답을 받은 경우에는 정상 Connection 이 이루어진다.
- 이 때 다시 ACK 응답을 받지 못한 경우, 위 SYN 재전송 시점으로부터
- 또는 ACK 응답을 받은 경우에는 정상 Connection 이 이루어진다.
- 이 때 다시 ACK 응답을 받지 못한 경우, 위 SYN 재전송 시점으로부터
- 또는 ACK 응답을 받은 경우에는 정상 Connection 이 이루어진다.
- 이 때 다시 ACK 응답을 받지 못한 경우, 위 SYN 재전송 시점으로부터
요약하자면 RTO 가 발생해도 중간에 ACK 를 응답받으면 Connection 이 이루어질 수 있다는 것이다.
그래서 꼭 1 + 4 retry 의 요청이 모두 실패했다고 가정하기 보다는,
3번의 RTO 발생 후 ACK 가 응답되어 Client 는 Exception 이 발생해도 overflow 는 3번만 발생할 수 있으므로 아래와 같이 정의할 수 있다.
최소 6,568,459 / 5 (1,313,691) < Client API 요청 실패 횟수 < 최대 6,568,459 / 3 (2,189,486)
RTO 가 2번 발생하고 연결된 경우는 최초 SYN 패킷 전송 후 1초 + 2초 = 3초가 된 상태이므로 Client 는 연결이 성공한 것에 유의하자.
테스트
부하테스트 결과에 대한 오해
다수의 개발자들이 부하테스트 결과의 TPS 만을 보고 성능과 임계치를 판단하는 경우가 많다.
TPS 는 말 그대로 Transactions Per Second, 서버가 초당 몇 개의 요청을 처리했냐 라는 값이다.
하지만, 저 값은 결과값일 뿐이지 조건에 대한 명시는 없다.
몇 명의 유저가 동시에(VUs), 몇 초 동안, 응답시간 과 같은 조건들은 중요하지 않은가에 대해 생각해볼 필요가 있다.
한 가지 예시를 들어보자.
부하테스트 예시 1
- 결과 : 서버는 10,000 TPS 를 처리
- 결과 : API 평균 응답시간 : 10ms
- 결과 : 처리량 : 100,000
- 조건 : 동시 유저 수 (VUs) : 100
- 조건 : 수행 시간 : 10초
부하테스트 예시 2
- 결과 : 서버는 10,000 TPS 를 처리
- 결과 : API 평균 응답시간 : 100ms
- 결과 : 처리량 : 1,000,000
- 조건 : 동시 유저 수 (VUs) : 1000
- 조건 : 수행 시간 : 100초
위 두 부하테스트 결과를 보면, TPS 는 동일하다.
하지만 API 평균 응답시간을 보자. 완전히 다른 양상을 보인다.
또한 조건을 보면 사용자 수가 10배 이상 차이남에도 우연히 TPS 가 비슷할 뿐이다.
따라서, 부하테스트를 결과를 분석할 때에는 아래 사항들을 반드시 명시해야 한다.
TPSAPI 최소/평균/최대 응답시간 (+ 하위5/10% 응답시간 등..)동시 유저 수 (VUs)수행 시간각 가상 유저의 API 호출 간 간격
k6 부하테스트 스크립트 및 수행 방식
K6 에 대해 궁금하다면, 위를 참고하자. Goroutine 기바능로 JMeter 보다 훨씬 경량으로 많은 수의 부하를 줄 수 있다.
부하테스트를 어떻게 수행했는지 공유한다.
K6 부하테스트 인스턴스 2개를 사용해 Long Polling 방식으로 테스트를 수행했으며,
K6 상의 가상 유저 수(VUs) 수와 Spring Boot 내장 Tomcat max-connections 값을 변경하며 테스트했다.
부하테스트 스크립트
import http from 'k6/http';
import { sleep, check, group } from 'k6';
import { Counter } from 'k6/metrics';
// 외부 환경변수로부터 stages 값 주입
const stage1_duration = __ENV.STAGE1_DURATION || '5s';
const stage1_target = Number(__ENV.STAGE1_TARGET || 2000);
const stage2_duration = __ENV.STAGE2_DURATION || '20s';
const stage2_target = Number(__ENV.STAGE2_TARGET || 4000);
const stage3_duration = __ENV.STAGE3_DURATION || '5s';
const stage3_target = Number(__ENV.STAGE3_TARGET || 0);
// 테스트 설정
export let options = {
stages: [
{ duration: stage1_duration, target: stage1_target },
{ duration: stage2_duration, target: stage2_target },
{ duration: stage3_duration, target: stage3_target },
],
tags: {
team : 'team1',
test_name: 'load-test'
},
};
// 커스텀 메트릭 정의
const waitRequests = new Counter('API1_requests_total');
const entryRequests = new Counter('API1_requests_total');
const canEnterFalse = new Counter('can_enter_false_count');
const canEnterTrue = new Counter('can_enter_true_count');
export function setup() {
console.log('Setup: Initializing test setup...');
// 공통으로 사용할 헤더 초기화
let headers = {
'accept': '*/*',
'Content-Type': 'application/json',
};
// 상황에 맞게 body 작성
const waitPayload = JSON.stringify({
"body": "value"
});
return {
headers: headers,
waitPayload: waitPayload
}
}
export default function (data) {
let token = null;
let canEnter = false;
group('POST /wait', function () {
let res = http.post('http://host.name.com:port/api/wait', data.waitPayload, {headers: data.headers});
waitRequests.add(1);
check(res, {'is WAIT status 200': (r) => r.status === 200 });
let resBody = res.json();
canEnter = resBody.canEnter;
console.log(`WAIT - canEnter: ${canEnter}, Status: ${res.status}, Body: ${res.body}, Duration: ${res.timings.duration}ms`);
token = resBody.token;
if (canEnter) {
canEnterTrue.add(1);
} else {
canEnterFalse.add(1);
const pollingPeriod = resBody.waiting?.pollingPeriod || 5000;
sleep(pollingPeriod / 1000);
}
});
if (!canEnter) {
group('POST /entry', function () {
const entryPayload = JSON.stringify({
"zoneId": "KTC_TEST_ZONE",
"token": token
});
while (!canEnter) {
entryRequests.add(1);
let res = http.post('http://host.name.com:port/api/entry', entryPayload, {headers: data.headers});
let resBody = res.json();
canEnter = resBody.canEnter;
check(res, {'is ENTRY status 200': (r) => r.status === 200 });
console.log(`ENTRY - Status code: ${res.status}, Body: ${res.body}, Duration: ${res.timings.duration}ms`);
if (canEnter) {
canEnterTrue.add(1);
break;
} else {
canEnterFalse.add(1);
const pollingPeriod = resBody.waiting?.pollingPeriod || 5000;
sleep(pollingPeriod / 1000);
}
}
});
} else {
console.log("Skipping ENTRY request because canEnter was not true or token was not obtained.");
}
console.log("1 user entered!\n\n")
}AWS SSM 으로 k6 인스턴스에 일괄 스크립트 수행
- k6-* 라는 tag 가 달린 인스턴스들을 일괄적으로 스크립트를 수행
- 조건에 따라 STAGE1_TARGET, STAGE2_TARGET 값을 변경하여 수행
- monitoring.influxdb 는 부하테스트 결과를 저장하는 별도로 구축한 시계열 DB
INSTANCE_IDS=$(aws ec2 describe-instances \
--filters "Name=tag:Name,Values=k6-*" "Name=instance-state-name,Values=running" \
--query "Reservations[*].Instances[*].InstanceId" \
--output text \
--region ap-northeast-2 | grep . | paste -s -d ',')
echo "Found Instance IDs (comma-separated): $INSTANCE_IDS"
aws ssm send-command \
--document-name "AWS-RunShellScript" \
--targets "Key=InstanceIds,Values=$INSTANCE_IDS" \
--parameters '{
"commands": [
"STAGE1_DURATION=5s",
"STAGE1_TARGET=2000",
"STAGE2_DURATION=20s",
"STAGE2_TARGET=4000",
"STAGE3_DURATION=5s",
"STAGE3_TARGET=0",
"k6 run --env STAGE1_DURATION=$STAGE1_DURATION --env STAGE1_TARGET=$STAGE1_TARGET --env STAGE2_DURATION=$STAGE2_DURATION --env STAGE2_TARGET=$STAGE2_TARGET --env STAGE3_DURATION=$STAGE3_DURATION --env STAGE3_TARGET=$STAGE3_TARGET --out influxdb=http://monitoring.influxdb:8086/metrics k6-sample.js | tee >(split -b 10M -d - k6_log_)"
]
}' \
--comment "Run k6 load test (targeting by Instance IDs)" \
--region ap-northeast-2테스트 조건
충분한 Warm-Up 후 진행
(Spring Boot 기동, VUs4000 * 2 로 Warm-Up 부하테스트 후 결과 분석)
고정값
- AWS EC2 - 동일한 instance type
- k6 인스턴스 2개
- long polling 방식 스크립트
변동값
- k6 부하테스트의 가상 유저 수 (VUs)
- Spring Boot 내장 Tomcat max-connections 값
유의사항
- k6 는 수행 시간이 끝나도, 정의한 행동이 끝나지 않았으면 graceful 하게 shutdown 하는 30초 간의 대기시간을 가진다.
- 그래서 ramp-up time 5초, ramp-max 20초, ramp-down 5초로 설정했음에도 60초간 수행되는 것에 참고하자.
Spring Boot 내장 Tomcat 의 max-connections 설정 방법
# tomcat default : 8192
server:
tomcat:
max-connections: 8192테스트 결과
01. max-connections 기본값, 가상유저 4000 * 2 로 테스트 -> overflow 발생 안함
server.tomcat.max-connections: 8192 (default) max VUs : 4000 * 2
k6 부하테스트 결과 text
HTTP
http_req_duration.......................................................: avg=23.14ms min=581.4µs med=9.12ms max=375.84ms p(90)=71.63ms p(95)=118.17ms
{ expected_response:true }............................................: avg=23.14ms min=581.4µs med=9.12ms max=375.84ms p(90)=71.63ms p(95)=118.17ms
http_req_failed.........................................................: 0.00% 0 out of 50971
http_reqs...............................................................: 50971 849.457156/s
EXECUTION
vus.....................................................................: 462 min=0 max=3999
vus_max.................................................................: 4000 min=2478 max=4000
HTTP
http_req_duration.......................................................: avg=28.5ms min=593.51µs med=9.89ms max=654.55ms p(90)=82.01ms p(95)=142.29ms
{ expected_response:true }............................................: avg=28.5ms min=593.51µs med=9.89ms max=654.55ms p(90)=82.01ms p(95)=142.29ms
http_req_failed.........................................................: 0.00% 0 out of 50260
http_reqs...............................................................: 50260 837.591508/s
EXECUTION
vus.....................................................................: 453 min=0 max=3999
vus_max.................................................................: 4000 min=2459 max=4000 k6 부하테스트 결과 influxdb, grafana 시각화 image
SpringBoot 기동되는 OS의 tcp 오류 확인
netstat -s | grep -i "listen"
>> # 0이라 노출되지 않음SpringBoot 기동되는 OS의 node_exporter metrics image
02. max-connections 기본값, 가상유저 5000 * 2 로 테스트 -> overflow 발생
server.tomcat.max-connections: 8192 (default) max VUs : 5000 * 2
k6 부하테스트 결과 text
HTTP
http_req_duration.......................................................: avg=28.89ms min=0s med=11.49ms max=466.09ms p(90)=94.77ms p(95)=133.74ms
{ expected_response:true }............................................: avg=29.36ms min=603.74µs med=11.72ms max=466.09ms p(90)=95.76ms p(95)=134.42ms
http_req_failed.........................................................: 1.60% 852 out of 52977
http_reqs...............................................................: 52977 882.863833/s
EXECUTION
iteration_duration......................................................: avg=32.09s min=30s med=32.16s max=32.89s p(90)=32.39s p(95)=32.42s
iterations..............................................................: 624 10.398985/s
vus.....................................................................: 63 min=0 max=5000
vus_max.................................................................: 5000 min=2503 max=5000
HTTP
http_req_duration.......................................................: avg=27.58ms min=0s med=12.01ms max=466.18ms p(90)=82.71ms p(95)=124.54ms
{ expected_response:true }............................................: avg=28.04ms min=619.48µs med=12.26ms max=466.18ms p(90)=83.61ms p(95)=125.43ms
http_req_failed.........................................................: 1.62% 854 out of 52497
http_reqs...............................................................: 52497 874.586077/s
EXECUTION
iteration_duration......................................................: avg=32.05s min=30s med=32.28s max=33.48s p(90)=32.67s p(95)=32.78s
iterations..............................................................: 584 9.729285/s
vus.....................................................................: 13 min=0 max=5000
vus_max.................................................................: 5000 min=2568 max=5000k6 부하테스트 결과 influxdb, grafana 시각화 image
SpringBoot 기동되는 OS의 tcp 오류 확인
netstat -s | grep -i "listen"
>>
8535 times the listen queue of a socket overflowed
8535 SYNs to LISTEN sockets droppedSpringBoot 기동되는 OS의 node_exporter metrics image
03. max-connections 16, 가상 유저 4000 * 2 로 테스트 -> overflow 발생
server.tomcat.max-connections: 16 max VUs : 4000 * 2
k6 부하테스트 결과 text
HTTP
http_req_duration.......................................................: avg=479.19µs min=0s med=0s max=22.99ms p(90)=0s p(95)=4.34ms
{ expected_response:true }............................................: avg=6.29ms min=2.04ms med=5.04ms max=22.99ms p(90)=10.52ms p(95)=13.61ms
http_req_failed.........................................................: 92.38% 3882 out of 4202
http_reqs...............................................................: 4202 70.028612/s
EXECUTION
iteration_duration......................................................: avg=30s min=30s med=30s max=30.02s p(90)=30s p(95)=30s
iterations..............................................................: 3882 64.695638/s
vus.....................................................................: 117 min=0 max=4000
vus_max.................................................................: 4000 min=2493 max=4000
HTTP
http_req_duration................................: avg=0s min=0s med=0s max=0s p(90)=0s p(95)=0s
http_req_failed..................................: 100.00% 3999 out of 3999
http_reqs........................................: 3999 72.702344/s
EXECUTION
iteration_duration...............................: avg=30s min=30s med=30s max=30.01s p(90)=30s p(95)=30s
iterations.......................................: 3999 72.702344/s
vus..............................................: 75 min=0 max=4000
vus_max..........................................: 4000 min=2487 max=4000 k6 부하테스트 결과 influxdb, grafana 시각화 image
SpringBoot 기동되는 OS의 tcp 오류 확인
netstat -s | grep -i "listen"
>>
39415 times the listen queue of a socket overflowed
39415 SYNs to LISTEN sockets droppedSpringBoot 기동되는 OS의 node_exporter metrics image
04. max-connections 16382, 가상 유저 8000 * 2 로 테스트 -> overflow 발생 안함
server.tomcat.max-connections: 16382 max VUs : 8000 * 2
k6 부하테스트 결과 text
HTTP
http_req_duration.......................................................: avg=33.06ms min=611.59µs med=11.75ms max=583.11ms p(90)=116.04ms p(95)=167.17ms
{ expected_response:true }............................................: avg=33.06ms min=611.59µs med=11.75ms max=583.11ms p(90)=116.04ms p(95)=167.17ms
http_req_failed.........................................................: 0.00% 0 out of 55113
http_reqs...............................................................: 55113 887.232557/s
EXECUTION
vus.....................................................................: 600 min=0 max=7999
vus_max.................................................................: 8000 min=2454 max=8000
HTTP
http_req_duration.......................................................: avg=31.35ms min=631.21µs med=12.57ms max=500.04ms p(90)=95.61ms p(95)=156.54ms
{ expected_response:true }............................................: avg=31.35ms min=631.21µs med=12.57ms max=500.04ms p(90)=95.61ms p(95)=156.54ms
http_req_failed.........................................................: 0.00% 0 out of 55907
http_reqs...............................................................: 55907 889.296189/s
EXECUTION
vus.....................................................................: 330 min=0 max=7999
vus_max.................................................................: 8000 min=2306 max=8000k6 부하테스트 결과 influxdb, grafana 시각화 image
SpringBoot 기동되는 OS의 tcp 오류 확인
netstat -s | grep -i "listen"
>> # 0이라 노출되지 않음SpringBoot 기동되는 OS의 node_exporter metrics image
결론
지금까지 Andriod 에서 발생한 SocketTimeoutException: failed to connecto to ... 에러를 재현하고,
원인을 분석해 어떠한 방식으로 개선할 수 있는지까지 알아보았다.
그러면 과연 이게 끝일까?
여기서 내가 강조하고자 하는 것은 OS (Kernel) 단의 모니터링도 필수라는 것이다.
이 포스팅에서는 이미 결론부터 설명해, 보는 사람 입장에서는 그다지 어렵지 않게 느껴질 수 있으나 listen queue overflow, SYN Drop 과 같은 metric 들은 직접 찾아보고자 하지 않는 이상 눈치채기가 힘들다.
또한 Kernel 에서는 수많은 metric 들이 존재하는데 반해, 모든 metric 들에 대해 개발자 또는 운영자가 모두 아는 것은 아니며,
이를 위 캡처한 node_exporter 와 같은 metric 수집기를 통해 특정 metric 의 이상현상이 감지되었다 또는 차후 분석을 위해 값이라도 저장해야되는 것이 아닐까 생각한다.
다시 한 번 강조하지만,
모든 오류는 Application 단에서만 발생하는 것이 아니며, 그 외적인 요소도 고려할 필요가 있다.
Reference
