Overhaul request accounting, particularly for ESI.

Give ESI subrequests a ReqAcct.

Make the bodycount in ReqAcct only the actual body, not including
transmission overhead (such as chunked encoding)

bin/varnishd/cache/cache.h

@@ -557,9 +557,6 @@ struct req {
 	unsigned char		wantbody;
 	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;
 
@@ -721,7 +718,6 @@ extern const int HTTP1_Req[3];
 extern const int HTTP1_Resp[3];
 
 /* cache_http1_deliver.c */
-unsigned V1D_FlushReleaseAcct(struct req *req);
 void V1D_Deliver(struct req *, struct busyobj *);
 
 /* cache_http1_pipe.c */

bin/varnishd/cache/cache_esi_deliver.c

@@ -56,7 +56,7 @@ ved_include(struct req *preq, const char *src, const char *host)
 	if (preq->esi_level >= cache_param->max_esi_depth)
 		return;
 
-	(void)V1D_FlushReleaseAcct(preq);
+	(void)WRW_FlushRelease(preq->wrk, NULL);
 
 	/* Take a workspace snapshot */
 	wrk_ws_wm = WS_Snapshot(wrk->aws); /* XXX ? */
@@ -132,11 +132,11 @@ ved_include(struct req *preq, const char *src, const char *host)
 	}
 	AN(WRW_IsReleased(wrk));
 
-	VSL_End(req->vsl);
-
-	/* Charge the transmitted body byte counts to the parent request */
+	/* Charge the transmitted body byte counts also to the parent request */
 	preq->acct.resp_bodybytes += req->acct.resp_bodybytes;
-	req->acct.resp_bodybytes = 0;
+
+	CNT_AcctLogCharge(wrk->stats, req);
+	VSL_End(req->vsl);
 
 	/* Reset the workspace */
 	WS_Reset(wrk->aws, wrk_ws_wm);	/* XXX ? */

bin/varnishd/cache/cache_req_fsm.c

@@ -791,10 +791,6 @@ CNT_Request(struct worker *wrk, struct req *req)
 	wrk->vsl = NULL;
 	if (nxt == REQ_FSM_DONE) {
 		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);
-
 		VRB_Free(req);
 		req->wrk = NULL;
 	}

bin/varnishd/cache/cache_session.c

@@ -366,8 +366,6 @@ SES_GetReq(const struct worker *wrk, struct sess *sp)
 	WS_Init(req->ws, "req", p, e - p);
 
 	req->req_bodybytes = 0;
-	req->resp_hdrbytes = 0;
-	req->resp_bodybytes = 0;
 
 	req->t_first = NAN;
 	req->t_prev = NAN;

bin/varnishd/http1/cache_http1_deliver.c

@@ -51,7 +51,7 @@ v1d_bytes(struct req *req, enum vdp_action act, void **priv,
 
 	if (len > 0)
 		wl = WRW_Write(req->wrk, ptr, len);
-	req->resp_bodybytes += wl;
+	req->acct.resp_bodybytes += len;
 	if (act > VDP_NULL && WRW_Flush(req->wrk))
 		return (-1);
 	if (len != wl)
@@ -227,33 +227,6 @@ v1d_WriteDirObj(struct req *req)
 	return (ois);
 }
 
-/*--------------------------------------------------------------------
- * V1D_FlushReleaseAcct()
- * Call WRW_FlushRelease on the worker and update the requests
- * byte accounting with the number of bytes transmitted
- *
- * Returns the return value from WRW_FlushRelease()
- */
-unsigned
-V1D_FlushReleaseAcct(struct req *req)
-{
-	unsigned u;
-	uint64_t txcnt = 0, hdrbytes;
-
-	CHECK_OBJ_NOTNULL(req, REQ_MAGIC);
-	CHECK_OBJ_NOTNULL(req->wrk, WORKER_MAGIC);
-	u = WRW_FlushRelease(req->wrk, &txcnt);
-	if (req->acct.resp_hdrbytes < req->resp_hdrbytes) {
-		hdrbytes = req->resp_hdrbytes - req->acct.resp_hdrbytes;
-		if (hdrbytes > txcnt)
-			hdrbytes = txcnt;
-	} else
-		hdrbytes = 0;
-	req->acct.resp_hdrbytes += hdrbytes;
-	req->acct.resp_bodybytes += txcnt - hdrbytes;
-	return (u);
-}
-
 /*--------------------------------------------------------------------
  */
 void
@@ -360,7 +333,7 @@ V1D_Deliver(struct req *req, struct busyobj *bo)
 	 * Send HTTP protocol header, unless interior ESI object
 	 */
 	if (!(req->res_mode & RES_ESI_CHILD))
-		req->resp_hdrbytes +=
+		req->acct.resp_hdrbytes +=
 		    HTTP1_Write(req->wrk, req->resp, HTTP1_Resp);
 
 	if (req->res_mode & RES_CHUNKED)
