[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