Request handling byte accounting

Counters show bytes received/transmitted, split between header and
body bytes.

SLT_ReqAcct logs per request counter values.

bin/varnishd/cache/cache.h

@@ -228,9 +228,9 @@ struct http_conn {
 
 /*--------------------------------------------------------------------*/
 
-struct acct {
+struct acct_req {
 #define ACCT(foo)	uint64_t	foo;
-#include "tbl/acct_fields.h"
+#include "tbl/acct_fields_req.h"
 #undef ACCT
 };
 
@@ -654,9 +654,9 @@ struct req {
 	double			d_ttl;
 
 	unsigned char		wantbody;
-	uint64_t		req_bodybytes;
+	uint64_t		req_bodybytes;	/* Parsed req bodybytes */
 
-	uint64_t		resp_bodybytes;
+	uint64_t		resp_hdrbytes;	/* Scheduled resp hdrbytes */
 
 	uint16_t		err_code;
 	const char		*err_reason;
@@ -716,7 +716,7 @@ struct req {
 	struct vsl_log		vsl[1];
 
 	/* Temporary accounting */
-	struct acct		acct_req;
+	struct acct_req		acct;
 
 	/* Synth content in vcl_error */
 	struct vsb		*synth_body;
@@ -847,6 +847,7 @@ int HTTP1_CacheReqBody(struct req *req, ssize_t maxsize);
 int HTTP1_IterateReqBody(struct req *req, req_body_iter_f *func, void *priv);
 
 /* cache_http1_deliver.c */
+unsigned V1D_FlushReleaseAcct(struct req *req);
 void V1D_Deliver(struct req *);
 void V1D_Deliver_Synth(struct req *req);
 
@@ -892,6 +893,7 @@ VDP_pop(struct req *req, vdp_bytes *func)
 
 /* cache_req_fsm.c [CNT] */
 enum req_fsm_nxt CNT_Request(struct worker *, struct req *);
+void CNT_AcctLogCharge(struct dstat *, struct req *);
 
 /* cache_cli.c [CLI] */
 void CLI_Init(void);
@@ -1099,14 +1101,13 @@ void WRW_Chunked(const struct worker *w);
 void WRW_EndChunk(const struct worker *w);
 void WRW_Reserve(struct worker *w, int *fd, struct vsl_log *, double t0);
 unsigned WRW_Flush(const struct worker *w);
-unsigned WRW_FlushRelease(struct worker *w);
+unsigned WRW_FlushRelease(struct worker *w, ssize_t *pacc);
 unsigned WRW_Write(const struct worker *w, const void *ptr, int len);
 unsigned WRW_WriteH(const struct worker *w, const txt *hh, const char *suf);
 
 /* cache_session.c [SES] */
 void SES_Close(struct sess *sp, enum sess_close reason);
 void SES_Delete(struct sess *sp, enum sess_close reason, double now);
-void SES_Charge(struct worker *, struct req *);
 struct sesspool *SES_NewPool(struct pool *pp, unsigned pool_no);
 void SES_DeletePool(struct sesspool *sp);
 int SES_ScheduleReq(struct req *);

bin/varnishd/cache/cache_cli.c

@@ -126,7 +126,7 @@ cli_debug_sizeof(struct cli *cli, const char * const *av, void *priv)
 	SZOF(struct ws);
 	SZOF(struct http);
 	SZOF(struct http_conn);
-	SZOF(struct acct);
+	SZOF(struct acct_req);
 	SZOF(struct worker);
 	SZOF(struct wrk_accept);
 	SZOF(struct storage);

bin/varnishd/cache/cache_esi_deliver.c

@@ -55,7 +55,7 @@ ved_include(struct req *preq, const char *src, const char *host)
 	if (preq->esi_level >= cache_param->max_esi_depth)
 		return;
 
-	(void)WRW_FlushRelease(wrk);
+	(void)V1D_FlushReleaseAcct(preq);
 
 	/* Take a workspace snapshot */
 	wrk_ws_wm = WS_Snapshot(wrk->aws); /* XXX ? */
@@ -120,9 +120,17 @@ ved_include(struct req *preq, const char *src, const char *host)
 		AZ(req->wrk);
 		(void)usleep(10000);
 	}
+	AN(WRW_IsReleased(wrk));
 
-	/* Make sure the VSL id has been released */
-	AZ(req->vsl->wid);
+	/* Flush and release the log */
+	AN(req->vsl->wid);
+	VSLb(req->vsl, SLT_End, "%s", "");
+	VSL_Flush(req->vsl, 0);
+	req->vsl->wid = 0;
+
+	/* Charge the transmitted body byte counts to the parent request */
+	preq->acct.resp_bodybytes += req->acct.resp_bodybytes;
+	req->acct.resp_bodybytes = 0;
 
 	/* Reset the workspace */
 	WS_Reset(wrk->aws, wrk_ws_wm);	/* XXX ? */

bin/varnishd/cache/cache_hash.c

@@ -501,7 +501,6 @@ HSH_Lookup(struct req *req, struct objcore **ocp, struct objcore **bocp,
 	}
 
 	wrk->stats.busy_sleep++;
-	SES_Charge(wrk, req);
 	/*
 	 * The objhead reference transfers to the sess, we get it
 	 * back when the sess comes off the waiting list and

bin/varnishd/cache/cache_http1_deliver.c

@@ -46,8 +46,6 @@ 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);
-	if (wl > 0)
-		req->acct_req.bodybytes += wl;
 	if (act > VDP_NULL && WRW_Flush(req->wrk))
 		return (-1);
 	if (len != wl)
@@ -193,6 +191,33 @@ 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;
+	ssize_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
 V1D_Deliver(struct req *req)
 {
@@ -288,7 +313,7 @@ V1D_Deliver(struct req *req)
 	 * Send HTTP protocol header, unless interior ESI object
 	 */
 	if (!(req->res_mode & RES_ESI_CHILD))
-		req->acct_req.hdrbytes += HTTP1_Write(req->wrk, req->resp, 1);
+		req->resp_hdrbytes += HTTP1_Write(req->wrk, req->resp, 1);
 
 	if (req->res_mode & RES_CHUNKED)
 		WRW_Chunked(req->wrk);
@@ -320,7 +345,7 @@ V1D_Deliver(struct req *req)
 	    !(req->res_mode & RES_ESI_CHILD))
 		WRW_EndChunk(req->wrk);
 
-	if ((WRW_FlushRelease(req->wrk) || ois != OIS_DONE) && req->sp->fd >= 0)
+	if ((V1D_FlushReleaseAcct(req) || ois != OIS_DONE) && req->sp->fd >= 0)
 		SES_Close(req->sp, SC_REM_CLOSE);
 }
 
@@ -395,7 +420,7 @@ V1D_Deliver_Synth(struct req *req)
 	 * Send HTTP protocol header, unless interior ESI object
 	 */
 	if (!(req->res_mode & RES_ESI_CHILD))
-		req->acct_req.hdrbytes += HTTP1_Write(req->wrk, req->resp, 1);
+		req->resp_hdrbytes += HTTP1_Write(req->wrk, req->resp, 1);
 
 	if (req->res_mode & RES_CHUNKED)
 		WRW_Chunked(req->wrk);
@@ -418,6 +443,6 @@ V1D_Deliver_Synth(struct req *req)
 	if (req->res_mode & RES_CHUNKED && !(req->res_mode & RES_ESI_CHILD))
 		WRW_EndChunk(req->wrk);
 
-	if (WRW_FlushRelease(req->wrk) && req->sp->fd >= 0)
+	if (V1D_FlushReleaseAcct(req) && req->sp->fd >= 0)
 		SES_Close(req->sp, SC_REM_CLOSE);
 }

