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 48730ddeacb1cd3b750563dacd48a717cd6ce9d5..f3b48cbaaaf2bde6898efa55f2f6adee8c49a2ae 100644 (file)
--- 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 9d35285c911def1ecbbdeaf9300052c4ba64cc9f..f769d1d41f8d55692ac36a711fb6d13600114aea 100644 (file)
--- 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 5879c00a62df0b3c74cc20b300a50d901cc53587..c56f4e64158cc8377ec28b9049a546de72e1854a 100644 (file)
--- 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 ce9a9a203d42c94f3086f7eaef9d522fadf5b391..790443fcfdf48b6038d306ab22aafe3266c0dfd8 100644 (file)
--- 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 ac97958cf31976dd562fafdf455793861b16f176..283bed14eb25129878623779e99c443d0572b6fb 100644 (file)
--- 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 16779147f1294fabe1d6f7e756aabdd735a7d827..84b978ebc0da327a1784154b93f54304772c8656 100644 (file)
--- 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 9361f2578d5fc7268b7c9d7f384255edcb8c0ce1..1eb9b04b81551065b9ecdde81272e7d3dbe02484 100644 (file)
--- 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 85c4d69a72d82d7e0965686e1def76deeaca6956..c38dcf2ef292a57327fe15888899879b964e1829 100644 (file)
--- 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",