Rename sp->t_end to sp->t_idle, which marks when we start listening

for a request.

t_open and t_idle are session timestamps.

Have the waiters pass in a T(now) timestamp

bin/varnishd/cache/cache.h

@@ -616,6 +616,10 @@ struct sess {
 
 	VTAILQ_ENTRY(sess)	list;
 
+	/* Timestamps, all on TIM_real() timescale */
+	double			t_open;		/* fd accepted */
+	double			t_idle;		/* fd accepted or resp sent */
+
 #if defined(HAVE_EPOLL_CTL)
 	struct epoll_event ev;
 #endif
@@ -665,15 +669,13 @@ struct sess {
 
 	uint64_t		req_bodybytes;
 
-	/* TBD fields ------------------------------------------------*/
-
-	struct http_conn	htc[1];
-
 	/* Timestamps, all on TIM_real() timescale */
-	double			t_open;
 	double			t_req;
 	double			t_resp;
-	double			t_end;
+
+	/* TBD fields ------------------------------------------------*/
+
+	struct http_conn	htc[1];
 
 };
 
@@ -915,12 +917,12 @@ void WRW_Sendfile(struct worker *w, int fd, off_t off, unsigned len);
 struct sess *SES_New(struct worker *wrk, struct sesspool *pp);
 struct sess *SES_Alloc(void);
 void SES_Close(struct sess *sp, const char *reason);
-void SES_Delete(struct sess *sp, const char *reason);
+void SES_Delete(struct sess *sp, const char *reason, double now);
 void SES_Charge(struct sess *sp);
 struct sesspool *SES_NewPool(struct pool *pp, unsigned pool_no);
 void SES_DeletePool(struct sesspool *sp, struct worker *wrk);
 int SES_Schedule(struct sess *sp);
-void SES_Handle(struct sess *sp);
+void SES_Handle(struct sess *sp, double now);
 
 /* cache_shmlog.c */
 extern struct VSC_C_main *VSC_C_main;

bin/varnishd/cache/cache_acceptor.c

@@ -276,7 +276,7 @@ VCA_SetupSess(struct worker *w)
 	sp->vsl_id = wa->acceptsock | VSL_CLIENTMARKER ;
 	wa->acceptsock = -1;
 	sp->t_open = VTIM_real();
-	sp->t_end = sp->t_open;
+	sp->t_idle = sp->t_open;
 	sp->mylsock = wa->acceptlsock;
 	CHECK_OBJ_NOTNULL(sp->mylsock, LISTEN_SOCK_MAGIC);
 	assert(wa->acceptaddrlen <= sp->sockaddrlen);

bin/varnishd/cache/cache_center.c

@@ -365,15 +365,14 @@ cnt_done(struct sess *sp)
 	}
 
 
-	sp->t_end = W_TIM_real(wrk);
+	sp->t_idle = W_TIM_real(wrk);
 WSP(sp, SLT_Debug, "PHK req %.9f resp %.9f end %.9f open %.9f",
-    sp->t_req, sp->t_resp, sp->t_end,  sp->t_open);
+    sp->t_req, sp->t_resp, sp->t_idle,  sp->t_open);
 	if (sp->xid == 0) {
-		// sp->t_req = sp->t_end;
-		sp->t_resp = sp->t_end;
+		sp->t_resp = sp->t_idle;
 	} else {
 		dp = sp->t_resp - sp->t_req;
-		da = sp->t_end - sp->t_resp;
+		da = sp->t_idle - sp->t_resp;
 		dh = sp->t_req - sp->t_open;
 		/* XXX: Add StatReq == StatSess */
 		/* XXX: Workaround for pipe */
@@ -382,17 +381,16 @@ WSP(sp, SLT_Debug, "PHK req %.9f resp %.9f end %.9f open %.9f",
 			    (uintmax_t)sp->req_bodybytes);
 		}
 		WSP(sp, SLT_ReqEnd, "%u %.9f %.9f %.9f %.9f %.9f",
-		    sp->xid, sp->t_req, sp->t_end, dh, dp, da);
+		    sp->xid, sp->t_req, sp->t_idle, dh, dp, da);
 	}
 	sp->xid = 0;
 	WSL_Flush(wrk, 0);
 
-	sp->t_open = sp->t_end;
+	sp->t_req = NAN;
 	sp->t_resp = NAN;
 
 	sp->req_bodybytes = 0;
 
-	sp->t_req = NAN;
 	sp->hash_always_miss = 0;
 	sp->hash_ignore_busy = 0;
 
