Mailing List Archive

Hello all, First sorry for the long email.
I have a strange issue with varnish. At least I think it is strange.

We start some tests with varnish, but we have an issue.

I am running varnish 4.1.6 on FreeBSD 11.1-prerelease. Where varnish
listen on port 82 and apache on 80, This is just for the tests.
We use the following start options.

# Varnish
varnishd_enable="YES"
varnishd_listen="192.168.2.247:82"
varnishd_pidfile="/var/run/varnishd.pid"
varnishd_storage="default=malloc,2024M"
varnishd_config="/usr/local/etc/varnish/default.vcl"
varnishd_hash="critbit"
varnishd_admin=":6082"
varnishncsa_enable="YES"

We did a test with a static page and that went fine. First we see it is
not cached, second attempt is cached.

root@desk:~ # curl -I www.testdomain.nl:82/info.html
HTTP/1.1 200 OK
Date: Fri, 02 Jun 2017 09:19:52 GMT
Last-Modified: Thu, 01 Jun 2017 12:50:37 GMT
ETag: "cf4-550e57bc1f812"
Content-Length: 3316
Content-Type: text/html
cache-control: max-age = 259200
X-Varnish: 2
Age: 0
Via: 1.1 varnish-v4
Server: varnish
X-Powered-By: My Varnish
X-Cache: MISS
Accept-Ranges: bytes
Connection: keep-alive

root@desk:~ # curl -I www.testdomain.nl:82/info.html
HTTP/1.1 200 OK
Date: Fri, 02 Jun 2017 09:19:52 GMT
Last-Modified: Thu, 01 Jun 2017 12:50:37 GMT
ETag: "cf4-550e57bc1f812"
Content-Length: 3316
Content-Type: text/html
cache-control: max-age = 259200
X-Varnish: 5 3
Age: 6
Via: 1.1 varnish-v4
Server: varnish
X-Powered-By: My Varnish
X-Cache: HIT
Accept-Ranges: bytes
Connection: keep-alive

if I benchmark the server I get the following.
First is derectly to Apache

root@testserver:~ # bombardier -c400 -n10000
http://www.testdomain.nl/info.html
Bombarding http://www.testdomain.nl/info.html with 10000 requests using
400 connections
10000 / 10000
[=============================================================] 100.00% 0s
Done!
Statistics Avg Stdev Max
Reqs/sec 12459.00 898.32 13301
Latency 31.04ms 25.28ms 280.90ms
HTTP codes:
1xx - 0, 2xx - 10000, 3xx - 0, 4xx - 0, 5xx - 0
others - 0
Throughput: 42.16MB/s

This is via varnish. So that works as intended.
Varnish does its job and servers the page better.

root@testserver:~ # bombardier -c400 -n10000
http://www.testdomain.nl:82/info.html
Bombarding http://www.testdomain.nl:82/info.html with 10000 requests
using 400 connections
10000 / 10000
[=============================================================] 100.00% 0s
Done!
Statistics Avg Stdev Max
Reqs/sec 19549.00 7649.32 24313
Latency 17.90ms 66.77ms 485.07ms
HTTP codes:
1xx - 0, 2xx - 10000, 3xx - 0, 4xx - 0, 5xx - 0
others - 0
Throughput: 71.58MB/s


The next one is against a info.php file, which runs phpinfo();

So first agains the server without varnish.

root@testserver:~ # bombardier -c400 -n10000
http://www.testdomain.nl/info.php
Bombarding http://www.testdomain.nl/info.php with 10000 requests using
400 connections
10000 / 10000
[============================================================] 100.00% 11s
Done!
Statistics Avg Stdev Max
Reqs/sec 828.00 127.66 1010
Latency 472.10ms 59.10ms 740.43ms
HTTP codes:
1xx - 0, 2xx - 10000, 3xx - 0, 4xx - 0, 5xx - 0
others - 0
Throughput: 75.51MB/s

But then against the server with varnish.
So we make sure it is in cache

