Record timestamp when we have received completed HTTP request header,

and define this as the "start of request timestamp".

Define "end of request timestamp" as when we are ready to transmit
HTTP header back.

SHMlog the start and difference between start and stop with ReqServTime
tag.

Keep track of idle sessions using CLOCK_MONOTONIC to avoid trouble
here should our clock get stepped.




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

bin/varnishd/cache.h

@@ -243,8 +243,8 @@ struct sess {
 	const char		*doclose;
 	struct http		*http;
 
-	time_t			t_req;
-	time_t			t_resp;
+	struct timespec		t_req;
+	struct timespec		t_idle;
 
 	enum step		step;
 	unsigned 		handling;

bin/varnishd/cache_acceptor.c

@@ -41,15 +41,15 @@ static void
 vca_tick(int a, short b, void *c)
 {
 	struct sess *sp, *sp2;
-	time_t t;
+	struct timespec t;
 
 	(void)a;
 	(void)b;
 	(void)c;
 	AZ(evtimer_add(&tick_e, &tick_rate));
-	(void)time(&t);
+	clock_gettime(CLOCK_MONOTONIC, &t);
 	TAILQ_FOREACH_SAFE(sp, &sesshead, list, sp2) {
-		if (sp->t_resp + 30 < t) {
+		if (sp->t_idle.tv_sec + 30 < t.tv_sec) {
 			TAILQ_REMOVE(&sesshead, sp, list);
 			vca_close_session(sp, "timeout");
 			vca_return_session(sp);
@@ -88,7 +88,7 @@ pipe_f(int fd, short event, void *arg)
 	(void)arg;
 	i = read(fd, &sp, sizeof sp);
 	assert(i == sizeof sp);
-	sp->t_resp = time(NULL);
+	clock_gettime(CLOCK_MONOTONIC, &sp->t_idle);
 	TAILQ_INSERT_TAIL(&sesshead, sp, list);
 	http_RecvHead(sp->http, sp->fd, evb, vca_callback, sp);
 }
@@ -132,7 +132,7 @@ accept_f(int fd, short event, void *arg)
 
 	TCP_name(addr, l, sp->addr, sizeof sp->addr, sp->port, sizeof sp->port);
 	VSL(SLT_SessionOpen, sp->fd, "%s %s", sp->addr, sp->port);
-	(void)time(&sp->t_resp);
+	clock_gettime(CLOCK_MONOTONIC, &sp->t_idle);
 	TAILQ_INSERT_TAIL(&sesshead, sp, list);
 	http_RecvHead(sp->http, sp->fd, evb, vca_callback, sp);
 }

bin/varnishd/cache_fetch.c

@@ -291,7 +291,6 @@ FetchHeaders(struct sess *sp)
 		    sp->backend->hostname);
 	}
 
-	sp->t_req = time(NULL);
 	WRK_Reset(w, &vc->fd);
 	http_Write(w, vc->http, 0);
 	i = WRK_Flush(w);
@@ -303,8 +302,10 @@ FetchHeaders(struct sess *sp)
 	 */
 	http_RecvHead(vc->http, vc->fd, w->eb, NULL, NULL);
 	(void)event_base_loop(w->eb, 0);
-	sp->t_resp = time(NULL);
 	assert(http_DissectResponse(vc->http, vc->fd) == 0);
 	sp->vbc = vc;
+
+	sp->obj->entered = time(NULL);
+
 	return (0);
 }

bin/varnishd/cache_hash.c