bin/varnishd/cache/cache_http1_fetch.c

@@ -330,7 +330,7 @@ V1F_fetch_hdr(struct worker *wrk, struct busyobj *bo, struct req *req)
 		}
 	}
 
-	if (WRW_FlushRelease(wrk) || i != 0) {
+	if (WRW_FlushRelease(wrk, NULL) || i != 0) {
 		VSLb(bo->vsl, SLT_FetchError, "backend write error: %d (%s)",
 		    errno, strerror(errno));
 		VSLb_ts_busyobj(bo, "Bereq", W_TIM_real(wrk));

bin/varnishd/cache/cache_http1_fsm.c

@@ -126,6 +126,7 @@ http1_wait(struct sess *sp, struct worker *wrk, struct req *req)
 				VSLb_ts_req(req, "Start", now);
 			VSLb_ts_req(req, "Req", now);
 			req->t_req = req->t_prev;
+			req->acct.req_hdrbytes += Tlen(req->htc->rxbuf);
 			return (REQ_FSM_MORE);
 		} else if (hs == HTTP1_ERROR_EOF) {
 			why = SC_REM_CLOSE;
@@ -161,6 +162,8 @@ http1_wait(struct sess *sp, struct worker *wrk, struct req *req)
 			}
 		}
 	}
+	req->acct.req_hdrbytes += Tlen(req->htc->rxbuf);
+	CNT_AcctLogCharge(&wrk->stats, req);
 	SES_ReleaseReq(req);
 	assert(why != SC_NULL);
 	SES_Delete(sp, why, now);