@@ -407,7 +405,7 @@ WSP(sp, SLT_Debug, "PHK req %.9f resp %.9f end %.9f open %.9f",
 
 	if (sp->fd < 0) {
 		wrk->stats.sess_closed++;
-		SES_Delete(sp, NULL);
+		SES_Delete(sp, NULL, NAN);
 		return (1);
 	}
 

bin/varnishd/cache/cache_session.c

@@ -168,9 +168,9 @@ ses_setup(struct sessmem *sm)
 	sp->mysockaddrlen = sizeof(sp->mysockaddr);
 	sp->sockaddr.ss_family = sp->mysockaddr.ss_family = PF_UNSPEC;
 	sp->t_open = NAN;
+	sp->t_idle = NAN;
 	sp->t_req = NAN;
 	sp->t_resp = NAN;
-	sp->t_end = NAN;
 	EXP_Clr(&sp->exp);
 
 	WS_Init(sp->ws, "sess", sm->wsp, sm->workspace);
@@ -268,7 +268,7 @@ SES_Schedule(struct sess *sp)
 
 	if (Pool_Schedule(pp->pool, sp)) {
 		VSC_C_main->client_drop_late++;
-		sp->t_end = VTIM_real();
+		sp->t_idle = VTIM_real();
 		if (sp->vcl != NULL) {
 			/*
 			 * A session parked on a busy object can come here
@@ -276,7 +276,7 @@ SES_Schedule(struct sess *sp)
 			 */
 			VCL_Rel(&sp->vcl);
 		}
-		SES_Delete(sp, "dropped");
+		SES_Delete(sp, "dropped", sp->t_idle);
 		return (1);
 	}
 	return (0);
@@ -284,20 +284,21 @@ SES_Schedule(struct sess *sp)
 
 /*--------------------------------------------------------------------
  * Handle a session (from waiter)
- *
- * Status: see HTC_Rx()
  */
 
 void
-SES_Handle(struct sess *sp)
+SES_Handle(struct sess *sp, double now)
 {
 
 	sp->step = STP_WAIT;
+	sp->t_req = now;
 	(void)SES_Schedule(sp);
 }
 
 /*--------------------------------------------------------------------
  * Close a sessions connection.
+ * XXX: Technically speaking we should catch a t_end timestamp here
+ * XXX: for SES_Delete() to use.
  */
 
 void
@@ -322,7 +323,7 @@ SES_Close(struct sess *sp, const char *reason)
  */
 
 void
-SES_Delete(struct sess *sp, const char *reason)
+SES_Delete(struct sess *sp, const char *reason, double now)
 {
 	struct acct *b;
 	struct sessmem *sm;
@@ -340,9 +341,10 @@ SES_Delete(struct sess *sp, const char *reason)
 	wrk = sp->wrk;
 	CHECK_OBJ_ORNULL(wrk, WORKER_MAGIC);
 
-
 	if (reason != NULL)
 		SES_Close(sp, reason);
+	if (isnan(now))
+		now = VTIM_real();
 	assert(sp->fd < 0);
 
 	AZ(sp->vcl);
@@ -353,10 +355,10 @@ SES_Delete(struct sess *sp, const char *reason)
 
 	b = &sp->acct_ses;
 	assert(!isnan(b->first));
-	assert(!isnan(sp->t_end));
 
 	VSL(SLT_StatSess, sp->vsl_id, "%s %s %.0f %ju %ju %ju %ju %ju %ju %ju",
-	    sp->addr, sp->port, sp->t_end - b->first,
+	    sp->addr, sp->port,
+	    now - b->first, 	// XXX ??? 
 	    b->sess, b->req, b->pipe, b->pass,
 	    b->fetch, b->hdrbytes, b->bodybytes);
 

bin/varnishd/waiter/cache_waiter_epoll.c

@@ -104,7 +104,7 @@ vwe_cond_modadd(struct vwe *vwe, int fd, void *data)
 }
 
 static void
-vwe_eev(struct vwe *vwe, const struct epoll_event *ep)
+vwe_eev(struct vwe *vwe, const struct epoll_event *ep, double now)
 {
 	struct sess *ss[NEEV], *sp;
 	int i, j;
@@ -130,16 +130,16 @@ vwe_eev(struct vwe *vwe, const struct epoll_event *ep)
 		CAST_OBJ_NOTNULL(sp, ep->data.ptr, SESS_MAGIC);
 		if (ep->events & EPOLLIN || ep->events & EPOLLPRI) {
 			VTAILQ_REMOVE(&vwe->sesshead, sp, list);
-			SES_Handle(sp);
+			SES_Handle(sp, now);
 		} else if (ep->events & EPOLLERR) {
 			VTAILQ_REMOVE(&vwe->sesshead, sp, list);
-			SES_Delete(sp, "ERR");
+			SES_Delete(sp, "ERR", now);
 		} else if (ep->events & EPOLLHUP) {
 			VTAILQ_REMOVE(&vwe->sesshead, sp, list);
-			SES_Delete(sp, "HUP");
+			SES_Delete(sp, "HUP", now);
 		} else if (ep->events & EPOLLRDHUP) {
 			VTAILQ_REMOVE(&vwe->sesshead, sp, list);
-			SES_Delete(sp, "RHUP");
+			SES_Delete(sp, "RHUP", now);
 		}
 	}
 }
