varnishd: add backend age & reuses to Open & Close

This extra information comes handy when trubleshooting idle timeout from the backend. Signed-off-by: Asad Sajjad Ahmed <[email protected]>
varnishcache · Nov 7, 2024 · e244e96 · e244e96
1 parent febf5a0
commit e244e96
Show file tree

Hide file tree

Showing 5 changed files with 76 additions and 13 deletions.
diff --git a/bin/varnishd/cache/cache_backend.c b/bin/varnishd/cache/cache_backend.c
@@ -328,9 +328,15 @@ vbe_dir_getfd(VRT_CTX, struct worker *wrk, VCL_BACKEND dir, struct backend *bp,
 
 	PFD_LocalName(pfd, abuf1, sizeof abuf1, pbuf1, sizeof pbuf1);
 	PFD_RemoteName(pfd, abuf2, sizeof abuf2, pbuf2, sizeof pbuf2);
-	VSLb(bo->vsl, SLT_BackendOpen, "%d %s %s %s %s %s %s",
-	    *fdp, VRT_BACKEND_string(dir), abuf2, pbuf2, abuf1, pbuf1,
-	    PFD_State(pfd) == PFD_STATE_STOLEN ? "reuse" : "connect");
+	if (PFD_State(pfd) != PFD_STATE_STOLEN) {
+		VSLb(bo->vsl, SLT_BackendOpen, "%d %s %s %s %s %s connect",
+		    *fdp, VRT_BACKEND_string(dir), abuf2, pbuf2, abuf1, pbuf1);
+	} else {
+		VSLb(bo->vsl, SLT_BackendOpen,
+		    "%d %s %s %s %s %s reuse %.6f %ju", *fdp,
+		    VRT_BACKEND_string(dir), abuf2, pbuf2, abuf1, pbuf1,
+		    PFD_Age(pfd), PFD_Reused(pfd));
+	}
 
 	INIT_OBJ(bo->htc, HTTP_CONN_MAGIC);
 	bo->htc->priv = pfd;

diff --git a/bin/varnishd/cache/cache_conn_pool.c b/bin/varnishd/cache/cache_conn_pool.c
@@ -64,6 +64,9 @@ struct pfd {
 	struct conn_pool	*conn_pool;
 
 	pthread_cond_t		*cond;
+
+	vtim_mono		created;
+	uint64_t		reused;
 };
 
 /*--------------------------------------------------------------------
@@ -131,6 +134,25 @@ PFD_Fd(struct pfd *p)
 	return (&(p->fd));
 }
 
+vtim_mono
+PFD_Age(const struct pfd *p)
+{
+	vtim_mono now;
+
+	CHECK_OBJ_NOTNULL(p, PFD_MAGIC);
+	now = VTIM_mono();
+	assert(now >= p->created);
+
+	return (now - p->created);
+}
+
+uint64_t
+PFD_Reused(const struct pfd *p)
+{
+	CHECK_OBJ_NOTNULL(p, PFD_MAGIC);
+	return (p->reused);
+}
+
 void
 PFD_LocalName(const struct pfd *p, char *abuf, unsigned alen, char *pbuf,
 	      unsigned plen)
@@ -469,6 +491,7 @@ VCP_Get(struct conn_pool *cp, vtim_dur tmo, struct worker *wrk,
 		VSC_C_main->backend_reuse++;
 		pfd->state = PFD_STATE_STOLEN;
 		pfd->cond = &wrk->cond;
+		pfd->reused++;
 	}
 	cp->n_used++;			// Opening mostly works
 	Lck_Unlock(&cp->mtx);
@@ -487,8 +510,10 @@ VCP_Get(struct conn_pool *cp, vtim_dur tmo, struct worker *wrk,
 		Lck_Lock(&cp->mtx);
 		cp->n_used--;		// Nope, didn't work after all.
 		Lck_Unlock(&cp->mtx);
-	} else
+	} else {
+		pfd->created = VTIM_mono();
 		VSC_C_main->backend_conn++;
+	}
 
 	return (pfd);
 }

diff --git a/bin/varnishd/cache/cache_conn_pool.h b/bin/varnishd/cache/cache_conn_pool.h
@@ -45,6 +45,8 @@ struct pfd;
 
 unsigned PFD_State(const struct pfd *);
 int *PFD_Fd(struct pfd *);
+vtim_real PFD_Age(const struct pfd *);
+uint64_t PFD_Reused(const struct pfd *);
 void PFD_LocalName(const struct pfd *, char *, unsigned, char *, unsigned);
 void PFD_RemoteName(const struct pfd *, char *, unsigned, char *, unsigned);
 

diff --git a/bin/varnishtest/tests/b00092.vtc b/bin/varnishtest/tests/b00092.vtc
@@ -0,0 +1,28 @@
+varnishtest "VSL tags backend age & reuse"
+
+server s1 {
+	rxreq
+	txresp
+	rxreq
+	txresp
+} -start
+
+varnish v1 -vcl+backend {} -start
+varnish v1 -cliok "param.set debug +syncvsl"
+
+client c1 {
+	txreq
+	rxresp
+	expect resp.status == 200
+	txreq -url /2
+	rxresp
+	expect resp.status == 200
+} -run
+
+logexpect l1 -v v1 -d 1 -g session {
+	expect * *	Begin		^bereq
+	expect * =	BackendOpen	"connect$"
+	expect * =	BackendClose	"s1 recycle$"
+	expect * *	BackendOpen	"reuse \\d+\\.\\d\\d\\d\\d\\d\\d 1$"
+	expect * =	BackendClose	"s1 recycle$"
+} -run
diff --git a/include/tbl/vsl_tags.h b/include/tbl/vsl_tags.h
@@ -138,15 +138,17 @@ SLTM(SessClose, 0, "Client connection closed",
 SLTM(BackendOpen, 0, "Backend connection opened",
 	"Logged when a new backend connection is opened.\n\n"
 	"The format is::\n\n"
-	"\t%d %s %s %s %s %s %s\n"
-	"\t|  |  |  |  |  |  |\n"
-	"\t|  |  |  |  |  |  +- \"connect\" or \"reuse\"\n"
-	"\t|  |  |  |  |  +---- Local port\n"
-	"\t|  |  |  |  +------- Local address\n"
-	"\t|  |  |  +---------- Remote port\n"
-	"\t|  |  +------------- Remote address\n"
-	"\t|  +---------------- Backend display name\n"
-	"\t+------------------- Connection file descriptor\n"
+	"\t%d %s %s %s %s %s %s [ %.6f %ld ]\n"
+	"\t|  |  |  |  |  |  |    |    |\n"
+	"\t|  |  |  |  |  |  |    |    +- Connection reuses\n"
+	"\t|  |  |  |  |  |  |    +------ Connection age\n"
+	"\t|  |  |  |  |  |  +----------- \"connect\" or \"reuse\"\n"
+	"\t|  |  |  |  |  +-------------- Local port\n"
+	"\t|  |  |  |  +----------------- Local address\n"
+	"\t|  |  |  +-------------------- Remote port\n"
+	"\t|  |  +----------------------- Remote address\n"
+	"\t|  +-------------------------- Backend display name\n"
+	"\t+----------------------------- Connection file descriptor\n"
 	"\n"
 )