@@ -200,20 +203,28 @@ http1_cleanup(struct sess *sp, struct worker *wrk, struct req *req)
 		req->vcl = NULL;
 	}
 
+	/* Charge and log byte counters */
+	AN(req->vsl->wid);
+	CNT_AcctLogCharge(&wrk->stats, req);
+	req->req_bodybytes = 0;
+	req->resp_hdrbytes = 0;
+
+	/* Nuke the VXID. http1_dissect() will allocate a new one when
+	   necessary */
+	VSLb(req->vsl, SLT_End, "%s", "");
+	VSL_Flush(req->vsl, 0);
+	req->vsl->wid = 0;
+
 	if (!isnan(req->t_prev) && req->t_prev > 0.)
 		sp->t_idle = req->t_prev;
 	else
 		sp->t_idle = W_TIM_real(wrk);
-	VSL_Flush(req->vsl, 0);
 
 	req->t_first = NAN;
 	req->t_prev = NAN;
 	req->t_req = NAN;
 	req->req_body_status = REQ_BODY_INIT;
 
-	// req->req_bodybytes = 0;
-	req->resp_bodybytes = 0;
-
 	req->hash_always_miss = 0;
 	req->hash_ignore_busy = 0;
 
@@ -235,10 +246,17 @@ http1_cleanup(struct sess *sp, struct worker *wrk, struct req *req)
 	WS_Reset(wrk->aws, NULL);
 
 	if (HTTP1_Reinit(req->htc) == HTTP1_COMPLETE) {
+		AZ(req->vsl->wid);
+		req->vsl->wid = VXID_Get(&wrk->vxid_pool) | VSL_CLIENTMARKER;
+		VSLb(req->vsl, SLT_Begin, "req %u rxreq",
+		    req->sp->vxid & VSL_IDENTMASK);
+		VSL(SLT_Link, req->sp->vxid, "req %u rxreq",
+		    req->vsl->wid & VSL_IDENTMASK);
 		VSLb_ts_req(req, "Start", sp->t_idle);
 		VSLb_ts_req(req, "Req", sp->t_idle);
 		req->t_req = req->t_prev;
 		wrk->stats.sess_pipeline++;
+		req->acct.req_hdrbytes += Tlen(req->htc->rxbuf);
 		return (SESS_DONE_RET_START);
 	} else {
 		if (Tlen(req->htc->rxbuf))
@@ -285,6 +303,7 @@ http1_dissect(struct worker *wrk, struct req *req)
 	const char *r_411 = "HTTP/1.1 411 Length Required\r\n\r\n";
 	const char *r_417 = "HTTP/1.1 417 Expectation Failed\r\n\r\n";
 	char *p;
+	ssize_t r;
 
 	CHECK_OBJ_NOTNULL(wrk, WORKER_MAGIC);
 	CHECK_OBJ_NOTNULL(req, REQ_MAGIC);
@@ -314,7 +333,9 @@ http1_dissect(struct worker *wrk, struct req *req)
 	/* If we could not even parse the request, just close */
 	if (req->err_code != 0) {
 		wrk->stats.client_req_400++;
-		(void)write(req->sp->fd, r_400, strlen(r_400));
+		r = write(req->sp->fd, r_400, strlen(r_400));
+		if (r > 0)
+			req->acct.resp_hdrbytes += r;
 		SES_Close(req->sp, SC_RX_JUNK);
 		return (REQ_FSM_DONE);
 	}
@@ -326,7 +347,9 @@ http1_dissect(struct worker *wrk, struct req *req)
 
 	if (req->req_body_status == REQ_BODY_FAIL) {
 		wrk->stats.client_req_411++;
-		(void)write(req->sp->fd, r_411, strlen(r_411));
+		r = write(req->sp->fd, r_411, strlen(r_411));
+		if (r > 0)
+			req->acct.resp_hdrbytes += r;
 		SES_Close(req->sp, SC_RX_JUNK);
 		return (REQ_FSM_DONE);
 	}
@@ -335,21 +358,25 @@ http1_dissect(struct worker *wrk, struct req *req)
 		if (strcasecmp(p, "100-continue")) {
 			wrk->stats.client_req_417++;
 			req->err_code = 417;
-			(void)write(req->sp->fd, r_417, strlen(r_417));
+			r = write(req->sp->fd, r_417, strlen(r_417));
+			if (r > 0)
+				req->resp_hdrbytes += r;
 			SES_Close(req->sp, SC_RX_JUNK);
 			return (REQ_FSM_DONE);
 		}
-		if (strlen(r_100) != write(req->sp->fd, r_100, strlen(r_100))) {
-			// XXX: stats counter ?
+		r = write(req->sp->fd, r_100, strlen(r_100));
+		if (r > 0)
+			req->acct.resp_hdrbytes += r;
+		if (r != strlen(r_100)) {
 			SES_Close(req->sp, SC_REM_CLOSE);
 			return (REQ_FSM_DONE);
 		}
 	}
 
 	wrk->stats.client_req++;
+	wrk->stats.s_req++;
 
 	AZ(req->err_code);
-	req->acct_req.req++;
 	req->ws_req = WS_Snapshot(req->ws);
 	req->doclose = http_DoConnection(req->http);
 
@@ -475,6 +502,7 @@ http1_iter_req_body(struct req *req, void *buf, ssize_t len)
 	}
 	req->h1.bytes_done += len;
 	req->h1.bytes_yet = req->req_bodybytes - req->h1.bytes_done;
