[4.0] c654dc5 ESI byte accounting
Martin Blix Grydeland
martin at varnish-software.com
Tue Apr 1 15:09:55 CEST 2014
commit c654dc51e6bbb5b58ab8f9cc80b2cd6b12c85e1e
Author: Martin Blix Grydeland <martin at varnish-software.com>
Date: Sat Mar 29 23:04:07 2014 +0100
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.
diff --git a/bin/varnishd/cache/cache.h b/bin/varnishd/cache/cache.h
index de7d895..2e41e24 100644
--- a/bin/varnishd/cache/cache.h
+++ b/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;
diff --git a/bin/varnishd/cache/cache_esi_deliver.c b/bin/varnishd/cache/cache_esi_deliver.c
index dbbe7b1..5aa85ee 100644
--- a/bin/varnishd/cache/cache_esi_deliver.c
+++ b/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);
diff --git a/bin/varnishd/cache/cache_http1_deliver.c b/bin/varnishd/cache/cache_http1_deliver.c
index 5e99668..765fd83 100644
--- a/bin/varnishd/cache/cache_http1_deliver.c
+++ b/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)
diff --git a/bin/varnishd/cache/cache_http1_fsm.c b/bin/varnishd/cache/cache_http1_fsm.c
index a46534c..9bb5e79 100644
--- a/bin/varnishd/cache/cache_http1_fsm.c
+++ b/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 */
diff --git a/bin/varnishd/cache/cache_req_fsm.c b/bin/varnishd/cache/cache_req_fsm.c
index 8888226..2236553 100644
--- a/bin/varnishd/cache/cache_req_fsm.c
+++ b/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);
diff --git a/bin/varnishd/cache/cache_session.c b/bin/varnishd/cache/cache_session.c
index 0c5d2f9..0c010c1 100644
--- a/bin/varnishd/cache/cache_session.c
+++ b/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;
diff --git a/bin/varnishtest/tests/l00003.vtc b/bin/varnishtest/tests/l00003.vtc
new file mode 100644
index 0000000..cb03a18
--- /dev/null
+++ b/bin/varnishtest/tests/l00003.vtc
@@ -0,0 +1,84 @@
+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
diff --git a/include/tbl/vsl_tags.h b/include/tbl/vsl_tags.h
index 252b859..0213a61 100644
--- a/include/tbl/vsl_tags.h
+++ b/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
More information about the varnish-commit
mailing list