[master] 8edf31f Add the TTL, grace and keep to Hit log records
Dridi Boukelmoune
dridi.boukelmoune at gmail.com
Mon Aug 28 13:10:08 CEST 2017
commit 8edf31f12b0a6870c35d9b23419486aff7babd42
Author: Dridi Boukelmoune <dridi.boukelmoune at gmail.com>
Date: Mon Aug 28 11:32:48 2017 +0200
Add the TTL, grace and keep to Hit log records
For HitMiss and HitPass, only show the remaining TTL. Seeing these
values should help debugging of timing-sensitive transactions. The
grace and keep periods are absolute, but the TTL is the remaining
time relative to the current request. Same as obj.{ttl,grace,keep}
variables in VCL.
diff --git a/bin/varnishd/cache/cache_hash.c b/bin/varnishd/cache/cache_hash.c
index 56d06c2..3549867 100644
--- a/bin/varnishd/cache/cache_hash.c
+++ b/bin/varnishd/cache/cache_hash.c
@@ -440,13 +440,13 @@ HSH_Lookup(struct req *req, struct objcore **ocp, struct objcore **bocp,
assert(oc->objhead == oh);
if (oc->flags & OC_F_HFP) {
wrk->stats->cache_hitpass++;
- VSLb(req->vsl, SLT_HitPass, "%u",
- ObjGetXID(wrk, oc));
+ VSLb(req->vsl, SLT_HitPass, "%u %.6f",
+ ObjGetXID(wrk, oc), EXP_Dttl(req, oc));
oc = NULL;
} else if (oc->flags & OC_F_PASS) {
wrk->stats->cache_hitmiss++;
- VSLb(req->vsl, SLT_HitMiss, "%u",
- ObjGetXID(wrk, oc));
+ VSLb(req->vsl, SLT_HitMiss, "%u %.6f",
+ ObjGetXID(wrk, oc), EXP_Dttl(req, oc));
oc = NULL;
*bocp = hsh_insert_busyobj(wrk, oh);
} else {
@@ -470,7 +470,8 @@ HSH_Lookup(struct req *req, struct objcore **ocp, struct objcore **bocp,
if (exp_oc != NULL && exp_oc->flags & OC_F_PASS) {
wrk->stats->cache_hitmiss++;
- VSLb(req->vsl, SLT_HitMiss, "%u", ObjGetXID(wrk, exp_oc));
+ VSLb(req->vsl, SLT_HitMiss, "%u %.6f", ObjGetXID(wrk, exp_oc),
+ EXP_Dttl(req, exp_oc));
exp_oc = NULL;
busy_found = 0;
}
diff --git a/bin/varnishd/cache/cache_priv.h b/bin/varnishd/cache/cache_priv.h
index 66071b9..941d567 100644
--- a/bin/varnishd/cache/cache_priv.h
+++ b/bin/varnishd/cache/cache_priv.h
@@ -52,6 +52,8 @@ double EXP_Ttl(const struct req *, const struct objcore *);
void EXP_Insert(struct worker *wrk, struct objcore *oc);
void EXP_Remove(struct objcore *);
+#define EXP_Dttl(req, oc) (oc->ttl - (req->t_req - oc->t_origin))
+
/* From cache_main.c */
void BAN_Init(void);
void BAN_Compile(void);
diff --git a/bin/varnishd/cache/cache_req_fsm.c b/bin/varnishd/cache/cache_req_fsm.c
index 2697b4c..f6cb8e9 100644
--- a/bin/varnishd/cache/cache_req_fsm.c
+++ b/bin/varnishd/cache/cache_req_fsm.c
@@ -506,7 +506,11 @@ cnt_lookup(struct worker *wrk, struct req *req)
req->objcore = oc;
AZ(oc->flags & OC_F_PASS);
- VSLb(req->vsl, SLT_Hit, "%u", ObjGetXID(wrk, req->objcore));
+ 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);
diff --git a/bin/varnishtest/tests/c00011.vtc b/bin/varnishtest/tests/c00011.vtc
index 38a91f2..2462267 100644
--- a/bin/varnishtest/tests/c00011.vtc
+++ b/bin/varnishtest/tests/c00011.vtc
@@ -23,7 +23,7 @@ varnish v1 -vcl+backend {
} -start
logexpect l1 -v v1 -g vxid {
- expect 1003 * HitMiss "^1002$"
+ expect 1003 * HitMiss "^1002 119.*$"
} -start
client c1 {
diff --git a/bin/varnishtest/tests/c00081.vtc b/bin/varnishtest/tests/c00081.vtc
index 0cf9827..5b7c551 100644
--- a/bin/varnishtest/tests/c00081.vtc
+++ b/bin/varnishtest/tests/c00081.vtc
@@ -30,7 +30,7 @@ varnish v1 -vcl+backend {
} -start
logexpect l1 -v v1 -g vxid {
- expect 1003 * HitPass "^1002$"
+ expect 1003 * HitPass "^1002 1.*$"
} -start
client c1 {
diff --git a/bin/varnishtest/tests/r01858.vtc b/bin/varnishtest/tests/r01858.vtc
index 23ff7c2..fe1cbe1 100644
--- a/bin/varnishtest/tests/r01858.vtc
+++ b/bin/varnishtest/tests/r01858.vtc
@@ -24,7 +24,7 @@ varnish v1 -vcl+backend {
# Tests logging hit-for-miss on an expired object
logexpect l1 -v v1 -g vxid {
- expect 1003 * HitMiss "^1002$"
+ expect 1003 * HitMiss "^1002 -.*$"
} -start
client c1 {
diff --git a/include/tbl/vsl_tags.h b/include/tbl/vsl_tags.h
index c34df04..a40205c 100644
--- a/include/tbl/vsl_tags.h
+++ b/include/tbl/vsl_tags.h
@@ -276,12 +276,25 @@ SLTM(ReqStart, 0, "Client request start",
)
SLTM(Hit, 0, "Hit object in cache",
- "Object looked up in cache. Shows the VXID of the object.\n\n"
+ "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"
+ "\n"
)
SLTM(HitPass, 0, "Hit for pass object in cache.",
- "Hit-for-pass object looked up in cache. Shows the VXID of the"
- " hit-for-pass object.\n\n"
+ "Hit-for-pass object looked up in cache.\n\n"
+ "The format is::\n\n"
+ "\t%u %f\n"
+ "\t| |\n"
+ "\t| +- Remaining TTL\n"
+ "\t+---- VXID of the object\n"
+ "\n"
)
SLTM(ExpBan, 0, "Object evicted due to ban",
@@ -543,8 +556,13 @@ SLTM(H2TxBody, 0, "Transmitted HTTP2 frame body",
)
SLTM(HitMiss, 0, "Hit for miss object in cache.",
- "Hit-for-miss object looked up in cache. Shows the VXID of the"
- " hit-for-miss object.\n\n"
+ "Hit-for-miss object looked up in cache.\n\n"
+ "The format is::\n\n"
+ "\t%u %f\n"
+ "\t| |\n"
+ "\t| +- Remaining TTL\n"
+ "\t+---- VXID of the object\n"
+ "\n"
)
#undef NODEF_NOTICE
More information about the varnish-commit
mailing list