Object no cached when TTL expires

[Kristian Lyngstol]

On Wed, Jan 12, 2011 at 11:34:54AM -0300, Roberto O. Fernández Crisial wrote:
> Here is the VCL and varnishstats requested. Unfortunatelly the varnishlog
> runs so fast so I can't catch the HIT/MISS logs just for one request.

Then you need to filter it...

> # VCL
> 
> sub vcl_pass {
>     return (pass);
> }

Why define vcl_pass when you only do this? It's just in your way.

> sub vcl_hash {
>     if (req.http.Cookie) {
>         set req.hash += req.http.Cookie;
>     }

Cookies in the hash == misses. We need varnishlog to confirm if your cookie
normalization works or not.

> sub vcl_hit {
>     return (deliver);
> }
> 
> sub vcl_miss {
>     return (fetch);
> }

Don't define these if you aren't doing anything with them. Let the default
VCL do its job.

> sub vcl_fetch {
>     unset beresp.http.Etag;
>     if (!beresp.cacheable) {
>         set beresp.http.X-Cacheable = "NO:Not Cacheable";
>     }
>     elsif(req.http.Cookie ~"(UserID|_session)") {
>         set beresp.http.X-Cacheable = "NO:Got Session";
>         return (pass);

This decision will stick for the hash.

>     }
>     elsif ( beresp.http.Cache-Control ~ "private") {
>         set beresp.http.X-Cacheable = "NO:Cache-Control=private";
>         return (pass);

As will this.

>     }
>     elsif ( beresp.ttl < 1s ) {
>         set beresp.ttl   = 5s;
>         set beresp.grace = 5s;
>         set beresp.http.X-Cacheable = "YES:FORCED";
>     }
>     else {
>         set beresp.http.X-Cacheable = "YES";
>     }
>     if (req.url ~
> "\.(jpg|png|gif|gz|tgz|bz2|tbz|mp3|ogg|flv|swf|mp4|mp3|js|xml)$") {
>         unset beresp.http.set-cookie;
>     }
>     if (beresp.http.Set-Cookie) {
>         return (pass);

And this.

> # varnishstats -1
> 
> client_conn           9514820       148.86 Client connections accepted
> client_drop                 0         0.00 Connection dropped, no sess/wrk
> client_req          102670372      1606.26 Client requests received
> cache_hit            96847567      1515.16 Cache hits
> cache_hitpass         5716515        89.43 Cache hits for pass

90 hitpasses/second is a pretty large number. You are most likely passing
something in vcl_fetch that you really don't want to create a hitpass
object for.

Based on the VCL and varnishstat, this seems like excessive tweaking to VCL
resulting in unexpected passing in vcl_fetch and subsequent creation of
hitpass objects - and there's the cache misses to things you would normally
expect to cache.

Keep in mind that VCL is like most other coding: You're not finished when
there's nothing more you can add - you're finished when there's nothing
more you can remove.

Varnishlog is needed to verify if the theory above is true or not.

- Kristian