Re: Random latency in reentrant calls (Bug 57916) (Apache Users)

On Tue, May 12, 2015 at 10:03 AM, Luc Andre <landre3567@xxxxxxxxx> wrote:

Thanks for your reply.

We did a test on a powerful server with

StartServers 20
MinSpareServers 5
MaxSpareServers 20

And we still have the issue...

As you pointed out the logging happens after the request and we get the time at the beginning of the php script to make sure that we ignore the time spent after.

Even if Apache creates a new child for a request I don't think that it can take more than 1 sec, and we can get up to 1.8 secs latency between the request and the start of the script.

Regards,

Luc
On Tue, May 12, 2015 at 9:30 AM, Dr James Smith <js5@xxxxxxxxxxxx> wrote:
You are probably hitting child spin up issues...

Out of the box apache uses a process per apache child... There is an overhead/delay when a child is initially spun up,
and that is what you are possibly seeing...

nginx works a different way - and can cope with a moderate number of "light" requests better than apache, but once
the numbers of requests get higher (or they get heavier) then nginx can start dropping requests in "interesting" ways!

Additionally there is a cleanup phase in the apache process which handles logging (and other potential custom
code) which happens after the request is finished - so although you think you have only two simultaneous requests
there are probably more in the process (after each request there will be a write to disk to write the access log)

<IfModule mpm_prefork_module> StartServers 5 MinSpareServers 5 MaxSpareServers 10 MaxRequestWorkers 150 MaxConnectionsPerChild 0</IfModule>
You can tune apache by increasing the first 3 values and this will likely remove the effect you are seeing at least
for the number of requests you are making...

HTH

On 12/05/2015 08:13, Luc Andre wrote:
This issue was first submitted as a bug report but I was advised to use this mailing list instead.

The problem occurs with an 'out of the box' configuration (tested on debian and windows)

Our php web site requires sometimes a reentrant call (i.e. it calls file_get_contents(http://127.0.0.1/reentrant.php).

Most of the times calls are really fast (<1ms) but a few ones take over 0.5 secs.

We had a hard time reproducing the bug but we finally found a php script that calls itself (see enclosure).

To test it just try http://127.0.0.1/reentrant.php?count=10 where 10 is the reentrancy level.

The script works fine with NGINX that's why we suspect apache rather than PHP.

Sample output with count=15

Each value of 'report' is the time spent between the http request and the execution of the first PHP line.
{
    "microtime": 1431414304.2875,
    "report": [
        0.0014371871948242,
        0.1552619934082,
        0.020139932632446,
        0.82674908638,
        0.5719690322876,
        0.00056719779968262,
        0.00065994262695312,
        0.00075387954711914,
        0.00066518783569336,
        0.00063514709472656,
        0.00071001052856445,
        0.00066900253295898,
        0.00063490867614746,
        0.00070381164550781,
        0.00070095062255859
    ] 
}

You can see that 3 calls are ridiculously slow for a simple localhost request.

We don't believe in an misconfiguration issue since we reproduced it with an out of the box config.

Feel free to reopen the BR 57916 if you agree that it is a bug.

Regards,

Luc
---------------------------------------------------------------------
To unsubscribe, e-mail: users-unsubscribe@xxxxxxxxxxxxxxxx
For additional commands, e-mail: users-help@xxxxxxxxxxxxxxxx
This email has been checked for viruses by Avast antivirus software.
www.avast.com

-- The Wellcome Trust Sanger Institute is operated by Genome Research Limited, a charity registered in England with number 1021457 and a company registered in England with number 2742969, whose registered office is 215 Euston Road, London, NW1 2BE.