Bug Report #4638
Kohana 3.3 slow response with Apache Bench
|Assignee:||Lorenzo Pisani||% Done:|
Kohana 3.3 is a bit slow while testing it with Apache Bench -n100 -c10, on clean K3.3 install and welcome controller it looks like this:
Concurrency Level: 10
Time taken for tests: 55.547 seconds
Complete requests: 100
Failed requests: 0
Write errors: 0
Total transferred: 22500 bytes
HTML transferred: 1300 bytes
Requests per second: 1.80 [#/sec] (mean)
Time per request: 5554.722 [ms] (mean)
Time per request: 555.472 [ms] (mean, across all concurrent requests)
Tested on XAMPP 1.7.7 Lite (PHP 5.3.8) and XAMPP 1.8.1 Lite (PHP 5.4.7) installed on Windows7 x64.
K3.2 has created 3 cachegrind.out files (2 on second run) while K3.3 created 12 files (14 on second run). Dunno why, I have no idea what it means, does 1 file mean 1 request (I guess not) or what.
After removing send_headers(TRUE) from index.php:
echo Request::factory(TRUE, array(), FALSE) ->execute() //->send_headers(TRUE) ->body();
results are back to normal, K3.3 is as fast as previous releases.
#5 Updated by Jeremy Bush over 1 year ago
I just tried this with httperf (a better benchmarking tool than ab):
-> % httperf --server=localhost --port 3001 --rate=10 --num-conns=500 httperf --client=0/1 --server=localhost --port=3001 --uri=/ --rate=10 --send-buffer=4096 --recv-buffer=16384 --num-conns=500 --num-calls=1 httperf: warning: open file limit > FD_SETSIZE; limiting max. # of open files to FD_SETSIZE Maximum connect burst length: 1 Total: connections 500 requests 500 replies 500 test-duration 49.902 s Connection rate: 10.0 conn/s (99.8 ms/conn, <=1 concurrent connections) Connection time [ms]: min 0.9 avg 1.3 max 73.4 median 1.5 stddev 3.2 Connection time [ms]: connect 0.2 Connection length [replies/conn]: 1.000 Request rate: 10.0 req/s (99.8 ms/req) Request size [B]: 62.0 Reply rate [replies/s]: min 10.0 avg 10.0 max 10.0 stddev 0.0 (9 samples) Reply time [ms]: response 1.1 transfer 0.1 Reply size [B]: header 120.0 content 3959.0 footer 0.0 (total 4079.0) Reply status: 1xx=0 2xx=500 3xx=0 4xx=0 5xx=0 CPU time [s]: user 11.12 system 38.74 (user 22.3% system 77.6% total 99.9%) Net I/O: 40.5 KB/s (0.3*10^6 bps) Errors: total 0 client-timo 0 socket-timo 0 connrefused 0 connreset 0 Errors: fd-unavail 0 addrunavail 0 ftab-full 0 other 0
Can you try with httperf?
#6 Updated by thejw23 . over 1 year ago
1) I used http://www.turnkeylinux.org/lampstack with VirtualBox
2) Installed PHP modules: cUrl and GD
3) Installed Httpref
No other changes made. It should be much easier to reproduce this issue.
For Kohana 3.2.2 AB took 0.339 seconds and for K3.3 it was 150.369 seconds.
Httpref took 49.904 s (99.8 ms/req) for both Kohana versions.
Detailes results from both tests: https://gist.github.com/3976271
#8 Updated by thejw23 . over 1 year ago
Good question is: AB problem with what? What caused thes AB malfunction. Are we sure that this won't happen in real production enviroments or with some other tools?
Something that was introduced along with K3.3 showed this strange AB behaviour and I guess it's worth checking what exactly it is - just to be sure that this won't pop up on another occasion. Maybe it's not so hard to fix and make K3.3 work with AB as fast as K3.2 and other versions.
#9 Updated by Jeremy Bush over 1 year ago
I just tried this on my system, and I get very different results:
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 192.168.1.103 (be patient).....done Server Software: Server Hostname: 192.168.1.103 Server Port: 3001 Document Path: / Document Length: 3959 bytes Concurrency Level: 10 Time taken for tests: 0.245 seconds Complete requests: 100 Failed requests: 0 Write errors: 0 Total transferred: 408800 bytes HTML transferred: 395900 bytes Requests per second: 407.34 [#/sec] (mean) Time per request: 24.550 [ms] (mean) Time per request: 2.455 [ms] (mean, across all concurrent requests) Transfer rate: 1626.16 [Kbytes/sec] received Connection Times (ms) min mean[+/-sd] median max Connect: 4 10 6.5 8 42 Processing: 5 14 8.1 12 45 Waiting: 4 14 8.1 12 45 Total: 9 24 10.8 21 56 Percentage of the requests served within a certain time (ms) 50% 21 66% 24 75% 25 80% 27 90% 41 95% 52 98% 56 99% 56 100% 56 (longest request)
#13 Updated by Gah Gneh over 1 year ago
Windows 7 x64, 6GB RAM, Intel i3 2.53Ghz.
C:\Users\Webdev\Apache2\bin>httpd -v Server version: Apache/2.2.22 (Win32) Server built: May 13 2012 13:32:42 C:\Users\Webdev\Apache2\bin>php -v PHP 5.3.17 (cli) (built: Sep 13 2012 00:33:20) Copyright (c) 1997-2012 The PHP Group Zend Engine v2.3.0, Copyright (c) 1998-2012 Zend Technologies
the results ApacheBench:
C:\Users\Webdev\Apache2\bin>ab -n100 -c10 http://127.0.0.1/kohana3.3/ 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 127.0.0.1 (be patient).....done Server Software: Apache/2.2.22 Server Hostname: 127.0.0.1 Server Port: 80 Document Path: /kohana3.3/ Document Length: 13 bytes Concurrency Level: 10 Time taken for tests: 55.511 seconds Complete requests: 100 Failed requests: 0 Write errors: 0 Total transferred: 16000 bytes HTML transferred: 1300 bytes Requests per second: 1.80 [#/sec] (mean) Time per request: 5551.089 [ms] (mean) Time per request: 555.109 [ms] (mean, across all concurrent requests) Transfer rate: 0.28 [Kbytes/sec] received Connection Times (ms) min mean[+/-sd] median max Connect: 0 0 1.6 0 16 Processing: 5517 5543 29.2 5535 5660 Waiting: 16 30 30.1 20 151 Total: 5517 5543 29.5 5535 5660 Percentage of the requests served within a certain time (ms) 50% 5535 66% 5540 75% 5550 80% 5551 90% 5553 95% 5629 98% 5660 99% 5660 100% 5660 (longest request)
JMeter otherwise, shows a good result around 89 reqs/sec: http://pastebin.com/raw.php?i=TgAUqKVK
#14 Updated by Dominik Chvila over 1 year ago
I just updated to K3.3 and noticed a strange behavior with '->send_headers(TRUE)'.
On local Win7 x64 or local Ubuntu Linux in VMWare is everything OK (I did not test performance issue as above, however I didn't catch any slow down), but on live Linux server (on virtual hosting) when the '->send_headers(TRUE)
' is not commented out then on the page of web there is printed "26cc", or "2827", or "db30" etc. as first line before all output and after all output is printed 0. The same happens when fatal error occures.
Any idea or hints how to solve this? Btw is there any document expaining the reason of send_headers in this place?
I can provide more info if someone will request for it ;-)
#16 Updated by thejw23 . over 1 year ago
Exact same issue is discussed here: http://help.slimframework.com/discussions/problems/24-high-loading-times-in-apache-bench
Mentioned there -k parameter make ab as fast as it should be.
The discussion goes there a bit further: "It seems, that the trailing space after the status code leads to this behavior, just removing the space solves the Problem", or "ab -H 'Connection: close'"... I didn't check that, just '-k'.
#17 Updated by Robert-Jan Dreu -rjd22- about 1 year ago
That would mean that the following line in kohana is causing this: https://github.com/kohana/core/blob/3.3/master/classes/Kohana/HTTP/Header.php#L872
IMO I think we should not fix this. This is clearly an error of the benchmarking tool not an error on the Kohana side (is it even valid to delete the space? O_o)
#18 Updated by Lorenzo Pisani about 1 year ago
- Status changed from New to Feedback
- Assignee set to Lorenzo Pisani
It sounds like this is a bug with ab to me. Leaving open for feedback now but will close it unless someone can find a real fix for us. The slim guys seems to have come to the same conclusion. From reading their thread, the removal of the space was not a real fix.
I don't really see a need to spend much time on this if it's only happening with ab and not with any real traffic.