+	req->acct.req_bodybytes += len;
 	return (len);
 }
 

bin/varnishd/cache/cache_pipe.c

@@ -66,6 +66,7 @@ PipeRequest(struct req *req, struct busyobj *bo)
 	struct worker *wrk;
 	struct pollfd fds[2];
 	int i;
+	ssize_t txcnt;
 
 	CHECK_OBJ_NOTNULL(req, REQ_MAGIC);
 	CHECK_OBJ_NOTNULL(req->sp, SESS_MAGIC);
@@ -80,14 +81,13 @@ PipeRequest(struct req *req, struct busyobj *bo)
 	(void)VTCP_blocking(vc->fd);
 
 	WRW_Reserve(wrk, &vc->fd, bo->vsl, req->t_req);
-	req->acct_req.hdrbytes += HTTP1_Write(wrk, bo->bereq, 0);
+	(void)HTTP1_Write(wrk, bo->bereq, 0);
 
 	if (req->htc->pipeline.b != NULL)
-		req->acct_req.bodybytes +=
-		    WRW_Write(wrk, req->htc->pipeline.b,
+		(void)WRW_Write(wrk, req->htc->pipeline.b,
 		    Tlen(req->htc->pipeline));
 
-	i = WRW_FlushRelease(wrk);
+	i = WRW_FlushRelease(wrk, &txcnt);
 
 	VSLb_ts_req(req, "Pipe", W_TIM_real(wrk));
 

bin/varnishd/cache/cache_req_fsm.c

@@ -200,7 +200,7 @@ cnt_synth(struct worker *wrk, struct req *req)
 	CHECK_OBJ_NOTNULL(wrk, WORKER_MAGIC);
 	CHECK_OBJ_NOTNULL(req, REQ_MAGIC);
 
-	req->acct_req.synth++;
+	wrk->stats.s_synth++;
 
 	HTTP_Setup(req->resp, req->ws, req->vsl, SLT_RespMethod);
 	h = req->resp;
@@ -281,7 +281,7 @@ cnt_fetch(struct worker *wrk, struct req *req)
 	CHECK_OBJ_NOTNULL(req->objcore, OBJCORE_MAGIC);
 	AZ(req->obj);
 
-	req->acct_req.fetch++;
+	wrk->stats.s_fetch++;
 	(void)HTTP1_DiscardReqBody(req);
 
 	if (req->objcore->flags & OC_F_FAILED) {
@@ -554,7 +554,7 @@ cnt_pass(struct worker *wrk, struct req *req)
 		req->req_step = R_STP_RESTART;
 		break;
 	case VCL_RET_FETCH:
-		req->acct_req.pass++;
+		wrk->stats.s_pass++;
 		req->objcore = HSH_Private(wrk);
 		CHECK_OBJ_NOTNULL(req->objcore, OBJCORE_MAGIC);
 		VBF_Fetch(wrk, req, req->objcore, NULL, VBF_PASS);
@@ -593,7 +593,7 @@ cnt_pipe(struct worker *wrk, struct req *req)
 	CHECK_OBJ_NOTNULL(req, REQ_MAGIC);
 	CHECK_OBJ_NOTNULL(req->vcl, VCL_CONF_MAGIC);
 
-	req->acct_req.pipe++;
+	wrk->stats.s_pipe++;
 	bo = VBO_GetBusyObj(wrk, req);
 	HTTP_Setup(bo->bereq, bo->ws, bo->vsl, SLT_BereqMethod);
 	http_FilterReq(bo->bereq, req->http, 0);	// XXX: 0 ?
@@ -897,33 +897,43 @@ CNT_Request(struct worker *wrk, struct req *req)
 	}
 	if (nxt == REQ_FSM_DONE) {
 		/* XXX: Workaround for pipe */
-		if (req->sp->fd >= 0) {
-			VSLb(req->vsl, SLT_Length, "%ju",
-			    (uintmax_t)req->resp_bodybytes);
-		}
 
 		while (!VTAILQ_EMPTY(&req->body)) {
 			st = VTAILQ_FIRST(&req->body);
 			VTAILQ_REMOVE(&req->body, st, list);
 			STV_free(st);
 		}
-
-		/* done == 2 was charged by cache_hash.c */
-		SES_Charge(wrk, req);
-
-		/*
-		 * Nuke the VXID, cache_http1_fsm.c::http1_dissect() will
-		 * allocate a new one when necessary.
-		 */
-		VSLb(req->vsl, SLT_End, "%s", "");
-		req->vsl->wid = 0;
-		req->wrk = NULL;
 	}
-
+	req->wrk = NULL;
 	assert(WRW_IsReleased(wrk));
 	return (nxt);
 }
 
