Why php5-fpm post requests are slow, while same php-cli code/console curl works extremely fast?

Question

I am performing POST request to local api web service (via LAN) with dummy method, that works very fast itself (less then a second).

Problem is that if i use php5-fpm it takes extremely long time to perform POST request (curl post, streams).

If i use php-cli script with same code or console curl command - it works very fast, like a charm.

Strange thing: if i use system to execute console curl command from php5-fpm it tooks a lot of time to perform the request. So, no way to cheat :(

I am using direct ipv4 address to eliminate DNS problems (i tried to define CURLOPT_IPRESOLVE option, but perfomance was same).

If i omit curl CURLOPT_POSTFIELDS option, request is very fast in php5-fpm too.

I am using debian jessie with official php 5.6.9 package.

So, why this problem is happening with php5-fpm?

My curl php code:

$data = json_encode([
    'id'     => 1,
    'method' => 'test',
    'sid'    => session_id(),
]);

$curl = curl_init();
curl_setopt($curl, CURLOPT_URL, 'http://192.168.182.22');
curl_setopt($curl, CURLOPT_RETURNTRANSFER, true);
curl_setopt($curl, CURLOPT_POST, true);
curl_setopt($curl, CURLOPT_HTTPHEADER, [
    'Content-type: application/json',
    'Content-length: ' . strlen($data)
]);
curl_setopt($curl, CURLOPT_POSTFIELDS, $data);
$out = curl_exec($curl);
curl_close($curl);

Curl get info output (shows that starttransfer_time is very slow):

array(26) {
  ["url"]=>
  string(22) "http://192.168.182.22/"
  ["content_type"]=>
  string(24) "text/html; charset=UTF-8"
  ["http_code"]=>
  int(200)
  ["header_size"]=>
  int(532)
  ["request_size"]=>
  int(188)
  ["filetime"]=>
  int(-1)
  ["ssl_verify_result"]=>
  int(0)
  ["redirect_count"]=>
  int(0)
  ["total_time"]=>
  float(10.285093)
  ["namelookup_time"]=>
  float(3.2E-5)
  ["connect_time"]=>
  float(0.000156)
  ["pretransfer_time"]=>
  float(0.000181)
  ["size_upload"]=>
  float(82)
  ["size_download"]=>
  float(99)
  ["speed_download"]=>
  float(9)
  ["speed_upload"]=>
  float(7)
  ["download_content_length"]=>
  float(-1)
  ["upload_content_length"]=>
  float(82)
  ["starttransfer_time"]=>
  float(10.285052)
  ["redirect_time"]=>
  float(0)
  ["redirect_url"]=>
  string(0) ""
  ["primary_ip"]=>
  string(14) "192.168.182.22"
  ["certinfo"]=>
  array(0) {
  }
  ["primary_port"]=>
  int(80)
  ["local_ip"]=>
  string(14) "192.168.182.20"
  ["local_port"]=>
  int(49286)
}

Another try with streams. It also works slow (a bit faster then curl, but anyway i can get 40-50 seconds delay):

$url = 'http://192.168.182.22/';
$data = json_encode([ 
    'id'     => 1,
    'method' => 'test',
    'sid'    => session_id(),
]);

$headers = [
    'Content-type: application/json',
    'Connection: close',
    'Content-Length: ' . strlen($data)
];

$options = array(
    'http' => array(
        'header'  => join("
", $headers) . "
",
        'method'  => 'POST',
        'content' => $data,
    ),
);
$context  = stream_context_create($options);
$result = file_get_contents($url, false, $context);

There is no significant difference in diff /etc/php5/fpm/php.ini /etc/php5/cli/php.ini:

303c303
< disable_functions = pcntl_alarm,pcntl_fork,pcntl_waitpid,pcntl_wait,pcntl_wifexited,pcntl_wifstopped,pcntl_wifsignaled,pcntl_wexitstatus,pcntl_wtermsig,pcntl_wstopsig,pcntl_signal,pcntl_signal_dispatch,pcntl_get_last_error,pcntl_strerror,pcntl_sigprocmask,pcntl_sigwaitinfo,pcntl_sigtimedwait,pcntl_exec,pcntl_getpriority,pcntl_setpriority,
---
> disable_functions =
363c363
< expose_php = Off
---
> expose_php = On
393c393
< memory_limit = 256M
---
> memory_limit = -1
660c660
< post_max_size = 200M
---
> post_max_size = 8M
810c810
< upload_max_filesize = 200M
---
> upload_max_filesize = 2M

Main thing in tcpdump i can see differ - php5-fpm requests includes ARP requests. I can't see such in console curl/php-cli. Perhaps problem happens when remote api server wants to return response, but can't find a way how to perform this?

(@Mircea adviced to add static arp routes, we added them, ARP requests disappeared from tcpdump, but pauses are still present).

tcpdump output for php5-fpm:

    00:55:22.347822 IP 192.168.182.20.52659 > 192.168.182.22.80: Flags [S], seq 4210728690, win 29200, options [mss 1460,sackOK,TS val 301284147 ecr 0,nop,wscale 7], length 0
E..<..@.@..~...........P..........r............
..;3........
00:55:22.347898 IP 192.168.182.22.80 > 192.168.182.20.52659: Flags [S.], seq 2702388053, ack 4210728691, win 28960, options [mss 1460,sackOK,TS val 280740546 ecr 301284147,nop,wscale 7], length 0
E..<..@.@.M@.........P....+U......q .R.........
......;3....
00:55:22.347906 IP 192.168.182.20.52659 > 192.168.182.22.80: Flags [.], ack 1, win 229, options [nop,nop,TS val 301284147 ecr 280740546], length 0
E..4..@.@..............P......+V...........
..;3....
00:55:22.347942 IP 192.168.182.20.52659 > 192.168.182.22.80: Flags [P.], seq 1:206, ack 1, win 229, options [nop,nop,TS val 301284147 ecr 280740546], length 205
E.....@.@..............P......+V.....o.....
..;3....POST / HTTP/1.1
Host: 192.168.182.22
Content-Type: application/x-www-form-urlencoded
Content-Length: 82
Accept: */*

{"id":1,"method":"station.sync","params":[1],"sid":"1gn8f4mhctui9ki91bla6osnf4"}

00:55:22.347997 IP 192.168.182.22.80 > 192.168.182.20.52659: Flags [.], ack 206, win 235, options [nop,nop,TS val 280740547 ecr 301284147], length 0
E..4..@.@.c..........P....+V........2......
......;3
00:55:27.356575 ARP, Request who-has 192.168.182.22 tell 192.168.182.20, length 28
..........).4...............
00:55:27.356777 ARP, Reply 192.168.182.22 is-at 00:0c:29:46:99:bc, length 46
..........)F........).4.......................
00:55:36.742347 IP 192.168.182.22.80 > 192.168.182.20.52659: Flags [P.], seq 1:558, ack 206, win 235, options [nop,nop,TS val 280744145 ecr 301284147], length 557
E..a..@.@.a..........P....+V........a......
......;3HTTP/1.1 200 OK
Server: nginx/1.6.2
Date: Wed, 01 Jul 2015 21:55:36 GMT
Content-Type: application/json
Transfer-Encoding: chunked
Connection: keep-alive
Expires: Thu, 19 Nov 1981 08:52:00 GMT
Cache-Control: no-store, no-cache, must-revalidate, post-check=0, pre-check=0
Pragma: no-cache
Access-Control-Allow-Credentials: true
Access-Control-Allow-Headers: Content-Type, X-Requested-With
Access-Control-Allow-Methods: GET, POST, OPTIONS
p3p: CP=IDC DSP COR ADM DEVi TAIi PSA PSD IVAi IVDi CONi HIS OUR IND CNT

16
{"id":1,"result":true}
0


00:55:36.742374 IP 192.168.182.20.52659 > 192.168.182.22.80: Flags [.], ack 558, win 237, options [nop,nop,TS val 301287746 ecr 280744145], length 0
E..4..@.@..............P......-............
..IB....
00:55:36.742486 IP 192.168.182.20.52659 > 192.168.182.22.80: Flags [F.], seq 206, ack 558, win 237, options [nop,nop,TS val 301287746 ecr 280744145], length 0
E..4..@.@..............P......-............
..IB....
00:55:36.742559 IP 192.168.182.22.80 > 192.168.182.20.52659: Flags [F.], seq 558, ack 207, win 235, options [nop,nop,TS val 280744145 ecr 301287746], length 0
E..4..@.@.c..........P....-..........:.....
......IB
00:55:36.742566 IP 192.168.182.20.52659 > 192.168.182.22.80: Flags [.], ack 559, win 237, options [nop,nop,TS val 301287746 ecr 280744145], length 0
E..4..@.@..............P......-............
..IB....
00:55:41.744102 ARP, Request who-has 192.168.182.20 tell 192.168.182.22, length 46
..........)F..................................
00:55:41.744121 ARP, Reply 192.168.182.20 is-at 00:0c:29:04:34:c9, length 28
..........).4.......)F......

tcpdump output for fast (console/php-cli) requests:

0:43:46.854062 IP 192.168.182.20.52527 > 192.168.182.22.80: Flags [S], seq 560731240, win 29200, options [mss 1460,sackOK,TS val 301110274 ecr 0,nop,wscale 7], length 0
E..<.j@.@............/.P!l.h......r............
............
00:43:46.854198 IP 192.168.182.22.80 > 192.168.182.20.52527: Flags [S.], seq 1849811122, ack 560731241, win 28960, options [mss 1460,sackOK,TS val 280566673 ecr 301110274,nop,wscale 7], length 0
E..<..@.@.M@.........P./nA..!l.i..q ...........
............
00:43:46.854216 IP 192.168.182.20.52527 > 192.168.182.22.80: Flags [.], ack 1, win 229, options [nop,nop,TS val 301110274 ecr 280566673], length 0
E..4.k@.@............/.P!l.inA.............
........
00:43:46.854265 IP 192.168.182.20.52527 > 192.168.182.22.80: Flags [P.], seq 1:233, ack 1, win 229, options [nop,nop,TS val 301110274 ecr 280566673], length 232
E....l@.@............/.P!l.inA.............
........POST / HTTP/1.1
User-Agent: curl/7.38.0
Host: 192.168.182.22
Accept: */*
Content-Length: 84
Content-Type: application/x-www-form-urlencoded

{"id":1, "sid": "1gn8f4mhctui9ki91bla6osnf4","method":"station.sync", "params":[10]}
00:43:46.854317 IP 192.168.182.22.80 > 192.168.182.20.52527: Flags [.], ack 233, win 235, options [nop,nop,TS val 280566673 ecr 301110274], length 0
E..4."@.@.R%.........P./nA..!l.Q....b......
........
00:43:46.891248 IP 192.168.182.22.80 > 192.168.182.20.52527: Flags [P.], seq 1:615, ack 233, win 235, options [nop,nop,TS val 280566682 ecr 301110274], length 614
E....#@.@.O..........P./nA..!l.Q...........
........HTTP/1.1 200 OK
Server: nginx/1.6.2
Date: Wed, 01 Jul 2015 21:43:46 GMT
Content-Type: application/json
Transfer-Encoding: chunked
Connection: keep-alive
Expires: Thu, 19 Nov 1981 08:52:00 GMT
Cache-Control: no-store, no-cache, must-revalidate, post-check=0, pre-check=0
Pragma: no-cache
Access-Control-Allow-Credentials: true
Access-Control-Allow-Headers: Content-Type, X-Requested-With
Access-Control-Allow-Methods: GET, POST, OPTIONS
p3p: CP=IDC DSP COR ADM DEVi TAIi PSA PSD IVAi IVDi CONi HIS OUR IND CNT

4f
{"id":1,"error":{"code":"SERVER_ERROR","message":"Station #10 is not running"}}
0


00:43:46.891273 IP 192.168.182.20.52527 > 192.168.182.22.80: Flags [.], ack 615, win 238, options [nop,nop,TS val 301110283 ecr 280566682], length 0
E..4.m@.@............/.P!l.QnA.............
........
00:43:46.891932 IP 192.168.182.20.52527 > 192.168.182.22.80: Flags [F.], seq 233, ack 615, win 238, options [nop,nop,TS val 301110283 ecr 280566682], length 0
E..4.n@.@............/.P!l.QnA.............
........
00:43:46.896944 IP 192.168.182.22.80 > 192.168.182.20.52527: Flags [F.], seq 615, ack 234, win 235, options [nop,nop,TS val 280566684 ecr 301110283], length 0
E..4.$@.@.R#.........P./nA..!l.R....`i.....
........
00:43:46.896954 IP 192.168.182.20.52527 > 192.168.182.22.80: Flags [.], ack 616, win 238, options [nop,nop,TS val 301110285 ecr 280566684], length 0
E..4.o@.@............/.P!l.RnA.............
........

A Smith · Accepted Answer

One thing I've noticed on my own instance of FPM (using Nginx) is that I will not get interim output. I've never bothered to investigate this as it has never mattered for my own usage needs (small units of work with little output).

In your case, perhaps the response is being sent quickly but the connection is kept alive -- causing the recipient to wait around for more data that never arrives. You may be able to check on this by investigating server side logging to check response times from the server's point of view.

cwhsu · Answer

I just track down a similar issue of my own. I think it might be the same reason. I encounter the similar issue like avasin. I found that php-fpm curl to localhost is slow, but php-cli curl to localhost is extremely fast. Plus, debugging curl timing shows high starttransfer_time in php-fpm but rather low in php process.

I found the root cause yesterday, the issue is the php-fpm www.conf config. Becuase php-fpm has low start_server, php-fpm actually has to process curl with limited number of php-fpm processes. The solution is to increase the number of start_server, this will affect the number of concurrency which your php-fpm could handle. The performance will decrease drastically when the concurrency exceeds the number of current php-fpm processes. Hence, making everything feels slow. The php-cli does not have the same issue since it could launch many php processes as long as you have enough memory, so it is always fast. I did a lot of experiments here php curl localhost is slow when making concurrent requests. Take a look if you're interested.

Why php5-fpm post requests are slow, while same php-cli code/console curl works extremely fast?

Tags:

post

php

curl

avasin

2 Answers

A Smith

cwhsu

Recent Activity

Donate For Us

Why php5-fpm post requests are slow, while same php-cli code/console curl works extremely fast?

Tags:

post

php

curl

avasin

2 Answers

A Smith

cwhsu

Related questions

Recent Activity

Donate For Us