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