root@desk:~ # curl -I www.testdomain.nl:82/info.php
HTTP/1.1 200 OK
Date: Fri, 02 Jun 2017 09:36:16 GMT
Content-Type: text/html; charset=UTF-8
cache-control: max-age = 259200
X-Varnish: 7
Age: 0
Via: 1.1 varnish-v4
Server: varnish
X-Powered-By: My Varnish
X-Cache: MISS
Accept-Ranges: bytes
Connection: keep-alive

root@desk:~ # curl -I www.testdomain.nl:82/info.php
HTTP/1.1 200 OK
Date: Fri, 02 Jun 2017 09:36:16 GMT
Content-Type: text/html; charset=UTF-8
cache-control: max-age = 259200
X-Varnish: 10 8
Age: 2
Via: 1.1 varnish-v4
Server: varnish
X-Powered-By: My Varnish
X-Cache: HIT
Accept-Ranges: bytes
Connection: keep-alive

So it is in cache now.
root@testserver:~ # bombardier -c400 -n10000
http://www.testdomain.nl:82/info.php
Bombarding http://www.testdomain.nl:82/info.php with 10000 requests
using 400 connections
10000 / 10000
[===========================================================================================================================================================================================================]
100.00% 8s
Done!
Statistics Avg Stdev Max
Reqs/sec 1179.00 230.77 1981
Latency 219.94ms 340.29ms 2.00s
HTTP codes:
1xx - 0, 2xx - 9938, 3xx - 0, 4xx - 0, 5xx - 0
others - 62
Errors:
dialing to the given TCP address timed out - 62
Throughput: 83.16MB/s

I expected this to be much more in favour of varnish, but it even
generated some errors! Time taken is lower but I expected it to be much
faster. Also the 62 errors is not good i guess.

I do see the following with varnish log
* << Request >> 11141123
- Begin req 1310723 rxreq
- Timestamp Start: 1496396250.098654 0.000000 0.000000
- Timestamp Req: 1496396250.098654 0.000000 0.000000
- ReqStart 192.168.2.39 14818
- ReqMethod GET
- ReqURL /info.php
- ReqProtocol HTTP/1.1
- ReqHeader User-Agent: fasthttp
- ReqHeader Host: www.testdomain.nl:82
- ReqHeader X-Forwarded-For: 192.168.2.39
- VCL_call RECV
- ReqUnset X-Forwarded-For: 192.168.2.39
- ReqHeader X-Forwarded-For: 192.168.2.39, 192.168.2.39
- VCL_return hash
- VCL_call HASH
- VCL_return lookup
- Hit 8
- VCL_call HIT
- VCL_return deliver
- RespProtocol HTTP/1.1
- RespStatus 200
- RespReason OK
- RespHeader Date: Fri, 02 Jun 2017 09:36:16 GMT
- RespHeader Server: Apache/2.4.25 (FreeBSD) OpenSSL/1.0.2l
- RespHeader X-Powered-By: PHP/7.0.19
- RespHeader Content-Type: text/html; charset=UTF-8
- RespHeader cache-control: max-age = 259200
- RespHeader X-Varnish: 11141123 8
- RespHeader Age: 73
- RespHeader Via: 1.1 varnish-v4
- VCL_call DELIVER
- RespUnset Server: Apache/2.4.25 (FreeBSD) OpenSSL/1.0.2l
- RespHeader Server: varnish
- RespUnset X-Powered-By: PHP/7.0.19
- RespHeader X-Powered-By: My Varnish
- RespHeader X-Cache: HIT
- VCL_return deliver
- Timestamp Process: 1496396250.098712 0.000058 0.000058
- RespHeader Accept-Ranges: bytes
- RespHeader Content-Length: 95200
- Debug "RES_MODE 2"
- RespHeader Connection: keep-alive
*- Debug "Hit idle send timeout, wrote = 89972/95508; retrying"**
**- Debug "Write error, retval = -1, len = 5536, errno =
Resource temporarily unavailable"*
- Timestamp Resp: 1496396371.131526 121.032872 121.032814
- ReqAcct 82 0 82 308 95200 95508
- End

Sometimes I see this Debug line also - *Debug "Write error,
retval = -1, len = 95563, errno = Broken pipe"*


I also installed varnish 5.1.2 but the results are the same.
Is there something I miss?

My vcl file is pretty basic.

https://pastebin.com/rbb42x7h

Thanks all for your time.

regards
Johan