fnctl() taking a looong time

Hoggins! <[email protected]> Tue, 21 Jun 2016 14:18:53 +0200
Newsgroups gmane.comp.web.curl.php
Message-ID <[email protected]>
This is an OpenPGP/MIME signed message (RFC 4880 and 3156)
--===============0002281022==
Content-Type: multipart/signed; micalg=pgp-sha1;
 protocol="application/pgp-signature";
 boundary="R0TTN1trpItf3kjNQsSGaSlgEjf04sAVQ"

This is an OpenPGP/MIME signed message (RFC 4880 and 3156)
--R0TTN1trpItf3kjNQsSGaSlgEjf04sAVQ
Content-Type: multipart/mixed; boundary="JDKX7j0P2Qh45hfEMvA7Gu8ocM2Qke1Kb"
From: Hoggins! <[email protected]>
To: [email protected]
Message-ID: <[email protected]>
Subject: fnctl() taking a looong time

--JDKX7j0P2Qh45hfEMvA7Gu8ocM2Qke1Kb
Content-Type: text/plain; charset=utf-8
Content-Transfer-Encoding: quoted-printable

Hello list,

First post here, I have an issue.

I'm using PHP 5.6.22, and my system has libcurl-7.43.0-7 on my Fedora 23
server.
I'm running a script that is looping through events received on a
socket. Each time such an event is received, it triggers a series of
cURL requests with the following code :

                // LOOP START
                [...]
                $params_url =3D http_build_query($params, '', '&');
                $ch =3D curl_init();
                   $options =3D array(
                        CURLOPT_TCP_NODELAY            =3D> 1,  =20
/*****************************************************************/
                        CURLOPT_FORBID_REUSE           =3D> 1,    /* adde=
d
these two, having read that it could help. No luck      */
                                                              =20
/*****************************************************************/
                        CURLOPT_URL                    =3D> $url,
                        CURLOPT_RETURNTRANSFER         =3D> TRUE,
                        CURLOPT_POST                   =3D> TRUE,
                        CURLOPT_POSTFIELDS             =3D> $params_url,
                        CURLINFO_HEADER_OUT            =3D> TRUE,
                        CURLOPT_CONNECTTIMEOUT         =3D> 5,
                        CURLOPT_TIMEOUT                =3D> 10,
                );
                curl_setopt_array($ch, $options);
                $data =3D curl_exec($ch);
                curl_close($ch);
                [...]
                // LOOP END

My problem is that over time, the cURL requests take more and more time
to complete. This is a *new* behavior on my code, but I'm not absolutely
sure of where it comes from, hence my call for help.
I can see that it seems to be stalled for a while under a specific call
using strace (strace -p <pid> -f -T -r -s 10000):

     0.000277 socket(AF_INET, SOCK_STREAM, IPPROTO_TCP) =3D 11 <0.000061>=

     0.000129 setsockopt(11, SOL_TCP, TCP_NODELAY, [1], 4) =3D 0 <0.00004=
5>
     0.000107 fcntl(11, F_GETFL)        =3D 0x2 (flags O_RDWR) <0.000040>=

     0.000094 fcntl(11, F_SETFL, O_RDWR|O_NONBLOCK) =3D 0 <0.000043>
     0.000125 connect(11, {sa_family=3DAF_INET, sin_port=3Dhtons(443),
sin_addr=3Dinet_addr("64.30.224.206")}, 16) =3D -1 EINPROGRESS (Operation=

now in progress) <0.000051>
     0.000140 poll([{fd=3D11, events=3DPOLLOUT|POLLWRNORM}], 1, 0) =3D 0
(Timeout) <0.000027>
     0.000083 poll([{fd=3D11, events=3DPOLLOUT}], 1, 1) =3D 0 (Timeout) <=
0.001111>
     0.001228 poll([{fd=3D11, events=3DPOLLOUT|POLLWRNORM}], 1, 0) =3D 0
(Timeout) <0.000055>
     0.000141 poll([{fd=3D11, events=3DPOLLOUT}], 1, 197) =3D 1 ([{fd=3D1=
1,
revents=3DPOLLOUT}]) <0.130495>
     0.130676 poll([{fd=3D11, events=3DPOLLOUT|POLLWRNORM}], 1, 0) =3D 1
