In linux-CLI, when CURL accesses a URL, the access speed is normal, but in PHP environment is slow?

In a web product developed by PHP, The Guzzle6 library is used as the HTTPClient to access the external interface. It is found that the access speed to the external interface is very slow, and it takes 15 seconds to receive the response. In CLI, the external interface CURL directly responds quickly. Try to solve this problem by yourself... in this case, a web product developed by PHP uses the Guzzle6 library as an HTTP Client to access the external interface. It is found that the access speed to the external interface is very slow and it takes 15 seconds to receive the response. In CLI, the external interface CURL directly responds quickly.
I tried to solve this problem and found the following phenomena:
1. First, Guzzle should also be accessed using CURL, which is seen from the occasional curl error reported by Guzzle. Occasionally, errors such as CURLE_COULDNT_RESOLVE_HOST may occur.

2. Then, determine if it is a DNS issue and directly use ip addresses for access. The results are the same.

3. Then I tried two CURL options: timeout setting and IPV6, corresponding to Guzzle:

['connect_timeout' => 2, 'curl' => [        CURLOPT_IPRESOLVE => CURL_IPRESOLVE_V4  ]，]

Still unchanged.

4. Replace the access interface host with baidu, qq, and taobao, and find that most of the access speeds are normal at this time, except qq .. Also very slow

5. The access duration is currently 15 seconds. Finally, execute strace on php-fpm and extract the following content:

5519 22:30:08. 260401 connect (7, {sa_family = AF_INET, sin_port = htons (80), sin_addr = inet_addr ("121. xx. xx. xx ")}, 16) =-1 EINPROGRESS (Operation now in progress) 5519 22:30:08. 260744 clock_gettime (CLOCK_MONOTONIC, {278258,519 214625}) = 05519 22:30:08. 260853 poll ([{fd = 7, events = POLLOUT | POLLWRNORM}], 1, 149999) = 1 ([{fd = 7, revents = POLLOUT | POLLWRNORM}]) 5519 22:30:08. 286791 getsockopt (7, SOL_SOCKET, SO_ERROR, [0], [4]) = 05519 22:30:08. 286851 clock_gettime (CLOCK_MONOTONIC, {278258,545 285059}) = 05519 22:30:08. 286891 clock_gettime (CLOCK_MONOTONIC, {278258,545 323358}) = 05519 22:30:08. 286926 clock_gettime (CLOCK_MONOTONIC, {278258,545 358858}) = 05519 22:30:08. 286962 clock_gettime (CLOCK_MONOTONIC, {278258,545 394658}) = 05519 22:30:08. 286997 clock_gettime (CLOCK_MONOTONIC, {278258,545 429558}) = 05519 22:30:08. 287055 sendto (7, "GET/v1/xxx HTTP/1.1 "..., 110, MSG_NOSIGNAL, NULL, 0) = 1105519 22:30:08. 287206 poll ([{fd = 7, events = POLLIN | POLLPRI | POLLRDNORM | POLLRDBAND}], 1, 0) = 0 (Timeout) 5519 22:30:08. 287248 poll ([{fd = 7, events = POLLIN | POLLPRI | POLLRDNORM | POLLRDBAND}], 1, 0) = 0 (Timeout) 5519 22:30:08. 287284 clock_gettime (CLOCK_MONOTONIC, {278258,545 716856}) = 05519 22:30:08. 287350 clock_gettime (CLOCK_MONOTONIC, {278258,545 782755}) = 05519 22:30:08. 287388 clock_gettime (CLOCK_MONOTONIC, {278258,545 820755}) = 05519 22:30:08. 287471 poll ([{fd = 7, events = POLLIN | POLLPRI | POLLRDNORM | POLLRDBAND}], 1, 1000
  
   
.... 5519 22:30:09. 288586 <... poll resumed>) = 0 (Timeout) 5519 22:30:09. 288678 poll ([{fd = 7, events = POLLIN | POLLPRI | POLLRDNORM | POLLRDBAND}], 1, 0) = 0 (Timeout) 5519 22:30:09. 288727 clock_gettime (CLOCK_MONOTONIC, {278259,547 161322}) = 05519 22:30:09. 288767 clock_gettime (CLOCK_MONOTONIC, {278259,547}) = 05519 22:30:09. 288806 clock_gettime (CLOCK_MONOTONIC, {278259,547 239318}) = 05519 22:30:09. 288842 poll ([{fd = 7, events = POLLIN | POLLPRI | POLLRDNORM | POLLRDBAND}], 1, 1000
   
    
... 5519 22:30:10. 289957 <... poll resumed>) = 0 (Timeout) 5519 22:30:10. 290024 poll ([{fd = 7, events = POLLIN | POLLPRI | POLLRDNORM | POLLRDBAND}], 1, 0) = 0 (Timeout) 5519 22:30:10. 290070 clock_gettime (CLOCK_MONOTONIC, {278260,548 504637}) = 05519 22:30:10. 290110 clock_gettime (CLOCK_MONOTONIC, {278260,548 542537}) = 05519 22:30:10. 290149 clock_gettime (CLOCK_MONOTONIC, {278260,548 581437}) = 05519 22:30:10. 290184 poll ([{fd = 7, events = POLLIN | POLLPRI | POLLRDNORM | POLLRDBAND}], 1, 1000
    
     
... It lasted until 15th seconds and received the response 5519 22:30:23. 309074 <... poll resumed>) = 0 (Timeout) 5519 22:30:23. 309151 poll ([{fd = 7, events = POLLIN | POLLPRI | POLLRDNORM | POLLRDBAND}], 1, 0) = 0 (Timeout) 5519 22:30:23. 309210 clock_gettime (CLOCK_MONOTONIC, {278273,567 644629}) = 05519 22:30:23. 309250 clock_gettime (CLOCK_MONOTONIC, {278273,567 682629}) = 05519 22:30:23. 309289 clock_gettime (CLOCK_MONOTONIC, {278273,567 721628}) = 05519 22:30:23. 309324 poll ([{fd = 7, events = POLLIN | POLLPRI | POLLRDNORM | POLLRDBAND}], 1, 1000) = 1 ([{fd = 7, revents = POLLIN | POLLRDNORM}]) 5519 22:30:23. 386517 poll ([{fd = 7, events = POLLIN | POLLPRI | POLLRDNORM | POLLRDBAND}], 1, 0) = 1 ([{fd = 7, revents = POLLIN | POLLRDNORM}]) 5519 22:30:23. 386578 recvfrom (7, "HTTP/1.1 200 OK \ r \ nServer: XXX "..., 16384, 0, NULL, NULL) = 18375519 22:30:23. 386676 clock_gettime (CLOCK_MONOTONIC, {278273,645 121620}) = 0
    
   
  

