Logging Hits and Misses Tutorial

One of the first thing you will want to know about your Varnish setup is whether or not content is cached. In this tutorial we’ll provide a vcl snippet to achieve this as well as explain how to leverage it via varnishlog and varnishncsa.

VCL

Code

The code is fairly straightforward:

sub vcl_recv {
	unset req.http.x-cache;
}

sub vcl_hit {
	set req.http.x-cache = "hit";
	if (obj.ttl <= 0s && obj.grace > 0s) {
		set req.http.x-cache = "hit graced";
	}
}

sub vcl_miss {
	set req.http.x-cache = "miss";
}

sub vcl_pass {
	set req.http.x-cache = "pass";
}

sub vcl_pipe {
	set req.http.x-cache = "pipe uncacheable";
}

sub vcl_synth {
	set req.http.x-cache = "synth synth";
	# uncomment the following line to show the information in the response
	# set resp.http.x-cache = req.http.x-cache;
}

sub vcl_deliver {
	if (obj.uncacheable) {
		set req.http.x-cache = req.http.x-cache + " uncacheable" ;
	} else {
		set req.http.x-cache = req.http.x-cache + " cached" ;
	}
	# uncomment the following line to show the information in the response
	# set resp.http.x-cache = req.http.x-cache;
}

The x-cache header is were we store the information, using two terms that cover slightly different aspect of the content,

The first word can be:

hit: we are delivering an object from the cache
- graced: a hit except the object TTL has elapsed (but still within the grace period) and being served while a refreshed object is being obtained.
miss: the object comes from the backend after failing to find it in the cache.
pass: the object comes from the backend because the request bypassed the cache.
synth: we created a synthetic object on-the-fly to satisfy the request.

The second word will be:

cached: the object will be reused.
uncacheable: the object comes from the backend but will not be reused.
synth: synthetic object.

Installation

You can either copy-paste the above snippet at the top of your vcl file (after the vcl 4.X; statement), or you can save it as /etc/varnish/hit-miss.vcl and include it:

vcl 4.0;

import std;

include "hit-miss.vcl";
...

Using this information

From the client

You’ll need to uncomment the last line to see this information as a response header. This is not done by default as it outputs information that should possibly be hidden from regular users.

You can then use the -i switch in a curl command to see the headers:

$ curl -i http://VARNISHSERVER/

HTTP/1.1 200 OK
Date: Tue, 24 Jul 2018 18:43:16 GMT
Server: Varnish
Content-Type: text/html; charset=utf-8
X-Varnish: 32773
Age: 0
Via: 1.1 varnish
connection: close
x-cache: miss cached
Content-Length: 282
...

Note: Piped responses can’t be modified, so you can’t get the information for them that way.

In varnishncsa

varnishncsa grabs information about an HTTP transaction and formats it, usually as a line for easy logging (man varnishncsa):

# log the full header
varnishncsa -F '<%{x-cache}i> %U %s'

In varnishlog

varnishlog (and varnishncsa) uses a powerful VSL query language (man vsl-query) that allows for versatile filters.

For example, you can:

# only show passes:
varnishlog -q 'ReqHeader:x-cache[1] eq pass'
# only show cached objects
varnishlog -q 'ReqHeader:x-cache[2] eq cached'

*Note: you can apply the same -q arguments to varnishncsa.