HTTP/304 response from backend takes 15s to be returned to client

Wido den Hollander wido at widodh.nl
Wed Feb 23 15:35:01 CET 2011


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





More information about the varnish-misc mailing list