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