[master] e15f957 Backend fetch timestamps
Martin Blix Grydeland
martin at varnish-software.com
Wed Mar 26 12:42:22 CET 2014
commit e15f9573f1536497716e4f6d08b58b427e4db36c
Author: Martin Blix Grydeland <martin at varnish-software.com>
Date: Tue Mar 25 16:28:31 2014 +0100
Backend fetch timestamps
diff --git a/bin/varnishd/cache/cache.h b/bin/varnishd/cache/cache.h
index ecc2185..ea5d990 100644
--- a/bin/varnishd/cache/cache.h
+++ b/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);
diff --git a/bin/varnishd/cache/cache_busyobj.c b/bin/varnishd/cache/cache_busyobj.c
index db1c7a1..69f849b 100644
--- a/bin/varnishd/cache/cache_busyobj.c
+++ b/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);
}
diff --git a/bin/varnishd/cache/cache_fetch.c b/bin/varnishd/cache/cache_fetch.c
index e689913..cd627cd 100644
--- a/bin/varnishd/cache/cache_fetch.c
+++ b/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);
}
diff --git a/bin/varnishd/cache/cache_http1_fetch.c b/bin/varnishd/cache/cache_http1_fetch.c
index e25ced9..317bfcb 100644
--- a/bin/varnishd/cache/cache_http1_fetch.c
+++ b/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;
More information about the varnish-commit
mailing list