[master] 3398877 Backend fetch byte accounting
Martin Blix Grydeland
martin at varnish-software.com
Mon Mar 31 11:28:00 CEST 2014
commit 3398877276d228cae9cdcb3c2f5f9a5e7d8178a9
Author: Martin Blix Grydeland <martin at varnish-software.com>
Date: Sun Mar 30 15:17:18 2014 +0200
Backend fetch byte accounting
Add SLT_BereqAcct log records showing headers and bodybytes
received/transmitted when doing backend fetch operations.
diff --git a/bin/varnishd/cache/cache.h b/bin/varnishd/cache/cache.h
index c58a1fc..bf28983 100644
--- a/bin/varnishd/cache/cache.h
+++ b/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;
diff --git a/bin/varnishd/cache/cache_busyobj.c b/bin/varnishd/cache/cache_busyobj.c
index 69f849b..22f6441 100644
--- a/bin/varnishd/cache/cache_busyobj.c
+++ b/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);
diff --git a/bin/varnishd/cache/cache_http1_fetch.c b/bin/varnishd/cache/cache_http1_fetch.c
index 82dcab6..b6fac38 100644
--- a/bin/varnishd/cache/cache_http1_fetch.c
+++ b/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;
diff --git a/bin/varnishtest/tests/l00005.vtc b/bin/varnishtest/tests/l00005.vtc
new file mode 100644
index 0000000..51d0d7e
--- /dev/null
+++ b/bin/varnishtest/tests/l00005.vtc
@@ -0,0 +1,68 @@
+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
diff --git a/include/Makefile.am b/include/Makefile.am
index e996fc0..8291a50 100644
--- a/include/Makefile.am
+++ b/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 \
diff --git a/include/tbl/acct_fields_bereq.h b/include/tbl/acct_fields_bereq.h
new file mode 100644
index 0000000..6454bad
--- /dev/null
+++ b/include/tbl/acct_fields_bereq.h
@@ -0,0 +1,35 @@
+/*-
+ * Copyright (c) 2008 Verdens Gang AS
+ * Copyright (c) 2008-2014 Varnish Software AS
+ * All rights reserved.
+ *
+ * Author: Poul-Henning Kamp <phk at 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)
diff --git a/include/tbl/vsl_tags.h b/include/tbl/vsl_tags.h
index 99894cc..af15d07 100644
--- a/include/tbl/vsl_tags.h
+++ b/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
More information about the varnish-commit
mailing list