Varnish 4 and 5. Log slow backend requests

Here is quick top on how to log slow backend requests with varnishncsa. You can monitor URL and backend name used to fulfil requests:

At the top of you main VCL file add:

import std;

Adjust your vcl_backend_response procedure.

sub vcl_backend_response {
   std.log("backend:" + beresp.backend.name);
}

Monitor slow requests:

varnishncsa -b -F '%t "%r" %s %{Varnish:time_firstbyte}x %{VCL_Log:backend}x' | awk '$7 > 3 {print}'

The above command will log only backend requests which take more than 3 seconds to complete.

Explanation of command.

The default mode of varnishncsa is “client mode”. Which is why we are switching the mode to backend using the -b switch. We are interested in only backend requests.

We log time to first byte via %{Varnish:time_firstbyte}x. It is time from the request was sent to the backend to the entire header had been received. This falls into our definition of backend processing time. Additionally it allows us milliseconds resolutions in our slow log query, i.e.:

varnishncsa -b -F '%t "%r" %s %{Varnish:time_firstbyte}x %{VCL_Log:backend}x' | awk '$7 > 0.3 {print}'

Here we are logging slow backend requests which take longer than 300ms.

Wait. Who needs awk? Use VSL query!

Instead of using awk, we are better off using VSL to filter slow backend requests:

varnishncsa -b -F '%t "%r" %s %{Varnish:time_firstbyte}x %{VCL_Log:backend}x' -q "Timestamp:Beresp[3] > 3 or Timestamp:Error[3] > 3"

For Varnish below 4.1.5 (untested)

The above approach for logging slow backend requests will not work with Varnish versions earlier than 4.1.5. There is no -b switch to log backend requests only and varnishncsa will log all transactions. So for earlier Varnish versions, the approach to VCL changes will be different:

sub vcl_recv {
   # after all the code, put:
   std.log("backend:" + req.backend_hint);
}

Now, log slow backend requests like this:

varnishncsa -F '%t "%r" %s %{Varnish:time_firstbyte}x %{VCL_Log:backend}x' -q "Timestamp:Beresp[3] > 3 or Timestamp:Error[3] > 3"