Very slow responses from backend-requests

[Martin Schuhfuss]

Hi all,

I'm having some problems with a newly installed varnish-server.
Since I'm pretty new to varnish after all, it might be i'm missing something
i currently don't see.

My setup consists of a varnish-server (2.1.4 SVN) sitting in front of an
apache/mod_php-backend.

It seems that nearly any request that is passed on to the backend takes
(more or less) exactly 15sec to complete.
Anything coming from the cache is delivered in no time.
There is, however, no reason I can see since the backend-processing takes
only 82ms.

When an URL is called, it hits the backend immediately which in turn takes
only 82ms to deliver the content - but for some reason it seems to hang
around in varnish for about 15 sec.

I'm left with absolutely no idea where to look for a solution for this
problem and I hope someone here can give me a hint.

Regards, Martin


For reference, here's the VCL used and an example of such a request from the
varnishlog:

# cat /etc/varnish/default.vcl
backend default {
    .host = "127.0.0.1";
    .port = "8080";
}

sub vcl_recv {
    if( req.url ~ "\.(png|jpg|gif|swf|flv|css|js|ico)$" ) {
       unset req.http.cookie;
    }

    if( req.url ~ "^/(downloads|css|js|images)" ) {
       unset req.http.cookie;
    }
}

sub vcl_fetch {
    # http://www.varnish-cache.org/trac/ticket/806
    if (req.request != "HEAD") {
        unset beresp.http.content-length;
    }

    if( req.url ~ "\.(png|jpg|gif|swf|flv|css|js|ico)$") {
        unset beresp.http.set-cookie;
        set beresp.ttl = 900s;
    }
}


# varnishlog -c -o rxurl 'foobar'
   22 SessionOpen  c 123.123.123.123 53337 :80
   22 ReqStart     c 123.123.123.123 53337 1717196682
   22 RxRequest    c GET
   22 RxURL        c /?foobar
   22 RxProtocol   c HTTP/1.1
   22 RxHeader     c Host: example.com
   22 RxHeader     c Connection: keep-alive
   22 RxHeader     c Cache-Control: max-age=0
   22 RxHeader     c Accept:
application/xml,application/xhtml+xml,text/html;q=0.9,text/plain;q=0.8,image/png,*/*;q=0.5
   22 RxHeader     c User-Agent: Mozilla/5.0 (X11; U; Linux i686; en-US)
AppleWebKit/534.10 (KHTML, like Gecko) Ubuntu/10.04 Chromium/8.0.552.18
Chrome/8.0.552.18 Safari/534.10
   22 RxHeader     c Accept-Encoding: gzip,deflate,sdch
   22 RxHeader     c Accept-Language: en-US;q=0.6,en;q=0.4
   22 RxHeader     c Accept-Charset: utf-8;q=0.7,*;q=0.3
   22 RxHeader     c Cookie: foo=649cffb6cebc98dcb50121d68931e26c
   22 VCL_call     c recv pass
   22 VCL_call     c hash hash
   22 VCL_call     c pass pass
   22 Backend      c 26 default default
   22 TTL          c 1717196682 RFC 0 1288655727 1288655727 375007920 0 0
   22 VCL_call     c fetch pass
   22 ObjProtocol  c HTTP/1.1
   22 ObjStatus    c 200
   22 ObjResponse  c OK
   22 ObjHeader    c Date: Mon, 01 Nov 2010 23:55:27 GMT
   22 ObjHeader    c Server: Apache/2.2.9 (Debian) PHP/5.2.6-1+lenny9 with
Suhosin-Patch
   22 ObjHeader    c X-Powered-By: PHP/5.2.6-1+lenny9
   22 ObjHeader    c Expires: Thu, 19 Nov 1981 08:52:00 GMT
   22 ObjHeader    c Pragma: no-cache
   22 ObjHeader    c X-Time: t=1288655727366215 D=82924
   22 ObjHeader    c Vary: Accept-Encoding
   22 ObjHeader    c Content-Encoding: gzip
   22 ObjHeader    c Content-Type: text/html; charset=utf-8
   22 VCL_call     c deliver deliver
   22 TxProtocol   c HTTP/1.1
   22 TxStatus     c 200
   22 TxResponse   c OK
   22 TxHeader     c Server: Apache/2.2.9 (Debian) PHP/5.2.6-1+lenny9 with
Suhosin-Patch
   22 TxHeader     c X-Powered-By: PHP/5.2.6-1+lenny9
   22 TxHeader     c Expires: Thu, 19 Nov 1981 08:52:00 GMT
   22 TxHeader     c Pragma: no-cache
   22 TxHeader     c X-Time: t=1288655727366215 D=82924
   22 TxHeader     c Vary: Accept-Encoding
   22 TxHeader     c Content-Encoding: gzip
   22 TxHeader     c Content-Type: text/html; charset=utf-8
   22 TxHeader     c Content-Length: 6747
   22 TxHeader     c Date: Mon, 01 Nov 2010 23:55:42 GMT
   22 TxHeader     c X-Varnish: 1717196682
   22 TxHeader     c Age: 15
   22 TxHeader     c Via: 1.1 varnish
   22 TxHeader     c Connection: keep-alive
   22 Length       c 6747
   22 ReqEnd       c 1717196682 1288655727.366053343 1288655742.456236839
0.000039101 15.090134859 0.000048637
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <https://www.varnish-cache.org/lists/pipermail/varnish-misc/attachments/20101102/d40fb136/attachment-0003.html>