@@ -108,7 +108,7 @@ HSH_Lookup(struct sess *sp)
 			/* ignore */
 		} else if (o->ttl == 0) {
 			/* Object banned but not reaped yet */
-		} else if (o->ttl < sp->t_req) {
+		} else if (o->ttl < sp->t_req.tv_sec) {
 			/* Object expired */
 		} else if (BAN_CheckObject(o, url)) {
 			o->ttl = 0;

bin/varnishd/cache_pool.c

@@ -189,7 +189,7 @@ WRK_QueueSession(struct sess *sp)
 	struct worker *w;
 	pthread_t tp;
 
-	sp->t_req = time(NULL);
+	clock_gettime(CLOCK_REALTIME, &sp->t_req);
 
 	sp->workreq.sess = sp;
 

bin/varnishd/cache_response.c

@@ -33,7 +33,7 @@ RES_Error(struct sess *sp, int error, const char *msg)
 
 	sbuf_clear(sb);
 	sbuf_printf(sb, "HTTP/1.1 %03d %s\r\n", error, msg);
-	TIM_format(sp->t_req, buf);
+	TIM_format(sp->t_req.tv_sec, buf);
 	sbuf_printf(sb, "Date: %s\r\n", buf);
 	sbuf_cat(sb,
 		"Server: Varnish\r\n"
@@ -106,7 +106,7 @@ res_do_conds(struct sess *sp)
 	if (sp->obj->last_modified > 0 &&
 	    http_GetHdr(sp->http, H_If_Modified_Since, &p)) {
 		ims = TIM_parse(p);
-		if (ims > sp->t_req)	/* [RFC2616 14.25] */
+		if (ims > sp->t_req.tv_sec)	/* [RFC2616 14.25] */
 			return (0);
 		if (ims > sp->obj->last_modified) {
 			VSL(SLT_Debug, sp->fd,
@@ -128,7 +128,15 @@ RES_WriteObj(struct sess *sp)
 {
 	struct storage *st;
 	unsigned u = 0;
+	double dt;
+	struct timespec t_resp;
 	
+	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);
+
 	if (sp->obj->response == 200 && sp->http->conds && res_do_conds(sp))
 		return;
 		
@@ -144,7 +152,7 @@ RES_WriteObj(struct sess *sp)
 	else
 		http_PrintfHeader(sp->fd, sp->http, "X-Varnish: %u", sp->xid);
 	http_PrintfHeader(sp->fd, sp->http, "Age: %u",
-	    sp->obj->age + sp->t_req - sp->obj->entered);
+	    sp->obj->age + sp->t_req.tv_sec - sp->obj->entered);
 	http_SetHeader(sp->fd, sp->http, "Via: 1.1 varnish");
 	if (sp->doclose != NULL)
 		http_SetHeader(sp->fd, sp->http, "Connection: close");

bin/varnishd/cache_vrt.c

@@ -119,7 +119,16 @@ VRT_r_backend_##onm(struct backend *be)			\
 VBACKEND(const char *,	host,	hostname)
 VBACKEND(const char *,	port,	portname)
 
-/*--------------------------------------------------------------------*/
+/*--------------------------------------------------------------------
+ * XXX: Working relative to t_req is maybe not the right thing, we could
+ * XXX: have spent a long time talking to the backend since then.
+ * XXX: It might make sense to cache a timestamp as "current time"
+ * XXX: before vcl_recv (== t_req) and vcl_fetch.
+ * XXX: On the other hand, that might lead to inconsistent behaviour
+ * XXX: where an object expires while we are running VCL code, and
+ * XXX: and that may not be a good idea either.
+ * XXX: See also related t_req use in cache_hash.c
+ */
 
 void
 VRT_l_obj_ttl(struct sess *sp, double a)
@@ -130,7 +139,7 @@ VRT_l_obj_ttl(struct sess *sp, double a)
 	VSL(SLT_TTL, sp->fd, "%u VCL %.0f %u", sp->obj->xid, a, sp->t_req);
 	if (a < 0)
 		a = 0;
-	sp->obj->ttl = sp->t_req + (int)a;
+	sp->obj->ttl = sp->t_req.tv_sec + (int)a;
 	if (sp->obj->heap_idx != 0)
 		EXP_TTLchange(sp->obj);
 }
@@ -140,7 +149,7 @@ VRT_r_obj_ttl(struct sess *sp)
 {
 	CHECK_OBJ_NOTNULL(sp, SESS_MAGIC);
 	CHECK_OBJ_NOTNULL(sp->obj, OBJECT_MAGIC);	/* XXX */
-	return (sp->obj->ttl - sp->t_req);
+	return (sp->obj->ttl - sp->t_req.tv_sec);
 }
 
 /*--------------------------------------------------------------------*/

bin/varnishd/rfc2616.c

@@ -71,15 +71,13 @@
 #endif
 
 static time_t
-RFC2616_Ttl(struct sess *sp, struct http *hp, time_t t_req, time_t t_resp, struct object *obj)
+RFC2616_Ttl(struct sess *sp, struct http *hp, struct object *obj)
 {
 	int retirement_age;
 	unsigned u1, u2;
 	time_t h_date, h_expires, ttd;
 	char *p;
 	
-	(void)t_resp;	/* XXX */
-
 	retirement_age = INT_MAX;
 
 	u1 = u2 = 0;
@@ -102,10 +100,11 @@ RFC2616_Ttl(struct sess *sp, struct http *hp, time_t t_req, time_t t_resp, struc
 	if (http_GetHdr(hp, H_Expires, &p))
 		h_expires = TIM_parse(p);
 
-	if (h_date < t_req && h_expires > t_req) {
+	if (h_date < obj->entered && h_expires > obj->entered) {
 		ttd = h_expires;
-		if (retirement_age != INT_MAX && t_req + retirement_age < ttd)
-			ttd = t_req + retirement_age;
+		if (retirement_age != INT_MAX &&
+		    obj->entered + retirement_age < ttd)
+			ttd = obj->entered + retirement_age;
 	} else {
 		if (h_date != 0 && h_expires != 0) {
 			if (h_date < h_expires &&
@@ -115,13 +114,13 @@ RFC2616_Ttl(struct sess *sp, struct http *hp, time_t t_req, time_t t_resp, struc
 		if (retirement_age == INT_MAX)
 			retirement_age = heritage.default_ttl;
 
-		ttd = t_req + retirement_age;
+		ttd = obj->entered + retirement_age;
 	}
 
 	/* calculated TTL, Our time, Date, Expires, max-age, age */
 	VSL(SLT_TTL, sp->fd, "%u RFC %d %d %d %d %d %d", sp->xid,
-	    (int)(ttd - t_req), (int)t_req, (int)h_date, (int)h_expires,
-	    (int)u1, (int)u2);
+	    (int)(ttd - obj->entered), (int)obj->entered, (int)h_date,
+	    (int)h_expires, (int)u1, (int)u2);
 
 	return (ttd);
 }
@@ -155,8 +154,7 @@ RFC2616_cache_policy(struct sess *sp, struct http *hp)
 		break;
 	}
 
-	sp->obj->ttl = RFC2616_Ttl(sp, hp, sp->t_req, sp->t_resp, sp->obj);
-	sp->obj->entered = sp->t_req;
+	sp->obj->ttl = RFC2616_Ttl(sp, hp, sp->obj);
 	if (sp->obj->ttl == 0) {
 		sp->obj->cacheable = 0;
 	}

include/shmlog_tags.h

@@ -13,6 +13,7 @@ SLTM(Error)
 SLTM(CLI)
 SLTM(StatAddr)
 SLTM(StatSess)
+SLTM(ReqServTime)
 SLTM(SessionOpen)
 SLTM(SessionReuse)
 SLTM(SessionClose)