Mailing List Archive

Varnish bypassing cache when if-modified-since header present?
Hey guys,

I've been playing with varnish for the last few days, trying to eval it as a squid replacement my image serving farm. I enabled it on one of the squids friday (replacing 2 seperate squid processes on a single server), and seen pretty awesome results:

http://boom.net/~mike/squid_vs_varnish.GIF

However, the load on my backend NFS server went up by a substantial amount. I let it run over the weekend thinking it would smooth out once the caches were primed, but to my dismay, this morning nfs load was still the same. After doing some basic debugging, it appears as if the (default) varnish config is always re-validating if-modified-since headers (when supplied by the client), thus bypassing the local cache and hitting the origin server again. My cache objects *never* change, so if a client supplies an if-modified-since header, I'd like the cache to always respond '304 not modified' immediately. I've configured squid to do this, but my vcl-fu is very weak. Before I spent more time investigating the VCL config options, I just wanted a sanity check to make sure it was possible to do this in varnish. At the bottom of this message i've included a small sample of a log file i generated this morning, I could be misreading it completely. Thanks!


ps: the above load graph is from an image server in my production pool, that was spitting out around 150Mb/s of images at the time.

-mike




11 SessionOpen c 10.1.1.9 33194
11 ReqStart c 10.1.1.9 33194 249494004
11 RxRequest c GET
11 RxURL c /85/40/458/tn_4096253716.jpg
11 RxProtocol c HTTP/1.1
11 RxHeader c Accept: */*
11 RxHeader c Accept-Language: en-us
11 RxHeader c Accept-Encoding: gzip, deflate
11 RxHeader c If-Modified-Since: Thu, 23 Feb 2006 00:02:51 GMT
11 RxHeader c If-None-Match: "13c02df-b23-40d6af72600c0"
11 RxHeader c User-Agent: Mozilla/4.0 (compatible; MSIE 6.0; Windows NT 5.1; SV1)
11 RxHeader c Host: a.pc.xyz.com:87
11 RxHeader c Connection: Keep-Alive
11 VCL_call c recv
11 VCL_return c pass
11 VCL_call c pass
11 VCL_return c pass
14 BackendClose default
14 BackendOpen b default 127.0.0.1 33977 127.0.0.1 81
14 BackendXID b 249494004
11 Backend c 14 default
14 TxRequest b GET
14 TxURL b /85/40/458/tn_4096253716.jpg
14 TxProtocol b HTTP/1.1
14 TxHeader b Accept: */*
14 TxHeader b Accept-Language: en-us
14 TxHeader b Accept-Encoding: gzip, deflate
14 TxHeader b User-Agent: Mozilla/4.0 (compatible; MSIE 6.0; Windows NT 5.1; SV1)
14 TxHeader b Host: a.pc.xyz.com:87
14 TxHeader b X-Varnish: 249494004
14 TxHeader b X-Forwarded-for: 10.1.1.9
14 RxProtocol b HTTP/1.1
14 RxStatus b 200
14 RxResponse b OK
14 RxHeader b Date: Mon, 02 Jul 2007 17:59:03 GMT
14 RxHeader b Server: Apache
14 RxHeader b Last-Modified: Thu, 23 Feb 2006 00:02:51 GMT
14 RxHeader b ETag: "13c02df-b23-40d6af72600c0"
14 RxHeader b Accept-Ranges: bytes
14 RxHeader b Content-Length: 2851
14 RxHeader b Content-Type: image/jpeg
11 ObjProtocol c HTTP/1.1
11 ObjStatus c 200
11 ObjResponse c OK
11 ObjHeader c Date: Mon, 02 Jul 2007 17:59:03 GMT
11 ObjHeader c Server: Apache
11 ObjHeader c Last-Modified: Thu, 23 Feb 2006 00:02:51 GMT
11 ObjHeader c ETag: "13c02df-b23-40d6af72600c0"
11 ObjHeader c Content-Type: image/jpeg
11 ObjHeader c Content-Length: 2851
14 BackendReuse b default
11 TTL c 249494004 RFC 3600 1183399143 1183399143 0 0 0
11 VCL_call c fetch
11 VCL_return c insert
11 Length c 0
11 TxProtocol c HTTP/1.1
11 TxStatus c 304
11 TxResponse c Not Modified
11 TxHeader c Date: Mon, 02 Jul 2007 17:59:03 GMT
11 TxHeader c Via: 1.1 varnish
11 TxHeader c X-Varnish: 249494004
11 TxHeader c Last-Modified: Thu, 23 Feb 2006 00:02:51 GMT
11 ReqEnd c 249494004 1183399143.654401000 1183399143.656763000 0.000043000 0.002308000 0.000054000
0 StatAddr 10.1.1.9 0 579 116 68 0 0 13 18505 6270
11 SessionOpen c 10.1.1.9 61746
11 ReqStart c 10.1.1.9 61746 249494005
11 RxRequest c GET
11 RxURL c /85/40/458/tn_4096253716.jpg
11 RxProtocol c HTTP/1.1
11 RxHeader c Accept: */*
11 RxHeader c Accept-Language: en-us
11 RxHeader c Accept-Encoding: gzip, deflate
11 RxHeader c If-Modified-Since: Thu, 23 Feb 2006 00:02:51 GMT
11 RxHeader c If-None-Match: "13c02df-b23-40d6af72600c0"
11 RxHeader c User-Agent: Mozilla/4.0 (compatible; MSIE 6.0; Windows NT 5.1; SV1)
11 RxHeader c Host: a.pc.xyz.com:87
11 RxHeader c Connection: Keep-Alive
11 VCL_call c recv
11 VCL_return c pass
11 VCL_call c pass
11 VCL_return c pass
14 BackendClose b default
14 BackendOpen b default 127.0.0.1 33978 127.0.0.1 81
14 BackendXID b 249494005
11 Backend c 14 default
14 TxRequest b GET
14 TxURL b /85/40/458/tn_4096253716.jpg
14 TxProtocol b HTTP/1.1
14 TxHeader b Accept: */*
14 TxHeader b Accept-Language: en-us
14 TxHeader b Accept-Encoding: gzip, deflate
14 TxHeader b User-Agent: Mozilla/4.0 (compatible; MSIE 6.0; Windows NT 5.1; SV1)
14 TxHeader b Host: a.pc.xyz.com:87
14 TxHeader b X-Varnish: 249494005
14 TxHeader b X-Forwarded-for: 10.1.1.9
14 RxProtocol b HTTP/1.1
14 RxStatus b 200
14 RxResponse b OK
14 RxHeader b Date: Mon, 02 Jul 2007 17:59:21 GMT
14 RxHeader b Server: Apache
14 RxHeader b Last-Modified: Thu, 23 Feb 2006 00:02:51 GMT
14 RxHeader b ETag: "13c02df-b23-40d6af72600c0"
14 RxHeader b Accept-Ranges: bytes
14 RxHeader b Content-Length: 2851
14 RxHeader b Content-Type: image/jpeg
11 ObjProtocol c HTTP/1.1
11 ObjStatus c 200
11 ObjResponse c OK
11 ObjHeader c Date: Mon, 02 Jul 2007 17:59:21 GMT
11 ObjHeader c Server: Apache
11 ObjHeader c Last-Modified: Thu, 23 Feb 2006 00:02:51 GMT
11 ObjHeader c ETag: "13c02df-b23-40d6af72600c0"
11 ObjHeader c Content-Type: image/jpeg
11 ObjHeader c Content-Length: 2851
14 BackendReuse b default
11 TTL c 249494005 RFC 3600 1183399161 1183399161 0 0 0
11 VCL_call c fetch
11 VCL_return c insert
11 Length c 0
11 TxProtocol c HTTP/1.1
11 TxStatus c 304
11 TxResponse c Not Modified
11 TxHeader c Date: Mon, 02 Jul 2007 17:59:21 GMT
11 TxHeader c Via: 1.1 varnish
11 TxHeader c X-Varnish: 249494005
11 TxHeader c Last-Modified: Thu, 23 Feb 2006 00:02:51 GMT
11 ReqEnd c 249494005 1183399161.148634000 1183399161.149295000 0.000041000 0.000607000 0.000054000
0 StatAddr 10.1.1.9 0 597 117 69 0 0 14 18657 6270
Varnish bypassing cache when if-modified-since header present? [ In reply to ]
sorry for the spam, but i just realized the cause of the behavior i was seeing-- the cookie being set. after i modified the default vcl to:

