[master] d3a6a6076 vsl: Log the progress of streaming hits
Dridi Boukelmoune
dridi.boukelmoune at gmail.com
Mon Aug 30 12:28:04 UTC 2021
commit d3a6a60769a751676df0bf478741573f4efc6281
Author: Dridi Boukelmoune <dridi.boukelmoune at gmail.com>
Date: Thu Apr 1 08:10:17 2021 +0200
vsl: Log the progress of streaming hits
The larger the response we hit, the more likely we are to hit an ongoing
fetch and since we buffer transaction logs it can become really tedious
to infer whether the backend transaction may have already been overrun
or not flushed yet. At least, such a heuristic was impossible with a VSL
query until now.
diff --git a/bin/varnishd/cache/cache_hash.c b/bin/varnishd/cache/cache_hash.c
index 1af3a3793..5d24e0479 100644
--- a/bin/varnishd/cache/cache_hash.c
+++ b/bin/varnishd/cache/cache_hash.c
@@ -369,6 +369,7 @@ HSH_Lookup(struct req *req, struct objcore **ocp, struct objcore **bocp)
vtim_real exp_t_origin;
int busy_found;
const uint8_t *vary;
+ intmax_t boc_progress;
unsigned xid = 0;
float dttl = 0.0;
@@ -519,7 +520,9 @@ HSH_Lookup(struct req *req, struct objcore **ocp, struct objcore **bocp)
return (HSH_HITMISS);
}
oc->hits++;
+ boc_progress = oc->boc == NULL ? -1 : oc->boc->len_so_far;
AN(hsh_deref_objhead_unlock(wrk, &oh, HSH_RUSH_POLICY));
+ Req_LogHit(wrk, req, oc, boc_progress);
return (HSH_HIT);
}
@@ -539,6 +542,11 @@ HSH_Lookup(struct req *req, struct objcore **ocp, struct objcore **bocp)
return (HSH_HITMISS);
}
+ if (exp_oc != NULL && exp_oc->boc != NULL)
+ boc_progress = exp_oc->boc->len_so_far;
+ else
+ boc_progress = -1;
+
if (!busy_found) {
*bocp = hsh_insert_busyobj(wrk, oh);
@@ -548,6 +556,7 @@ HSH_Lookup(struct req *req, struct objcore **ocp, struct objcore **bocp)
if (EXP_Ttl_grace(req, exp_oc) >= req->t_req) {
exp_oc->hits++;
Lck_Unlock(&oh->mtx);
+ Req_LogHit(wrk, req, exp_oc, boc_progress);
return (HSH_GRACE);
}
}
@@ -562,6 +571,7 @@ HSH_Lookup(struct req *req, struct objcore **ocp, struct objcore **bocp)
*ocp = exp_oc;
exp_oc->hits++;
AN(hsh_deref_objhead_unlock(wrk, &oh, 0));
+ Req_LogHit(wrk, req, exp_oc, boc_progress);
return (HSH_GRACE);
}
diff --git a/bin/varnishd/cache/cache_req.c b/bin/varnishd/cache/cache_req.c
index 09addfde4..5b3fe1964 100644
--- a/bin/varnishd/cache/cache_req.c
+++ b/bin/varnishd/cache/cache_req.c
@@ -72,6 +72,33 @@ Req_AcctLogCharge(struct VSC_main_wrk *ds, struct req *req)
memset(a, 0, sizeof *a);
}
+void
+Req_LogHit(struct worker *wrk, struct req *req, struct objcore *oc,
+ intmax_t fetch_progress)
+{
+ const char *clen, *sep;
+
+ CHECK_OBJ_NOTNULL(wrk, WORKER_MAGIC);
+ CHECK_OBJ_NOTNULL(req, REQ_MAGIC);
+ CHECK_OBJ_NOTNULL(oc, OBJCORE_MAGIC);
+
+ if (fetch_progress >= 0) {
+ clen = HTTP_GetHdrPack(wrk, oc, H_Content_Length);
+ if (clen == NULL)
+ clen = sep = "";
+ else
+ sep = " ";
+ VSLb(req->vsl, SLT_Hit, "%u %.6f %.6f %.6f %jd%s%s",
+ ObjGetXID(wrk, oc), EXP_Dttl(req, oc),
+ oc->grace, oc->keep,
+ fetch_progress, sep, clen);
+ } else {
+ VSLb(req->vsl, SLT_Hit, "%u %.6f %.6f %.6f",
+ ObjGetXID(wrk, oc), EXP_Dttl(req, oc),
+ oc->grace, oc->keep);
+ }
+}
+
/*--------------------------------------------------------------------
* Alloc/Free a request
*/
diff --git a/bin/varnishd/cache/cache_req_fsm.c b/bin/varnishd/cache/cache_req_fsm.c
index 9ad2aa28d..6c6484236 100644
--- a/bin/varnishd/cache/cache_req_fsm.c
+++ b/bin/varnishd/cache/cache_req_fsm.c
@@ -602,12 +602,6 @@ cnt_lookup(struct worker *wrk, struct req *req)
req->objcore = oc;
AZ(oc->flags & OC_F_HFM);
- VSLb(req->vsl, SLT_Hit, "%u %.6f %.6f %.6f",
- ObjGetXID(wrk, req->objcore),
- EXP_Dttl(req, req->objcore),
- req->objcore->grace,
- req->objcore->keep);
-
VCL_hit_method(req->vcl, wrk, req, NULL, NULL);
switch (wrk->handling) {
diff --git a/bin/varnishd/cache/cache_varnishd.h b/bin/varnishd/cache/cache_varnishd.h
index c3defbdce..653976cdc 100644
--- a/bin/varnishd/cache/cache_varnishd.h
+++ b/bin/varnishd/cache/cache_varnishd.h
@@ -403,6 +403,7 @@ void Req_Rollback(VRT_CTX);
void Req_Cleanup(struct sess *sp, struct worker *wrk, struct req *req);
void Req_Fail(struct req *req, enum sess_close reason);
void Req_AcctLogCharge(struct VSC_main_wrk *, struct req *);
+void Req_LogHit(struct worker *, struct req *, struct objcore *, intmax_t);
/* cache_req_body.c */
int VRB_Ignore(struct req *);
diff --git a/bin/varnishtest/tests/b00077.vtc b/bin/varnishtest/tests/b00077.vtc
new file mode 100644
index 000000000..d44cc1073
--- /dev/null
+++ b/bin/varnishtest/tests/b00077.vtc
@@ -0,0 +1,73 @@
+varnishtest "SLT_Hit ongoing fetch"
+
+barrier b1 cond 2 -cyclic
+barrier b2 cond 2 -cyclic
+
+server s1 {
+ rxreq
+ txresp -nolen -hdr "Content-Length: 10"
+ send hello
+ barrier b1 sync
+ barrier b2 sync
+ send world
+
+ rxreq
+ txresp -nolen -hdr "Transfer-Encoding: chunked"
+ chunked hello
+ barrier b1 sync
+ barrier b2 sync
+ chunked world
+ chunked ""
+} -start
+
+varnish v1 -cliok "param.set debug +syncvsl"
+varnish v1 -cliok "param.set thread_pools 1"
+varnish v1 -vcl+backend "" -start
+
+client c1 {
+ txreq
+ rxresp
+ expect resp.body == helloworld
+} -start
+
+barrier b1 sync
+
+logexpect l1 -v v1 -g raw {
+ # vxid TTL grace keep fetch length
+ expect * 1004 Hit "^1002 [0-9.]+ 10.000000 0.000000 [0-5] 10$"
+} -start
+
+client c2 {
+ txreq
+ rxresp
+ expect resp.body == helloworld
+} -start
+
+logexpect l1 -wait
+
+barrier b2 sync
+
+client c1 -wait
+client c2 -wait
+
+# Recycle almost everything for the chunked variant
+
+varnish v1 -cliok "ban obj.status != 0"
+
+client c1 -start
+
+barrier b1 sync
+
+logexpect l2 -v v1 -g raw {
+ # vxid TTL grace keep fetch
+ expect * 1009 Hit "^1007 [0-9.]+ 10.000000 0.000000 [0-5]$"
+} -start
+
+client c2 -start
+
+logexpect l2 -wait
+
+barrier b2 sync
+
+client c1 -wait
+client c2 -wait
diff --git a/include/tbl/vsl_tags.h b/include/tbl/vsl_tags.h
index 2d3d3cf86..0ff7e0301 100644
--- a/include/tbl/vsl_tags.h
+++ b/include/tbl/vsl_tags.h
@@ -338,12 +338,14 @@ SLTM(ReqStart, 0, "Client request start",
SLTM(Hit, 0, "Hit object in cache",
"Object looked up in cache.\n\n"
"The format is::\n\n"
- "\t%u %f %f %f\n"
- "\t| | | |\n"
- "\t| | | +- Keep period\n"
- "\t| | +---- Grace period\n"
- "\t| +------- Remaining TTL\n"
- "\t+---------- VXID of the object\n"
+ "\t%u %f %f %f [%u [%u]]\n"
+ "\t| | | | | |\n"
+ "\t| | | | | +- Content length\n"
+ "\t| | | | +----- Fetched so far\n"
+ "\t| | | +--------- Keep period\n"
+ "\t| | +------------ Grace period\n"
+ "\t| +--------------- Remaining TTL\n"
+ "\t+------------------ VXID of the object\n"
"\n"
)
More information about the varnish-commit
mailing list