@@ -152,7 +152,7 @@ vwe_thread(void *priv)
 	struct epoll_event ev[NEEV], *ep;
 	struct sess *sp;
 	char junk;
-	double deadline;
+	double now, deadline;
 	int dotimer, i, n;
 	struct vwe *vwe;
 
@@ -169,6 +169,7 @@ vwe_thread(void *priv)
 	while (1) {
 		dotimer = 0;
 		n = epoll_wait(vwe->epfd, ev, NEEV, -1);
+		now = VTIM_real();
 		for (ep = ev, i = 0; i < n; i++, ep++) {
 			if (ep->data.ptr == vwe->timer_pipes &&
 			    (ep->events == EPOLLIN || ep->events == EPOLLPRI))
@@ -176,22 +177,22 @@ vwe_thread(void *priv)
 				assert(read(vwe->timer_pipes[0], &junk, 1));
 				dotimer = 1;
 			} else
-				vwe_eev(vwe, ep);
+				vwe_eev(vwe, ep, now);
 		}
 		if (!dotimer)
 			continue;
 
 		/* check for timeouts */
-		deadline = VTIM_real() - cache_param->sess_timeout;
+		deadline = now - cache_param->sess_timeout;
 		for (;;) {
 			sp = VTAILQ_FIRST(&vwe->sesshead);
 			if (sp == NULL)
 				break;
-			if (sp->t_open > deadline)
+			if (sp->t_idle > deadline)
 				break;
 			VTAILQ_REMOVE(&vwe->sesshead, sp, list);
 			// XXX: not yet VTCP_linger(sp->fd, 0);
-			SES_Delete(sp, "timeout");
+			SES_Delete(sp, "timeout", now);
 		}
 	}
 	return (NULL);

bin/varnishd/waiter/cache_waiter_kqueue.c

@@ -114,7 +114,7 @@ vwk_pipe_ev(struct vwk *vwk, const struct kevent *kp)
 /*--------------------------------------------------------------------*/
 
 static void
