Mailing List Archive

commit 5963b6dc0e146d03bdfc7ed0d4cc39fb1053f122
Author: AlveElde <alve_elde@hotmail.com>
Date: Tue Jan 3 03:04:08 2023 +0100

expire: New EXP_Removed log statement

It is generally useful to know when an object leaves the cache and while
it may sometimes be logged by call sites (like bans) it is more helpful
centralize it in ExpKill records to get a (more) complete view of what
goes in and out of (durable) storage.

The hits attribute is especially useful, as it can give an indication of
the popularity of objects being removed before they expire.

diff --git a/bin/varnishd/cache/cache_expire.c b/bin/varnishd/cache/cache_expire.c
index c179f94f8..240dc99f0 100644
--- a/bin/varnishd/cache/cache_expire.c
+++ b/bin/varnishd/cache/cache_expire.c
@@ -261,7 +261,7 @@ EXP_Rearm(struct objcore *oc, vtim_real now,
*/

static void
-exp_inbox(struct exp_priv *ep, struct objcore *oc, unsigned flags)
+exp_inbox(struct exp_priv *ep, struct objcore *oc, unsigned flags, double now)
{

CHECK_OBJ_NOTNULL(ep, EXP_PRIV_MAGIC);
@@ -279,6 +279,9 @@ exp_inbox(struct exp_priv *ep, struct objcore *oc, unsigned flags)
assert(oc->timer_idx == VBH_NOIDX);
assert(oc->refcnt > 0);
AZ(oc->exp_flags);
+ VSLb(&ep->vsl, SLT_ExpKill, "EXP_Removed x=%ju t=%.0f h=%ld",
+ VXID(ObjGetXID(ep->wrk, oc)), EXP_Ttl(NULL, oc) - now,
+ oc->hits);
ObjSendEvent(ep->wrk, oc, OEV_EXPIRE);
(void)HSH_DerefObjCore(ep->wrk, &oc, 0);
return;
@@ -427,7 +430,7 @@ exp_thread(struct worker *wrk, void *priv)
t = VTIM_real();

if (oc != NULL)
- exp_inbox(ep, oc, flags);
+ exp_inbox(ep, oc, flags, t);
else
tnext = exp_expire(ep, t);
}
diff --git a/bin/varnishtest/tests/c00126.vtc b/bin/varnishtest/tests/c00126.vtc
new file mode 100644
index 000000000..7403f7585
--- /dev/null
+++ b/bin/varnishtest/tests/c00126.vtc
@@ -0,0 +1,42 @@
+varnishtest "Make sure EXP_Removed is logged correctly"
+
+server s1 -repeat 4 {
+ rxreq
+ txresp -bodylen 500000
+} -start
+
+varnish v1 -arg "-ss1=default,1m" -vcl+backend { } -start
+varnish v1 -cliok "param.set vsl_mask +ExpKill"
+
+logexpect l1 -v v1 -g raw {
+ expect * 0 ExpKill "EXP_Removed x=1002 t=.* h=1"
+ expect * 0 ExpKill "EXP_Removed x=1005 t=.* h=0"
+} -start
+
+client c1 {
+ loop 2 {
+ txreq -url "/1"
+ rxresp
+ expect resp.status == 200
+ }
+
+ txreq -url "/2"
+ rxresp
+ expect resp.status == 200
+
+ txreq -url "/3"
+ rxresp
+ expect resp.status == 200
+
+ txreq -url "/4"
+ rxresp
+ expect resp.status == 200
+} -run
+
+# NOTE: Nuked objects are mailed twice
+varnish v1 -expect n_lru_nuked == 2
+varnish v1 -expect MAIN.n_object == 2
+varnish v1 -expect MAIN.exp_mailed == 6
+varnish v1 -expect MAIN.exp_received == 6
+
+logexpect l1 -wait
diff --git a/include/tbl/vsl_tags.h b/include/tbl/vsl_tags.h
index c65257dcc..84632b861 100644
--- a/include/tbl/vsl_tags.h
+++ b/include/tbl/vsl_tags.h
@@ -355,6 +355,8 @@ SLTM(ExpKill, 0, "Object expiry event",
"\tLogged when the expiry thread moves an object on the binheap.\n\n"
"EXP_Expired\n"
"\tLogged when the expiry thread expires an object.\n\n"
+ "EXP_Removed\n"
+ "\tLogged when the expiry thread removes an object before expiry.\n\n"
"LRU_Cand\n"
"\tLogged when an object is evaluated for LRU force expiry.\n\n"
"LRU\n"
@@ -368,6 +370,7 @@ SLTM(ExpKill, 0, "Object expiry event",
"\tEXP_Kill p=%p e=%f f=0x%x\n"
"\tEXP_When p=%p e=%f f=0x%x\n"
"\tEXP_Expired x=%u t=%f h=%u\n"
+ "\tEXP_Removed x=%u t=%f h=%u\n"
"\tLRU_Cand p=%p f=0x%x r=%d\n"
"\tLRU x=%u\n"
"\tLRU_Fail\n"
_______________________________________________
varnish-commit mailing list
varnish-commit@varnish-cache.org
https://www.varnish-cache.org/lists/mailman/listinfo/varnish-commit