From: phk Date: Fri, 4 Aug 2006 19:36:35 +0000 (+0000) Subject: More comprehensive performance stats and a few asserts, just in case. X-Git-Url: https://err.no/cgi-bin/gitweb.cgi?a=commitdiff_plain;h=a6b6f798298b832d4f73257f1b66e2c2fabd907a;p=varnish More comprehensive performance stats and a few asserts, just in case. git-svn-id: svn+ssh://projects.linpro.no/svn/varnish/trunk@640 d4fa192b-c00b-0410-8231-f00ffab90ce4 --- diff --git a/varnish-cache/bin/varnishd/cache.h b/varnish-cache/bin/varnishd/cache.h index 48730dde..f3b48cba 100644 --- a/varnish-cache/bin/varnishd/cache.h +++ b/varnish-cache/bin/varnishd/cache.h @@ -235,7 +235,9 @@ struct sess { const char *doclose; struct http *http; + struct timespec t_open; struct timespec t_req; + struct timespec t_resp; struct timespec t_idle; enum step step; diff --git a/varnish-cache/bin/varnishd/cache_acceptor.c b/varnish-cache/bin/varnishd/cache_acceptor.c index 9d35285c..f769d1d4 100644 --- a/varnish-cache/bin/varnishd/cache_acceptor.c +++ b/varnish-cache/bin/varnishd/cache_acceptor.c @@ -49,6 +49,7 @@ vca_accept_sess(int fd) sp = SES_New(addr, l); assert(sp != NULL); /* XXX handle */ + (void)clock_gettime(CLOCK_REALTIME, &sp->t_open); sp->fd = i; sp->id = i; @@ -246,6 +247,7 @@ vca_return_session(struct sess *sp) SES_Delete(sp); return; } + (void)clock_gettime(CLOCK_REALTIME, &sp->t_open); VSL(SLT_SessionReuse, sp->fd, "%s %s", sp->addr, sp->port); assert(sizeof sp == write(pipes[1], &sp, sizeof sp)); } @@ -364,6 +366,7 @@ vca_return_session(struct sess *sp) SES_Delete(sp); return; } + (void)clock_gettime(CLOCK_REALTIME, &sp->t_open); VSL(SLT_SessionReuse, sp->fd, "%s %s", sp->addr, sp->port); if (http_RecvPrepAgain(sp->http)) vca_handover(sp, 0); diff --git a/varnish-cache/bin/varnishd/cache_backend.c b/varnish-cache/bin/varnishd/cache_backend.c index 5879c00a..c56f4e64 100644 --- a/varnish-cache/bin/varnishd/cache_backend.c +++ b/varnish-cache/bin/varnishd/cache_backend.c @@ -195,8 +195,10 @@ VBE_GetFd(struct backend *bp, unsigned xid) TAILQ_REMOVE(&bp->connlist, vc, list); } else { vc2 = TAILQ_FIRST(&vbe_head); - if (vc2 != NULL) + if (vc2 != NULL) { + VSL_stats->backend_unused--; TAILQ_REMOVE(&vbe_head, vc2, list); + } } AZ(pthread_mutex_unlock(&vbemtx)); if (vc == NULL) @@ -229,6 +231,7 @@ VBE_GetFd(struct backend *bp, unsigned xid) if (vc->fd < 0) { vc->backend = NULL; TAILQ_INSERT_HEAD(&vbe_head, vc, list); + VSL_stats->backend_unused++; vc = NULL; } else { vc->backend = bp; @@ -262,6 +265,7 @@ VBE_ClosedFd(struct vbe_conn *vc) vc->backend = NULL; AZ(pthread_mutex_lock(&vbemtx)); TAILQ_INSERT_HEAD(&vbe_head, vc, list); + VSL_stats->backend_unused++; AZ(pthread_mutex_unlock(&vbemtx)); } diff --git a/varnish-cache/bin/varnishd/cache_center.c b/varnish-cache/bin/varnishd/cache_center.c index ce9a9a20..790443fc 100644 --- a/varnish-cache/bin/varnishd/cache_center.c +++ b/varnish-cache/bin/varnishd/cache_center.c @@ -79,9 +79,21 @@ DOT label="Request completed" DOT ] */ +static double +cnt_dt(struct timespec *t1, struct timespec *t2) +{ + double dt; + + dt = (t2->tv_sec - t1->tv_sec); + dt += (t2->tv_nsec - t1->tv_nsec) * 1e-9; + return (dt); +} + static int cnt_done(struct sess *sp) { + double dh, dp, da; + struct timespec te; assert(sp->obj == NULL); assert(sp->vbc == NULL); @@ -90,6 +102,14 @@ cnt_done(struct sess *sp) VCL_Rel(sp->vcl); sp->vcl = NULL; + clock_gettime(CLOCK_REALTIME, &te); + dh = cnt_dt(&sp->t_open, &sp->t_req); + dp = cnt_dt(&sp->t_req, &sp->t_resp); + da = cnt_dt(&sp->t_resp, &te); + VSL(SLT_ReqServTime, sp->fd, "%u %ld.%09ld %.9f %.9f %.9f", + sp->xid, (long)sp->t_req.tv_sec, (long)sp->t_req.tv_nsec, + dh, dp, da); + SES_Charge(sp); vca_return_session(sp); return (1); @@ -523,6 +543,7 @@ cnt_recv(struct sess *sp) char *b; sp->t0 = time(NULL); + assert(sp->vcl == NULL); sp->vcl = VCL_Get(); assert(sp->obj == NULL); diff --git a/varnish-cache/bin/varnishd/cache_pass.c b/varnish-cache/bin/varnishd/cache_pass.c index ac97958c..283bed14 100644 --- a/varnish-cache/bin/varnishd/cache_pass.c +++ b/varnish-cache/bin/varnishd/cache_pass.c @@ -149,6 +149,8 @@ PassBody(struct sess *sp) assert(vc != NULL); sp->vbc = NULL; + clock_gettime(CLOCK_REALTIME, &sp->t_resp); + http_ClrHeader(sp->http); http_CopyResp(sp->fd, sp->http, vc->http); http_FilterHeader(sp->fd, sp->http, vc->http, HTTPH_A_PASS); diff --git a/varnish-cache/bin/varnishd/cache_pipe.c b/varnish-cache/bin/varnishd/cache_pipe.c index 16779147..84b978eb 100644 --- a/varnish-cache/bin/varnishd/cache_pipe.c +++ b/varnish-cache/bin/varnishd/cache_pipe.c @@ -68,6 +68,8 @@ PipeSession(struct sess *sp) return; } + clock_gettime(CLOCK_REALTIME, &sp->t_resp); + memset(fds, 0, sizeof fds); fds[0].fd = vc->fd; fds[0].events = POLLIN | POLLERR; diff --git a/varnish-cache/bin/varnishd/cache_response.c b/varnish-cache/bin/varnishd/cache_response.c index 9361f257..1eb9b04b 100644 --- a/varnish-cache/bin/varnishd/cache_response.c +++ b/varnish-cache/bin/varnishd/cache_response.c @@ -128,15 +128,9 @@ RES_WriteObj(struct sess *sp) { struct storage *st; unsigned u = 0; - double dt; - struct timespec t_resp; CHECK_OBJ_NOTNULL(sp, SESS_MAGIC); - clock_gettime(CLOCK_REALTIME, &t_resp); - dt = (t_resp.tv_sec - sp->t_req.tv_sec); - dt += (t_resp.tv_nsec - sp->t_req.tv_nsec) * 1e-9; - VSL(SLT_ReqServTime, sp->fd, "%ld.%09ld %.9f", - (long)sp->t_req.tv_sec, (long)sp->t_req.tv_nsec, dt); + clock_gettime(CLOCK_REALTIME, &sp->t_resp); if (sp->obj->response == 200 && sp->http->conds && res_do_conds(sp)) return; diff --git a/varnish-cache/bin/varnishd/cache_session.c b/varnish-cache/bin/varnishd/cache_session.c index 85c4d69a..c38dcf2e 100644 --- a/varnish-cache/bin/varnishd/cache_session.c +++ b/varnish-cache/bin/varnishd/cache_session.c @@ -217,6 +217,8 @@ SES_Delete(struct sess *sp) struct acct *b = &sp->acct; CHECK_OBJ_NOTNULL(sp, SESS_MAGIC); + assert(sp->obj == NULL); + assert(sp->vcl == NULL); VSL_stats->n_sess--; ses_relsrcaddr(sp); VSL(SLT_StatSess, sp->id, "%s %s %d %ju %ju %ju %ju %ju %ju %ju",