Home → Problems →

High loading times in Apache Bench

• Edit

merlijn

20 Jan, 2012 07:19 AM

I am testing slim as framework for a RESTful API. I love the neat OO interface and clear documentation. There is however 1 issue that is frustrating me.
Whenever I test a very simple slim app (for example the hello world example) the loading time in the browser is blazingly fast, but when testing the loading times with AB, I never get a loading time < 5000 ms.

I ruled out several possible causes (autoloader, overhead from my own framework, checking a 200 is really returned, testing both from localhost as remote) but whatever I try the loading times are very very high.

I did google around, but didn't find anything. Any pointers are highly appreciated.

1. Support Staff 1 Posted by Josh Lockhart on 01 Feb, 2012 01:35 PM

   

   That certainly seems odd as there really isn't anything that would slow Slim down that much by default. I'd double-check your AB flags when you run the benchmarks. Otherwise I'll defer to others on the forum who are more familiar with it.

   • Edit

2. 2 Posted by M. Fischer on 09 Feb, 2012 04:12 PM

   

   I have the same problem, here is my ab2 Result with the hello world example from the homepage:

   $ ab2 -v 4 -n 10 -c 1 http://localhost/slimtest/index.php/hello/world 
   This is ApacheBench, Version 2.3 <$Revision: 655654 $>
   Copyright 1996 Adam Twiss, Zeus Technology Ltd, http://www.zeustech.net/
   Licensed to The Apache Software Foundation, http://www.apache.org/
   
   Benchmarking localhost (be patient)...INFO: POST header == 
   ---
   GET /slimtest/index.php/hello/world HTTP/1.0
   Host: dev.api.berlinonline.de
   User-Agent: ApacheBench/2.3
   Accept: */*
   
   
   ---
   LOG: header received:
   HTTP/1.1 200 OK
   Date: Thu, 09 Feb 2012 15:56:44 GMT
   Server: Apache/2.2.17 (Linux/SUSE)
   X-Powered-By: PHP/5.3.5
   Set-Cookie: PHPSESSID=aebb3a9937a5f13d95edd1efe2a18d6d; path=/
   Content-Length: 13
   Set-Cookie: aebb3a9937a5f13d95edd1efe2a18d6d=DEFAULT%7C0%7C%2BwqQ8qA8kTpRq9lmn%2FQDVK08ahoS9gJgJl0JOYmMXrZzlR3S5m88jQ4TNRBsvSJa6zjfxkhhhci377E9n4gYPw%3D%3D%7C5c7715257d81ed78f6e73bfb885adff3ce823bf1; path=/
   Vary: Accept-Encoding
   Content-Type: text/html
   
   
   LOG: Response code = 200
   LOG: header received:
   HTTP/1.1 200 OK
   Date: Thu, 09 Feb 2012 15:56:59 GMT
   Server: Apache/2.2.17 (Linux/SUSE)
   X-Powered-By: PHP/5.3.5
   Set-Cookie: PHPSESSID=082d471b1d8a2dd902bc052ce0e98ed6; path=/
   Content-Length: 13
   Set-Cookie: 082d471b1d8a2dd902bc052ce0e98ed6=DEFAULT%7C0%7C%2BwqQ8qA8kTpRq9lmn%2FQDVK08ahoS9gJgJl0JOYmMXrZzlR3S5m88jQ4TNRBsvSJa6zjfxkhhhci377E9n4gYPw%3D%3D%7C5c7715257d81ed78f6e73bfb885adff3ce823bf1; path=/
   Vary: Accept-Encoding
   Content-Type: text/html
   
   
   LOG: Response code = 200
   LOG: header received:
   HTTP/1.1 200 OK
   Date: Thu, 09 Feb 2012 15:57:14 GMT
   Server: Apache/2.2.17 (Linux/SUSE)
   X-Powered-By: PHP/5.3.5
   Set-Cookie: PHPSESSID=2e2f0ec20b57ba3127236ec69c5a1058; path=/
   Content-Length: 13
   Set-Cookie: 2e2f0ec20b57ba3127236ec69c5a1058=DEFAULT%7C0%7C%2BwqQ8qA8kTpRq9lmn%2FQDVK08ahoS9gJgJl0JOYmMXrZzlR3S5m88jQ4TNRBsvSJa6zjfxkhhhci377E9n4gYPw%3D%3D%7C5c7715257d81ed78f6e73bfb885adff3ce823bf1; path=/
   Vary: Accept-Encoding
   Content-Type: text/html
   
   
   LOG: Response code = 200
   ^C
   
   Server Software:        Apache/2.2.17
   Server Hostname:        localhost
   Server Port:            80
   
   Document Path:          /slimtest/index.php/hello/world
   Document Length:        13 bytes
   
   Concurrency Level:      1
   Time taken for tests:   33.157 seconds
   Complete requests:      2
   Failed requests:        0
   Write errors:           0
   Total transferred:      1410 bytes
   HTML transferred:       39 bytes
   Requests per second:    0.06 [#/sec] (mean)
   Time per request:       16578.458 [ms] (mean)
   Time per request:       16578.458 [ms] (mean, across all concurrent requests)
   Transfer rate:          0.04 [Kbytes/sec] received
   
   Connection Times (ms)
                 min  mean[+/-sd] median   max
   Connect:        0    0   0.0      0       0
   Processing: 15028 15029   1.5  15030   15030
   Waiting:       10   11   0.9     11      11
   Total:      15028 15029   1.5  15030   15030
   
   Percentage of the requests served within a certain time (ms)
     50%  15030
     66%  15030
     75%  15030
     80%  15030
     90%  15030
     95%  15030
     98%  15030
     99%  15030
    100%  15030 (longest request)
   

   • Edit

3. 3 Posted by M.Fischer on 09 Feb, 2012 04:39 PM

   

   Perhaps this helps solving the problem:

   Using the switch -k (Use Keep-Alive) helps to solve the problem, so I believe Slim has a bug, if no keep-alive is used.

   The working command line:

   ab2 -k -n 1000 -c 5 http://localhost/slimtest/index.php/hello/world
   

   • Edit

4. Support Staff 4 Posted by Josh Lockhart on 09 Feb, 2012 04:44 PM

   

   I found this thread on StackOverflow that may provide some further help. If you can narrow down what is causing the slow down I'll work on a fix.

   http://serverfault.com/questions/254765/apache-benchmark-keep-alive

   • Edit

5. 5 Posted by merlijn on 09 Feb, 2012 05:17 PM

   

   Yup, i can confirm that. With the keep-alive option, loading times are as expected.

   • Edit

6. 6 Posted by M.Fischer on 09 Feb, 2012 05:32 PM

   

   I tried to find some clue by using an strace, both on client and on the server-process. Each process hangs in an epoll_wait and seems to wait for some input. The apache benchmark times are exactly the setting for the keep alive timeout (Apache 2.2.17 used).
   In some way, Slim does not closes the output all right (other PHP-Apps and Frameworks behave better on the same server).
   I tried to hack Slim in some parts, closing the output buffering or using a die(), but nothing solved the problem, so I believe, the bug has to be somewhere in the initialization.

   • Edit

7. Support Staff 7 Posted by Josh Lockhart on 09 Feb, 2012 05:47 PM

   

   Slim will read from php://input to fetch POST/PUT request bodies (in Environment.php). Do you think that may cause the wait?

   • Edit

8. 8 Posted by M. Fischer on 09 Feb, 2012 06:01 PM

   

   I've set the line to

   $this->body = "";
   

   but it did not help. With some further hacking by uncommenting header()-functions I found the buggy line in the function sendHeaders():

   header(sprintf('HTTP/%s %s', $this->httpVersion, self::getMessageForCode($this->status())));
   

   It seems, that the trailing space after the status code leads to this behavior, just removing the space solves the Problem, at least for status 200. But do not ask me, why this causes the problem ;-)

   • Edit

9. Support Staff 9 Posted by Josh Lockhart on 09 Feb, 2012 06:12 PM

   

   Hmm... can you post the changed code that resolved the issue? I don't understand what you changed. The sprintf('HTTP/%s %s', args) will output HTTP/1.1 200 OK, which is correct. Maybe I misunderstand what you changed.

   • Edit

10. Support Staff 10 Posted by Josh Lockhart on 09 Feb, 2012 06:29 PM

    

    This problem may also be with Apache Bench... read this:

    http://seancoates.com/blogs/http-1-and-the-connection-header

    What happens when you send a Connection: close header with the request?

    ab -H "Connection: close" ...
    

    • Edit

11. Support Staff 11 Posted by Josh Lockhart on 09 Feb, 2012 06:34 PM

    

    My own tests with a Hello World example:

    ab -H "Connection:close" -n 1000 -c 5 http://slim/
    

    And the results:

    Server Software:        Apache
    Server Hostname:        slim
    Server Port:            80
    
    Document Path:          /
    Document Length:        5231 bytes
    
    Concurrency Level:      5
    Time taken for tests:   5.491854 seconds
    Complete requests:      1000
    Failed requests:        0
    Write errors:           0
    Total transferred:      5394000 bytes
    HTML transferred:       5231000 bytes
    Requests per second:    182.09 [#/sec] (mean)
    Time per request:       27.459 [ms] (mean)
    Time per request:       5.492 [ms] (mean, across all concurrent requests)
    Transfer rate:          959.06 [Kbytes/sec] received
    
    Connection Times (ms)
                  min  mean[+/-sd] median   max
    Connect:        0    1   2.2      0      22
    Processing:     9   25  21.7     18     169
    Waiting:        0   23  20.4     16     155
    Total:          9   26  21.8     20     169
    

    And the test WITHOUT sending the Connection: close header:

    ab -n 1000 -c 5 http://slim/
    

    The result:

    It hangs for a long time.
    

    • Edit

12. 12 Posted by M. Fischer on 10 Feb, 2012 09:15 AM

    

    Sorry,

    the working (but not useable) line is:

    header(sprintf('HTTP/%s%s', $this->httpVersion, self::getMessageForCode($this->status())));
    

    I just removed the space between the two "%s" placeholders. I believe, a real bugfix needs some further investigation of the problem.

    • Edit

13. 13 Posted by merlijn on 10 Feb, 2012 09:24 AM

    

    I've done some more testing, ruling out my own autoloading mechanism and XDebug as possible causes. The problem really seems to be the connection handling of ab. I am not a HTTP guru. Again, the problem doesn't exist in the browser or when accessing the script by Curl.
    The 5000 ms is typical in my case, and very consistent... in other tests people are reporting for example 15000 ms. Sounds to me as an OS/Kernel specific tcp timeout value.

    • Edit

14. 14 Posted by M. Fischer on 10 Feb, 2012 09:56 AM

    

    I did not find the bug with other tools than ab2, either. In some way apache benchmarking has some problems with the header-line Slim sends, perhaps this is a bug in ab2 itself.

    The timeout is the keep-alive-timeout, wich is set by the webserver. The server closes the connection exactly after the time as expected.

    • Edit

15. 15 Posted by MarcosBL on 10 Feb, 2012 10:48 AM

    

    My own try, i can't reproduce, Apache/2.2.17 Slim latest stable

    No change with

    -H "Connection: close"
    

    nor with

    ab2 -k
    

    Maybe ab version bug ?

    GOLEM ~ # ab -c100 -n5000 http://domain.com/marcos/ 
    This is ApacheBench, Version 2.3 <$Revision: 655654 $>
    Copyright 1996 Adam Twiss, Zeus Technology Ltd, http://www.zeustech.net/
    Licensed to The Apache Software Foundation, http://www.apache.org/
    
    Benchmarking domain.com (be patient)
    Completed 500 requests
    Completed 1000 requests
    Completed 1500 requests
    Completed 2000 requests
    Completed 2500 requests
    Completed 3000 requests
    Completed 3500 requests
    Completed 4000 requests
    Completed 4500 requests
    Completed 5000 requests
    Finished 5000 requests
    
    Server Software:        Apache/2.2.17
    Server Hostname:        domain.com
    Server Port:            80
    
    Document Path:          /marcos/
    Document Length:        4207 bytes
    
    Concurrency Level:      100
    Time taken for tests:   2.818 seconds
    Complete requests:      5000
    Failed requests:        0
    Write errors:           0
    Total transferred:      22710000 bytes
    HTML transferred:       21035000 bytes
    Requests per second:    1774.20 [#/sec] (mean)
    Time per request:       56.363 [ms] (mean)
    Time per request:       0.564 [ms] (mean, across all concurrent requests)
    Transfer rate:          7869.57 [Kbytes/sec] received
    
    Connection Times (ms)
              min  mean[+/-sd] median   max
    Connect:        0   11   6.9     12      27
    Processing:    15   44   9.5     44     112
    Waiting:        1   37  10.0     37      99
    Total:         28   56   7.2     56     119
    
    Percentage of the requests served within a certain time (ms)
    50%     56
    66%     58
    75%     60
    80%     61
    90%     64
    95%     67
    98%     72
    99%     74
    100%    119 (longest request)
    

    • Edit

16. 16 Posted by merlijn on 10 Feb, 2012 10:52 AM

    

    Same version of ab... different os maybe...
    I am using freeBSD.

    $ ab -V
    This is ApacheBench, Version 2.3 <$Revision: 655654 $>
    Copyright 1996 Adam Twiss, Zeus Technology Ltd, http://www.zeustech.net/
    Licensed to The Apache Software Foundation, http://www.apache.org/

    • Edit

17. 17 Posted by MarcosBL on 10 Feb, 2012 11:02 AM

    

    Ubuntu Server 11.04 here

    Linux 2.6.38.2-grsec-xxxx-grs-ipv6-64

    • Edit

18. 18 Posted by M. Fischer on 10 Feb, 2012 11:07 AM

    

    Well, in the morning everything is a bit more clear... The space between is nonsense, causes a 500, but uncommenting the header-line works. Switching to HTTP/1.0 does the same, but we already know that keep alive has to do something with it.

    • Edit

19. 19 Posted by M. Fischer on 10 Feb, 2012 11:10 AM

    

    Testsystem:
    openSUSE 11.4 (x86_64) with Apache 2.2.17 and Linux 2.6.37.6-0.9-desktop #1 SMP PREEMPT 2011-10-19 22:33:27 +0200 x86_64 x86_64 x86_64 GNU/Linux using PHP 5.3.5

    • Edit

20. 20 Posted by MarcosBL on 10 Feb, 2012 11:17 AM

    

    Forgot PHP version:

    GOLEM ~ # php -v
    PHP 5.3.8-1~dotdeb.2 with Suhosin-Patch (cli) (built: Aug 25 2011 13:30:46) 
    Copyright (c) 1997-2011 The PHP Group
    Zend Engine v2.3.0, Copyright (c) 1998-2011 Zend Technologies
    

    • Edit

21. Support Staff 21 Posted by Josh Lockhart on 10 Feb, 2012 01:58 PM

    

    I'm running the stock ab that comes with OS X 10.7.x.

    This is ApacheBench, Version 2.0.41-dev <$Revision: 1.121.2.12 $> apache-2.0
    

    Also using Apache/2.0.64 with PHP 5.3.5.

    I'm very confident this entire issue is due to ab mishandling the connection with the web server. I believe Slim is irrelevant in this case. For me, sending a Connection: close header resolves the issue. So does enabling Keep-Alive with ab -k. So I'm recommending that you upgrade ab to a version that works for you or use an alternative testing tool like siege.

    Will leave this thread open more comments.

    Josh

    • Edit

22. 22 Posted by eko3alpha on 25 Mar, 2014 10:45 AM

    

    I'm having this exact same issue! I was wondering what the heck was going on! Im on OSX 10.8.5
    AMPPS
    Apache 2.2
    ab -V
    This is ApacheBench, Version 2.3 <$Revision: 655654 $>

    As you can see below the test is rather light! and I have a host record for dev.slim-app.com
    

    ab -n 10 -c 1 http://dev.slim-app.com/hello/test
    This is ApacheBench, Version 2.3 <$Revision: 655654 $>
    Copyright 1996 Adam Twiss, Zeus Technology Ltd, http://www.zeustech.net/
    Licensed to The Apache Software Foundation, http://www.apache.org/
    
    
    
    
    
    
    
    Benchmarking dev.slim-app.com (be patient).....done
    
    
    
    
    
    
    
    Server Software:        Apache/2.4.7
    Server Hostname:        dev.slim-app.com
    Server Port:            80
    
    
    
    
    
    
    
    Document Path:          /hello/test
    Document Length:        12 bytes
    
    
    
    
    
    
    
    Concurrency Level:      1
    Time taken for tests:   50.149 seconds
    Complete requests:      10
    Failed requests:        0
    Write errors:           0
    Total transferred:      2050 bytes
    HTML transferred:       120 bytes
    Requests per second:    0.20 #/sec
    Time per request:       5014.900 ms
    Time per request:       5014.900 ms
    Transfer rate:          0.04 [Kbytes/sec] received
    
    
    
    
    
    
    
    Connection Times (ms)
                  min  mean[+/-sd] median   max
    Connect:        0    0   0.1      0       0
    Processing:  5010 5014   1.6   5015    5016
    Waiting:        9   13   1.7     14      15
    Total:       5011 5015   1.6   5015    5016
    
    
    
    
    
    
    
    Percentage of the requests served within a certain time (ms)
      50%   5015
      66%   5016
      75%   5016
      80%   5016
      90%   5016
      95%   5016
      98%   5016
      99%   5016
     100%   5016 (longest request)
    

    • Edit

23. Support Staff 23 Posted by Josh Lockhart on 25 Mar, 2014 01:20 PM

    

    @eko3alpha As described above, ab has an issue with closing connections. Be sure you pass along an HTTP header with your ab call, like this:

    -H "Connection:close"

    • Edit

24. 24 Posted by eko3alpha on 26 Mar, 2014 12:40 AM

    

    Wow, Im not sure how I missed that! Thanks! Here are the new results

    Percentage of the requests served within a certain time (ms)
      50%     10
      66%     10
      75%     11
      80%     13
      90%     13
      95%     13
      98%     13
      99%     13
     100%     13 (longest request)
    

    • Edit

25. 25 Posted by Taleveteonext on 27 Mar, 2014 05:43 PM

    

    comment_body

    • Edit

26. 26 Posted by Oscar on 08 May, 2014 12:29 PM

    

    I solved the issue by adding the following:

    $app->response()->header('Connection', 'close');

    ... and finally;

    $app->run();

    I hope it saves your time.

    • Edit

27. 27 Posted by Aaron on 22 Jul, 2014 06:38 PM

    

    I've run into the same problem and I think it's caused by a mismatch between the HTTP version of the request and the response.

    If you change (in Slim\Slim.php) the default value of http_version to $_SERVER['SERVER_PROTOCOL'] rather than '1.1' and also change this:

    header(sprintf('HTTP/%s %s', $this->httpVersion, self::getMessageForCode($this->status())));

    to this (just removes the 'HTTP/' as it's already provided from $_SERVER):

    header(sprintf('%s %s', $this->config('http.version'), \Slim\Http\Response::getMessageForCode($status)));

    then responses will automatically follow whatever the request used.

    Before this change all requests to Slim via ab or file_get_contents() were taking 5 seconds, now they are nearly instant. Browsers were fine for me either way, but I think that's because the ones I tried were using HTTP/1.1 already.

    Hope this helps.

    • Edit

28. 28 Posted by razorness on 23 Jan, 2015 03:07 PM

    

    If anybody does still have this problem:

    Check if you create responses in a regular way Slim is offering. The problem is probably that you do not close your connection in a way that ab is understanting. To ensure this, read:

    http://stackoverflow.com/questions/138374/close-a-connection-early?answertab=active#tab-top

    The 5000ms is the timout ab waits.

    • Edit

29. 29 Posted by xuhifula on 06 May, 2017 01:51 AM

    

    High Loading time for site opening. http://leanbellysecret.com/

    • 1_(57).jpg 19 KB
    • Edit

30. 30 Posted by ulg on 06 Jun, 2017 02:44 AM

    

    I am also having same problem of Apache Bench at Red Smoothie Detox Factor Review - Reviewprotocol

    • Edit