([{fd=3D11, revents=3DPOLLOUT|POLLWRNORM}]) <0.000062>
     0.000165 getsockopt(11, SOL_SOCKET, SO_ERROR, [0], [4]) =3D 0 <0.000=
061>
     0.000147 getpeername(11, {sa_family=3DAF_INET, sin_port=3Dhtons(443)=
,
sin_addr=3Dinet_addr("64.30.224.206")}, [16]) =3D 0 <0.000056>
     0.000165 getsockname(11, {sa_family=3DAF_INET, sin_port=3Dhtons(4450=
2),
sin_addr=3Dinet_addr("192.168.100.190")}, [16]) =3D 0 <0.000036>
     0.000124 socket(AF_INET, SOCK_STREAM, IPPROTO_IP) =3D 12 <0.000059>
     0.000195 fcntl(12, F_GETFL)        =3D 0x2 (flags O_RDWR) <0.000044>=

     0.000108 fcntl(12, F_SETFL, O_RDWR|O_NONBLOCK) =3D 0 <0.000032>
     0.000096 getpeername(12, 0x7ffe5203f800, 0x7ffe5203f7d4) =3D -1
ENOTCONN (Transport endpoint is not connected) <0.000035>
     0.000098 stat("/etc/pki/tls/certs/ca-bundle.crt",
{st_mode=3DS_IFREG|0444, st_size=3D253335, ...}) =3D 0 <0.000059>
     0.000181 open("/etc/pki/tls/certs/ca-bundle.crt", O_RDONLY) =3D 13
<0.000056>
     0.000137 fstat(13, {st_mode=3DS_IFREG|0444, st_size=3D253335, ...}) =
=3D 0
<0.000033>
     0.000115 read(13, "-----BEGIN
CERTIFICATE-----\nMIIE2DCCBEGgAwIBAgIEN0rSQzANBgkqhkiG9w0BAQUFADCBwzELMAk=
GA1UEBhMC
[...]
            =20
C5u\nZXQvQ1BTIGluY29ycC4gYnkgcmVmLiAobGltaXRzIGxpYWIuKTElMCMGA1UECxMc"...=
,
253335) =3D 253335 <0.000102>
     0.001565 close(13)                 =3D 0 <0.000072>
    13.618840 fcntl(11, F_GETFL)        =3D 0x802 (flags
O_RDWR|O_NONBLOCK) <0.000083>
     0.000148 fcntl(11, F_SETFL, O_RDWR|O_NONBLOCK) =3D 0 <0.000028>
     0.000075 getpeername(11, {sa_family=3DAF_INET, sin_port=3Dhtons(443)=
,
sin_addr=3Dinet_addr("64.30.224.206")}, [16]) =3D 0 <0.000035>
     0.000141 close(12)                 =3D 0 <0.000036>
     0.000103 close(11)                 =3D 0 <0.000044>

(hope I'm not missing parts of the strace here)

As you can see, fnctl() takes a lot of time to complete. I'm not skilled
enough to understand what it does, why it does that, and if it's really
inside the cURL call that the problem resides. But the time fnctl()
takes increases at each new iteration.

Any hint ?

Thank you !

    Hoggins!


--JDKX7j0P2Qh45hfEMvA7Gu8ocM2Qke1Kb--

--R0TTN1trpItf3kjNQsSGaSlgEjf04sAVQ
Content-Type: application/pgp-signature; name="signature.asc"
Content-Description: OpenPGP digital signature
Content-Disposition: attachment; filename="signature.asc"

-----BEGIN PGP SIGNATURE-----
Version: GnuPG v2

iEYEARECAAYFAldpMK0ACgkQ7om13ryHIB/P5ACeKJrx1dvPl1pUAExDZx8xAcYG
qRUAn0TN067Dv7GpH2wjojmC1fd8qg/2
=aMEL
-----END PGP SIGNATURE-----

--R0TTN1trpItf3kjNQsSGaSlgEjf04sAVQ--

--===============0002281022==
Content-Type: text/plain; charset="utf-8"
MIME-Version: 1.0
Content-Transfer-Encoding: base64
Content-Disposition: inline

X19fX19fX19fX19fX19fX19fX19fX19fX19fX19fX19fX19fX19fX19fX19fX18KaHR0cDovL2Nv
b2wuaGF4eC5zZS9jZ2ktYmluL21haWxtYW4vbGlzdGluZm8vY3VybC1hbmQtcGhwCg==

--===============0002281022==--