The Slim Framework support forum has moved to http://discourse.slimframework.com. This Tender forum is no longer maintained or monitored.

High loading times in Apache Bench

merlijn's Avatar

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

    Josh Lockhart's Avatar

    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.

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

    M. Fischer's Avatar

    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)
    
  3. 3 Posted by M.Fischer on 09 Feb, 2012 04:39 PM

    M.Fischer's Avatar

    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
    
  4. Support Staff 4 Posted by Josh Lockhart on 09 Feb, 2012 04:44 PM

    Josh Lockhart's Avatar

    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

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

    merlijn's Avatar

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

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

    M.Fischer's Avatar

    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.

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

    Josh Lockhart's Avatar

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

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

    M. Fischer's Avatar

    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 ;-)

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

    Josh Lockhart's Avatar

    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.

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

    Josh Lockhart's Avatar

    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" ...
    
  11. Support Staff 11 Posted by Josh Lockhart on 09 Feb, 2012 06:34 PM

    Josh Lockhart's Avatar

    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.
    
  12. 12 Posted by M. Fischer on 10 Feb, 2012 09:15 AM

    M. Fischer's Avatar

    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.

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

    merlijn's Avatar

    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.

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

    M. Fischer's Avatar

    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.

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

    MarcosBL's Avatar

    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)
    
  16. 16 Posted by merlijn on 10 Feb, 2012 10:52 AM

    merlijn's Avatar

    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/

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

    MarcosBL's Avatar

    Ubuntu Server 11.04 here

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

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

    M. Fischer's Avatar

    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.

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

    M. Fischer's Avatar

    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

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

    MarcosBL's Avatar

    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
    
  21. Support Staff 21 Posted by Josh Lockhart on 10 Feb, 2012 01:58 PM

    Josh Lockhart's Avatar

    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

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

    eko3alpha's Avatar

    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)
  23. Support Staff 23 Posted by Josh Lockhart on 25 Mar, 2014 01:20 PM

    Josh Lockhart's Avatar

    @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"

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

    eko3alpha's Avatar

    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)
    
  25. 25 Posted by Taleveteonext on 27 Mar, 2014 05:43 PM

    Taleveteonext's Avatar

    comment_body

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

    Oscar's Avatar

    I solved the issue by adding the following:

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

    ... and finally;

    $app->run();

    I hope it saves your time.

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

    Aaron's Avatar

    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.

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

    razorness's Avatar

    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.

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

    xuhifula's Avatar

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

Reply to this discussion

Internal reply

Formatting help / Preview (switch to plain text) No formatting (switch to Markdown)

Attaching KB article:

»

Attached Files

You can attach files up to 10MB

If you don't have an account yet, we need to confirm you're human and not a machine trying to post spam.

Keyboard shortcuts

Generic

? Show this help
ESC Blurs the current field

Comment Form

r Focus the comment reply box
^ + ↩ Submit the comment

You can use Command ⌘ instead of Control ^ on Mac