Please help us analyze the possible causes.
Thank you.

Reply content:

In this case, a web product developed by PHP uses the Guzzle6 library as an HTTP Client to access the external interface. It is found that the access speed to the external interface is very slow and it takes 15 seconds to receive the response. In CLI, the external interface CURL directly responds quickly.
I tried to solve this problem and found the following phenomena:
1. First, Guzzle should also be accessed using CURL, which is seen from the occasional curl error reported by Guzzle. Occasionally, errors such as CURLE_COULDNT_RESOLVE_HOST may occur.

2. Then, determine if it is a DNS issue and directly use ip addresses for access. The results are the same.

3. Then I tried two CURL options: timeout setting and IPV6, corresponding to Guzzle:

['connect_timeout' => 2, 'curl' => [        CURLOPT_IPRESOLVE => CURL_IPRESOLVE_V4  ]，]

Still unchanged.

4. Replace the access interface host with baidu, qq, and taobao, and find that most of the access speeds are normal at this time, except qq .. Also very slow

5. The access duration is currently 15 seconds. Finally, execute strace on php-fpm and extract the following content:

5519 22:30:08. 260401 connect (7, {sa_family = AF_INET, sin_port = htons (80), sin_addr = inet_addr ("121. xx. xx. xx ")}, 16) =-1 EINPROGRESS (Operation now in progress) 5519 22:30:08. 260744 clock_gettime (CLOCK_MONOTONIC, {278258,519 214625}) = 05519 22:30:08. 260853 poll ([{fd = 7, events = POLLOUT | POLLWRNORM}], 1, 149999) = 1 ([{fd = 7, revents = POLLOUT | POLLWRNORM}]) 5519 22:30:08. 286791 getsockopt (7, SOL_SOCKET, SO_ERROR, [0], [4]) = 05519 22:30:08. 286851 clock_gettime (CLOCK_MONOTONIC, {278258,545 285059}) = 05519 22:30:08. 286891 clock_gettime (CLOCK_MONOTONIC, {278258,545 323358}) = 05519 22:30:08. 286926 clock_gettime (CLOCK_MONOTONIC, {278258,545 358858}) = 05519 22:30:08. 286962 clock_gettime (CLOCK_MONOTONIC, {278258,545 394658}) = 05519 22:30:08. 286997 clock_gettime (CLOCK_MONOTONIC, {278258,545 429558}) = 05519 22:30:08. 287055 sendto (7, "GET/v1/xxx HTTP/1.1 "..., 110, MSG_NOSIGNAL, NULL, 0) = 1105519 22:30:08. 287206 poll ([{fd = 7, events = POLLIN | POLLPRI | POLLRDNORM | POLLRDBAND}], 1, 0) = 0 (Timeout) 5519 22:30:08. 287248 poll ([{fd = 7, events = POLLIN | POLLPRI | POLLRDNORM | POLLRDBAND}], 1, 0) = 0 (Timeout) 5519 22:30:08. 287284 clock_gettime (CLOCK_MONOTONIC, {278258,545 716856}) = 05519 22:30:08. 287350 clock_gettime (CLOCK_MONOTONIC, {278258,545 782755}) = 05519 22:30:08. 287388 clock_gettime (CLOCK_MONOTONIC, {278258,545 820755}) = 05519 22:30:08. 287471 poll ([{fd = 7, events = POLLIN | POLLPRI | POLLRDNORM | POLLRDBAND}], 1, 1000
  
   
.... 5519 22:30:09. 288586 <... poll resumed>) = 0 (Timeout) 5519 22:30:09. 288678 poll ([{fd = 7, events = POLLIN | POLLPRI | POLLRDNORM | POLLRDBAND}], 1, 0) = 0 (Timeout) 5519 22:30:09. 288727 clock_gettime (CLOCK_MONOTONIC, {278259,547 161322}) = 05519 22:30:09. 288767 clock_gettime (CLOCK_MONOTONIC, {278259,547}) = 05519 22:30:09. 288806 clock_gettime (CLOCK_MONOTONIC, {278259,547 239318}) = 05519 22:30:09. 288842 poll ([{fd = 7, events = POLLIN | POLLPRI | POLLRDNORM | POLLRDBAND}], 1, 1000
   
    
... 5519 22:30:10. 289957 <... poll resumed>) = 0 (Timeout) 5519 22:30:10. 290024 poll ([{fd = 7, events = POLLIN | POLLPRI | POLLRDNORM | POLLRDBAND}], 1, 0) = 0 (Timeout) 5519 22:30:10. 290070 clock_gettime (CLOCK_MONOTONIC, {278260,548 504637}) = 05519 22:30:10. 290110 clock_gettime (CLOCK_MONOTONIC, {278260,548 542537}) = 05519 22:30:10. 290149 clock_gettime (CLOCK_MONOTONIC, {278260,548 581437}) = 05519 22:30:10. 290184 poll ([{fd = 7, events = POLLIN | POLLPRI | POLLRDNORM | POLLRDBAND}], 1, 1000
    
     
... It lasted until 15th seconds and received the response 5519 22:30:23. 309074 <... poll resumed>) = 0 (Timeout) 5519 22:30:23. 309151 poll ([{fd = 7, events = POLLIN | POLLPRI | POLLRDNORM | POLLRDBAND}], 1, 0) = 0 (Timeout) 5519 22:30:23. 309210 clock_gettime (CLOCK_MONOTONIC, {278273,567 644629}) = 05519 22:30:23. 309250 clock_gettime (CLOCK_MONOTONIC, {278273,567 682629}) = 05519 22:30:23. 309289 clock_gettime (CLOCK_MONOTONIC, {278273,567 721628}) = 05519 22:30:23. 309324 poll ([{fd = 7, events = POLLIN | POLLPRI | POLLRDNORM | POLLRDBAND}], 1, 1000) = 1 ([{fd = 7, revents = POLLIN | POLLRDNORM}]) 5519 22:30:23. 386517 poll ([{fd = 7, events = POLLIN | POLLPRI | POLLRDNORM | POLLRDBAND}], 1, 0) = 1 ([{fd = 7, revents = POLLIN | POLLRDNORM}]) 5519 22:30:23. 386578 recvfrom (7, "HTTP/1.1 200 OK \ r \ nServer: XXX "..., 16384, 0, NULL, NULL) = 18375519 22:30:23. 386676 clock_gettime (CLOCK_MONOTONIC, {278273,645 121620}) = 0
    
   
  

Please help us analyze the possible causes.
Thank you.

If the requirement is not too complex, encapsulate a simple httpclient by yourself. It is still troublesome to find a third-party library, or you can run it with a debugging tool.

Try again and use curl to check the access speed.