Logging hits and misses Tutorial

One of the first things you will want to know about your Varnish setup is whether or not your content is cached. In this tutorial, we’ll provide a VCL snippet and 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 where we store the information using two terms that cover slightly different aspects 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 fetched
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.