+void
+CNT_AcctLogCharge(struct dstat *ds, struct req *req)
+{
+	struct acct_req *a;
+
+	AN(ds);
+	CHECK_OBJ_NOTNULL(req, REQ_MAGIC);
+
+	a = &req->acct;
+
+	VSLb(req->vsl, SLT_ReqAcct, "%ju %ju %ju %ju %ju %ju",
+	    (uintmax_t)a->req_hdrbytes,
+	    (uintmax_t)a->req_bodybytes,
+	    (uintmax_t)(a->req_hdrbytes + a->req_bodybytes),
+	    (uintmax_t)a->resp_hdrbytes,
+	    (uintmax_t)a->resp_bodybytes,
+	    (uintmax_t)(a->resp_hdrbytes + a->resp_bodybytes));
+
+#define ACCT(foo)			\
+	ds->s_##foo += a->foo;		\
+	a->foo = 0;
+#include "tbl/acct_fields_req.h"
+#undef ACCT
+}
+
 /*
 DOT }
 */

bin/varnishd/cache/cache_session.c

@@ -61,31 +61,6 @@ struct sesspool {
 	struct mempool		*mpl_sess;
 };
 
-/*--------------------------------------------------------------------
- * Charge statistics from worker to request and session.
- */
-
-void
-SES_Charge(struct worker *wrk, struct req *req)
-{
-	struct sess *sp;
-	struct acct *a;
-
-	CHECK_OBJ_NOTNULL(wrk, WORKER_MAGIC);
-	CHECK_OBJ_NOTNULL(req, REQ_MAGIC);
-	sp = req->sp;
-	CHECK_OBJ_NOTNULL(sp, SESS_MAGIC);
-
-	a = &req->acct_req;
-	req->resp_bodybytes += a->bodybytes;
-
-#define ACCT(foo)				\
-	wrk->stats.s_##foo += a->foo;		\
-	a->foo = 0;
-#include "tbl/acct_fields.h"
-#undef ACCT
-}
-
 /*--------------------------------------------------------------------
  * Get a new session, preferably by recycling an already ready one
  *
@@ -395,6 +370,9 @@ SES_GetReq(struct worker *wrk, struct sess *sp)
 
 	WS_Init(req->ws, "req", p, e - p);
 
+	req->req_bodybytes = 0;
+	req->resp_hdrbytes = 0;
+
 	req->t_first = NAN;
 	req->t_prev = NAN;
 	req->t_req = NAN;
@@ -411,10 +389,14 @@ SES_ReleaseReq(struct req *req)
 	struct sesspool *pp;
 
 	CHECK_OBJ_NOTNULL(req, REQ_MAGIC);
-	AZ(req->vcl);
-#define ACCT(foo)	AZ(req->acct_req.foo);
-#include "tbl/acct_fields.h"
+
+	/* Make sure the request counters have all been zeroed */
+#define ACCT(foo) \
+	AZ(req->acct.foo);
+#include "tbl/acct_fields_req.h"
 #undef ACCT
