Optional symbiosis-httpd-logger package fails under load

[pcammish]

Under high loads with a large number of sites (and therefore large number of instances of the logger), the symbiosis-httpd-logger process stalls and fails to write logs, apparently causing Apache to stall and spin up more processes to deal with the incoming traffic.

A workaround for this seems to be to be to adjust the Apache templates for HTTP/HTTPS sites to log directly to disk, saving the extra processor time and RAM, however this means the logs directories won't be automatically generated (should be fixable in symbiosis-httpd-configure or elsewhere, and log files will not be owned by admin:admin (which is not a huge problem, as they are cycled automatically, and still readable by admin).

[jamielinux]

Golang logger seems to slow the rate that connections can be processed by 20x. ab test takes 7 seconds with Ruby logger and 138 seconds with Golang logger.

ab test on vanilla Symbiosis Jessie (using default Ruby logger):

ab -n 10000 -c 100 http://symbiosis8.test.jnguyen.uk0.bigv.io/
This is ApacheBench, Version 2.3 <$Revision: 1826891 $>
Copyright 1996 Adam Twiss, Zeus Technology Ltd, http://www.zeustech.net/
Licensed to The Apache Software Foundation, http://www.apache.org/

Benchmarking symbiosis8.test.jnguyen.uk0.bigv.io (be patient)
Completed 1000 requests
Completed 2000 requests
Completed 3000 requests
Completed 4000 requests
Completed 5000 requests
Completed 6000 requests
Completed 7000 requests
Completed 8000 requests
Completed 9000 requests
Completed 10000 requests
Finished 10000 requests


Server Software:        Apache
Server Hostname:        symbiosis8.test.jnguyen.uk0.bigv.io
Server Port:            80

Document Path:          /
Document Length:        209 bytes

Concurrency Level:      100
Time taken for tests:   7.571 seconds
Complete requests:      10000
Failed requests:        0
Non-2xx responses:      10000
Total transferred:      3730000 bytes
HTML transferred:       2090000 bytes
Requests per second:    1320.80 [#/sec] (mean)
Time per request:       75.712 [ms] (mean)
Time per request:       0.757 [ms] (mean, across all concurrent requests)
Transfer rate:          481.11 [Kbytes/sec] received

Connection Times (ms)
              min  mean[+/-sd] median   max
Connect:        2    6   1.8      5      17
Processing:    13   70  20.9     63     159
Waiting:        3   69  20.9     63     159
Total:         17   75  20.4     69     162

Percentage of the requests served within a certain time (ms)
  50%     69
  66%     78
  75%     85
  80%     91
  90%    108
  95%    117
  98%    126
  99%    134
 100%    162 (longest request)

After installing golang logger:

$ ab -n 10000 -c 100 http://symbiosis8.test.jnguyen.uk0.bigv.io/
This is ApacheBench, Version 2.3 <$Revision: 1826891 $>
Copyright 1996 Adam Twiss, Zeus Technology Ltd, http://www.zeustech.net/
Licensed to The Apache Software Foundation, http://www.apache.org/

Benchmarking symbiosis8.test.jnguyen.uk0.bigv.io (be patient)
Completed 1000 requests
Completed 2000 requests
Completed 3000 requests
Completed 4000 requests
Completed 5000 requests
Completed 6000 requests
Completed 7000 requests
Completed 8000 requests
Completed 9000 requests
Completed 10000 requests
Finished 10000 requests


Server Software:        Apache
Server Hostname:        symbiosis8.test.jnguyen.uk0.bigv.io
Server Port:            80

Document Path:          /
Document Length:        209 bytes

Concurrency Level:      100
Time taken for tests:   138.132 seconds
Complete requests:      10000
Failed requests:        0
Non-2xx responses:      10000
Total transferred:      3730000 bytes
HTML transferred:       2090000 bytes
Requests per second:    72.39 [#/sec] (mean)
Time per request:       1381.321 [ms] (mean)
Time per request:       13.813 [ms] (mean, across all concurrent requests)
Transfer rate:          26.37 [Kbytes/sec] received

Connection Times (ms)
              min  mean[+/-sd] median   max
Connect:        2    4  17.7      3    1024
Processing:     2 1374 11853.6      3  135906
Waiting:        2 1374 11853.6      3  135906
Total:          4 1377 11853.6      6  135909

Percentage of the requests served within a certain time (ms)
  50%      6
  66%      7
  75%      9
  80%     17
  90%    281
  95%    661
  98%   1026
  99%  57380
 100%  135909 (longest request)

[patch0]

I think this might be explained by the sync flag.

The ruby script logger doesn't seem to be obeying the sync flag, based on tests. When apachebench hits the golang logger I/O wait soars up. Whereas this does not happen under ruby, despite the writes being supposedly synchronous.

I think a fix might be to remove the --sync flag from the apache template.

[jamielinux]

Fixed by 69a6a9e