Backend fetch timestamps

bin/varnishd/cache/cache.h

@@ -569,11 +569,8 @@ struct busyobj {
 	double			between_bytes_timeout;
 
 	/* Timers */
-	double			t_start;
-	double			t_send;
-	double			t_sent;
-	double			t_hdr;
-	double			t_body;
+	double			t_first;	/* First timestamp logged */
+	double			t_prev;		/* Previous timestamp logged */
 
 	const char		*storage_hint;
 	struct director		*director;
@@ -1143,6 +1140,7 @@ void VSLb(struct vsl_log *, enum VSL_tag_e tag, const char *fmt, ...)
 void VSLbt(struct vsl_log *, enum VSL_tag_e tag, txt t);
 void VSLb_ts(struct vsl_log *, const char *event, double first, double *pprev,
     double now);
+
 static inline void
 VSLb_ts_req(struct req *req, const char *event, double now)
 {
@@ -1152,6 +1150,15 @@ VSLb_ts_req(struct req *req, const char *event, double now)
 	VSLb_ts(req->vsl, event, req->t_first, &req->t_prev, now);
 }
 
+static inline void
+VSLb_ts_busyobj(struct busyobj *bo, const char *event, double now)
+{
+
+	if (isnan(bo->t_first) || bo->t_first == 0.)
+		bo->t_first = bo->t_prev = now;
+	VSLb_ts(bo->vsl, event, bo->t_first, &bo->t_prev, now);
+}
+
 
 void VSL_Flush(struct vsl_log *, int overflow);
 

bin/varnishd/cache/cache_busyobj.c

@@ -149,6 +149,8 @@ VBO_GetBusyObj(struct worker *wrk, const struct req *req)
 	VCL_Ref(bo->vcl);
 
 	bo->t_fetch = req->t_req;
+	assert(!isnan(bo->t_fetch) && bo->t_fetch != 0.);
+	bo->t_first = bo->t_prev = NAN;
 
 	return (bo);
 }

bin/varnishd/cache/cache_fetch.c

@@ -226,6 +226,8 @@ vbf_stp_retry(struct worker *wrk, struct busyobj *bo)
 	CHECK_OBJ_NOTNULL(wrk, WORKER_MAGIC);
 	CHECK_OBJ_NOTNULL(bo, BUSYOBJ_MAGIC);
 
+	VSLb_ts_busyobj(bo, "Retry", W_TIM_real(wrk));
+
 	// XXX: BereqEnd + BereqAcct ?
 	wid = VXID_Get(&wrk->vxid_pool);
 	VSLb(bo->vsl, SLT_Link, "bereq %u retry", wid);
@@ -234,6 +236,7 @@ vbf_stp_retry(struct worker *wrk, struct busyobj *bo)
 	owid = bo->vsl->wid & VSL_IDENTMASK;
 	bo->vsl->wid = wid | VSL_BACKENDMARKER;
 	VSLb(bo->vsl, SLT_Begin, "bereq %u retry", owid);
+	VSLb_ts_busyobj(bo, "Start", bo->t_prev);
 
 	return (F_STP_STARTFETCH);
 }
@@ -285,9 +288,11 @@ vbf_stp_startfetch(struct worker *wrk, struct busyobj *bo)
 	 * Do a single retry in that case.
 	 */
 	if (i == 1) {
+		VSLb_ts_busyobj(bo, "Beresp", W_TIM_real(wrk));
 		VSC_C_main->backend_retry++;
 		i = V1F_fetch_hdr(wrk, bo, bo->req);
 	}
+	VSLb_ts_busyobj(bo, "Beresp", W_TIM_real(wrk));
 
 	if (i) {
 		AZ(bo->vbc);
@@ -364,8 +369,6 @@ vbf_stp_startfetch(struct worker *wrk, struct busyobj *bo)
 
 	assert(wrk->handling == VCL_RET_DELIVER);
 
-	bo->t_body = VTIM_mono();
-
 	return (do_ims ? F_STP_CONDFETCH : F_STP_FETCH);
 }
 
@@ -525,6 +528,7 @@ vbf_stp_fetch(struct worker *wrk, struct busyobj *bo)
 		assert(bo->state == BOS_REQ_DONE);
 		HSH_Unbusy(&wrk->stats, obj->objcore);
 	}
+	VSLb_ts_busyobj(bo, "BerespBody", W_TIM_real(wrk));
 	VBO_setstate(bo, BOS_FINISHED);
 	return (F_STP_DONE);
 }
