httpd-bugs mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From bugzi...@apache.org
Subject [Bug 53693] New: mod_fcgid performance suffers under request concurrency (serialization of requests)
Date Fri, 10 Aug 2012 23:47:40 GMT
https://issues.apache.org/bugzilla/show_bug.cgi?id=53693

          Priority: P2
            Bug ID: 53693
          Assignee: bugs@httpd.apache.org
           Summary: mod_fcgid performance suffers under request
                    concurrency (serialization of requests)
          Severity: normal
    Classification: Unclassified
          Reporter: xyntrix@bitz.org
          Hardware: PC
            Status: NEW
           Version: 2.2-HEAD
         Component: mod_fcgid
           Product: Apache httpd-2

https://gist.github.com/3318709


I wrote a simple PHP script to simulate activity (sleep for 500ms).  I set up a
vhost to handle PHP requests via mod_fcgid. I 
- used PHP5.2, PHP5.3, PHP5.4 -- doesn't seem to matter. 
- used the latest trunk snapshot of mod_fcgid (2.3.8), and that didn't change
behavior 
- used Apache 2.2.22 (and 2.2.17) with both worker and prefork mpms
- httpd is configured with 512 StartServers and at least 1024 MaxClients

Trying to figure out how to prevent serialized blocking of requests  in
mod_fcgid.

What seems to happen is mod_fcgid on initial process spin-up won't tune the
number of available of child processes to handle the concurrent request load.. 
there is a serialization that occurs.  I have tried turning a number of the
spawn parameters to try to spin up more at once.. and I can't seem to make it
happen.

So here's an extreme case of 100 concurrent clients with 1 requests to be made,
each:

Concurrency Level:      100
Time taken for tests:   5.672 seconds
Complete requests:      100
Failed requests:        0
Write errors:           0
Total transferred:      15600 bytes
HTML transferred:       0 bytes
Requests per second:    17.63 [#/sec] (mean)
Time per request:       5671.918 [ms] (mean)
Time per request:       56.719 [ms] (mean, across all concurrent requests)
Transfer rate:          2.69 [Kbytes/sec] received

Connection Times (ms)
              min  mean[+/-sd] median   max
Connect:        4    8   2.1      8      10
Processing:   614 2956 1604.2   2665    5661
Waiting:      614 2956 1604.2   2664    5661
Total:        618 2963 1604.1   2674    5671

Percentage of the requests served within a certain time (ms)
  50%   2674
  66%   3612
  75%   4540
  80%   4627
  90%   5633
  95%   5634
  98%   5668
  99%   5671
 100%   5671 (longest request)


The process spin up for this over time looks like:
Fri Aug 10 16:37:19 MST 2012
USER       PID %CPU %MEM    VSZ   RSS TTY      STAT START   TIME COMMAND
apache    3571  0.0  0.3  57004  8040 ?        R    16:37   0:00
/usr/bin/php-cgi
apache    3572  0.0  0.4  57132  8412 ?        S    16:37   0:00
/usr/bin/php-cgi
apache    3573  0.0  0.4  57132  8412 ?        S    16:37   0:00
/usr/bin/php-cgi
apache    3574  0.0  0.4  57132  8412 ?        S    16:37   0:00
/usr/bin/php-cgi
apache    3575  0.0  0.3  56872  7928 ?        R    16:37   0:00
/usr/bin/php-cgi
apache    3576  0.0  0.3  56872  7832 ?        R    16:37   0:00
/usr/bin/php-cgi
apache    3577  0.0  0.3  56872  7868 ?        R    16:37   0:00
/usr/bin/php-cgi
apache    3578  0.0  0.3  56744  7808 ?        R    16:37   0:00
/usr/bin/php-cgi
apache    3580  0.0  0.0   8112   384 ?        R    16:37   0:00
/usr/bin/php-cgi
10
Fri Aug 10 16:37:19 MST 2012
Fri Aug 10 16:37:19 MST 2012
USER       PID %CPU %MEM    VSZ   RSS TTY      STAT START   TIME COMMAND
apache    3571  6.0  0.4  57132  8412 ?        S    16:37   0:00
/usr/bin/php-cgi
apache    3572  5.0  0.4  57132  8412 ?        S    16:37   0:00
/usr/bin/php-cgi
apache    3573  6.0  0.4  57132  8412 ?        S    16:37   0:00
/usr/bin/php-cgi
apache    3574  5.0  0.4  57132  8412 ?        S    16:37   0:00
/usr/bin/php-cgi
apache    3575  6.0  0.4  57132  8412 ?        S    16:37   0:00
/usr/bin/php-cgi
apache    3576  6.0  0.4  57132  8416 ?        S    16:37   0:00
/usr/bin/php-cgi
apache    3577  6.0  0.4  57132  8412 ?        S    16:37   0:00
/usr/bin/php-cgi
apache    3578  6.0  0.4  57132  8416 ?        S    16:37   0:00
/usr/bin/php-cgi
apache    3580  6.0  0.4  57132  8416 ?        S    16:37   0:00
/usr/bin/php-cgi
apache    3582  5.0  0.4  57132  8408 ?        S    16:37   0:00
/usr/bin/php-cgi
10
Fri Aug 10 16:37:19 MST 2012
Fri Aug 10 16:37:19 MST 2012
USER       PID %CPU %MEM    VSZ   RSS TTY      STAT START   TIME COMMAND
apache    3571  6.0  0.4  57132  8412 ?        S    16:37   0:00
/usr/bin/php-cgi
apache    3572  5.0  0.4  57132  8412 ?        S    16:37   0:00
/usr/bin/php-cgi
apache    3573  6.0  0.4  57132  8412 ?        S    16:37   0:00
/usr/bin/php-cgi
apache    3574  5.0  0.4  57132  8412 ?        S    16:37   0:00
/usr/bin/php-cgi
apache    3575  6.0  0.4  57132  8412 ?        S    16:37   0:00
/usr/bin/php-cgi
apache    3576  6.0  0.4  57132  8416 ?        S    16:37   0:00
/usr/bin/php-cgi
apache    3577  6.0  0.4  57132  8412 ?        S    16:37   0:00
/usr/bin/php-cgi
apache    3578  6.0  0.4  57132  8416 ?        S    16:37   0:00
/usr/bin/php-cgi
apache    3580  6.0  0.4  57132  8416 ?        S    16:37   0:00
/usr/bin/php-cgi
apache    3582  5.0  0.4  57132  8408 ?        S    16:37   0:00
/usr/bin/php-cgi
10
Fri Aug 10 16:37:19 MST 2012
Fri Aug 10 16:37:19 MST 2012
USER       PID %CPU %MEM    VSZ   RSS TTY      STAT START   TIME COMMAND
apache    3571  6.0  0.4  57132  8412 ?        S    16:37   0:00
/usr/bin/php-cgi
apache    3572  5.0  0.4  57132  8412 ?        S    16:37   0:00
/usr/bin/php-cgi
apache    3573  6.0  0.4  57132  8412 ?        S    16:37   0:00
/usr/bin/php-cgi
apache    3574  5.0  0.4  57132  8412 ?        S    16:37   0:00
/usr/bin/php-cgi
apache    3575  6.0  0.4  57132  8412 ?        S    16:37   0:00
/usr/bin/php-cgi
apache    3576  6.0  0.4  57132  8416 ?        S    16:37   0:00
/usr/bin/php-cgi
apache    3577  6.0  0.4  57132  8412 ?        S    16:37   0:00
/usr/bin/php-cgi
apache    3578  6.0  0.4  57132  8416 ?        S    16:37   0:00
/usr/bin/php-cgi
apache    3580  6.0  0.4  57132  8416 ?        S    16:37   0:00
/usr/bin/php-cgi
apache    3582  5.0  0.4  57132  8408 ?        S    16:37   0:00
/usr/bin/php-cgi
10
Fri Aug 10 16:37:19 MST 2012
...
Fri Aug 10 16:37:23 MST 2012
USER       PID %CPU %MEM    VSZ   RSS TTY      STAT START   TIME COMMAND
apache    3571  1.2  0.4  57132  8480 ?        S    16:37   0:00
/usr/bin/php-cgi
apache    3572  1.0  0.4  57132  8480 ?        S    16:37   0:00
/usr/bin/php-cgi
apache    3573  1.2  0.4  57132  8480 ?        S    16:37   0:00
/usr/bin/php-cgi
apache    3574  1.2  0.4  57132  8480 ?        S    16:37   0:00
/usr/bin/php-cgi
apache    3575  1.2  0.4  57132  8480 ?        S    16:37   0:00
/usr/bin/php-cgi
apache    3576  1.2  0.4  57132  8484 ?        S    16:37   0:00
/usr/bin/php-cgi
apache    3577  1.2  0.4  57132  8480 ?        S    16:37   0:00
/usr/bin/php-cgi
apache    3578  1.2  0.4  57132  8484 ?        S    16:37   0:00
/usr/bin/php-cgi
apache    3580  1.2  0.4  57132  8484 ?        S    16:37   0:00
/usr/bin/php-cgi
apache    3582  1.0  0.4  57132  8476 ?        S    16:37   0:00
/usr/bin/php-cgi
apache    3657  1.5  0.4  57132  8484 ?        S    16:37   0:00
/usr/bin/php-cgi
apache    3706  2.0  0.4  57132  8480 ?        S    16:37   0:00
/usr/bin/php-cgi
apache    3760  3.5  0.4  57132  8480 ?        S    16:37   0:00
/usr/bin/php-cgi
apache    3816  6.0  0.4  57132  8408 ?        S    16:37   0:00
/usr/bin/php-cgi
14

It takes at least 4 seconds to spin up to 14 processes (well under our
concurrent connection limit). 

On a very small scale, I ran some tests to simulate this:

test.php script:

usleep(500000);
echo $_SERVER['SCRIPT_FILENAME']." :: ".$_SERVER['SERVER_NAME'];

With this script, each run should take ~500ms plus some very minor overhead.

o Loaded Apache with the worker MPM.. Used ab concurrency level of 2, feeding
10 requests, we see a bottleneck due to this serialization:

Concurrency Level:      2
Time taken for tests:   3.116 seconds
Complete requests:      10
Failed requests:        0
Write errors:           0
Total transferred:      1560 bytes
HTML transferred:       0 bytes
Requests per second:    3.21 [#/sec] (mean)
Time per request:       623.257 [ms] (mean)
Time per request:       311.628 [ms] (mean, across all concurrent requests)
Transfer rate:          0.49 [Kbytes/sec] received

Connection Times (ms)
              min  mean[+/-sd] median   max
Connect:        3    3   0.2      3       3
Processing:   504  619 336.6    505    1574
Waiting:      504  619 336.6    505    1574
Total:        507  622 336.6    508    1577

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

o Once the processes are spun up however, we see 500ms (+~10ms overhead) for
all requests as long as our concurrency does not exceed the number of child
processes available

USER       PID %CPU %MEM    VSZ   RSS TTY      STAT START   TIME COMMAND
apache   30209  0.0  0.4  57132  8488 ?        S    15:30   0:00
/usr/bin/php-cgi
apache   30214  0.0  0.4  57132  8480 ?        S    15:30   0:00
/usr/bin/php-cgi


Concurrency Level:      2
Time taken for tests:   2.546 seconds
Complete requests:      10
Failed requests:        0
Write errors:           0
Total transferred:      1560 bytes
HTML transferred:       0 bytes
Requests per second:    3.93 [#/sec] (mean)
Time per request:       509.200 [ms] (mean)
Time per request:       254.600 [ms] (mean, across all concurrent requests)
Transfer rate:          0.60 [Kbytes/sec] received

Connection Times (ms)
              min  mean[+/-sd] median   max
Connect:        3    3   0.1      3       3
Processing:   504  506   1.7    505     509
Waiting:      504  506   1.7    505     509
Total:        507  508   1.7    508     512

Percentage of the requests served within a certain time (ms)
  50%    508
  66%    509
  75%    509
  80%    511
  90%    512
  95%    512
  98%    512
  99%    512
 100%    512 (longest request)

o Adding +1 concurrency level (taking concurrency to 3), we produce a
serializing bottleneck again:

USER       PID %CPU %MEM    VSZ   RSS TTY      STAT START   TIME COMMAND
apache   30209  0.0  0.4  57132  8488 ?        S    15:30   0:00
/usr/bin/php-cgi
apache   30214  0.0  0.4  57132  8484 ?        S    15:30   0:00
/usr/bin/php-cgi
apache   31866  1.2  0.4  57132  8488 ?        S    15:34   0:00
/usr/bin/php-cgi

Concurrency Level:      3
Time taken for tests:   2.083 seconds
Complete requests:      10
Failed requests:        0
Write errors:           0
Total transferred:      1560 bytes
HTML transferred:       0 bytes
Requests per second:    4.80 [#/sec] (mean)
Time per request:       625.025 [ms] (mean)
Time per request:       208.342 [ms] (mean, across all concurrent requests)
Transfer rate:          0.73 [Kbytes/sec] received

Connection Times (ms)
              min  mean[+/-sd] median   max
Connect:        3    3   0.2      3       3
Processing:   504  612 337.9    505    1573
Waiting:      504  612 337.9    505    1573
Total:        507  615 337.9    508    1576

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

o And again, at 3 concurrency since 3 already spun up processes, no bottleneck:

USER       PID %CPU %MEM    VSZ   RSS TTY      STAT START   TIME COMMAND
apache   30209  0.0  0.4  57132  8488 ?        S    15:30   0:00
/usr/bin/php-cgi
apache   30214  0.0  0.4  57132  8484 ?        S    15:30   0:00
/usr/bin/php-cgi
apache   31866  1.2  0.4  57132  8488 ?        S    15:34   0:00
/usr/bin/php-cgi


Concurrency Level:      3
Time taken for tests:   2.032 seconds
Complete requests:      10
Failed requests:        0
Write errors:           0
Total transferred:      1716 bytes
HTML transferred:       0 bytes
Requests per second:    4.92 [#/sec] (mean)
Time per request:       609.480 [ms] (mean)
Time per request:       203.160 [ms] (mean, across all concurrent requests)
Transfer rate:          0.82 [Kbytes/sec] received

Connection Times (ms)
              min  mean[+/-sd] median   max
Connect:        3    3   0.2      3       3
Processing:   504  505   0.5    505     506
Waiting:      504  505   0.5    505     506
Total:        507  508   0.5    508     508

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

-- 
You are receiving this mail because:
You are the assignee for the bug.

---------------------------------------------------------------------
To unsubscribe, e-mail: bugs-unsubscribe@httpd.apache.org
For additional commands, e-mail: bugs-help@httpd.apache.org


Mime
View raw message