diff --git a/bin/varnishd/cache/cache_backend.c b/bin/varnishd/cache/cache_backend.c index d3a98ac56f..b97495c023 100644 --- 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 index 9e940d42d1..a562c281ed 100644 --- 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 index 0da4c99c6e..318d80decc 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 *); +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 new file mode 100644 index 0000000000..da5c37a7b7 --- /dev/null +++ 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 index 9c1aae69d3..da56c616af 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 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" )