Hi all,
I have a small script that retrieves data from a local API and stores
the response values in a database.
I can use file_get_contents or curl to request the API. I discovered
that there is a difference, in the
request, causing a 60 seconds response time difference.
When I use curl, this is the code:
$start=time();
$ch = curl_init();
curl_setopt($ch, CURLOPT_URL, 'http://localmachine/api/v1/data’);
curl_setopt($ch, CURLOPT_RETURNTRANSFER, 1);
$jsonstring = curl_exec($ch);
curl_close($ch);
$end=time();
$duration=$end-$start;
echo "duration:".$duration;
printf($jsonstring);
It outputs a duration of 0 seconds with a valid response. Using
Wireshark I see normal behaviour.
22.22 is the workstation executing the php script, .23.21 is the
location of the API:
No. Time Source Destination Protocol Length Info
7 2.786141662 192.168.22.22 192.168.23.21 TCP 74
56826 → 80 [SYN] Seq=0 Win=64240 Len=0 MSS=1460 SACK_PERM
TSval=214738169 TSecr=0 WS=128
8 2.795679230 192.168.23.21 192.168.22.22 TCP 60 80
→ 56826 [SYN, ACK] Seq=0 Ack=1 Win=5744 Len=0 MSS=1440
9 2.795702271 192.168.22.22 192.168.23.21 TCP 54
56826 → 80 [ACK] Seq=1 Ack=1 Win=64240 Len=0
10 2.795737091 192.168.22.22 192.168.23.21 HTTP 127
GET /api/v1/data HTTP/1.1
11 2.880292134 192.168.23.21 192.168.22.22 TCP 124
80 → 56826 [PSH, ACK] Seq=1 Ack=74 Win=5671 Len=70 [TCP segment of a
reassembled PDU]
12 2.880302574 192.168.22.22 192.168.23.21 TCP 54
56826 → 80 [ACK] Seq=74 Ack=71 Win=64170 Len=0
13 2.885116374 192.168.23.21 192.168.22.22 HTTP/JSON
935 HTTP/1.1 200 OK ,JSON (application/json)
14 2.885123894 192.168.22.22 192.168.23.21 TCP 54
56826 → 80 [ACK] Seq=74 Ack=952 Win=63432 Len=0
When I use file_get_contents, this is the code:
$start=time();
$jsonstring=file_get_contents('http://localmachine/api/v1/data’);
$end=time();
$duration=$end-$start;
echo "duration2:".$duration;
printf($jsonstring);
It outputs a duration of 60 to 61 seconds with a valid response. The
wireshark output is interesting.
First I get quite a normal chat, that does include the response (No.
26) and is finished within a second:
No. Time Source Destination Protocol Length Info
20 3.885642095 192.168.22.22 192.168.23.21 TCP 74
56836 → 80 [SYN] Seq=0 Win=64240 Len=0 MSS=1460 SACK_PERM
TSval=214739269 TSecr=0 WS=128
21 3.891391022 192.168.23.21 192.168.22.22 TCP 60 80
→ 56836 [SYN, ACK] Seq=0 Ack=1 Win=5744 Len=0 MSS=1440
22 3.891433093 192.168.22.22 192.168.23.21 TCP 54
56836 → 80 [ACK] Seq=1 Ack=1 Win=64240 Len=0
23 3.891467773 192.168.22.22 192.168.23.21 HTTP 133
GET /api/v1/data HTTP/1.1
24 3.974408422 192.168.23.21 192.168.22.22 TCP 124
80 → 56836 [PSH, ACK] Seq=1 Ack=80 Win=5665 Len=70 [TCP segment of a
reassembled PDU]
25 3.974441932 192.168.22.22 192.168.23.21 TCP 54
56836 → 80 [ACK] Seq=80 Ack=71 Win=64170 Len=0
26 3.978116192 192.168.23.21 192.168.22.22 HTTP/JSON
935 HTTP/1.1 200 OK ,JSON (application/json)
27 3.978128913 192.168.22.22 192.168.23.21 TCP 54
56836 → 80 [ACK] Seq=80 Ack=952 Win=63432 Len=0
Then, 60 seconds later, I get the following in wireshark:
No. Time Source Destination Protocol Length Info
175 64.038494990 192.168.22.22 192.168.23.21 TCP 54
56836 → 80 [FIN, ACK] Seq=80 Ack=952 Win=63432 Len=0
176 64.038573841 192.168.22.22 192.168.23.21 TCP 54
56826 → 80 [FIN, ACK] Seq=74 Ack=952 Win=63432 Len=0
177 64.042788246 192.168.23.21 192.168.22.22 TCP 60
80 → 56826 [ACK] Seq=952 Ack=75 Win=5670 Len=0
178 64.042843386 192.168.23.21 192.168.22.22 TCP 60
80 → 56836 [ACK] Seq=952 Ack=81 Win=5664 Len=0
179 64.045362427 192.168.23.21 192.168.22.22 TCP 60
80 → 56826 [FIN, ACK] Seq=952 Ack=75 Win=5670 Len=0
180 64.045381737 192.168.22.22 192.168.23.21 TCP 54
56826 → 80 [ACK] Seq=75 Ack=953 Win=63432 Len=0
181 64.047301343 192.168.23.21 192.168.22.22 TCP 60
80 → 56836 [FIN, ACK] Seq=952 Ack=81 Win=5664 Len=0
182 64.047313753 192.168.22.22 192.168.23.21 TCP 54
56836 → 80 [ACK] Seq=81 Ack=953 Win=63432 Len=0
When these (No 175 to 182) passed, php shows me the API response, that
it already got at No. 26.
Comparing the initial GET request, I noticed that when using Curl,
there is a request header:
ACCEPT: */*
While file_get_contents does not have that header, but instead does
include the following header:
Connection: close
This is the relevant RFC: RFC 2616 - Hypertext Transfer Protocol -- HTTP/1.1
It says: "Once a close has been signaled, the client MUST NOT send any
more requests on that connection."
To me it looks like file_get_contents does not comply here.
Fun fact: I have tested this with a different (public) API. Using
file_get_contents it shows me a proper response
within a second.
Fun fact 2: I have tested the curl way by adding the header
'Connection: close' explicitly. This doesn't seem
to have any impact, response is shown on screen within a second.
Did a google search, found this:
PHP file_get_contents very slow when using full url – Make Me Engineer.
Last but not least, I'm using PHP 8.3.8 (cli) on Suse Tumbleweed.
Would this be a bug in file_get_contents, or am I doing something
wrong here, or is my local API not responding properly?
Any thoughts are welcome!
Martin