More comprehensive performance stats and a few asserts, just in case.

git-svn-id: http://www.varnish-cache.org/svn/trunk/varnish-cache@640 d4fa192b-c00b-0410-8231-f00ffab90ce4

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;

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);

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));
 }
 

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);

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);

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;

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;

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",