ESI byte accounting

Charge ESI bodybytes to the parent request.

Log SLT_ESI_BodyBytes in each ESI-involved log transaction. This shows
how many bytes each request adds to the total byte count.

SLT_ReqAcct is not logged for ESI sub-requests.

bin/varnishd/cache/cache.h

@@ -657,6 +657,7 @@ struct req {
 	uint64_t		req_bodybytes;	/* Parsed req bodybytes */
 
 	uint64_t		resp_hdrbytes;	/* Scheduled resp hdrbytes */
+	uint64_t		resp_bodybytes; /* Scheduled resp bodybytes */
 
 	uint16_t		err_code;
 	const char		*err_reason;

bin/varnishd/cache/cache_esi_deliver.c

@@ -218,15 +218,17 @@ ved_pretend_gzip(struct req *req, const uint8_t *p, ssize_t l)
 	while (l > 0) {
 		if (l >= 65535) {
 			lx = 65535;
-			(void)WRW_Write(req->wrk, buf1, sizeof buf1);
+			req->resp_bodybytes +=
+			    WRW_Write(req->wrk, buf1, sizeof buf1);
 		} else {
 			lx = (uint16_t)l;
 			buf2[0] = 0;
 			vle16enc(buf2 + 1, lx);
 			vle16enc(buf2 + 3, ~lx);
-			(void)WRW_Write(req->wrk, buf2, sizeof buf2);
+			req->resp_bodybytes +=
+			    WRW_Write(req->wrk, buf2, sizeof buf2);
 		}
-		(void)WRW_Write(req->wrk, p, lx);
+		req->resp_bodybytes += WRW_Write(req->wrk, p, lx);
 		req->crc = crc32(req->crc, p, lx);
 		req->l_crc += lx;
 		l -= lx;
@@ -283,7 +285,8 @@ ESI_Deliver(struct req *req)
 		if (isgzip && !(req->res_mode & RES_GUNZIP)) {
 			assert(sizeof gzip_hdr == 10);
 			/* Send out the gzip header */
-			(void)WRW_Write(req->wrk, gzip_hdr, 10);
+			req->resp_bodybytes +=
+			    WRW_Write(req->wrk, gzip_hdr, 10);
 			req->l_crc = 0;
 			req->gzip_resp = 1;
 			req->crc = crc32(0L, Z_NULL, 0);
@@ -339,8 +342,9 @@ ESI_Deliver(struct req *req)
 					 * We have a gzip'ed VEC and delivers
 					 * a gzip'ed ESI response.
 					 */
-					(void)WRW_Write(req->wrk,
-					    st->ptr + off, l2);
+					req->resp_bodybytes +=
+					    WRW_Write(req->wrk,
+						st->ptr + off, l2);
 				} else if (req->gzip_resp) {
 					/*
 					 * A gzip'ed ESI response, but the VEC
@@ -367,8 +371,9 @@ ESI_Deliver(struct req *req)
 					/*
 					 * Ungzip'ed VEC, ungzip'ed ESI response
 					 */
-					(void)WRW_Write(req->wrk,
-					    st->ptr + off, l2);
+					req->resp_bodybytes +=
+					    WRW_Write(req->wrk,
+						st->ptr + off, l2);
 				}
 				off += l2;
 				if (off == st->len) {
@@ -441,7 +446,7 @@ ESI_Deliver(struct req *req)
 		/* MOD(2^32) length */
 		vle32enc(tailbuf + 9, req->l_crc);
 
-		(void)WRW_Write(req->wrk, tailbuf, 13);
+		req->resp_bodybytes += WRW_Write(req->wrk, tailbuf, 13);
 	}
 	(void)WRW_Flush(req->wrk);
 }
@@ -451,7 +456,7 @@ ESI_Deliver(struct req *req)
  */
 
 static uint8_t
-ved_deliver_byterange(const struct req *req, ssize_t low, ssize_t high)
+ved_deliver_byterange(struct req *req, ssize_t low, ssize_t high)
 {
 	struct storage *st;
 	ssize_t l, lx;
@@ -477,7 +482,7 @@ ved_deliver_byterange(const struct req *req, ssize_t low, ssize_t high)
 			l = high - lx;
 		assert(lx >= low && lx + l <= high);
 		if (l != 0)
-			(void)WRW_Write(req->wrk, p, l);
+			req->resp_bodybytes += WRW_Write(req->wrk, p, l);
 		if (p + l < st->ptr + st->len)
 			return(p[l]);
 		lx += l;
@@ -532,7 +537,7 @@ ESI_DeliverChild(struct req *req)
 	 */
 	*dbits = ved_deliver_byterange(req, start/8, last/8);
 	*dbits &= ~(1U << (last & 7));
-	(void)WRW_Write(req->wrk, dbits, 1);
+	req->resp_bodybytes += WRW_Write(req->wrk, dbits, 1);
 	cc = ved_deliver_byterange(req, 1 + last/8, stop/8);
 	switch((int)(stop & 7)) {
 	case 0: /* xxxxxxxx */
@@ -576,7 +581,7 @@ ESI_DeliverChild(struct req *req)
 		INCOMPL();
 	}
 	if (lpad > 0)
-		(void)WRW_Write(req->wrk, dbits + 1, lpad);
+		req->resp_bodybytes += WRW_Write(req->wrk, dbits + 1, lpad);
 
 	/* We need the entire tail, but it may not be in one storage segment */
 	st = VTAILQ_LAST(&req->obj->store, storagehead);

bin/varnishd/cache/cache_http1_deliver.c

@@ -46,6 +46,7 @@ v1d_bytes(struct req *req, enum vdp_action act, const void *ptr, ssize_t len)
 
 	if (len > 0)
 		wl = WRW_Write(req->wrk, ptr, len);
+	req->resp_bodybytes += wl;
 	if (act > VDP_NULL && WRW_Flush(req->wrk))
 		return (-1);
 	if (len != wl)

bin/varnishd/cache/cache_http1_fsm.c

@@ -208,6 +208,7 @@ http1_cleanup(struct sess *sp, struct worker *wrk, struct req *req)
 	CNT_AcctLogCharge(&wrk->stats, req);
 	req->req_bodybytes = 0;
 	req->resp_hdrbytes = 0;
+	req->resp_bodybytes = 0;
 
 	/* Nuke the VXID. http1_dissect() will allocate a new one when
 	   necessary */

bin/varnishd/cache/cache_req_fsm.c

@@ -897,6 +897,10 @@ CNT_Request(struct worker *wrk, struct req *req)
 	}
 	if (nxt == REQ_FSM_DONE) {
 		/* XXX: Workaround for pipe */
+		AN(req->vsl->wid);
+		if (req->res_mode & (RES_ESI|RES_ESI_CHILD))
+			VSLb(req->vsl, SLT_ESI_BodyBytes, "%ju",
+			    (uintmax_t)req->resp_bodybytes);
 
 		while (!VTAILQ_EMPTY(&req->body)) {
 			st = VTAILQ_FIRST(&req->body);

bin/varnishd/cache/cache_session.c

@@ -372,6 +372,7 @@ SES_GetReq(struct worker *wrk, struct sess *sp)
 
 	req->req_bodybytes = 0;
 	req->resp_hdrbytes = 0;
+	req->resp_bodybytes = 0;
 
 	req->t_first = NAN;
 	req->t_prev = NAN;

bin/varnishtest/tests/l00003.vtc

+varnishtest "Test request byte counters with ESI"
+
+server s1 {
+	rxreq
+	expect req.url == "/"
+	txresp -body {<esi:include src="/1"/>ghi}
+
+	rxreq
+	expect req.url == "/1"
+	txresp -body {<esi:include src="/2"/>abc<esi:include src="/2"/>def}
+
+	rxreq
+	expect req.url == "/2"
+	txresp -body {123}
+} -start
+
+varnish v1 -vcl+backend {
+	sub vcl_backend_response {
+		set beresp.do_esi = true;
+	}
+	sub vcl_deliver {
+		unset resp.http.date;
+		unset resp.http.age;
+		unset resp.http.via;
+		unset resp.http.x-varnish;
+	}
+} -start
+
+# Request (1001):
+# GET / HTTP/1.1\r\n			16 bytes
+# \r\n					 2 bytes
+# Total:				18 bytes
+
+# Reponse:
+# HTTP/1.1 200 Ok\r\n			17 bytes
+# Transfer-Encoding: chunked\r\n	28 bytes
+# Connection: keep-alive\r\n		24 bytes
+# \r\n					 2 bytes
+# Total:				71 bytes
+
+# Response body:
+# 003\r\n				 5 bytes
+# 123\r\n				 5 bytes
+# 003\r\n				 5 bytes
+# abc\r\n				 5 bytes
+# 003\r\n				 5 bytes
+# 123\r\n				 5 bytes
+# 003\r\n				 5 bytes
+# def\r\n				 5 bytes
+# 003\r\n				 5 bytes
+# ghi\r\n				 5 bytes
+# 0\r\n					 3 bytes
+# \r\n					 2 bytes
+# Total:				55 bytes
+
+logexpect l1 -v v1 -g request {
+	expect 0 1001	Begin	"^req .* rxreq"
+	expect * =	ESI_BodyBytes	"^3"
+	expect * =	ReqAcct		"^18 0 18 71 55 126$"
+	expect 0 =	End
+	expect * 1003	Begin		"^req .* esi"
+	expect * =	ESI_BodyBytes	"^6$"
+	expect 0 =	End
+	expect * 1005	Begin		"^req .* esi"
+	expect * =	ESI_BodyBytes	"^3$"
+	expect 0 =	End
+	expect * 1007	Begin		"^req .* esi"
+	expect * =	ESI_BodyBytes	"^3$"
+	expect 0 =	End
+} -start
+
+client c1 {
+	txreq -url "/"
+	rxresp
+	expect resp.status == 200
+	expect resp.body == "123abc123defghi"
+} -run
+
+logexpect l1 -wait
+
+varnish v1 -expect s_req_hdrbytes == 18
+varnish v1 -expect s_req_bodybytes == 0
+varnish v1 -expect s_resp_hdrbytes == 71
+varnish v1 -expect s_resp_bodybytes == 55

include/tbl/vsl_tags.h

@@ -475,7 +475,9 @@ SLTM(Timestamp, 0, "Timing information",
 )
 
 SLTM(ReqAcct, 0, "Request handling byte counts",
-	"Contains byte counts for the request handling.\n\n"
+	"Contains byte counts for the request handling. This record is not"
+	" logged for ESI sub-requests, but the sub-requests' response"
+	" body count is added to the main request.\n\n"
 	"The format is::\n\n"
 	"\t%d %d %d %d %d %d\n"
 	"\t|  |  |  |  |  |\n"
@@ -488,4 +490,14 @@ SLTM(ReqAcct, 0, "Request handling byte counts",
 	"\n"
 )
 
+SLTM(ESI_BodyBytes, 0, "ESI body fragment byte counter",
+	"Contains the body byte count for this ESI body fragment."
+	" This number does not include any transfer encoding overhead.\n\n"
+	"The format is::\n\n"
+	"\t%d\n"
+	"\t|\n"
+	"\t+- Body bytes\n"
+	"\n"
+)
+
 #undef NODEF_NOTICE