Bug Report #4638

Kohana 3.3 slow response with Apache Bench

Added by thejw23 . about 2 years ago. Updated over 1 year ago.

Status:ClosedStart date:10/29/2012
Priority:NormalDue date:
Assignee:Lorenzo Pisani% Done:

0%

Category:Core
Target version:3.3.1
Resolution:invalid Points:1

Description

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.

xdebud and webgrind, raw files: http://www.sendspace.com/file/nrou24 screenshots: http://imgur.com/a/j9y8E#0

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.


Related issues

Related to Kohana v3.x - Bug Report #4661: Output before and after all content, probably chunk size New 11/15/2012

History

#1 Updated by Jeremy Bush about 2 years ago

  • Target version set to 3.3.1

#2 Updated by Dmitry T. about 2 years ago

Yeah, I've got the same results. 1.8rps :(
@Zombor, please raise the issue priority, it's really very important

#3 Updated by Jeremy Bush about 2 years ago

If we can't reliably reproduce it, I have no idea what's going on. I don't experience this and I don't think any other devs do either.

Is the same slowness experienced when you just load the page in a browser?

#4 Updated by Dmitry T. about 2 years ago

Is the same slowness experienced when you just load the page in a browser?

No. Probably it's ab bug, but I think we need to be sure it is.

#5 Updated by Jeremy Bush about 2 years 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 . about 2 years 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

#7 Updated by Jeremy Bush about 2 years ago

Sounds like a problem with ab then?

#8 Updated by thejw23 . about 2 years 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 about 2 years 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)

#10 Updated by thejw23 . about 2 years ago

With Lampstack on VirtualBox? Then it's really strage.
I get those strage AB results on 2 systems, desktop and laptop, on the first one with XAMPP and Lampstack, on second with XAMPP.
Both run on Win7 x64, however Lampstack use Debian...

#11 Updated by Jeremy Bush about 2 years ago

No, this was on my mac running against the built in php server.

#12 Updated by thejw23 . about 2 years ago

Can you try the Lampstack ? It also runs on VMware.

#13 Updated by Gah Gneh almost 2 years ago

For me:

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 almost 2 years ago

Hi all,

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

#15 Updated by Dominik Chvila almost 2 years ago

Dominik Chvila wrote:

Btw is there any document expaining the reason of send_headers in this place?

Sorry, I thought this method is a new feature, but I used it a time before as well to send changed headers...

#16 Updated by thejw23 . almost 2 years 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- over 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 over 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.

#19 Updated by Lorenzo Pisani over 1 year ago

  • Status changed from Feedback to Closed
  • Resolution set to invalid

Closing since no one replied with more comments and ideas.

Also available in: Atom PDF