Troubleshooting / Varnish

Varnish 4 and 5. Log slow backend requests

by , , revisited on

We have by far the largest RPM repository with NGINX module packages and VMODs for Varnish. If you want to install NGINX, Varnish, and lots of useful performance/security software with smooth yum upgrades for production use, this is the repository for you.
Active subscription is required.

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"

Leave a Reply

Your email address will not be published. Required fields are marked *

You may use these HTML tags and attributes:

<a href="" title=""> <abbr title=""> <acronym title=""> <b> <blockquote cite=""> <cite> <code> <del datetime=""> <em> <i> <q cite=""> <s> <strike> <strong>

This site uses Akismet to reduce spam. Learn how your comment data is processed.