+
+	AZ(req->vcl);
 	sp = req->sp;
 	CHECK_OBJ_NOTNULL(sp, SESS_MAGIC);
 	pp = sp->sesspool;

bin/varnishd/cache/cache_wrw.c

@@ -58,6 +58,7 @@ struct wrw {
 	unsigned		ciov;	/* Chunked header marker */
 	double			t0;
 	struct vsl_log		*vsl;
+	ssize_t			cnt;	/* Flushed byte count */
 };
 
 /*--------------------------------------------------------------------
@@ -101,7 +102,7 @@ WRW_Reserve(struct worker *wrk, int *fd, struct vsl_log *vsl, double t0)
 }
 
 static void
-WRW_Release(struct worker *wrk)
+wrw_release(struct worker *wrk, ssize_t *pacc)
 {
 	struct wrw *wrw;
 
@@ -109,6 +110,8 @@ WRW_Release(struct worker *wrk)
 	wrw = wrk->wrw;
 	wrk->wrw = NULL;
 	CHECK_OBJ_NOTNULL(wrw, WRW_MAGIC);
+	if (pacc != NULL)
+		*pacc += wrw->cnt;
 	WS_Release(wrk->aws, 0);
 	WS_Reset(wrk->aws, NULL);
 }
@@ -171,6 +174,8 @@ WRW_Flush(const struct worker *wrk)
 		}
 
 		i = writev(*wrw->wfd, wrw->iov, wrw->niov);
+		if (i > 0)
+			wrw->cnt += i;
 		while (i != wrw->liov && i > 0) {
 			/* Remove sent data from start of I/O vector,
 			 * then retry; we hit a timeout, but some data
@@ -195,6 +200,8 @@ WRW_Flush(const struct worker *wrk)
 
 			wrw_prune(wrw, i);
 			i = writev(*wrw->wfd, wrw->iov, wrw->niov);
+			if (i > 0)
+				wrw->cnt += i;
 		}
 		if (i <= 0) {
 			wrw->werr++;
@@ -212,14 +219,14 @@ WRW_Flush(const struct worker *wrk)
 }
 
 unsigned
-WRW_FlushRelease(struct worker *wrk)
+WRW_FlushRelease(struct worker *wrk, ssize_t *pacc)
 {
 	unsigned u;
 
 	CHECK_OBJ_NOTNULL(wrk, WORKER_MAGIC);
 	AN(wrk->wrw->wfd);
 	u = WRW_Flush(wrk);
-	WRW_Release(wrk);
+	wrw_release(wrk, pacc);
 	return (u);
 }
 

bin/varnishtest/tests/l00002.vtc

+varnishtest "Test request byte counters"
+
+server s1 {
+	rxreq
+	expect req.url == "/1"
+	txresp -bodylen 1000
+
+	rxreq
+	expect req.url == "/2"
+	txresp -bodylen 2000
+} -start
+
+varnish v1 -vcl+backend {
+	sub vcl_deliver {
+		unset resp.http.date;
+		unset resp.http.age;
+		unset resp.http.via;
+		unset resp.http.x-varnish;
+	}
+} -start
+
+# Request (1001):
+# GET /1 HTTP/1.1\r\n		 17 bytes
+# Content-Length: 4\r\n		 19 bytes
+# \r\n				  2 bytes
+# Total:			 38 bytes
+# Response:
+# HTTP/1.1 200 Ok\r\n		 17 bytes
+# Content-Length: 1000\r\n	 22 bytes
+# Connection: keep-alive\r\n	 24 bytes
+# Accept-Ranges: bytes\r\n	 22 bytes
+# \r\n				  2 bytes
+# Total:			 87 bytes
+
+# Request (1003):
+# GET /2 HTTP/1.1\r\n		 17 bytes
+# \r\n				  2 bytes
+# Total:			 19 bytes
+# Response:
+# HTTP/1.1 200 Ok\r\n		 17 bytes
+# Content-Length: 2000\r\n	 22 bytes
+# Connection: keep-alive\r\n	 24 bytes
+# Accept-Ranges: bytes\r\n	 22 bytes
+# \r\n				  2 bytes
+# Total:			 87 bytes
+
+# Request (1005):
+# GET /2 HTTP/1.1\r\n		 17 bytes
+# \r\n				  2 bytes
+# Total:			 19 bytes
+# Response:
+# HTTP/1.1 200 Ok\r\n		 17 bytes
+# Content-Length: 2000\r\n	 22 bytes
+# Connection: keep-alive\r\n	 24 bytes
+# Accept-Ranges: bytes\r\n	 22 bytes
+# \r\n				  2 bytes
+# Total:			 87 bytes
+
+# Request (1006):
+# GET\r\n			  5 bytes
+# \r\n				  2 bytes
+# Total:			  7 bytes
+# Response:
+# HTTP/1.1 400 Bad Request\r\n	 26 bytes
+# \r\n				  2 bytes
+# Total:			 28 bytes
+logexpect l1 -v v1 -g request {
+	expect 0 1001	Begin	"^req .* rxreq"
+	expect * =	ReqAcct	"^38 4 42 87 1000 1087$"
+	expect 0 =	End
+	expect 0 1002	Begin	"^bereq "
+	expect * =	End
+	expect 0 1003	Begin	"^req .* rxreq"
+	expect * =	ReqAcct "^19 0 19 87 2000 2087$"
+	expect 0 =	End
+	expect 0 1004	Begin	"^bereq"
+	expect * =	End
+	expect 0 1005	Begin	"^req .* rxreq"
+	expect * =	ReqAcct "^19 0 19 87 2000 2087$"
+	expect 0 =	End
+	expect 0 1006	Begin	"^req .* rxreq"
+	expect * =	ReqAcct	"^7 0 7 28 0 28$"
+	expect 0 =	End
+} -start
+
+# Request 1001
+client c1 {
+	txreq -url "/1" -body "asdf"
+	rxresp
+	expect resp.status == 200
+
+	send "GET /2 HTTP/1.1\r\n\r\nGET /2 HTTP/1.1\r\n\r\n"
+	rxresp
+	expect resp.status == 200
+	rxresp
+	expect resp.status == 200
+
+	send "GET\r\n\r\n"
+	rxresp
+	expect resp.status == 400
+} -run
+
+logexpect l1 -wait
+
+varnish v1 -expect s_req_hdrbytes == 83
+varnish v1 -expect s_req_bodybytes == 4
+varnish v1 -expect s_resp_hdrbytes == 289
+varnish v1 -expect s_resp_bodybytes == 5000

include/Makefile.am

@@ -2,7 +2,7 @@
 
 # API headers
 nobase_pkginclude_HEADERS = \
-	tbl/acct_fields.h \
+	tbl/acct_fields_req.h \
 	tbl/backend_poll.h \
 	tbl/ban_vars.h \
 	tbl/bo_flags.h \

include/tbl/acct_fields.h → include/tbl/acct_fields_req.h

 /*-
  * Copyright (c) 2008 Verdens Gang AS
- * Copyright (c) 2008-2009 Varnish Software AS
+ * Copyright (c) 2008-2014 Varnish Software AS
  * All rights reserved.
  *
  * Author: Poul-Henning Kamp <phk@phk.freebsd.dk>
@@ -26,15 +26,11 @@
  * 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 session.
- * SES_Charge() sums them into wrk->stats
+ * These are the stats we keep track of per request.
  * NB: Remember to mark those in vsc_fields.h to be included in struct dstat.
  */
 
