[master] 5117664 Accurate byte counters
Martin Blix Grydeland
martin at varnish-software.com
Mon Feb 19 12:51:08 UTC 2018
commit 51176640603b123a38b49ae271cb9c9de9df1d28
Author: Martin Blix Grydeland <martin at varnish-software.com>
Date: Tue Feb 6 15:21:39 2018 +0100
Accurate byte counters
There was a regression from Varnish 4.0 to 4.1, where the response
bytes was counted as the number of bytes fed to the outgoing write
vector, rather than the bytes that was actually handed off to the OS'
socket buffer. This would cause for many cases the complete object
size counted as transmitted bytes, even though the client hung up the
connection early.
This patch changes the counters to show the amount of bytes sent as
reported from the write() system calls rather than the bytes we planned
and prepared to send. The counters will include any protocol overhead (ie
chunked encoding in HTTP/1 and the frame headers in HTTP/2).
ESI subrequests will as before in their log transactions report the number
of bytes it (and any subrequests below it) contributed to the total body
bytes produced.
Some test cases have been adjusted to account for the new counter behaviour.
Fixes: 2558
diff --git a/bin/varnishd/cache/cache_backend.c b/bin/varnishd/cache/cache_backend.c
index 4d31680..204c3c7 100644
--- a/bin/varnishd/cache/cache_backend.c
+++ b/bin/varnishd/cache/cache_backend.c
@@ -233,7 +233,8 @@ vbe_dir_gethdrs(const struct director *d, struct worker *wrk,
if (vtp->state != VTP_STATE_STOLEN)
extrachance = 0;
- i = V1F_SendReq(wrk, bo, &bo->acct.bereq_hdrbytes, 0);
+ i = V1F_SendReq(wrk, bo, &bo->acct.bereq_hdrbytes,
+ &bo->acct.bereq_bodybytes, 0);
if (vtp->state != VTP_STATE_USED) {
if (VTP_Wait(wrk, vtp, VTIM_real() +
@@ -317,7 +318,8 @@ vbe_dir_http1pipe(const struct director *d, struct req *req, struct busyobj *bo)
if (vtp == NULL) {
retval = SC_TX_ERROR;
} else {
- i = V1F_SendReq(req->wrk, bo, &v1a.bereq, 1);
+ CHECK_OBJ_NOTNULL(bo->htc, HTTP_CONN_MAGIC);
+ i = V1F_SendReq(req->wrk, bo, &v1a.bereq, &v1a.out, 1);
VSLb_ts_req(req, "Pipe", W_TIM_real(req->wrk));
if (i == 0)
V1P_Process(req, vtp->fd, &v1a);
diff --git a/bin/varnishd/cache/cache_req.c b/bin/varnishd/cache/cache_req.c
index 8fa77b9..4ced78a 100644
--- a/bin/varnishd/cache/cache_req.c
+++ b/bin/varnishd/cache/cache_req.c
@@ -63,8 +63,10 @@ Req_AcctLogCharge(struct VSC_main *ds, struct req *req)
(uintmax_t)(a->resp_hdrbytes + a->resp_bodybytes));
}
+ /* Charge to main byte counters (except for ESI subrequests) */
#define ACCT(foo) \
- ds->s_##foo += a->foo; \
+ if (req->esi_level == 0) \
+ ds->s_##foo += a->foo; \
a->foo = 0;
#include "tbl/acct_fields_req.h"
}
diff --git a/bin/varnishd/http1/cache_http1.h b/bin/varnishd/http1/cache_http1.h
index ba010db..f3b3ed2 100644
--- a/bin/varnishd/http1/cache_http1.h
+++ b/bin/varnishd/http1/cache_http1.h
@@ -30,8 +30,8 @@
struct VSC_vbe;
/* cache_http1_fetch.c [V1F] */
-int V1F_SendReq(struct worker *, struct busyobj *, uint64_t *ctr,
- int onlycached);
+int V1F_SendReq(struct worker *, struct busyobj *, uint64_t *ctr_hdrbytes,
+ uint64_t *ctr_bodybytes, int onlycached);
int V1F_FetchRespHdr(struct busyobj *);
int V1F_Setup_Fetch(struct vfp_ctx *vfc, struct http_conn *htc);
@@ -59,5 +59,5 @@ void V1L_EndChunk(const struct worker *w);
void V1L_Open(struct worker *, struct ws *, int *fd, struct vsl_log *,
double t0, unsigned niov);
unsigned V1L_Flush(const struct worker *w);
-unsigned V1L_Close(struct worker *w);
+unsigned V1L_Close(struct worker *w, uint64_t *cnt);
size_t V1L_Write(const struct worker *w, const void *ptr, ssize_t len);
diff --git a/bin/varnishd/http1/cache_http1_deliver.c b/bin/varnishd/http1/cache_http1_deliver.c
index b1b8627..c7a6226 100644
--- a/bin/varnishd/http1/cache_http1_deliver.c
+++ b/bin/varnishd/http1/cache_http1_deliver.c
@@ -50,7 +50,6 @@ v1d_bytes(struct req *req, enum vdp_action act, void **priv,
if (len > 0)
wl = V1L_Write(req->wrk, ptr, len);
- req->acct.resp_bodybytes += len;
if (act > VDP_NULL && V1L_Flush(req->wrk))
return (-1);
if (len != wl)
@@ -87,6 +86,8 @@ void v_matchproto_(vtr_deliver_f)
V1D_Deliver(struct req *req, struct boc *boc, int sendbody)
{
int err;
+ unsigned u;
+ uint64_t hdrbytes, bytes;
CHECK_OBJ_NOTNULL(req, REQ_MAGIC);
CHECK_OBJ_ORNULL(boc, BOC_MAGIC);
@@ -140,17 +141,23 @@ V1D_Deliver(struct req *req, struct boc *boc, int sendbody)
return;
}
- req->acct.resp_hdrbytes += HTTP1_Write(req->wrk, req->resp, HTTP1_Resp);
+ hdrbytes = HTTP1_Write(req->wrk, req->resp, HTTP1_Resp);
if (DO_DEBUG(DBG_FLUSH_HEAD))
(void)V1L_Flush(req->wrk);
- if (!sendbody || req->res_mode & RES_ESI)
- if (V1L_Close(req->wrk) && req->sp->fd >= 0) {
+ if (!sendbody || req->res_mode & RES_ESI) {
+ if (V1L_Close(req->wrk, &bytes) && req->sp->fd >= 0) {
Req_Fail(req, SC_REM_CLOSE);
sendbody = 0;
}
+ /* Charge bytes sent as reported from V1L_Close. Only
+ * header-bytes have been attempted sent. */
+ req->acct.resp_hdrbytes += bytes;
+ hdrbytes = 0;
+ }
+
if (!sendbody) {
AZ(req->wrk->v1l);
VDP_close(req);
@@ -178,7 +185,17 @@ V1D_Deliver(struct req *req, struct boc *boc, int sendbody)
if (!err && (req->res_mode & RES_CHUNKED))
V1L_EndChunk(req->wrk);
- if ((V1L_Close(req->wrk) || err) && req->sp->fd >= 0)
+ u = V1L_Close(req->wrk, &bytes);
+
+ /* Bytes accounting */
+ if (bytes < hdrbytes)
+ req->acct.resp_hdrbytes += bytes;
+ else {
+ req->acct.resp_hdrbytes += hdrbytes;
+ req->acct.resp_bodybytes += bytes - hdrbytes;
+ }
+
+ if ((u || err) && req->sp->fd >= 0)
Req_Fail(req, SC_REM_CLOSE);
AZ(req->wrk->v1l);
VDP_close(req);
diff --git a/bin/varnishd/http1/cache_http1_fetch.c b/bin/varnishd/http1/cache_http1_fetch.c
index 07a2194..a3b7b4f 100644
--- a/bin/varnishd/http1/cache_http1_fetch.c
+++ b/bin/varnishd/http1/cache_http1_fetch.c
@@ -53,7 +53,7 @@ vbf_iter_req_body(void *priv, int flush, const void *ptr, ssize_t l)
CAST_OBJ_NOTNULL(bo, priv, BUSYOBJ_MAGIC);
if (l > 0) {
- bo->acct.bereq_bodybytes += V1L_Write(bo->wrk, ptr, l);
+ (void)V1L_Write(bo->wrk, ptr, l);
if (flush && V1L_Flush(bo->wrk))
return (-1);
}
@@ -69,12 +69,13 @@ vbf_iter_req_body(void *priv, int flush, const void *ptr, ssize_t l)
*/
int
-V1F_SendReq(struct worker *wrk, struct busyobj *bo, uint64_t *ctr,
- int onlycached)
+V1F_SendReq(struct worker *wrk, struct busyobj *bo, uint64_t *ctr_hdrbytes,
+ uint64_t *ctr_bodybytes, int onlycached)
{
struct http *hp;
int j;
ssize_t i;
+ uint64_t bytes, hdrbytes;
struct http_conn *htc;
int do_chunked = 0;
char abuf[VTCP_ADDRBUFSIZE];
@@ -84,6 +85,8 @@ V1F_SendReq(struct worker *wrk, struct busyobj *bo, uint64_t *ctr,
CHECK_OBJ_NOTNULL(bo, BUSYOBJ_MAGIC);
CHECK_OBJ_NOTNULL(bo->htc, HTTP_CONN_MAGIC);
CHECK_OBJ_ORNULL(bo->req, REQ_MAGIC);
+ AN(ctr_hdrbytes);
+ AN(ctr_bodybytes);
htc = bo->htc;
assert(*htc->rfd > 0);
@@ -100,7 +103,7 @@ V1F_SendReq(struct worker *wrk, struct busyobj *bo, uint64_t *ctr,
(void)VTCP_blocking(*htc->rfd); /* XXX: we should timeout instead */
V1L_Open(wrk, wrk->aws, htc->rfd, bo->vsl, bo->t_prev, 0);
- *ctr += HTTP1_Write(wrk, hp, HTTP1_Req);
+ hdrbytes = HTTP1_Write(wrk, hp, HTTP1_Req);
/* Deal with any message-body the request might (still) have */
i = 0;
@@ -122,7 +125,16 @@ V1F_SendReq(struct worker *wrk, struct busyobj *bo, uint64_t *ctr,
V1L_EndChunk(wrk);
}
- j = V1L_Close(wrk);
+ j = V1L_Close(wrk, &bytes);
+
+ /* Bytes accounting */
+ if (bytes < hdrbytes)
+ *ctr_hdrbytes += bytes;
+ else {
+ *ctr_hdrbytes += hdrbytes;
+ *ctr_bodybytes += bytes - hdrbytes;
+ }
+
if (j != 0 || i < 0) {
VSLb(bo->vsl, SLT_FetchError, "backend write error: %d (%s)",
errno, strerror(errno));
diff --git a/bin/varnishd/http1/cache_http1_line.c b/bin/varnishd/http1/cache_http1_line.c
index 2ab0712..7897cca 100644
--- a/bin/varnishd/http1/cache_http1_line.c
+++ b/bin/varnishd/http1/cache_http1_line.c
@@ -127,16 +127,18 @@ V1L_Open(struct worker *wrk, struct ws *ws, int *fd, struct vsl_log *vsl,
}
unsigned
-V1L_Close(struct worker *wrk)
+V1L_Close(struct worker *wrk, uint64_t *cnt)
{
struct v1l *v1l;
unsigned u;
CHECK_OBJ_NOTNULL(wrk, WORKER_MAGIC);
+ AN(cnt);
u = V1L_Flush(wrk);
v1l = wrk->v1l;
wrk->v1l = NULL;
CHECK_OBJ_NOTNULL(v1l, V1L_MAGIC);
+ *cnt = v1l->cnt;
if (v1l->ws->r)
WS_Release(v1l->ws, 0);
WS_Reset(v1l->ws, v1l->res);
diff --git a/bin/varnishtest/tests/e00003.vtc b/bin/varnishtest/tests/e00003.vtc
index b3e65fa..71c5c63 100644
--- a/bin/varnishtest/tests/e00003.vtc
+++ b/bin/varnishtest/tests/e00003.vtc
@@ -32,7 +32,8 @@ varnish v1 -vcl+backend {
logexpect l1 -v v1 -g request {
expect 0 1001 Begin "^req .* rxreq"
- expect * = ReqAcct "^18 0 18 187 75 262$"
+ # ReqAcct body counts include chunked overhead
+ expect * = ReqAcct "^18 0 18 187 104 291$"
expect 0 = End
} -start
@@ -54,7 +55,9 @@ logexpect l4 -v v1 -g request {
logexpect l5 -v v1 -g request {
expect * 1005 Begin "^req .* rxreq"
- expect * = ReqAcct "^18 0 18 192 75 267$"
+ # ReqAcct body counts include chunked overhead
+ # Header bytes is 5 larger than in l1 due to two item X-Varnish hdr
+ expect * = ReqAcct "^18 0 18 192 104 296$"
expect 0 = End
} -start
diff --git a/bin/varnishtest/tests/l00003.vtc b/bin/varnishtest/tests/l00003.vtc
index af3675e..6ef90a3 100644
--- a/bin/varnishtest/tests/l00003.vtc
+++ b/bin/varnishtest/tests/l00003.vtc
@@ -35,22 +35,34 @@ varnish v1 -vcl+backend {
# Reponse:
# HTTP/1.1 200 OK\r\n 17 bytes
+# Accept-Ranges: bytes\r\n 22 bytes
# Transfer-Encoding: chunked\r\n 28 bytes
# Connection: keep-alive\r\n 24 bytes
# \r\n 2 bytes
-# Total: 71 bytes
+# Total: 93 bytes
# Response body:
-# 123\r\n 5 bytes
-# abc\r\n 5 bytes
-# 123\r\n 5 bytes
-# def\r\n 5 bytes
-# ghi\r\n 5 bytes
-# Total: 15 bytes
+# Chunk len 5 bytes
+# 123 3 bytes
+# Chunk end 2 bytes
+# Chunk len 5 bytes
+# abc 3 bytes
+# Chunk end 2 bytes
+# Chunk len 5 bytes
+# 123 3 bytes
+# Chunk end 2 bytes
+# Chunk len 5 bytes
+# def 3 bytes
+# Chunk end 2 bytes
+# Chunk len 5 bytes
+# ghi 3 bytes
+# Chunk end 2 bytes
+# Chunked end 5 bytes
+# Total: 55 bytes
logexpect l1 -v v1 -g request {
expect 0 1001 Begin "^req .* rxreq"
- expect * = ReqAcct "^18 0 18 93 15 108$"
+ expect * = ReqAcct "^18 0 18 93 55 148$"
expect 0 = End
expect * 1003 Begin "^req .* esi"
expect * = ReqAcct "^0 0 0 0 12 12$"
@@ -75,4 +87,4 @@ logexpect l1 -wait
varnish v1 -expect s_req_hdrbytes == 18
varnish v1 -expect s_req_bodybytes == 0
varnish v1 -expect s_resp_hdrbytes == 93
-varnish v1 -expect s_resp_bodybytes == 33
+varnish v1 -expect s_resp_bodybytes == 55
diff --git a/doc/changes.rst b/doc/changes.rst
index a82cacc..ba00c69 100644
--- a/doc/changes.rst
+++ b/doc/changes.rst
@@ -57,6 +57,13 @@ Logging / statistics
* added ``cache_hit_grace`` statistics counter
+* The byte counters in ReqAcct now show the numbers reported from the
+ operating system rather than what we anticipated to send. This will give
+ more accurate numbers when e.g. the client hung up early without
+ receiving the entire response. Also these counters now show how many
+ bytes was attributed to the body, including any protocol overhead (ie
+ chunked encoding).
+
C APIs (for vmod and utility authors)
-------------------------------------
diff --git a/include/tbl/vsl_tags.h b/include/tbl/vsl_tags.h
index f7fa3d5..dc57526 100644
--- a/include/tbl/vsl_tags.h
+++ b/include/tbl/vsl_tags.h
@@ -475,9 +475,10 @@ SLTM(Timestamp, 0, "Timing information",
SLTM(ReqAcct, 0, "Request handling byte counts",
"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 body bytes count includes transmission overhead"
+ " (ie: chunked encoding).\n"
+ "ESI sub-requests show the body bytes this ESI fragment including"
+ " any subfragments contributed to the top level request.\n"
"The format is::\n\n"
"\t%d %d %d %d %d %d\n"
"\t| | | | | |\n"
More information about the varnish-commit
mailing list