[master] d496f0004 varnishd: add backend age & reuses to Open & Close

[Nils Goroll]

commit d496f0004e31e85700701b2d6cdc263d30eab857
Author: Asad Sajjad Ahmed <asadsa at varnish-software.com>
Date:   Mon Aug 19 13:48:29 2024 +0200

    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 <asadsa at varnish-software.com>

diff --git a/bin/varnishd/cache/cache_backend.c b/bin/varnishd/cache/cache_backend.c
index 35b26f084..4af19052b 100644
--- a/bin/varnishd/cache/cache_backend.c
+++ b/bin/varnishd/cache/cache_backend.c
@@ -334,9 +334,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
index 5dd02723a..00a190da3 100644
--- a/bin/varnishd/cache/cache_conn_pool.c
+++ b/bin/varnishd/cache/cache_conn_pool.c
@@ -66,6 +66,9 @@ struct pfd {
 	struct conn_pool	*conn_pool;
 
 	pthread_cond_t		*cond;
+
+	vtim_mono		created;
+	uint64_t		reused;
 };
 
 /*--------------------------------------------------------------------
@@ -139,6 +142,25 @@ PFD_Fd(struct pfd *p)
 	return (&(p->fd));
 }
 
+vtim_dur
+PFD_Age(const struct pfd *p)
+{
+	vtim_mono t_mono;
+
+	CHECK_OBJ_NOTNULL(p, PFD_MAGIC);
+	t_mono = VTIM_mono();
+	assert(t_mono >= p->created);
+
+	return (t_mono - 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)
@@ -541,6 +563,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);
@@ -559,8 +582,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
index 0da4c99c6..1b3903277 100644
--- 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_dur 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/b00098.vtc b/bin/varnishtest/tests/b00098.vtc
new file mode 100644
index 000000000..da5c37a7b
--- /dev/null
+++ b/bin/varnishtest/tests/b00098.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
index 9c1aae69d..9954f1494 100644
--- 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 [ %f %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"
 )