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

Adrian Lienhard adi at netstyle.ch
Mon Feb 28 17:37:30 CET 2011


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
> 





More information about the varnish-misc mailing list