Backend fetch byte accounting

Add SLT_BereqAcct log records showing headers and bodybytes
received/transmitted when doing backend fetch operations.

bin/varnishd/cache/cache.h

@@ -236,6 +236,14 @@ struct acct_req {
 
 /*--------------------------------------------------------------------*/
 
+struct acct_bereq {
+#define ACCT(foo)	ssize_t		foo;
+#include "tbl/acct_fields_bereq.h"
+#undef ACCT
+};
+
+/*--------------------------------------------------------------------*/
+
 #define L0(t, n)
 #define L1(t, n)		t n;
 #define VSC_F(n,t,l,f,v,e,d)	L##l(t, n)
@@ -566,6 +574,9 @@ struct busyobj {
 	double			t_first;	/* First timestamp logged */
 	double			t_prev;		/* Previous timestamp logged */
 
+	/* Acct */
+	struct acct_bereq	acct;
+
 	const char		*storage_hint;
 	struct director		*director;
 	struct VCL_conf		*vcl;

bin/varnishd/cache/cache_busyobj.c

@@ -187,6 +187,14 @@ VBO_DerefBusyObj(struct worker *wrk, struct busyobj **pbo)
 	if (r)
 		return;
 
+	VSLb(bo->vsl, SLT_BereqAcct, "%ju %ju %ju %ju %ju %ju",
+	    (uintmax_t)bo->acct.bereq_hdrbytes,
+	    (uintmax_t)bo->acct.bereq_bodybytes,
+	    (uintmax_t)(bo->acct.bereq_hdrbytes + bo->acct.bereq_bodybytes),
+	    (uintmax_t)bo->acct.beresp_hdrbytes,
+	    (uintmax_t)bo->acct.beresp_bodybytes,
+	    (uintmax_t)(bo->acct.beresp_hdrbytes + bo->acct.beresp_bodybytes));
+
 	VSLb(bo->vsl, SLT_End, "%s", "");
 	VSL_Flush(bo->vsl, 0);
 

bin/varnishd/cache/cache_http1_fetch.c

@@ -91,6 +91,7 @@ v1f_pull_straight(struct busyobj *bo, void *p, ssize_t *lp, intptr_t *priv)
 	if (*priv < l)
 		l = *priv;
 	lr = HTTP1_Read(&bo->htc, p, l);
+	bo->acct.beresp_bodybytes += lr;
 	if (lr <= 0)
 		return (VFP_Error(bo, "straight insufficient bytes"));
 	*lp = lr;
@@ -127,8 +128,10 @@ v1f_pull_chunked(struct busyobj *bo, void *p, ssize_t *lp, intptr_t *priv)
 	if (*priv == -1) {
 		/* Skip leading whitespace */
 		do {
-			if (HTTP1_Read(&bo->htc, buf, 1) <= 0)
+			lr = HTTP1_Read(&bo->htc, buf, 1);
+			if (lr <= 0)
 				return (VFP_Error(bo, "chunked read err"));
+			bo->acct.beresp_bodybytes += lr;
 		} while (vct_islws(buf[0]));
 
 		if (!vct_ishex(buf[0]))
@@ -137,9 +140,11 @@ v1f_pull_chunked(struct busyobj *bo, void *p, ssize_t *lp, intptr_t *priv)
 		/* Collect hex digits, skipping leading zeros */
 		for (u = 1; u < sizeof buf; u++) {
 			do {
-				if (HTTP1_Read(&bo->htc, buf + u, 1) <= 0)
+				lr = HTTP1_Read(&bo->htc, buf + u, 1);
+				if (lr <= 0)
 					return (VFP_Error(bo,
 					    "chunked read err"));
+				bo->acct.beresp_bodybytes += lr;
 			} while (u == 1 && buf[0] == '0' && buf[u] == '0');
 			if (!vct_ishex(buf[u]))
 				break;
@@ -149,9 +154,12 @@ v1f_pull_chunked(struct busyobj *bo, void *p, ssize_t *lp, intptr_t *priv)
 			return (VFP_Error(bo,"chunked header too long"));
 
 		/* Skip trailing white space */
-		while(vct_islws(buf[u]) && buf[u] != '\n')
-			if (HTTP1_Read(&bo->htc, buf + u, 1) <= 0)
+		while(vct_islws(buf[u]) && buf[u] != '\n') {
+			lr = HTTP1_Read(&bo->htc, buf + u, 1);
+			if (lr <= 0)
 				return (VFP_Error(bo, "chunked read err"));
+			bo->acct.beresp_bodybytes += lr;
+		}
 
 		if (buf[u] != '\n')
 			return (VFP_Error(bo,"chunked header no NL"));
@@ -169,6 +177,7 @@ v1f_pull_chunked(struct busyobj *bo, void *p, ssize_t *lp, intptr_t *priv)
 		lr = HTTP1_Read(&bo->htc, p, l);
 		if (lr <= 0)
 			return (VFP_Error(bo, "straight insufficient bytes"));
+		bo->acct.beresp_bodybytes += lr;
 		*lp = lr;
 		*priv -= lr;
 		if (*priv == 0)
@@ -179,6 +188,7 @@ v1f_pull_chunked(struct busyobj *bo, void *p, ssize_t *lp, intptr_t *priv)
 	i = HTTP1_Read(&bo->htc, buf, 1);
 	if (i <= 0)
 		return (VFP_Error(bo, "chunked read err"));
+	bo->acct.beresp_bodybytes += i;
 	if (buf[0] == '\r' && HTTP1_Read(&bo->htc, buf, 1) <= 0)
 		return (VFP_Error(bo, "chunked read err"));
 	if (buf[0] != '\n')
@@ -281,8 +291,9 @@ V1F_fetch_hdr(struct worker *wrk, struct busyobj *bo, struct req *req)
 	struct http *hp;
 	enum htc_status_e hs;
 	int retry = -1;
-	int i, first;
+	int i, j, first;
 	struct http_conn *htc;
+	ssize_t hdrbytes;
 
 	CHECK_OBJ_NOTNULL(wrk, WORKER_MAGIC);
 	CHECK_OBJ_ORNULL(req, REQ_MAGIC);
@@ -312,7 +323,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_prev);
-	(void)HTTP1_Write(wrk, hp, 0);	/* XXX: stats ? */
+	hdrbytes = HTTP1_Write(wrk, hp, 0);
 
 	/* Deal with any message-body the request might (still) have */
 	i = 0;
@@ -330,7 +341,12 @@ V1F_fetch_hdr(struct worker *wrk, struct busyobj *bo, struct req *req)
 		}
 	}
 
-	if (WRW_FlushRelease(wrk, NULL) || i != 0) {
+	j = WRW_FlushRelease(wrk, &bo->acct.bereq_hdrbytes);
+	if (bo->acct.bereq_hdrbytes > hdrbytes) {
+		bo->acct.bereq_bodybytes = bo->acct.bereq_hdrbytes - hdrbytes;
+		bo->acct.bereq_hdrbytes = hdrbytes;
+	}
+	if (j != 0 || i != 0) {
 		VSLb(bo->vsl, SLT_FetchError, "backend write error: %d (%s)",
 		    errno, strerror(errno));
 		VSLb_ts_busyobj(bo, "Bereq", W_TIM_real(wrk));
@@ -356,6 +372,7 @@ V1F_fetch_hdr(struct worker *wrk, struct busyobj *bo, struct req *req)
 	do {
 		hs = HTTP1_Rx(htc);
 		if (hs == HTTP1_OVERFLOW) {
+			bo->acct.beresp_hdrbytes += Tlen(htc->rxbuf);
 			VSLb(bo->vsl, SLT_FetchError,
 			    "http %sread error: overflow",
 			    first ? "first " : "");
@@ -364,6 +381,7 @@ V1F_fetch_hdr(struct worker *wrk, struct busyobj *bo, struct req *req)
 			return (-1);
 		}
 		if (hs == HTTP1_ERROR_EOF) {
+			bo->acct.beresp_hdrbytes += Tlen(htc->rxbuf);
 			VSLb(bo->vsl, SLT_FetchError, "http %sread error: EOF",
 			    first ? "first " : "");
 			VDI_CloseFd(&bo->vbc);
@@ -377,6 +395,7 @@ V1F_fetch_hdr(struct worker *wrk, struct busyobj *bo, struct req *req)
 			    vc->between_bytes_timeout);
 		}
 	} while (hs != HTTP1_COMPLETE);
+	bo->acct.beresp_hdrbytes += Tlen(htc->rxbuf);
 
 	hp = bo->beresp;
 

bin/varnishtest/tests/l00005.vtc

+varnishtest "Test backend fetch byte counters"
+
+server s1 {
+	rxreq
+	expect req.url == "/1"
+	txresp -bodylen 1000
+
+	rxreq
+	expect req.url == "/2"
+	send "HTTP/1.1\r\n\r\n"
+} -start
+
+varnish v1 -vcl+backend {
+	sub vcl_backend_fetch {
+		unset bereq.http.x-forwarded-for;
+		unset bereq.http.x-varnish;
+		set bereq.http.Host = "foo.bar";
+	}
+} -start
+
+# Request (1002):
+# POST /1 HTTP/1.1\r\n		 18 bytes
+# Content-Length: 4\r\n		 19 bytes
+# Host: foo.bar\r\n		 15 bytes
+# \r\n				  2 bytes
+# Total:			 54 bytes
+# Response:
+# HTTP/1.1 200 Ok\r\n		 17 bytes
+# Content-Length: 1000\r\n	 22 bytes
+# \r\n				  2 bytes
+# Total:			 41 bytes
+
+# Request (1004):
+# POST /2 HTTP/1.1\r\n		 18 bytes
+# Content-Length: 4\r\n		 19 bytes
+# Host: foo.bar\r\n		 15 bytes
+# \r\n				  2 bytes
+# Total:			 54 bytes
+# Reponse:
+# HTTP/1.1\r\n			 10 bytes
+# \r\n				  2 bytes
+# Total:			 12 bytes
+
+logexpect l1 -v v1 -g request {
+	expect 0 1001	Begin		"^req .* rxreq"
+	expect * =	End
+	expect 0 1002	Begin		"^bereq "
+	expect * =	BereqAcct	"^54 4 58 41 1000 1041$"
+	expect 0 =	End
+	expect 0 1003	Begin		"^req .* rxreq"
+	expect * =	End
+	expect 0 1004	Begin		"^bereq"
+	expect * =	BereqAcct	"^54 4 58 12 0 12$"
+	expect * =	End
+} -start
+
+# Request 1001
+client c1 {
+	txreq -req "POST" -url "/1" -body "asdf"
+	rxresp
+	expect resp.status == 200
+
+	txreq -req "POST" -url "/2" -body "asdf"
+	rxresp
+	expect resp.status == 503
+} -run
+
+logexpect l1 -wait

include/Makefile.am

@@ -3,6 +3,7 @@
 # API headers
 nobase_pkginclude_HEADERS = \
 	tbl/acct_fields_req.h \
+	tbl/acct_fields_bereq.h \
 	tbl/backend_poll.h \
 	tbl/ban_vars.h \
 	tbl/bo_flags.h \

include/tbl/acct_fields_bereq.h

+/*-
+ * Copyright (c) 2008 Verdens Gang AS
+ * Copyright (c) 2008-2014 Varnish Software AS
+ * All rights reserved.
+ *
+ * Author: Poul-Henning Kamp <phk@phk.freebsd.dk>
+ *
+ * Redistribution and use in source and binary forms, with or without
+ * modification, are permitted provided that the following conditions
+ * are met:
+ * 1. Redistributions of source code must retain the above copyright
+ *    notice, this list of conditions and the following disclaimer.
+ * 2. Redistributions in binary form must reproduce the above copyright
+ *    notice, this list of conditions and the following disclaimer in the
+ *    documentation and/or other materials provided with the distribution.
+ *
+ * THIS SOFTWARE IS PROVIDED BY THE AUTHOR AND CONTRIBUTORS ``AS IS'' AND
+ * ANY EXPRESS OR IMPLIED WARRANTIES, INCLUDING, BUT NOT LIMITED TO, THE
+ * IMPLIED WARRANTIES OF MERCHANTABILITY AND FITNESS FOR A PARTICULAR PURPOSE
+ * ARE DISCLAIMED.  IN NO EVENT SHALL AUTHOR OR CONTRIBUTORS BE LIABLE
+ * FOR ANY DIRECT, INDIRECT, INCIDENTAL, SPECIAL, EXEMPLARY, OR CONSEQUENTIAL
+ * DAMAGES (INCLUDING, BUT NOT LIMITED TO, PROCUREMENT OF SUBSTITUTE GOODS
+ * OR SERVICES; LOSS OF USE, DATA, OR PROFITS; OR BUSINESS INTERRUPTION)
+ * HOWEVER CAUSED AND ON ANY THEORY OF LIABILITY, WHETHER IN CONTRACT, STRICT
+ * LIABILITY, OR TORT (INCLUDING NEGLIGENCE OR OTHERWISE) ARISING IN ANY WAY
+ * OUT OF THE USE OF THIS SOFTWARE, EVEN IF ADVISED OF THE POSSIBILITY OF
+ * SUCH DAMAGE.
+ *
+ * These are the stats we keep track of per busyobj.
+ */
+
+ACCT(bereq_hdrbytes)
+ACCT(bereq_bodybytes)
+ACCT(beresp_hdrbytes)
+ACCT(beresp_bodybytes)

include/tbl/vsl_tags.h

@@ -512,4 +512,18 @@ SLTM(PipeAcct, 0, "Pipe byte counts",
 	"\n"
 )
 
+SLTM(BereqAcct, 0, "Backend request accounting",
+	"Contains byte counters from backend request processing.\n\n"
+	"The format is::\n\n"
+	"\t%d %d %d %d %d %d\n"
+	"\t|  |  |  |  |  |\n"
+	"\t|  |  |  |  |  +- Total bytes received\n"
+	"\t|  |  |  |  +---- Body bytes received\n"
+	"\t|  |  |  +------- Header bytes received\n"
+	"\t|  |  +---------- Total bytes transmitted\n"
+	"\t|  +------------- Body bytes transmitted\n"
+	"\t+---------------- Header bytes transmitted\n"
+	"\n"
+)
+
 #undef NODEF_NOTICE