On Wed, 27 Feb 2019, Andrew Kurushin via curl-library wrote:
Now I am stuck on strange libcurl behaviour:then I'm trying to run test without reusing same socket connection (CURLOPT_FORBID_REUSE==1), program starts to perform very slow and with higher CPU usage compared to apache ab tool with same run parameters.
Given your numbers, quite a significant difference too! I can't think of any good reasons why they should differ more than just a little.
BTW, you didn't say in there but I presume your test server is very close counted in RTT?
Using libcurl/7.58.0 OpenSSL/1.1.1 zlib/1.2.11 libidn2/2.0.4 libpsl/0.19.1 (+libidn2/2.0.4) nghttp2/1.30.0 librtmp/2.3
Going forward with researching this issue, I think it would be valuable if you'd bump your libcurl version to the very latest so that we know you're not seeing old or one-off behavior.
From strace point of view libcurl and ab doing essentially the same (except getsockopt,getpeername,getsockname which are insignficant according to perf):
Given the fairly huge speed difference, is that visible already by just doing 'strace -tt' and comparing the two tools. If so, is there any particular gap that is notable?
It'd be useful to see for example the time from connect to send to receive with libcurl compared to ab.
[pid 12716] fcntl(3, F_SETFL, O_RDWR|O_NONBLOCK) = 0
I see that both use non-blocking sockets.
[pid 12716] connect(3, {sa_family=AF_INET, sin_port=htons(80), sin_addr=inet_addr("172.19.161.85")}, 16) = -1 EINPROGRESS (Operation now in progress)[pid 12716] poll([{fd=3, events=POLLOUT|POLLWRNORM}], 1, 0) = 1 ([{fd=3, revents=POLLOUT|POLLWRNORM}])[pid 12716] getsockopt(3, SOL_SOCKET, SO_ERROR, [0], [4]) = 0
libcurl connects and then awaits for the socket to get writable with poll() and then use getsockopt() to figure out if it really is connected.
ab connects, epolls the socket and then calls connect again! Is there a detectable speed difference already there?
[pid 12716] sendto(3, "GET /resp200/ HTTP/1.1\r\nHost: 17"..., 60, MSG_NOSIGNAL, NULL, 0) = 60
curl uses sendto(), ab uses write(). curl's request is 60 bytes, ab sends 89 bytes. curl sends a HTTP/1.1 request, ab sends a HTTP/1.0 request.I bet it doesn't make a difference, but you could try to also tell curl to send an HTTP/1.0 request and just verify that it isn't a reason.
[pid 12716] poll([{fd=3, events=POLLIN|POLLPRI|POLLRDNORM|POLLRDBAND}], 1,
0) = 0 (Timeout)
[pid 12716] poll([{fd=3, events=POLLIN}], 1, 0) = 1 ([{fd=3,
revents=POLLIN}])
[pid 12716] poll([{fd=3, events=POLLIN|POLLPRI|POLLRDNORM|POLLRDBAND}], 1,
0) = 1 ([{fd=3, revents=POLLIN|POLLRDNORM}])
It is interesting that curl needs *three* calls to poll before it calls recvfrom()... ab only does a single epoll_wait() before it read()s.
[pid 12716] recvfrom(3, "HTTP/1.1 200 OK\r\nServer: nginx/1"..., 16384, 0, NULL, NULL) = 184
curl gets a 184 byte HTTP/1.1 response, while ab gets a 156 bytes response that says HTTP/1.1.
ab then reads again to get a zero back to learn that the connection has closed, which curl doesn't do since it knows how much data to get and it closes the connection without that zero read.
"perf record -F 1000 --call-graph dwarf -g" points to system "connect", but it's arguments are the same as in apache ab.
Yeah that is strange... the only difference I can spot there is that ab sets the SOCK_CLOEXEC bit on the socket and curl doesn't, but I can't imagine that to be a significant difference!
-- / daniel.haxx.se ------------------------------------------------------------------- Unsubscribe: https://cool.haxx.se/list/listinfo/curl-library Etiquette: https://curl.haxx.se/mail/etiquette.html