# if (req.http.Authenticate || req.http.Cookie) {
if (req.http.Authenticate) {
pass;
}

it works as expected...

-mike



On Mon, Jul 02, 2007 at 11:22:01AM -0700, Mike Hedlund <mike at boom.net> wrote:

> Hey guys,
>
> I've been playing with varnish for the last few days, trying to eval it as a squid replacement my image serving farm. I enabled it on one of the squids friday (replacing 2 seperate squid processes on a single server), and seen pretty awesome results:
>
> http://boom.net/~mike/squid_vs_varnish.GIF
>
> However, the load on my backend NFS server went up by a substantial amount. I let it run over the weekend thinking it would smooth out once the caches were primed, but to my dismay, this morning nfs load was still the same. After doing some basic debugging, it appears as if the (default) varnish config is always re-validating if-modified-since headers (when supplied by the client), thus bypassing the local cache and hitting the origin server again. My cache objects *never* change, so if a client supplies an if-modified-since header, I'd like the cache to always respond '304 not modified' immediately. I've configured squid to do this, but my vcl-fu is very weak. Before I spent more time investigating the VCL config options, I just wanted a sanity check to make sure it was possible to do this in varnish. At the bottom of this message i've included a small sample of a log file i generated this morning, I could be misreading it completely. Thanks!
>
>
> ps: the above load graph is from an image server in my production pool, that was spitting out around 150Mb/s of images at the time.
>
> -mike
>
>
>
>
> 11 SessionOpen c 10.1.1.9 33194
> 11 ReqStart c 10.1.1.9 33194 249494004
> 11 RxRequest c GET
> 11 RxURL c /85/40/458/tn_4096253716.jpg
> 11 RxProtocol c HTTP/1.1
> 11 RxHeader c Accept: */*
> 11 RxHeader c Accept-Language: en-us
> 11 RxHeader c Accept-Encoding: gzip, deflate
> 11 RxHeader c If-Modified-Since: Thu, 23 Feb 2006 00:02:51 GMT
> 11 RxHeader c If-None-Match: "13c02df-b23-40d6af72600c0"
> 11 RxHeader c User-Agent: Mozilla/4.0 (compatible; MSIE 6.0; Windows NT 5.1; SV1)
> 11 RxHeader c Host: a.pc.xyz.com:87
> 11 RxHeader c Connection: Keep-Alive
> 11 VCL_call c recv
> 11 VCL_return c pass
> 11 VCL_call c pass
> 11 VCL_return c pass
> 14 BackendClose default
> 14 BackendOpen b default 127.0.0.1 33977 127.0.0.1 81
> 14 BackendXID b 249494004
> 11 Backend c 14 default
> 14 TxRequest b GET
> 14 TxURL b /85/40/458/tn_4096253716.jpg
> 14 TxProtocol b HTTP/1.1
> 14 TxHeader b Accept: */*
> 14 TxHeader b Accept-Language: en-us
> 14 TxHeader b Accept-Encoding: gzip, deflate
> 14 TxHeader b User-Agent: Mozilla/4.0 (compatible; MSIE 6.0; Windows NT 5.1; SV1)
> 14 TxHeader b Host: a.pc.xyz.com:87
> 14 TxHeader b X-Varnish: 249494004
> 14 TxHeader b X-Forwarded-for: 10.1.1.9
> 14 RxProtocol b HTTP/1.1
> 14 RxStatus b 200
> 14 RxResponse b OK
> 14 RxHeader b Date: Mon, 02 Jul 2007 17:59:03 GMT
> 14 RxHeader b Server: Apache
> 14 RxHeader b Last-Modified: Thu, 23 Feb 2006 00:02:51 GMT
> 14 RxHeader b ETag: "13c02df-b23-40d6af72600c0"
> 14 RxHeader b Accept-Ranges: bytes
> 14 RxHeader b Content-Length: 2851
> 14 RxHeader b Content-Type: image/jpeg
> 11 ObjProtocol c HTTP/1.1
> 11 ObjStatus c 200
> 11 ObjResponse c OK
> 11 ObjHeader c Date: Mon, 02 Jul 2007 17:59:03 GMT
> 11 ObjHeader c Server: Apache
> 11 ObjHeader c Last-Modified: Thu, 23 Feb 2006 00:02:51 GMT
> 11 ObjHeader c ETag: "13c02df-b23-40d6af72600c0"
> 11 ObjHeader c Content-Type: image/jpeg
> 11 ObjHeader c Content-Length: 2851
> 14 BackendReuse b default
> 11 TTL c 249494004 RFC 3600 1183399143 1183399143 0 0 0
> 11 VCL_call c fetch
> 11 VCL_return c insert
> 11 Length c 0
> 11 TxProtocol c HTTP/1.1
> 11 TxStatus c 304
> 11 TxResponse c Not Modified
> 11 TxHeader c Date: Mon, 02 Jul 2007 17:59:03 GMT
> 11 TxHeader c Via: 1.1 varnish
> 11 TxHeader c X-Varnish: 249494004
> 11 TxHeader c Last-Modified: Thu, 23 Feb 2006 00:02:51 GMT
> 11 ReqEnd c 249494004 1183399143.654401000 1183399143.656763000 0.000043000 0.002308000 0.000054000
> 0 StatAddr 10.1.1.9 0 579 116 68 0 0 13 18505 6270
> 11 SessionOpen c 10.1.1.9 61746
> 11 ReqStart c 10.1.1.9 61746 249494005
> 11 RxRequest c GET
> 11 RxURL c /85/40/458/tn_4096253716.jpg
> 11 RxProtocol c HTTP/1.1
> 11 RxHeader c Accept: */*
> 11 RxHeader c Accept-Language: en-us
> 11 RxHeader c Accept-Encoding: gzip, deflate
> 11 RxHeader c If-Modified-Since: Thu, 23 Feb 2006 00:02:51 GMT
> 11 RxHeader c If-None-Match: "13c02df-b23-40d6af72600c0"
> 11 RxHeader c User-Agent: Mozilla/4.0 (compatible; MSIE 6.0; Windows NT 5.1; SV1)
> 11 RxHeader c Host: a.pc.xyz.com:87
> 11 RxHeader c Connection: Keep-Alive
> 11 VCL_call c recv
> 11 VCL_return c pass
> 11 VCL_call c pass
> 11 VCL_return c pass
> 14 BackendClose b default
> 14 BackendOpen b default 127.0.0.1 33978 127.0.0.1 81
> 14 BackendXID b 249494005
> 11 Backend c 14 default
> 14 TxRequest b GET
> 14 TxURL b /85/40/458/tn_4096253716.jpg
> 14 TxProtocol b HTTP/1.1
> 14 TxHeader b Accept: */*
> 14 TxHeader b Accept-Language: en-us
> 14 TxHeader b Accept-Encoding: gzip, deflate
> 14 TxHeader b User-Agent: Mozilla/4.0 (compatible; MSIE 6.0; Windows NT 5.1; SV1)
> 14 TxHeader b Host: a.pc.xyz.com:87
> 14 TxHeader b X-Varnish: 249494005
> 14 TxHeader b X-Forwarded-for: 10.1.1.9
> 14 RxProtocol b HTTP/1.1
> 14 RxStatus b 200
> 14 RxResponse b OK
> 14 RxHeader b Date: Mon, 02 Jul 2007 17:59:21 GMT
> 14 RxHeader b Server: Apache
> 14 RxHeader b Last-Modified: Thu, 23 Feb 2006 00:02:51 GMT
> 14 RxHeader b ETag: "13c02df-b23-40d6af72600c0"
> 14 RxHeader b Accept-Ranges: bytes
> 14 RxHeader b Content-Length: 2851
> 14 RxHeader b Content-Type: image/jpeg
> 11 ObjProtocol c HTTP/1.1
> 11 ObjStatus c 200
> 11 ObjResponse c OK
> 11 ObjHeader c Date: Mon, 02 Jul 2007 17:59:21 GMT
> 11 ObjHeader c Server: Apache
> 11 ObjHeader c Last-Modified: Thu, 23 Feb 2006 00:02:51 GMT
> 11 ObjHeader c ETag: "13c02df-b23-40d6af72600c0"
> 11 ObjHeader c Content-Type: image/jpeg
> 11 ObjHeader c Content-Length: 2851
> 14 BackendReuse b default
> 11 TTL c 249494005 RFC 3600 1183399161 1183399161 0 0 0
> 11 VCL_call c fetch
> 11 VCL_return c insert
> 11 Length c 0
> 11 TxProtocol c HTTP/1.1
> 11 TxStatus c 304
> 11 TxResponse c Not Modified
> 11 TxHeader c Date: Mon, 02 Jul 2007 17:59:21 GMT
> 11 TxHeader c Via: 1.1 varnish
> 11 TxHeader c X-Varnish: 249494005
> 11 TxHeader c Last-Modified: Thu, 23 Feb 2006 00:02:51 GMT
> 11 ReqEnd c 249494005 1183399161.148634000 1183399161.149295000 0.000041000 0.000607000 0.000054000
> 0 StatAddr 10.1.1.9 0 597 117 69 0 0 14 18657 6270
>
>
>
>
> _______________________________________________
> varnish-misc mailing list
> varnish-misc at projects.linpro.no
> http://projects.linpro.no/mailman/listinfo/varnish-misc
Varnish bypassing cache when if-modified-since header present? [ In reply to ]
In message <20070702182201.GF5005 at boom.net>, Mike Hedlund writes:
>Hey guys,
>
> I've been playing with varnish for the last few days, trying
>to eval it as a squid replacement my image serving farm. I enabled
>it on one of the squids friday (replacing 2 seperate squid processes
>on a single server), and seen pretty awesome results:
>
>http://boom.net/~mike/squid_vs_varnish.GIF

That's a pretty typical experience :-)

>[...] varnish config is always re-validating
>if-modified-since headers (when supplied by the client)[...]

This shouldn't happen, but there is on case where it will: if your
varnish and backend don't agree what time it is.

Could you check that ?

If you want to fill in some debugging look for "res_do_304" in
cache_response.c

--
Poul-Henning Kamp | UNIX since Zilog Zeus 3.20
phk at FreeBSD.ORG | TCP/IP since RFC 956
FreeBSD committer | BSD since 4.3-tahoe
Never attribute to malice what can adequately be explained by incompetence.