curl-library
Too many connections in TIME_WAIT state
Date: Sun, 20 Jan 2019 18:45:13 +0530
Hi,
I have a small clarification on the use of the libcurl library. In my
project, i am trying to send 3 requests using the multi interface and
polling via libuv based on multi-uv.c When we are comparing this w.r.t to
Apache bench, which I am using as my comparison tool, I am seeing that with
libcurl, there are so many connections in TIME_WAIT state.
One oddity I can see is that in Apache bench, they wait for the FIN from
the server, and then close the connection. However in case of libcurl, we
are sending the FIN. Is there any way to tweak this behaviour so that we
don't initiate the FIN, instead wait for the server to do it.
Another issue I request you help with understanding is that the CPU and
RAM utilization of Apache Bench for the same type of GET requests is pretty
low compared to my tool which internally uses libcurl to do the same thing.
I am posting all the logs I have for both these issues.
Observations :
With concurrency : 10 <concurrency = num_multi handles (each has 1 request)
my tool : 8600 CPS with CPU of 73%
ab : 9500 CPS with CPU of 35%
concurrency : 20
my tool : 10000 CPS with CPU of 98%
ab : 19000 CPS with CPU of 60%
Ran the following test : Concurrency == 1. Trying to gauge why my tool
reports much higher open connections.
Connection color legend:
First transaction
Second transaction
Third transaction
Client : 10.160.104.50
Server : 10.160.104.182
Behavior with my tool :
19:28:04.638774 IP 10.160.104.50.46069 > 10.160.104.182.http: Flags [S],
seq 1437188629, win 29200, options [mss 1460,sackOK,TS val 1360341540 ecr
0,nop,wscale 7], length 0
19:28:04.639100 IP 10.160.104.182.http > 10.160.104.50.46069: Flags [S.],
seq 1141937819, ack 1437188630, win 65535, options [mss 1460,nop,wscale
10,sackOK,TS val 20056908 ecr 1360341540], length 0
19:28:04.639138 IP 10.160.104.50.46069 > 10.160.104.182.http: Flags [.],
ack 1, win 229, options [nop,nop,TS val 1360341540 ecr 20056908], length 0
19:28:04.639165 IP 10.160.104.50.46069 > 10.160.104.182.http: Flags [P.],
seq 1:105, ack 1, win 229, options [nop,nop,TS val 1360341540 ecr
20056908], length 104
19:28:04.639364 IP 10.160.104.182.http > 10.160.104.50.46069: Flags [.],
ack 1, win 1025, options [nop,nop,TS val 20056908 ecr 1360341540], length 0
19:28:04.639371 IP 10.160.104.182.http > 10.160.104.50.46069: Flags [.],
ack 105, win 1025, options [nop,nop,TS val 20056908 ecr 1360341540], length
0
19:28:04.640188 IP 10.160.104.182.http > 10.160.104.50.46069: Flags [P.],
seq 1:365, ack 105, win 1025, options [nop,nop,TS val 20056909 ecr
1360341540], length 364
19:28:04.640194 IP 10.160.104.50.46069 > 10.160.104.182.http: Flags [.],
ack 365, win 237, options [nop,nop,TS val 1360341540 ecr 20056909], length 0
19:28:04.640265 IP 10.160.104.50.46069 > 10.160.104.182.http: Flags [F.],
seq 105, ack 365, win 237, options [nop,nop,TS val 1360341540 ecr
20056909], length 0
19:28:04.640333 IP 10.160.104.50.46070 > 10.160.104.182.http: Flags [S],
seq 3150148087, win 29200, options [mss 1460,sackOK,TS val 1360341540 ecr
0,nop,wscale 7], length 0
19:28:04.640383 IP 10.160.104.182.http > 10.160.104.50.46069: Flags [.],
ack 106, win 1025, options [nop,nop,TS val 20056909 ecr 1360341540], length
0
19:28:04.640452 IP 10.160.104.182.http > 10.160.104.50.46070: Flags [S.],
seq 162313904, ack 3150148088, win 65535, options [mss 1460,nop,wscale
10,sackOK,TS val 20056909 ecr 1360341540], length 0
19:28:04.640462 IP 10.160.104.50.46070 > 10.160.104.182.http: Flags [.],
ack 1, win 229, options [nop,nop,TS val 1360341540 ecr 20056909], length 0
19:28:04.640484 IP 10.160.104.50.46070 > 10.160.104.182.http: Flags [P.],
seq 1:105, ack 1, win 229, options [nop,nop,TS val 1360341540 ecr
20056909], length 104
19:28:04.640659 IP 10.160.104.182.http > 10.160.104.50.46070: Flags [.],
ack 1, win 1025, options [nop,nop,TS val 20056910 ecr 1360341540], length 0
19:28:04.640693 IP 10.160.104.182.http > 10.160.104.50.46069: Flags [F.],
seq 365, ack 106, win 1025, options [nop,nop,TS val 20056910 ecr
1360341540], length 0
19:28:04.640697 IP 10.160.104.182.http > 10.160.104.50.46070: Flags [.],
ack 105, win 1025, options [nop,nop,TS val 20056910 ecr 1360341540], length
0
19:28:04.640707 IP 10.160.104.50.46069 > 10.160.104.182.http: Flags [.],
ack 366, win 237, options [nop,nop,TS val 1360341540 ecr 20056910], length 0
19:28:04.641095 IP 10.160.104.182.http > 10.160.104.50.46070: Flags [P.],
seq 1:365, ack 105, win 1025, options [nop,nop,TS val 20056910 ecr
1360341540], length 364
19:28:04.641099 IP 10.160.104.50.46070 > 10.160.104.182.http: Flags [.],
ack 365, win 237, options [nop,nop,TS val 1360341540 ecr 20056910], length 0
19:28:04.641133 IP 10.160.104.50.46070 > 10.160.104.182.http: Flags [F.],
seq 105, ack 365, win 237, options [nop,nop,TS val 1360341540 ecr
20056910], length 0
19:28:04.641187 IP 10.160.104.50.46071 > 10.160.104.182.http: Flags [S],
seq 639511660, win 29200, options [mss 1460,sackOK,TS val 1360341540 ecr
0,nop,wscale 7], length 0
19:28:04.641222 IP 10.160.104.182.http > 10.160.104.50.46070: Flags [.],
ack 106, win 1025, options [nop,nop,TS val 20056910 ecr 1360341540], length
0
19:28:04.641294 IP 10.160.104.182.http > 10.160.104.50.46071: Flags [S.],
seq 2067305278, ack 639511661, win 65535, options [mss 1460,nop,wscale
10,sackOK,TS val 20056910 ecr 1360341540], length 0
19:28:04.641301 IP 10.160.104.50.46071 > 10.160.104.182.http: Flags [.],
ack 1, win 229, options [nop,nop,TS val 1360341541 ecr 20056910], length 0
19:28:04.641324 IP 10.160.104.50.46071 > 10.160.104.182.http: Flags [P.],
seq 1:105, ack 1, win 229, options [nop,nop,TS val 1360341541 ecr
20056910], length 104
19:28:04.641440 IP 10.160.104.182.http > 10.160.104.50.46070: Flags [F.],
seq 365, ack 106, win 1025, options [nop,nop,TS val 20056910 ecr
1360341540], length 0
19:28:04.641447 IP 10.160.104.50.46070 > 10.160.104.182.http: Flags [.],
ack 366, win 237, options [nop,nop,TS val 1360341541 ecr 20056910], length 0
Every 0.1s: netstat -planet | grep 10.160.104.182
Wed Jan 9 19:44:06 2019
tcp 0 0 10.160.104.50:46658 10.160.104.182:80
<http://10.160.104.182/> TIME_WAIT 0 0 -
tcp 0 0 10.160.104.50:46696 10.160.104.182:80
<http://10.160.104.182/> TIME_WAIT 0 0 -
tcp 0 0 10.160.104.50:53687 10.160.104.182:80
<http://10.160.104.182/> TIME_WAIT 0 0 -
tcp 0 0 10.160.104.50:53746 10.160.104.182:80
<http://10.160.104.182/> TIME_WAIT 0 0 -
[...SNIP...]
tcp 0 0 10.160.104.50:53631 10.160.104.182:80
<http://10.160.104.182/> TIME_WAIT 0 0 -
tcp 0 0 10.160.104.50:53873 10.160.104.182:80
<http://10.160.104.182/> TIME_WAIT 0 0 -
tcp 0 0 10.160.104.50:53706 10.160.104.182:80
<http://10.160.104.182/> TIME_WAIT 0 0 -
tcp 0 0 10.160.104.50:53850 10.160.104.182:80
<http://10.160.104.182/> TIME_WAIT 0 0 -
tcp 0 0 10.160.104.50:53812 10.160.104.182:80
<http://10.160.104.182/> TIME_WAIT 0 0 -
tcp 0 0 10.160.104.50:53816 10.160.104.182:80
<http://10.160.104.182/> TIME_WAIT 0 0 -
tcp 0 0 10.160.104.50:53648 10.160.104.182:80
<http://10.160.104.182/> TIME_WAIT 0 0 -
tcp 0 0 10.160.104.50:53690 10.160.104.182:80
<http://10.160.104.182/> TIME_WAIT 0 0 -
tcp 0 0 10.160.104.50:53537 10.160.104.182:80
<http://10.160.104.182/> TIME_WAIT 0 0 -
tcp 0 0 10.160.104.50:53674 10.160.104.182:80
<http://10.160.104.182/> TIME_WAIT 0 0 -
tcp 0 0 10.160.104.50:53722 10.160.104.182:80
<http://10.160.104.182/> TIME_WAIT 0 0 -
tcp 0 0 10.160.104.50:53900 10.160.104.182:80
<http://10.160.104.182/> ESTABLISHED 0 1112833089
27259/te_dp
tcp 0 0 10.160.104.50:53706 10.160.104.182:80
<http://10.160.104.182/> TIME_WAIT 0 0 -
tcp 0 0 10.160.104.50:53850 10.160.104.182:80
<http://10.160.104.182/> TIME_WAIT 0 0 -
tcp 0 0 10.160.104.50:53812 10.160.104.182:80
<http://10.160.104.182/> TIME_WAIT 0 0 -
[...SNIP...]
tcp 0 0 10.160.104.50:53816 10.160.104.182:80
<http://10.160.104.182/> TIME_WAIT 0 0 -
tcp 0 0 10.160.104.50:53648 10.160.104.182:80
<http://10.160.104.182/> TIME_WAIT 0 0 -
tcp 0 0 10.160.104.50:53690 10.160.104.182:80
<http://10.160.104.182/> TIME_WAIT 0 0 -
Stack usage :
6.30% [kernel] [k] vmxnet3_xmit_frame
5.65% [kernel] [k] context_tracking_user_exit
5.44% [kernel] [k] context_tracking_user_enter
2.35% libcurl.so.4.5.0 [.] dprintf_formatf
2.27% [kernel] [k] _raw_spin_unlock_irqrestore
2.21% libpthread-2.19.so [.] __libc_sigaction
2.05% [vdso] [.] __vdso_clock_gettime
1.55% libc-2.19.so [.] free
1.51% [kernel] [k] __do_softirq
1.47% libcurl.so.4.5.0 [.] Curl_llist_init
1.31% libcurl.so.4.5.0 [.] Curl_llist_destroy
1.14% libc-2.19.so [.] vfprintf
1.00% [kernel] [k] ____nf_conntrack_find
0.98% [kernel] [k] system_call_after_swapgs
0.91% libcurl.so.4.5.0 [.] multi_runsingle
0.89% libcurl.so.4.5.0 [.] Curl_hash_destroy
0.86% [kernel] [k] fib_table_lookup
0.84% libc-2.19.so [.] epoll_ctl
0.80% libc-2.19.so [.] _IO_vfscanf
0.79% [kernel] [k] nf_conntrack_tuple_taken
0.72% libc-2.19.so [.] memset
0.71% libcurl.so.4.5.0 [.] Curl_strncasecompare
0.66% libcurl.so.4.5.0 [.] Curl_hash_init
0.64% libcurl.so.4.5.0 [.] alloc_addbyter
0.60% [kernel] [k] vmxnet3_poll_rx_only
0.59% libcurl.so.4.5.0 [.] Curl_connect
0.56% [kernel] [k] fget_light
0.53% [kernel] [k] do_sigaction
0.53% libc-2.19.so [.] strlen
0.51% libc-2.19.so [.] malloc
0.49% [kernel] [k] ipt_do_table
0.48% [kernel] [k] _raw_spin_unlock
0.48% [kernel] [k] _raw_spin_lock_bh
0.48% libc-2.19.so [.] poll
0.46% [kernel] [k] copy_user_generic_unrolled
0.43% libcurl.so.4.5.0 [.] Curl_pgrsUpdate
0.43% [kernel] [k] __call_rcu
0.41% libuv.so.1.0.0 [.] uv__io_poll
0.41% [kernel] [k] _raw_spin_lock
0.40% [kernel] [k] tcp_recvmsg
0.40% [kernel] [k] syscall_trace_enter
0.38% libc-2.19.so [.] epoll_pwait
0.37% libc-2.19.so [.] _IO_default_xsputn
0.36% libcurl.so.4.5.0 [.] multi_socket
0.36% libc-2.19.so [.] __libc_calloc
0.36% [kernel] [k] tracesys
0.34% libcurl.so.4.5.0 [.] Curl_vsetopt
0.34% libcurl.so.4.5.0 [.] Curl_getinfo
0.31% [kernel] [k] tcp_in_window
Observations :
- My tool sends a new SYN before the first connection is complete
- My tool sees a lot of connections in TIME_WAIT state
- Avi reports open connections ~6 with num_sessions == 1 and open
connections ~8 with num_sessions == 2
- Looks like most cpu is spent in libcurl. But can we make this more
efficient ? Things like "vfprintf" are consuming >1% of CPU
- The closing of connection is different with AB
Behavior with AB :
19:50:53.037952 IP 10.160.104.50.31119 > 10.160.104.182.http: Flags [S],
seq 763252322, win 29200, options [mss 1460,sackOK,TS val 1360683640 ecr
0,nop,wscale 7], length 0
19:50:53.038349 IP 10.160.104.182.http > 10.160.104.50.31119: Flags [S.],
seq 2940986, ack 763252323, win 65535, options [mss 1460,nop,wscale
10,sackOK,TS val 21425444 ecr 1360683640], length 0
19:50:53.038381 IP 10.160.104.50.31119 > 10.160.104.182.http: Flags [.],
ack 1, win 229, options [nop,nop,TS val 1360683640 ecr 21425444], length 0
19:50:53.038404 IP 10.160.104.50.31119 > 10.160.104.182.http: Flags [P.],
seq 1:91, ack 1, win 229, options [nop,nop,TS val 1360683640 ecr 21425444],
length 90
19:50:53.038562 IP 10.160.104.182.http > 10.160.104.50.31119: Flags [.],
ack 1, win 1025, options [nop,nop,TS val 21425444 ecr 1360683640], length 0
19:50:53.038583 IP 10.160.104.182.http > 10.160.104.50.31119: Flags [.],
ack 91, win 1025, options [nop,nop,TS val 21425444 ecr 1360683640], length 0
19:50:53.039584 IP 10.160.104.182.http > 10.160.104.50.31119: Flags [P.],
seq 1:360, ack 91, win 1025, options [nop,nop,TS val 21425446 ecr
1360683640], length 359
19:50:53.039588 IP 10.160.104.50.31119 > 10.160.104.182.http: Flags [.],
ack 360, win 237, options [nop,nop,TS val 1360683640 ecr 21425446], length 0
19:50:53.039644 IP 10.160.104.182.http > 10.160.104.50.31119: Flags [F.],
seq 360, ack 91, win 1025, options [nop,nop,TS val 21425446 ecr
1360683640], length 0
19:50:53.039663 IP 10.160.104.50.31119 > 10.160.104.182.http: Flags [F.],
seq 91, ack 361, win 237, options [nop,nop,TS val 1360683640 ecr 21425446],
length 0
19:50:53.039690 IP 10.160.104.50.31120 > 10.160.104.182.http: Flags [S],
seq 2619721876, win 29200, options [mss 1460,sackOK,TS val 1360683640 ecr
0,nop,wscale 7], length 0
19:50:53.039815 IP 10.160.104.182.http > 10.160.104.50.31119: Flags [.],
ack 92, win 1025, options [nop,nop,TS val 21425446 ecr 1360683640], length 0
19:50:53.039835 IP 10.160.104.182.http > 10.160.104.50.31120: Flags [S.],
seq 1196035502, ack 2619721877, win 65535, options [mss 1460,nop,wscale
10,sackOK,TS val 21425446 ecr 1360683640], length 0
19:50:53.039846 IP 10.160.104.50.31120 > 10.160.104.182.http: Flags [.],
ack 1, win 229, options [nop,nop,TS val 1360683640 ecr 21425446], length 0
19:50:53.039859 IP 10.160.104.50.31120 > 10.160.104.182.http: Flags [P.],
seq 1:91, ack 1, win 229, options [nop,nop,TS val 1360683640 ecr 21425446],
length 90
19:50:53.039954 IP 10.160.104.182.http > 10.160.104.50.31120: Flags [.],
ack 1, win 1025, options [nop,nop,TS val 21425446 ecr 1360683640], length 0
19:50:53.040006 IP 10.160.104.182.http > 10.160.104.50.31120: Flags [.],
ack 91, win 1025, options [nop,nop,TS val 21425446 ecr 1360683640], length 0
19:50:53.040555 IP 10.160.104.182.http > 10.160.104.50.31120: Flags [P.],
seq 1:360, ack 91, win 1025, options [nop,nop,TS val 21425446 ecr
1360683640], length 359
19:50:53.040560 IP 10.160.104.50.31120 > 10.160.104.182.http: Flags [.],
ack 360, win 237, options [nop,nop,TS val 1360683640 ecr 21425446], length 0
19:50:53.040614 IP 10.160.104.182.http > 10.160.104.50.31120: Flags [F.],
seq 360, ack 91, win 1025, options [nop,nop,TS val 21425446 ecr
1360683640], length 0
19:50:53.040629 IP 10.160.104.50.31120 > 10.160.104.182.http: Flags [F.],
seq 91, ack 361, win 237, options [nop,nop,TS val 1360683640 ecr 21425446],
length 0
19:50:53.040649 IP 10.160.104.50.31121 > 10.160.104.182.http: Flags [S],
seq 158423305, win 29200, options [mss 1460,sackOK,TS val 1360683640 ecr
0,nop,wscale 7], length 0
19:50:53.040753 IP 10.160.104.182.http > 10.160.104.50.31120: Flags [.],
ack 92, win 1025, options [nop,nop,TS val 21425447 ecr 1360683640], length 0
19:50:53.040776 IP 10.160.104.182.http > 10.160.104.50.31121: Flags [S.],
seq 1206504465, ack 158423306, win 65535, options [mss 1460,nop,wscale
10,sackOK,TS val 21425447 ecr 1360683640], length 0
19:50:53.040785 IP 10.160.104.50.31121 > 10.160.104.182.http: Flags [.],
ack 1, win 229, options [nop,nop,TS val 1360683640 ecr 21425447], length 0
19:50:53.040801 IP 10.160.104.50.31121 > 10.160.104.182.http: Flags [P.],
seq 1:91, ack 1, win 229, options [nop,nop,TS val 1360683640 ecr 21425447],
length 90
19:50:53.040920 IP 10.160.104.182.http > 10.160.104.50.31121: Flags [.],
ack 1, win 1025, options [nop,nop,TS val 21425447 ecr 1360683640], length 0
19:50:53.045265 IP 10.160.104.182.http > 10.160.104.50.31121: Flags [.],
ack 91, win 1025, options [nop,nop,TS val 21425447 ecr 1360683640], length 0
19:50:53.045731 IP 10.160.104.182.http > 10.160.104.50.31121: Flags [P.],
seq 1:360, ack 91, win 1025, options [nop,nop,TS val 21425452 ecr
1360683640], length 359
19:50:53.045737 IP 10.160.104.50.31121 > 10.160.104.182.http: Flags [.],
ack 360, win 237, options [nop,nop,TS val 1360683642 ecr 21425452], length 0
19:50:53.045757 IP 10.160.104.182.http > 10.160.104.50.31121: Flags [F.],
seq 360, ack 91, win 1025, options [nop,nop,TS val 21425452 ecr
1360683640], length 0
19:50:53.045778 IP 10.160.104.50.31121 > 10.160.104.182.http: Flags [F.],
seq 91, ack 361, win 237, options [nop,nop,TS val 1360683642 ecr 21425452],
length 0
Every 0.1s: netstat -planet | grep 10.160.104.182
Wed Jan 9 19:48:59 2019
tcp 0 0 10.160.104.50:50080 10.160.104.182:80
<http://10.160.104.182/> ESTABLISHED 0 1113092121 -
Stack usage :
13.43% [kernel] [k] vmxnet3_xmit_frame
7.35% [kernel] [k] context_tracking_user_exit
6.27% [kernel] [k] context_tracking_user_enter
5.00% [kernel] [k] _raw_spin_unlock_irqrestore
2.77% [kernel] [k] ____nf_conntrack_find
2.46% [kernel] [k] __do_softirq
2.24% libc-2.19.so [.] epoll_ctl
1.57% [kernel] [k] nf_conntrack_tuple_taken
1.39% ab [.] main
1.34% [kernel] [k] fib_table_lookup
1.01% [kernel] [k] vmxnet3_poll_rx_only
0.99% [kernel] [k] _raw_spin_lock
0.98% [kernel] [k] fget_light
0.97% [kernel] [k] _raw_spin_lock_bh
0.94% [kernel] [k] system_call_after_swapgs
0.91% [vdso] [.] __vdso_gettimeofday
0.85% libc-2.19.so [.] epoll_wait
0.76% [kernel] [k] _raw_spin_unlock
0.76% [kernel] [k] __call_rcu
0.72% libpthread-2.19.so [.] __libc_connect
0.72% libpthread-2.19.so [.] __write_nocancel
0.67% libpthread-2.19.so [.] __libc_fcntl
0.64% [kernel] [k] _raw_spin_unlock_bh
0.62% [kernel] [k] tracesys
0.58% [kernel] [k] nf_iterate
0.53% libpthread-2.19.so [.] __read_nocancel
0.52% [kernel] [k] sys_epoll_ctl
0.52% [kernel] [k] md5_transform
0.50% [kernel] [k] ipt_do_table
0.48% [kernel] [k] tcp_sendmsg
0.45% [kernel] [k] kmem_cache_alloc
0.45% [kernel] [k] tcp_recvmsg
0.43% [kernel] [k] tcp_in_window
0.43% [kernel] [k] __memset
0.43% [kernel] [k] nf_conntrack_in
0.42% [kernel] [k] syscall_trace_leave
0.41% [kernel] [k] syscall_trace_enter
0.40% [kernel] [k] local_bh_enable
0.39% [kernel] [k] tcp_transmit_skb
0.38% [kernel] [k] nf_nat_setup_info
0.37% [kernel] [k] local_bh_enable_ip
0.37% [kernel] [k] tcp_poll
0.37% [kernel] [k] tcp_send_fin
0.36% [kernel] [k] common_file_perm
0.36% [kernel] [k] tcp_packet
0.35% [kernel] [k] ksize
0.35% [kernel] [k] hash_conntrack_raw
0.35% [kernel] [k] tcp_connect_queue_skb
0.35% [kernel] [k] __alloc_skb
Observations :
- AB waits for the connection to complete before sending a new SYN.
- AB only sees ESTABLISHED connections for the most part and 0 TIME_WAIT
connections
- Avi reports open connections ~3 with concurrency == 1 and open
connections ~6 with concurrency == 2
- Much more efficient CPU utilization
To summarize:
- My tool burns a lot more CPU than AB
- My tool keeps a lot more connections open than AB
- My tool opens a new connection before the current is closed and the
closing of connection with my tool is more chatty
Sincerely,
Vipin
-------------------------------------------------------------------
Unsubscribe: https://cool.haxx.se/list/listinfo/curl-library
Etiquette: https://curl.haxx.se/mail/etiquette.html
Received on 2019-01-20