@@ -617,6 +621,7 @@ vbf_stp_condfetch(struct worker *wrk, struct busyobj *bo)
 	assert(obj->len == al);
 	EXP_Rearm(bo->ims_obj, bo->ims_obj->exp.t_origin, 0, 0, 0);
 	VBO_setstate(bo, BOS_FINISHED);
+	VSLb_ts_busyobj(bo, "BerespBody", W_TIM_real(wrk));
 	return (F_STP_DONE);
 }
 
@@ -633,6 +638,8 @@ vbf_stp_error(struct worker *wrk, struct busyobj *bo)
 	CHECK_OBJ_NOTNULL(wrk, WORKER_MAGIC);
 	CHECK_OBJ_NOTNULL(bo, BUSYOBJ_MAGIC);
 
+	VSLb_ts_busyobj(bo, "Error", W_TIM_real(wrk));
+
 	AN(bo->fetch_objcore->flags & OC_F_BUSY);
 
 	AZ(bo->synth_body);
@@ -720,7 +727,6 @@ vbf_fetch_thread(struct worker *wrk, void *priv)
 {
 	struct busyobj *bo;
 	enum fetch_step stp;
-	double t_hdr, t_body;
 
 	CHECK_OBJ_NOTNULL(wrk, WORKER_MAGIC);
 	CAST_OBJ_NOTNULL(bo, priv, BUSYOBJ_MAGIC);
@@ -729,11 +735,9 @@ vbf_fetch_thread(struct worker *wrk, void *priv)
 
 	THR_SetBusyobj(bo);
 	stp = F_STP_MKBEREQ;
-	bo->t_start = VTIM_real();
-	bo->t_send = NAN;
-	bo->t_sent = NAN;
-	bo->t_hdr = NAN;
-	bo->t_body = NAN;
+	assert(isnan(bo->t_first));
+	assert(isnan(bo->t_prev));
+	VSLb_ts_busyobj(bo, "Start", W_TIM_real(wrk));
 
 	bo->stats = &wrk->stats;
 
@@ -790,14 +794,6 @@ vbf_fetch_thread(struct worker *wrk, void *priv)
 	if (bo->ims_obj != NULL)
 		(void)HSH_DerefObj(&wrk->stats, &bo->ims_obj);
 
-	t_hdr = bo->t_hdr - bo->t_sent;
-	t_body = bo->t_body - bo->t_hdr;
-	VSLb(bo->vsl, SLT_BereqEnd, "%.9f %.9f %.9f %.9f %.9f %.9f",
-	     bo->t_start,
-	     VTIM_real(),
-	     bo->t_sent - bo->t_send,
-	     t_hdr, t_body, t_hdr + t_body);
-
 	VBO_DerefBusyObj(wrk, &bo);
 	THR_SetBusyobj(NULL);
 }

bin/varnishd/cache/cache_http1_fetch.c

@@ -311,8 +311,7 @@ V1F_fetch_hdr(struct worker *wrk, struct busyobj *bo, struct req *req)
 		VDI_AddHostHeader(bo->bereq, vc);
 
 	(void)VTCP_blocking(vc->fd);	/* XXX: we should timeout instead */
-	WRW_Reserve(wrk, &vc->fd, bo->vsl, bo->t_fetch);
-	bo->t_send = VTIM_mono();
+	WRW_Reserve(wrk, &vc->fd, bo->vsl, bo->t_prev);
 	(void)HTTP1_Write(wrk, hp, 0);	/* XXX: stats ? */
 
 	/* Deal with any message-body the request might (still) have */
@@ -334,13 +333,14 @@ V1F_fetch_hdr(struct worker *wrk, struct busyobj *bo, struct req *req)
 	if (WRW_FlushRelease(wrk) || i != 0) {
 		VSLb(bo->vsl, SLT_FetchError, "backend write error: %d (%s)",
 		    errno, strerror(errno));
+		VSLb_ts_busyobj(bo, "Bereq", W_TIM_real(wrk));
 		VDI_CloseFd(&bo->vbc);
 		/* XXX: other cleanup ? */
 		return (retry);
 	}
+	VSLb_ts_busyobj(bo, "Bereq", W_TIM_real(wrk));
 
 	VSC_C_main->backend_req++;
-	bo->t_sent = VTIM_mono();
 
 	/* Receive response */
 
@@ -377,7 +377,6 @@ V1F_fetch_hdr(struct worker *wrk, struct busyobj *bo, struct req *req)
 			    vc->between_bytes_timeout);
 		}
 	} while (hs != HTTP1_COMPLETE);
-	bo->t_hdr = VTIM_mono();
 
 	hp = bo->beresp;