From bb5da78e8e23d5b149c723dfde15cddaac222202 Mon Sep 17 00:00:00 2001 From: Asad Sajjad Ahmed Date: Mon, 19 Aug 2024 13:48:29 +0200 Subject: [PATCH] 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 --- bin/varnishd/cache/cache_backend.c | 12 +++++++++--- bin/varnishd/cache/cache_conn_pool.c | 23 ++++++++++++++++++++++- bin/varnishd/cache/cache_conn_pool.h | 2 ++ bin/varnishtest/tests/b00087.vtc | 28 ++++++++++++++++++++++++++++ include/tbl/vsl_tags.h | 20 +++++++++++--------- 5 files changed, 72 insertions(+), 13 deletions(-) create mode 100644 bin/varnishtest/tests/b00087.vtc diff --git a/bin/varnishd/cache/cache_backend.c b/bin/varnishd/cache/cache_backend.c index 9956d30e009..ca00cb3d41d 100644 --- a/bin/varnishd/cache/cache_backend.c +++ b/bin/varnishd/cache/cache_backend.c @@ -325,9 +325,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, VTIM_real()), 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 c879dd66980..bf091ef9f04 100644 --- a/bin/varnishd/cache/cache_conn_pool.c +++ b/bin/varnishd/cache/cache_conn_pool.c @@ -63,6 +63,9 @@ struct pfd { struct conn_pool *conn_pool; pthread_cond_t *cond; + + vtim_real created; + uint64_t reused; }; /*-------------------------------------------------------------------- @@ -126,6 +129,21 @@ PFD_Fd(struct pfd *p) return (&(p->fd)); } +vtim_real +PFD_Age(const struct pfd *p, vtim_real now) +{ + CHECK_OBJ_NOTNULL(p, PFD_MAGIC); + 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) @@ -455,6 +473,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); @@ -473,8 +492,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_real(); 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 0da4c99c6ee..820769bcccd 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_real PFD_Age(const struct pfd *, vtim_real); +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/b00087.vtc b/bin/varnishtest/tests/b00087.vtc new file mode 100644 index 00000000000..da5c37a7b7f --- /dev/null +++ b/bin/varnishtest/tests/b00087.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 2c35404db41..a0e1b887cbf 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 [ %.6f %ld ]\n" + "\t| | | | | | | | |\n" + "\t| | | | | | | | +- Connection uses\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" )