-ACCT(req)
-ACCT(pipe)
-ACCT(pass)
-ACCT(fetch)
-ACCT(synth)
-ACCT(hdrbytes)
-ACCT(bodybytes)
+ACCT(req_hdrbytes)
+ACCT(req_bodybytes)
+ACCT(resp_hdrbytes)
+ACCT(resp_bodybytes)

include/tbl/vsc_f_main.h

@@ -384,13 +384,21 @@ VSC_F(s_synth,			uint64_t, 1, 'a', info,
     "Total synth",
 	""
 )
-VSC_F(s_hdrbytes,		uint64_t, 1, 'a', info,
-    "Total header bytes",
-	""
+VSC_F(s_req_hdrbytes,		uint64_t, 1, 'a', info,
+    "Request header bytes",
+	"Total request header bytes received"
 )
-VSC_F(s_bodybytes,		uint64_t, 1, 'a', info,
-    "Total body bytes",
-	""
+VSC_F(s_req_bodybytes,		uint64_t, 1, 'a', info,
+    "Request body bytes",
+	"Total request body bytes received"
+)
+VSC_F(s_resp_hdrbytes,		uint64_t, 1, 'a', info,
+    "Response header bytes",
+	"Total response header bytes transmitted"
+)
+VSC_F(s_resp_bodybytes,		uint64_t, 1, 'a', info,
+    "Reponse body bytes",
+	"Total response body bytes transmitted"
 )
 
 VSC_F(sess_closed,		uint64_t, 1, 'a', info,

include/tbl/vsl_tags.h

@@ -474,4 +474,18 @@ SLTM(Timestamp, 0, "Timing information",
 	"\n"
 )
 
+SLTM(ReqAcct, 0, "Request handling byte counts",
+	"Contains byte counts for the request handling.\n\n"
+	"The format is::\n\n"
+	"\t%d %d %d %d %d %d\n"
+	"\t|  |  |  |  |  |\n"
+	"\t|  |  |  |  |  +- Total bytes transmitted\n"
+	"\t|  |  |  |  +---- Body bytes transmitted\n"
+	"\t|  |  |  +------- Header bytes transmitted\n"
+	"\t|  |  +---------- Total bytes received\n"
+	"\t|  +------------- Body bytes received\n"
+	"\t+---------------- Header bytes received\n"
+	"\n"
+)
+
 #undef NODEF_NOTICE