-vwk_sess_ev(struct vwk *vwk, const struct kevent *kp)
+vwk_sess_ev(struct vwk *vwk, const struct kevent *kp, double now)
 {
 	struct sess *sp;
 
@@ -129,11 +129,11 @@ vwk_sess_ev(struct vwk *vwk, const struct kevent *kp)
 	assert((sp->vsl_id & VSL_IDENTMASK) == sp->fd);
 	if (kp->data > 0) {
 		VTAILQ_REMOVE(&vwk->sesshead, sp, list);
-		SES_Handle(sp);
+		SES_Handle(sp, now);
 		return;
 	} else if (kp->flags & EV_EOF) {
 		VTAILQ_REMOVE(&vwk->sesshead, sp, list);
-		SES_Delete(sp, "EOF");
+		SES_Delete(sp, "EOF", now);
 		return;
 	} else {
 		VSL(SLT_Debug, sp->vsl_id,
@@ -151,7 +151,7 @@ vwk_thread(void *priv)
 	struct vwk *vwk;
 	struct kevent ke[NKEV], *kp;
 	int j, n, dotimer;
-	double deadline;
+	double now, deadline;
 	struct sess *sp;
 
 	CAST_OBJ_NOTNULL(vwk, priv, VWK_MAGIC);
@@ -171,6 +171,7 @@ vwk_thread(void *priv)
 	while (1) {
 		dotimer = 0;
 		n = kevent(vwk->kq, vwk->ki, vwk->nki, ke, NKEV, NULL);
+		now = VTIM_real();
 		assert(n >= 1 && n <= NKEV);
 		vwk->nki = 0;
 		for (kp = ke, j = 0; j < n; j++, kp++) {
@@ -181,7 +182,7 @@ vwk_thread(void *priv)
 				vwk_pipe_ev(vwk, kp);
 			} else {
 				assert(kp->filter == EVFILT_READ);
-				vwk_sess_ev(vwk, kp);
+				vwk_sess_ev(vwk, kp, now);
 			}
 		}
 		if (!dotimer)
@@ -194,16 +195,16 @@ vwk_thread(void *priv)
 		 * would not know we meant "the old fd of this number".
 		 */
 		vwk_kq_flush(vwk);
-		deadline = VTIM_real() - cache_param->sess_timeout;
+		deadline = now - cache_param->sess_timeout;
 		for (;;) {
 			sp = VTAILQ_FIRST(&vwk->sesshead);
 			if (sp == NULL)
 				break;
-			if (sp->t_open > deadline)
+			if (sp->t_idle > deadline)
 				break;
 			VTAILQ_REMOVE(&vwk->sesshead, sp, list);
 			// XXX: not yet (void)VTCP_linger(sp->fd, 0);
-			SES_Delete(sp, "timeout");
+			SES_Delete(sp, "timeout", now);
 		}
 	}
 }

bin/varnishd/waiter/cache_waiter_poll.c

@@ -123,7 +123,7 @@ vwp_main(void *priv)
 	int v, v2;
 	struct vwp *vwp;
 	struct sess *ss[NEEV], *sp, *sp2;
-	double deadline;
+	double now, deadline;
 	int i, j, fd;
 
 	CAST_OBJ_NOTNULL(vwp, priv, VWP_MAGIC);
@@ -140,7 +140,8 @@ vwp_main(void *priv)
 		assert(vwp->pollfd[vwp->pipes[1]].fd == -1);
 		v = poll(vwp->pollfd, vwp->hpoll + 1, 100);
 		assert(v >= 0);
-		deadline = VTIM_real() - cache_param->sess_timeout;
+		now = VTIM_real();
+		deadline = now - cache_param->sess_timeout;
 		v2 = v;
 		VTAILQ_FOREACH_SAFE(sp, &vwp->sesshead, list, sp2) {
 			if (v != 0 && v2 == 0)
@@ -156,12 +157,12 @@ vwp_main(void *priv)
 				vwp->pollfd[fd].revents = 0;
 				VTAILQ_REMOVE(&vwp->sesshead, sp, list);
 				vwp_unpoll(vwp, fd);
-				SES_Handle(sp);
-			} else if (sp->t_open <= deadline) {
+				SES_Handle(sp, now);
+			} else if (sp->t_idle <= deadline) {
 				VTAILQ_REMOVE(&vwp->sesshead, sp, list);
 				vwp_unpoll(vwp, fd);
 				// XXX: not yet (void)VTCP_linger(sp->fd, 0);
-				SES_Delete(sp, "timeout");
+				SES_Delete(sp, "timeout", now);
 			}
 		}
 		if (v2 && vwp->pollfd[vwp->pipes[0]].revents) {

bin/varnishd/waiter/cache_waiter_ports.c

@@ -72,7 +72,7 @@ vws_del(struct vws *vws, int fd)
 }
 
 static inline void
-vws_port_ev(struct vws *vws, port_event_t *ev) {
+vws_port_ev(struct vws *vws, port_event_t *ev, double now) {
 	struct sess *sp;
 	if(ev->portev_source == PORT_SOURCE_USER) {
 		CAST_OBJ_NOTNULL(sp, ev->portev_user, SESS_MAGIC);
@@ -87,7 +87,7 @@ vws_port_ev(struct vws *vws, port_event_t *ev) {
 		if(ev->portev_events & POLLERR) {
 			vws_del(vws, sp->fd);
 			VTAILQ_REMOVE(&vws->sesshead, sp, list);
-			SES_Delete(sp, "EOF");
+			SES_Delete(sp, "EOF", now);
 			return;
 		}
 
@@ -108,7 +108,7 @@ vws_port_ev(struct vws *vws, port_event_t *ev) {
 		VTAILQ_REMOVE(&vws->sesshead, sp, list);
 
 		/* SES_Handle will also handle errors */
-		SES_Handle(sp);
+		SES_Handle(sp, now);
 	}
 	return;
 }
@@ -182,15 +182,15 @@ vws_thread(void *priv)
 		 */
 
 		ret = port_getn(vws->dport, ev, MAX_EVENTS, &nevents, timeout);
+		now = VTIM_real();
 
 		if (ret < 0)
 			assert((errno == EINTR) || (errno == ETIME));
 
 		for (ei = 0; ei < nevents; ei++)
-			vws_port_ev(vws, ev + ei);
+			vws_port_ev(vws, ev + ei, now);
 
 		/* check for timeouts */
-		now = VTIM_real();
 		deadline = now - cache_param->sess_timeout;
 
 		/*
@@ -204,14 +204,14 @@ vws_thread(void *priv)
 			sp = VTAILQ_FIRST(&vws->sesshead);
 			if (sp == NULL)
 				break;
-			if (sp->t_open > deadline) {
+			if (sp->t_idle > deadline) {
 				break;
 			}
 			VTAILQ_REMOVE(&vws->sesshead, sp, list);
 			if(sp->fd != -1) {
 				vws_del(vws, sp->fd);
 			}
-			SES_Delete(sp, "timeout");
+			SES_Delete(sp, "timeout", now);
 		}
 
 		/*