Integrate (with minor polishing) patch from Geoff to add a SLT_BereqEnd

record with timing info about the fetch.

Submitted by: Geoff Simmons @ UPLEX

bin/varnishd/cache/cache.h

@@ -579,6 +579,13 @@ struct busyobj {
 	double			first_byte_timeout;
 	double			between_bytes_timeout;
 
+	/* Timers */
+	double			t_start;
+	double			t_send;
+	double			t_sent;
+	double			t_hdr;
+	double			t_body;
+
 	const char		*storage_hint;
 	struct director		*director;
 	struct VCL_conf		*vcl;

bin/varnishd/cache/cache_fetch.c

@@ -586,6 +586,7 @@ vbf_fetch_thread(struct worker *wrk, void *priv)
 {
 	struct busyobj *bo;
 	enum fetch_step stp;
+	double t_hdr, t_body;
 
 	CHECK_OBJ_NOTNULL(wrk, WORKER_MAGIC);
 	CAST_OBJ_NOTNULL(bo, priv, BUSYOBJ_MAGIC);
@@ -593,6 +594,11 @@ vbf_fetch_thread(struct worker *wrk, void *priv)
 
 	THR_SetBusyobj(bo);
 	stp = F_STP_MKBEREQ;
+	bo->t_start = VTIM_real();
+	bo->t_send = NAN;
+	bo->t_sent = NAN;
+	bo->t_hdr = NAN;
+	bo->t_body = NAN;
 
 	while (stp != F_STP_DONE) {
 		CHECK_OBJ_NOTNULL(bo, BUSYOBJ_MAGIC);
@@ -618,6 +624,14 @@ vbf_fetch_thread(struct worker *wrk, void *priv)
 	if (bo->ims_obj != NULL)
 		(void)HSH_DerefObj(&wrk->stats, &bo->ims_obj);
 
+	t_hdr = bo->t_hdr - bo->t_sent;
+	t_body = bo->t_body - bo->t_hdr;
+	VSLb(bo->vsl, SLT_BereqEnd, "%.9f %.9f %.9f %.9f %.9f %.9f",
+	     bo->t_start,
+	     VTIM_real(),
+	     bo->t_sent - bo->t_send,
+	     t_hdr, t_body, t_hdr + t_body);
+
 	VBO_DerefBusyObj(wrk, &bo);
 	THR_SetBusyobj(NULL);
 }

bin/varnishd/cache/cache_http1_fetch.c

@@ -42,6 +42,7 @@
 #include "vcli_priv.h"
 #include "vct.h"
 #include "vtcp.h"
+#include "vtim.h"
 
 /*--------------------------------------------------------------------
  * Convert a string to a size_t safely
@@ -231,6 +232,7 @@ V1F_fetch_hdr(struct worker *wrk, struct busyobj *bo, struct req *req)
 
 	(void)VTCP_blocking(vc->fd);	/* XXX: we should timeout instead */
 	WRW_Reserve(wrk, &vc->fd, bo->vsl, bo->t_fetch);
+	bo->t_send = VTIM_mono();
 	(void)HTTP1_Write(wrk, hp, 0);	/* XXX: stats ? */
 
 	/* Deal with any message-body the request might (still) have */
@@ -257,8 +259,8 @@ V1F_fetch_hdr(struct worker *wrk, struct busyobj *bo, struct req *req)
 		return (retry);
 	}
 
-	/* XXX is this the right place? */
 	VSC_C_main->backend_req++;
+	bo->t_sent = VTIM_mono();
 
 	/* Receive response */
 
@@ -293,6 +295,7 @@ V1F_fetch_hdr(struct worker *wrk, struct busyobj *bo, struct req *req)
 			    vc->between_bytes_timeout);
 		}
 	} while (hs != HTTP1_COMPLETE);
+	bo->t_hdr = VTIM_mono();
 
 	hp = bo->beresp;
 
@@ -381,6 +384,7 @@ V1F_fetch_body(struct worker *wrk, struct busyobj *bo)
 	default:
 		INCOMPL();
 	}
+	bo->t_body = VTIM_mono();
 	AZ(bo->vgz_rx);
 
 	/*

bin/varnishd/cache/cache_http1_fsm.c

@@ -258,7 +258,7 @@ http1_req_body_status(struct req *req)
 		req->h1.bytes_yet = req->req_bodybytes - req->h1.bytes_done;
 		return (REQ_BODY_PRESENT);
 	}
-	if (http_GetHdr(req->http, H_Transfer_Encoding, NULL)) 
+	if (http_GetHdr(req->http, H_Transfer_Encoding, NULL))
 		return (REQ_BODY_FAIL);
 	return (REQ_BODY_NONE);
 }

include/tbl/vsl_tags.h

@@ -119,6 +119,16 @@ SLTM(HttpGarbage, "", "")
 SLTM(Backend, "Backend selected", "")
 SLTM(Length, "Size of object body", "")
 
+SLTM(BereqEnd, "Backend request end",
+	"Marks the end of a backend request.\n\n"
+	"Tstart\n    Timestamp when the fetch started (epoch)\n\n"
+	"Tend\n    Timestamp when the fetch ended (epoch)\n\n"
+	"dTsend\n    Time to send the backend request\n\n"
+	"dThdr\n    Time to receive the backend response headers\n\n"
+	"dTbody\n    Time to receive the backend response body\n\n"
+	"dTresp\n    Time to receive the backend response (dThdr + dTbody)\n\n"
+)
+
 SLTM(FetchError, "Error while fetching object", "")
 
 #define SLTH(tag, ind, req, resp, sdesc, ldesc) \