New Relic Request Queuing & Varnish Cache

Written by Peter Davies on 14 March 2013.

As written on the New Relic site directly: [Request Queuing]...provides the ability to track the time after a request enters your production infrastructure, before it reaches your application... which is quite convenient but complicated to configure if you have a varnish frontend cache. Additionally they write:

Tracking time spent in request queuing is useful for identifying certain types of performance and scaling problems; for example, if your front end webserver is spending time waiting for application workers to become available, or time spent warming up application workers after a deploy or restart.

Add the following at the top of the VCL file used by your installation of varnish. Mine is in the default Debian folder and is located/called /etc/varnish/magento.vcl:

C{
#include <stdio.h>
#include <stddef.h>
#include <sys/time.h>
}C

Then add in the sub vcl_recv block the following:

if (req.restarts == 0) {
    C{
        struct timeval detail_time;
        gettimeofday(&detail_time,NULL);
        char start[20];
        sprintf(start, "t=%lu%06lu", detail_time.tv_sec, detail_time.tv_usec);
        VRT_SetHdr(sp, HDR_REQ, "\020X-Request-Start:", start, vrt_magic_string_end);
    }C
}

As subsequently commented by several people on other technical blogs, X-Request-Start is not visible normally when examining through firebug for example. The idea is for Varnish to pass to your Application what the real start time of the request was, then New Relic listens for it in your application.

Now test the configuration without affecting the operational varnish:

varnishd -C -f /etc/varnish/magento.vcl | less

Assuming everything goes ok you will see that the compiled VCL is output to screen; if it has an issue with syntax you will see the error on the screen. Once you correct any issues simply restart varnish through your normal means like /etc/init.d/varnish restart.

When Varnish is running you can verify the header exists on live website viewings by using the command:

varnishlog -b -d | grep X-Request | head

This results in the output showing multiple requests containing the header:

root@server:~/# varnishlog -b -d | grep X-Request | head
   13 TxHeader     b X-Request-Start: t=1363274214004225
   13 TxHeader     b X-Request-Start: t=1363274214897701
   13 TxHeader     b X-Request-Start: t=1363274215302754
   13 TxHeader     b X-Request-Start: t=1363274215759020
   13 TxHeader     b X-Request-Start: t=1363274218047802
   13 TxHeader     b X-Request-Start: t=1363274218702690
   14 TxHeader     b X-Request-Start: t=1363274218923975
   15 TxHeader     b X-Request-Start: t=1363274218930915
   16 TxHeader     b X-Request-Start: t=1363274218941068
   17 TxHeader     b X-Request-Start: t=1363274218965959

But more importantly, when viewed in New Relic you get the additional request values in the "Monitoring" -> "Overview" -> "App server response time" graph, displayed like the following diagram. You may need to remove the "Web External", "Database" and "PHP" filters on the graph as at the time of testing the request queuing process was sub < 0.8ms and subsequently couldn't be compared to the other values - a good sign that varnish was doing a good job. I would be intrigued to find out whether "pound" had any impact on the response times, either positive or negative - maybe a test for another day.

Notes & References:

< Prev Next >