Logging cache hits and misses

One of the first things you’ll 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#

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 cache hit where the object TTL has elapsed, but is 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: a synthetic object created 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 save it as /etc/varnish/hit-miss.vcl and include it:

vcl 4.0;

import std;

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

How to use#

From the client#

You’ll need to uncomment the last line to see this information as a response header. This isn’t done by default, as its output might need to be hidden from regular users.

You can 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
...

Varnishncsa#

varnishncsa grabs information about an HTTP transaction and formats it, usually as a line for easy logging. See man varnishncsa for more information.

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

Varnishlog#

Both varnishlog and varnishncsa` use a powerful VSL query language that allows for versatile filters. See man vsl-query`` for more information about the VSL query language.

For example, you can run the following commands:

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