@@ -408,6 +381,7 @@ V1D_Deliver(struct req *req, struct busyobj *bo)
 	    !(req->res_mode & RES_ESI_CHILD))
 		WRW_EndChunk(req->wrk);
 
-	if ((V1D_FlushReleaseAcct(req) || ois != OIS_DONE) && req->sp->fd >= 0)
+	if ((WRW_FlushRelease(req->wrk, NULL) || ois != OIS_DONE) &&
+	    req->sp->fd >= 0)
 		SES_Close(req->sp, SC_REM_CLOSE);
 }

bin/varnishd/http1/cache_http1_fsm.c

@@ -171,8 +171,6 @@ http1_cleanup(struct sess *sp, struct worker *wrk, struct req *req)
 	AN(req->vsl->wid);
 	CNT_AcctLogCharge(wrk->stats, req);
 	req->req_bodybytes = 0;
-	req->resp_hdrbytes = 0;
-	req->resp_bodybytes = 0;
 
 	VSL_End(req->vsl);
 
@@ -285,7 +283,7 @@ http1_dissect(struct worker *wrk, struct req *req)
 			req->err_code = 417;
 			r = write(req->sp->fd, r_417, strlen(r_417));
 			if (r > 0)
-				req->resp_hdrbytes += r;
+				req->acct.resp_hdrbytes += r;
 			SES_Close(req->sp, SC_RX_JUNK);
 			return (REQ_FSM_DONE);
 		}

bin/varnishtest/tests/e00003.vtc

@@ -8,6 +8,7 @@ server s1 {
 		Before include
 		<esi:include src="/body" sr="foo"/>
 		After include
+		</html>
 	}
 	rxreq
 	expect req.url == "/body1"
@@ -27,17 +28,41 @@ varnish v1 -vcl+backend {
 	}
 } -start
 
+logexpect l1 -v v1 -g request {
+	expect 0 1001   Begin   "^req .* rxreq"
+	expect * =	ReqAcct	"^18 0 18 154 75 229$"
+	expect 0 =      End
+
+	expect 0 1002   Begin   "^bereq "
+	expect * =      End
+
+	expect 0 1003   Begin   "^req .* esi"
+	expect * = 	ReqAcct	"^0 0 0 0 18 18$"
+	expect 0 =      End
+
+	expect 0 1004   Begin   "^bereq "
+	expect * =      End
+
+	expect 0 1005   Begin   "^req .* rxreq"
+	expect * =	ReqAcct	"^18 0 18 159 75 234$"
+	expect 0 =      End
+} -start
+
 client c1 {
 	txreq
 	rxresp
-	expect resp.bodylen == 65
+	expect resp.bodylen == 75
 	expect resp.status == 200
+
+	delay .1
 	# test that there is no difference on miss/hit
 	txreq
 	rxresp
-	expect resp.bodylen == 65
+	expect resp.bodylen == 75
 	expect resp.status == 200
 }
 
 client c1 -run
 varnish v1 -expect esi_errors == 0
+
+logexpect l1 -wait

bin/varnishtest/tests/l00003.vtc

@@ -39,33 +39,25 @@ varnish v1 -vcl+backend {
 # 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
+# Total:				15 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 * =	ReqAcct		"^18 0 18 71 15 86$"
 	expect 0 =	End
 	expect * 1003	Begin		"^req .* esi"
-	expect * =	ESI_BodyBytes	"^6$"
+	expect * =	ReqAcct		"^0 0 0 0 12 12$"
 	expect 0 =	End
 	expect * 1005	Begin		"^req .* esi"
-	expect * =	ESI_BodyBytes	"^3$"
+	expect * =	ReqAcct		"^0 0 0 0 3 3$"
 	expect 0 =	End
 	expect * 1007	Begin		"^req .* esi"
-	expect * =	ESI_BodyBytes	"^3$"
+	expect * =	ReqAcct		"^0 0 0 0 3 3$"
 	expect 0 =	End
 } -start
 
@@ -81,4 +73,4 @@ 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
+varnish v1 -expect s_resp_bodybytes == 33

include/tbl/vsl_tags.h

@@ -444,9 +444,10 @@ SLTM(Timestamp, 0, "Timing information",
 )
 
 SLTM(ReqAcct, 0, "Request handling byte counts",
-	"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"
+	"Contains byte counts for the request handling.\n"
+	"ESI sub-request counts are also added to their parent request.\n"
+	"The body bytes count does not include transmission "
+	"(ie: chunked encoding) overhead.\n"
 	"The format is::\n\n"
 	"\t%d %d %d %d %d %d\n"
 	"\t|  |  |  |  |  |\n"
@@ -459,16 +460,6 @@ 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"
-)
-
 SLTM(PipeAcct, 0, "Pipe byte counts",
 	"Contains byte counters for pipe sessions.\n\n"
 	"The format is::\n\n"