[prev in list] [next in list] [prev in thread] [next in thread]
List: varnish-misc
Subject: HTTP/304 response from backend takes 15s to be returned to client
From: adi () netstyle ! ch (Adrian Lienhard)
Date: 2011-02-28 16:37:30
Message-ID: 06A6970D-AAA7-4AEC-9B5B-02649040CA61 () netstyle ! ch
[Download RAW message or body]
Hi Wido,
Thanks for the response. Upgrading to 2.1.5 indeed fixed the problem.
Cheers,
Adrian
On Feb 23, 2011, at 15:35 , Wido den Hollander wrote:
> Hi,
>
> On Wed, 2011-02-23 at 15:28 +0100, Adrian Lienhard wrote:
> > Hi,
> >
> > I'm experiencing a problem with passing conditional client requests that are not \
> > cached. We use Varnish to cache HTML documents. Static files like CSS are not \
> > cached (pass).
> > The relevant bit of vcl_recv trivially is:
> >
> > sub vcl_recv {
> > ...
> > if (req.url ~ "\.(css|js|jpg|jpeg|png|gif|mp3|ogg|flv|swf|pdf)$") {
> > return(pass);
> > }
> > ...
> >
> > If the client sends a conditional request (with If-Modified-Since header) the \
> > backend (Apache) responds with a HTTP/304 as expected.
> > The problem is that in this case it takes Varnish 15 seconds to send the 304 \
> > response to the client (this is consistently reproducible and always 15s plus a \
> > few milliseconds). If, however, the client request is not a conditional request, \
> > everything works as expected.
> > I've also tested with return(lookup) n vcl_recv, which always misses, but the \
> > problem is exactly the same. However if I return(pipe), it works OK.
> > I post the varnishlog of a failing 304 and of a succeeding 200 below (I've \
> > indicated where the 15s delay is). Maybe interesting to know is that I see the \
> > request being logged in Apache immediately. Also Apache works just fine without \
> > Varnish in front.
> > Versions:
> > - varnish-2.1.4 SVN on Debian Squeeze
> > - Apache (running on another host): 2.2.9
> >
>
> There was a fix regarding this in 2.1.5, I suggest you upgrade to that
> version.
>
> Wido
>
> > Any help appreciated.
> >
> > Cheers,
> > Adrian
> >
> > BTW: Should I anyway rather do pipe for static resources that are never cached?
>
> I think pass is fine?
>
> >
> >
> >
> > Conditional request (FAIL)
> > ==========================
> > HTTP/304 response takes 15s
> > -----------------------
> > 12 SessionOpen c 212.103.66.219 6147 :80
> > 12 ReqStart c 212.103.66.219 6147 391596406
> > 12 RxRequest c GET
> > 12 RxURL c /_cmsbox_2.2.13_85/layout/default.css
> > 12 RxProtocol c HTTP/1.1
> > 12 RxHeader c User-Agent: curl/7.19.7 (universal-apple-darwin10.0) \
> > libcurl/7.19.7 OpenSSL/0.9.8l zlib/1.2.3 12 RxHeader c Host: \
> > adrian.cmsbox.biz 12 RxHeader c Accept: */*
> > 12 RxHeader c If-Modified-Since: Wed, 16 Feb 2011 18:05:26 GMT
> > 12 VCL_call c recv
> > 12 VCL_return c pass
> > 12 VCL_call c hash
> > 12 VCL_return c hash
> > 12 VCL_call c pass
> > 12 VCL_return c pass
> > 14 BackendClose - cmsbox
> > 14 BackendOpen b cmsbox 212.103.66.208 55801 212.103.66.211 80
> > 12 Backend c 14 cmsbox cmsbox
> > 14 TxRequest b GET
> > 14 TxURL b /_cmsbox_2.2.13_85/layout/default.css
> > 14 TxProtocol b HTTP/1.1
> > 14 TxHeader b User-Agent: curl/7.19.7 (universal-apple-darwin10.0) \
> > libcurl/7.19.7 OpenSSL/0.9.8l zlib/1.2.3 14 TxHeader b Host: \
> > adrian.cmsbox.biz 14 TxHeader b Accept: */*
> > 14 TxHeader b If-Modified-Since: Wed, 16 Feb 2011 18:05:26 GMT
> > 14 TxHeader b X-Forwarded-For: 212.103.66.219
> > 14 TxHeader b X-Varnish: 391596406
> > =============== Waits 15s here / backend loggs request immediately \
> > =============== 14 RxProtocol b HTTP/1.1
> > 14 RxStatus b 304
> > 14 RxResponse b Not Modified
> > 14 RxHeader b Date: Wed, 23 Feb 2011 13:55:00 GMT
> > 14 RxHeader b Server: Apache/2.2.9 (Debian)
> > 14 RxHeader b ETag: "c46450-8120-49c6a201bc580"
> > 14 RxHeader b Expires: Thu, 23 Feb 2012 13:55:00 GMT
> > 14 RxHeader b Cache-Control: max-age=31536000
> > 14 RxHeader b Vary: Accept-Encoding
> > 12 TTL c 391596406 RFC 31536000 1298469297 0 0 31536000 0
> > 12 VCL_call c fetch
> > 12 VCL_return c pass
> > 12 ObjProtocol c HTTP/1.1
> > 12 ObjStatus c 304
> > 12 ObjResponse c Not Modified
> > 12 ObjHeader c Date: Wed, 23 Feb 2011 13:55:00 GMT
> > 12 ObjHeader c Server: Apache/2.2.9 (Debian)
> > 12 ObjHeader c ETag: "c46450-8120-49c6a201bc580"
> > 12 ObjHeader c Expires: Thu, 23 Feb 2012 13:55:00 GMT
> > 12 ObjHeader c Vary: Accept-Encoding
> > 14 Length b 0
> > 14 BackendClose b cmsbox
> > 12 VCL_call c deliver
> > 12 VCL_return c deliver
> > 12 TxProtocol c HTTP/1.1
> > 12 TxStatus c 304
> > 12 TxResponse c Not Modified
> > 12 TxHeader c Server: Apache/2.2.9 (Debian)
> > 12 TxHeader c Expires: Thu, 23 Feb 2012 13:55:00 GMT
> > 12 TxHeader c Vary: Accept-Encoding
> > 12 TxHeader c Content-Length: 0
> > 12 TxHeader c Date: Wed, 23 Feb 2011 13:55:12 GMT
> > 12 TxHeader c X-Varnish: 391596406
> > 12 TxHeader c Age: 15
> > 12 TxHeader c Via: 1.1 varnish
> > 12 TxHeader c Connection: keep-alive
> > 12 TxHeader c X-Cache-Hits: 0
> > 12 Length c 0
> > 12 ReqEnd c 391596406 1298469297.322397470 1298469312.322380066 0.000116587 \
> > 14.999900818 0.000081778 12 SessionClose c EOF
> > 12 StatSess c 212.103.66.219 6147 15 1 1 0 1 1 269 0
> >
> >
> >
> > Non-conditional request (OK)
> > ============================
> > HTTP/200 response within 100ms or less
> >
> > ------------------------
> > 12 SessionOpen c 212.103.66.219 23833 :80
> > 12 ReqStart c 212.103.66.219 23833 2103978089
> > 12 RxRequest c HEAD
> > 12 RxURL c /_cmsbox_2.2.13_85/layout/default.css
> > 12 RxProtocol c HTTP/1.1
> > 12 RxHeader c User-Agent: curl/7.19.7 (universal-apple-darwin10.0) \
> > libcurl/7.19.7 OpenSSL/0.9.8l zlib/1.2.3 12 RxHeader c Host: \
> > adrian.cmsbox.biz 12 RxHeader c Accept: */*
> > 12 VCL_call c recv
> > 12 VCL_return c lookup
> > 12 VCL_call c hash
> > 12 VCL_return c hash
> > 12 HitPass c 2103978045
> > 12 VCL_call c pass
> > 12 VCL_return c pass
> > 15 BackendClose b cmsbox
> > 15 BackendOpen b cmsbox 212.103.66.208 50035 212.103.66.211 80
> > 12 Backend c 15 cmsbox cmsbox
> > 15 TxRequest b HEAD
> > 15 TxURL b /_cmsbox_2.2.13_85/layout/default.css
> > 15 TxProtocol b HTTP/1.1
> > 15 TxHeader b User-Agent: curl/7.19.7 (universal-apple-darwin10.0) \
> > libcurl/7.19.7 OpenSSL/0.9.8l zlib/1.2.3 15 TxHeader b Host: \
> > adrian.cmsbox.biz 15 TxHeader b Accept: */*
> > 15 TxHeader b X-Forwarded-For: 212.103.66.219
> > 15 TxHeader b X-Varnish: 2103978089
> > 15 RxProtocol b HTTP/1.1
> > 15 RxStatus b 200
> > 15 RxResponse b OK
> > 15 RxHeader b Date: Wed, 23 Feb 2011 09:39:32 GMT
> > 15 RxHeader b Server: Apache/2.2.9 (Debian)
> > 15 RxHeader b Last-Modified: Wed, 16 Feb 2011 18:05:26 GMT
> > 15 RxHeader b ETag: "c46450-8120-49c6a201bc580"
> > 15 RxHeader b Accept-Ranges: bytes
> > 15 RxHeader b Content-Length: 33056
> > 15 RxHeader b Cache-Control: max-age=31536000
> > 15 RxHeader b Expires: Thu, 23 Feb 2012 09:39:32 GMT
> > 15 RxHeader b Vary: Accept-Encoding
> > 15 RxHeader b Content-Type: text/css
> > 12 TTL c 2103978089 RFC 31536000 1298453970 0 0 31536000 0
> > 12 VCL_call c fetch
> > 12 VCL_return c pass
> > 12 ObjProtocol c HTTP/1.1
> > 12 ObjStatus c 200
> > 12 ObjResponse c OK
> > 12 ObjHeader c Date: Wed, 23 Feb 2011 09:39:32 GMT
> > 12 ObjHeader c Server: Apache/2.2.9 (Debian)
> > 12 ObjHeader c Last-Modified: Wed, 16 Feb 2011 18:05:26 GMT
> > 12 ObjHeader c ETag: "c46450-8120-49c6a201bc580"
> > 12 ObjHeader c Content-Length: 33056
> > 12 ObjHeader c Expires: Thu, 23 Feb 2012 09:39:32 GMT
> > 12 ObjHeader c Vary: Accept-Encoding
> > 12 ObjHeader c Content-Type: text/css
> > 15 Length b 0
> > 15 BackendReuse b cmsbox
> > 12 VCL_call c deliver
> > 12 VCL_return c deliver
> > 12 TxProtocol c HTTP/1.1
> > 12 TxStatus c 200
> > 12 TxResponse c OK
> > 12 TxHeader c Server: Apache/2.2.9 (Debian)
> > 12 TxHeader c Last-Modified: Wed, 16 Feb 2011 18:05:26 GMT
> > 12 TxHeader c Content-Length: 33056
> > 12 TxHeader c Expires: Thu, 23 Feb 2012 09:39:32 GMT
> > 12 TxHeader c Vary: Accept-Encoding
> > 12 TxHeader c Content-Type: text/css
> > 12 TxHeader c Date: Wed, 23 Feb 2011 09:39:30 GMT
> > 12 TxHeader c X-Varnish: 2103978089
> > 12 TxHeader c Age: 0
> > 12 TxHeader c Via: 1.1 varnish
> > 12 TxHeader c Connection: keep-alive
> > 12 TxHeader c X-Cache-Hits: 0
> > 12 Length c 0
> > 12 ReqEnd c 2103978089 1298453970.929079056 1298453970.930070400 \
> > 0.000118494 0.000920773 0.000070572 12 Debug c "herding"
> > 12 SessionClose c no request
> > 12 StatSess c 212.103.66.219 23833 0 1 1 0 1 1 333 0
> > 0 ExpKill - 2103978084 -10
> > _______________________________________________
> > varnish-misc mailing list
> > varnish-misc at varnish-cache.org
> > http://www.varnish-cache.org/lists/mailman/listinfo/varnish-misc
>
[prev in list] [next in list] [prev in thread] [next in thread]
Configure |
About |
News |
Add a list |
Sponsored by KoreLogic