[master] c204366 Introduce SLT_Timestamp mechanism for request handling timing information.
Martin Blix Grydeland
martin at varnish-software.com
Wed Mar 26 12:42:22 CET 2014
commit c2043664d86377909145e1e54f84c58fc40858ad
Author: Martin Blix Grydeland <martin at varnish-software.com>
Date: Tue Mar 18 17:47:14 2014 +0100
Introduce SLT_Timestamp mechanism for request handling timing information.
diff --git a/bin/varnishd/cache/cache.h b/bin/varnishd/cache/cache.h
index 68c74ff..ecc2185 100644
--- a/bin/varnishd/cache/cache.h
+++ b/bin/varnishd/cache/cache.h
@@ -48,6 +48,7 @@
#include <string.h>
#include <limits.h>
#include <unistd.h>
+#include <math.h>
#if defined(HAVE_EPOLL_CTL)
#include <sys/epoll.h>
@@ -674,8 +675,10 @@ struct req {
char *ws_req; /* WS above request data */
- double t_req;
- double t_resp;
+ /* Timestamps */
+ double t_first; /* First timestamp logged */
+ double t_prev; /* Previous timestamp logged */
+ double t_req; /* Headers complete */
struct http_conn htc[1];
const char *client_identity;
@@ -1138,6 +1141,17 @@ void VSLbv(struct vsl_log *, enum VSL_tag_e tag, const char *fmt, va_list va);
void VSLb(struct vsl_log *, enum VSL_tag_e tag, const char *fmt, ...)
__printflike(3, 4);
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)
+{
+
+ if (isnan(req->t_first) || req->t_first == 0.)
+ req->t_first = req->t_prev = now;
+ VSLb_ts(req->vsl, event, req->t_first, &req->t_prev, now);
+}
+
void VSL_Flush(struct vsl_log *, int overflow);
diff --git a/bin/varnishd/cache/cache_esi_deliver.c b/bin/varnishd/cache/cache_esi_deliver.c
index 65ad51d..b1c3362 100644
--- a/bin/varnishd/cache/cache_esi_deliver.c
+++ b/bin/varnishd/cache/cache_esi_deliver.c
@@ -35,6 +35,7 @@
#include "cache.h"
+#include "vtim.h"
#include "cache_esi.h"
#include "vend.h"
#include "vgz.h"
@@ -98,12 +99,16 @@ ved_include(struct req *preq, const char *src, const char *host)
*/
req->req_step = R_STP_RECV;
req->t_req = preq->t_req;
+ assert(isnan(req->t_first));
+ assert(isnan(req->t_prev));
req->gzip_resp = preq->gzip_resp;
req->crc = preq->crc;
req->l_crc = preq->l_crc;
THR_SetRequest(req);
+ VSLb_ts_req(req, "Start", W_TIM_real(wrk));
+
while (1) {
req->wrk = wrk;
s = CNT_Request(wrk, req);
@@ -122,7 +127,7 @@ ved_include(struct req *preq, const char *src, const char *host)
/* Reset the workspace */
WS_Reset(wrk->aws, wrk_ws_wm); /* XXX ? */
- WRW_Reserve(preq->wrk, &preq->sp->fd, preq->vsl, preq->t_resp);
+ WRW_Reserve(preq->wrk, &preq->sp->fd, preq->vsl, preq->t_prev);
if (preq->res_mode & RES_CHUNKED)
WRW_Chunked(preq->wrk);
diff --git a/bin/varnishd/cache/cache_fetch.c b/bin/varnishd/cache/cache_fetch.c
index ecbcf2e..e689913 100644
--- a/bin/varnishd/cache/cache_fetch.c
+++ b/bin/varnishd/cache/cache_fetch.c
@@ -877,6 +877,7 @@ VBF_Fetch(struct worker *wrk, struct req *req, struct objcore *oc,
AZ(bo->fetch_objcore->flags & OC_F_BUSY);
}
}
+ VSLb_ts_req(req, "Fetch", W_TIM_real(wrk));
THR_SetBusyobj(NULL);
VBO_DerefBusyObj(wrk, &bo);
}
diff --git a/bin/varnishd/cache/cache_http1_deliver.c b/bin/varnishd/cache/cache_http1_deliver.c
index 231df94..e82ed31 100644
--- a/bin/varnishd/cache/cache_http1_deliver.c
+++ b/bin/varnishd/cache/cache_http1_deliver.c
@@ -282,7 +282,7 @@ V1D_Deliver(struct req *req)
if (req->res_mode & RES_ESI)
RFC2616_Weaken_Etag(req->resp);
- WRW_Reserve(req->wrk, &req->sp->fd, req->vsl, req->t_resp);
+ WRW_Reserve(req->wrk, &req->sp->fd, req->vsl, req->t_prev);
/*
* Send HTTP protocol header, unless interior ESI object
@@ -389,7 +389,7 @@ V1D_Deliver_Synth(struct req *req)
v1d_dorange(req, r);
}
- WRW_Reserve(req->wrk, &req->sp->fd, req->vsl, req->t_resp);
+ WRW_Reserve(req->wrk, &req->sp->fd, req->vsl, req->t_prev);
/*
* Send HTTP protocol header, unless interior ESI object
diff --git a/bin/varnishd/cache/cache_http1_fsm.c b/bin/varnishd/cache/cache_http1_fsm.c
index 5d0f286..37ed35a 100644
--- a/bin/varnishd/cache/cache_http1_fsm.c
+++ b/bin/varnishd/cache/cache_http1_fsm.c
@@ -103,8 +103,10 @@ http1_wait(struct sess *sp, struct worker *wrk, struct req *req)
AZ(req->vcl);
AZ(req->obj);
AZ(req->esi_level);
+ assert(!isnan(sp->t_idle));
+ assert(isnan(req->t_first));
+ assert(isnan(req->t_prev));
assert(isnan(req->t_req));
- assert(isnan(req->t_resp));
tmo = (int)(1e3 * cache_param->timeout_linger);
while (1) {
@@ -120,7 +122,10 @@ http1_wait(struct sess *sp, struct worker *wrk, struct req *req)
hs = HTTP1_Complete(req->htc);
if (hs == HTTP1_COMPLETE) {
/* Got it, run with it */
- req->t_req = now;
+ if (isnan(req->t_first))
+ VSLb_ts_req(req, "Start", now);
+ VSLb_ts_req(req, "Req", now);
+ req->t_req = req->t_prev;
return (REQ_FSM_MORE);
} else if (hs == HTTP1_ERROR_EOF) {
why = SC_REM_CLOSE;
@@ -138,7 +143,6 @@ http1_wait(struct sess *sp, struct worker *wrk, struct req *req)
when = sp->t_idle + cache_param->timeout_linger;
tmo = (int)(1e3 * (when - now));
if (when < now || tmo == 0) {
- req->t_req = NAN;
wrk->stats.sess_herd++;
SES_ReleaseReq(req);
WAIT_Enter(sp);
@@ -146,9 +150,10 @@ http1_wait(struct sess *sp, struct worker *wrk, struct req *req)
}
} else {
/* Working on it */
- if (isnan(req->t_req))
- req->t_req = now;
- when = req->t_req + cache_param->timeout_req;
+ if (isnan(req->t_first))
+ /* Timestamp Start on first byte received */
+ VSLb_ts_req(req, "Start", now);
+ when = sp->t_idle + cache_param->timeout_req;
tmo = (int)(1e3 * (when - now));
if (when < now || tmo == 0) {
why = SC_RX_TIMEOUT;
@@ -195,11 +200,15 @@ http1_cleanup(struct sess *sp, struct worker *wrk, struct req *req)
req->vcl = NULL;
}
- sp->t_idle = W_TIM_real(wrk);
+ if (!isnan(req->t_prev) && req->t_prev > 0.)
+ sp->t_idle = req->t_prev;
+ else
+ sp->t_idle = W_TIM_real(wrk);
VSL_Flush(req->vsl, 0);
+ req->t_first = NAN;
+ req->t_prev = NAN;
req->t_req = NAN;
- req->t_resp = NAN;
req->req_body_status = REQ_BODY_INIT;
// req->req_bodybytes = 0;
@@ -226,7 +235,9 @@ http1_cleanup(struct sess *sp, struct worker *wrk, struct req *req)
WS_Reset(wrk->aws, NULL);
if (HTTP1_Reinit(req->htc) == HTTP1_COMPLETE) {
- req->t_req = sp->t_idle;
+ VSLb_ts_req(req, "Start", sp->t_idle);
+ VSLb_ts_req(req, "Req", sp->t_idle);
+ req->t_req = req->t_prev;
wrk->stats.sess_pipeline++;
return (SESS_DONE_RET_START);
} else {
@@ -522,16 +533,19 @@ HTTP1_IterateReqBody(struct req *req, req_body_iter_f *func, void *priv)
l = http1_iter_req_body(req, buf, sizeof buf);
if (l < 0) {
req->doclose = SC_RX_BODY;
- return (l);
+ break;
}
if (l > 0) {
i = func(req, priv, buf, l);
if (i) {
- return (i);
+ l = i;
+ break;
}
}
} while (l > 0);
- return(0);
+ VSLb_ts_req(req, "ReqBody", VTIM_real());
+
+ return (l);
}
/*----------------------------------------------------------------------
@@ -605,7 +619,8 @@ HTTP1_CacheReqBody(struct req *req, ssize_t maxsize)
req->h1.bytes_yet : cache_param->fetch_chunksize);
if (st == NULL) {
req->req_body_status = REQ_BODY_FAIL;
- return (-1);
+ l = -1;
+ break;
} else {
VTAILQ_INSERT_TAIL(&req->body, st, list);
}
@@ -615,11 +630,12 @@ HTTP1_CacheReqBody(struct req *req, ssize_t maxsize)
l = http1_iter_req_body(req, st->ptr + st->len, l);
if (l < 0) {
req->doclose = SC_RX_BODY;
- return (l);
+ break;
}
if (req->req_bodybytes > maxsize) {
req->req_body_status = REQ_BODY_FAIL;
- return (-1);
+ l = -1;
+ break;
}
if (l > 0) {
st->len += l;
@@ -627,6 +643,8 @@ HTTP1_CacheReqBody(struct req *req, ssize_t maxsize)
st = NULL;
}
} while (l > 0);
- req->req_body_status = REQ_BODY_CACHED;
- return(0);
+ if (l == 0)
+ req->req_body_status = REQ_BODY_CACHED;
+ VSLb_ts_req(req, "ReqBody", VTIM_real());
+ return (l);
}
diff --git a/bin/varnishd/cache/cache_pipe.c b/bin/varnishd/cache/cache_pipe.c
index b4403bb..1a0a44f 100644
--- a/bin/varnishd/cache/cache_pipe.c
+++ b/bin/varnishd/cache/cache_pipe.c
@@ -89,14 +89,14 @@ PipeRequest(struct req *req, struct busyobj *bo)
i = WRW_FlushRelease(wrk);
+ VSLb_ts_req(req, "Pipe", W_TIM_real(wrk));
+
if (i) {
SES_Close(req->sp, SC_TX_PIPE);
VDI_CloseFd(&vc);
return;
}
- req->t_resp = VTIM_real();
-
memset(fds, 0, sizeof fds);
// XXX: not yet (void)VTCP_linger(vc->fd, 0);
@@ -130,6 +130,7 @@ PipeRequest(struct req *req, struct busyobj *bo)
fds[1].fd = -1;
}
}
+ VSLb_ts_req(req, "PipeSess", W_TIM_real(wrk));
SES_Close(req->sp, SC_TX_PIPE);
VDI_CloseFd(&vc);
bo->vbc = NULL;
diff --git a/bin/varnishd/cache/cache_req_fsm.c b/bin/varnishd/cache/cache_req_fsm.c
index fd9783c..9826ae7 100644
--- a/bin/varnishd/cache/cache_req_fsm.c
+++ b/bin/varnishd/cache/cache_req_fsm.c
@@ -88,6 +88,7 @@ static enum req_fsm_nxt
cnt_deliver(struct worker *wrk, struct req *req)
{
char time_str[30];
+ double now;
CHECK_OBJ_NOTNULL(wrk, WORKER_MAGIC);
CHECK_OBJ_NOTNULL(req, REQ_MAGIC);
@@ -99,9 +100,10 @@ cnt_deliver(struct worker *wrk, struct req *req)
assert(req->obj->objcore->refcnt > 0);
- req->t_resp = W_TIM_real(wrk);
+ now = W_TIM_real(wrk);
+ VSLb_ts_req(req, "Process", now);
if (req->obj->objcore->exp_flags & OC_EF_EXP)
- EXP_Touch(req->obj->objcore, req->t_resp);
+ EXP_Touch(req->obj->objcore, now);
HTTP_Setup(req->resp, req->ws, req->vsl, SLT_RespMethod);
@@ -109,7 +111,7 @@ cnt_deliver(struct worker *wrk, struct req *req)
http_FilterResp(req->obj->http, req->resp, 0);
http_Unset(req->resp, H_Date);
- VTIM_format(req->t_resp, time_str);
+ VTIM_format(now, time_str);
http_PrintfHeader(req->resp, "Date: %s", time_str);
if (req->wrk->stats.cache_hit)
@@ -121,7 +123,7 @@ cnt_deliver(struct worker *wrk, struct req *req)
"X-Varnish: %u", req->vsl->wid & VSL_IDENTMASK);
http_PrintfHeader(req->resp, "Age: %.0f",
- req->t_resp - req->obj->exp.t_origin);
+ now - req->obj->exp.t_origin);
http_SetHeader(req->resp, "Via: 1.1 varnish (v4)");
@@ -152,6 +154,7 @@ cnt_deliver(struct worker *wrk, struct req *req)
http_SetResp(req->resp, "HTTP/1.1", 304, "Not Modified");
V1D_Deliver(req);
+ VSLb_ts_req(req, "Resp", W_TIM_real(wrk));
if (http_HdrIs(req->resp, H_Connection, "close"))
req->doclose = SC_RESP_CLOSE;
@@ -192,6 +195,7 @@ cnt_synth(struct worker *wrk, struct req *req)
{
char date[40];
struct http *h;
+ double now;
CHECK_OBJ_NOTNULL(wrk, WORKER_MAGIC);
CHECK_OBJ_NOTNULL(req, REQ_MAGIC);
@@ -200,7 +204,9 @@ cnt_synth(struct worker *wrk, struct req *req)
HTTP_Setup(req->resp, req->ws, req->vsl, SLT_RespMethod);
h = req->resp;
- req->t_resp = VTIM_real();
+
+ now = W_TIM_real(wrk);
+ VSLb_ts_req(req, "Process", now);
if (req->err_code < 100 || req->err_code > 999)
req->err_code = 501;
@@ -208,7 +214,7 @@ cnt_synth(struct worker *wrk, struct req *req)
http_ClrHeader(h);
http_PutProtocol(h, "HTTP/1.1");
http_PutStatus(h, req->err_code);
- VTIM_format(req->t_resp, date);
+ VTIM_format(now, date);
http_PrintfHeader(h, "Date: %s", date);
http_SetHeader(h, "Server: Varnish");
http_PrintfHeader(req->resp,
@@ -242,6 +248,8 @@ cnt_synth(struct worker *wrk, struct req *req)
V1D_Deliver_Synth(req);
+ VSLb_ts_req(req, "Resp", W_TIM_real(wrk));
+
VSB_delete(req->synth_body);
req->synth_body = NULL;
@@ -326,6 +334,7 @@ cnt_lookup(struct worker *wrk, struct req *req)
struct object *o;
struct objhead *oh;
enum lookup_e lr;
+ int had_objhead = 0;
CHECK_OBJ_NOTNULL(wrk, WORKER_MAGIC);
CHECK_OBJ_NOTNULL(req, REQ_MAGIC);
@@ -336,6 +345,8 @@ cnt_lookup(struct worker *wrk, struct req *req)
VRY_Prep(req);
AZ(req->objcore);
+ if (req->hash_objhead)
+ had_objhead = 1;
lr = HSH_Lookup(req, &oc, &boc,
req->esi_level == 0 ? 1 : 0,
req->hash_always_miss ? 1 : 0
@@ -349,6 +360,8 @@ cnt_lookup(struct worker *wrk, struct req *req)
*/
return (REQ_FSM_DISEMBARK);
}
+ if (had_objhead)
+ VSLb_ts_req(req, "Waitinglist", W_TIM_real(wrk));
if (boc == NULL) {
VRY_Finish(req, DISCARD);
@@ -631,12 +644,14 @@ cnt_restart(struct worker *wrk, struct req *req)
} else {
wid = VXID_Get(&wrk->vxid_pool);
// XXX: ReqEnd + ReqAcct ?
+ VSLb_ts_req(req, "Restart", W_TIM_real(wrk));
VSLb(req->vsl, SLT_Link, "req %u restart", wid);
VSLb(req->vsl, SLT_End, "%s", "");
VSL_Flush(req->vsl, 0);
owid = req->vsl->wid & VSL_IDENTMASK;
req->vsl->wid = wid | VSL_CLIENTMARKER;
VSLb(req->vsl, SLT_Begin, "req %u restart", owid);
+ VSLb_ts_req(req, "Start", req->t_prev);
req->err_code = 0;
req->req_step = R_STP_RECV;
}
@@ -677,6 +692,10 @@ cnt_recv(struct worker *wrk, struct req *req)
AZ(req->obj);
AZ(req->objcore);
+ assert(!isnan(req->t_first));
+ assert(!isnan(req->t_prev));
+ assert(!isnan(req->t_req));
+
VSLb(req->vsl, SLT_ReqStart, "%s %s",
req->sp->client_addr_str, req->sp->client_port_str);
@@ -882,12 +901,6 @@ CNT_Request(struct worker *wrk, struct req *req)
VSLb(req->vsl, SLT_Length, "%ju",
(uintmax_t)req->resp_bodybytes);
}
- VSLb(req->vsl, SLT_ReqEnd, "%.9f %.9f %.9f %.9f %.9f",
- req->t_req,
- req->sp->t_idle,
- req->sp->t_idle - req->t_resp,
- req->t_resp - req->t_req,
- req->sp->t_idle - req->t_resp);
while (!VTAILQ_EMPTY(&req->body)) {
st = VTAILQ_FIRST(&req->body);
diff --git a/bin/varnishd/cache/cache_session.c b/bin/varnishd/cache/cache_session.c
index 96a2507..73ed5c7 100644
--- a/bin/varnishd/cache/cache_session.c
+++ b/bin/varnishd/cache/cache_session.c
@@ -399,8 +399,9 @@ SES_GetReq(struct worker *wrk, struct sess *sp)
WS_Init(req->ws, "req", p, e - p);
+ req->t_first = NAN;
+ req->t_prev = NAN;
req->t_req = NAN;
- req->t_resp = NAN;
VTAILQ_INIT(&req->body);
diff --git a/bin/varnishd/cache/cache_shmlog.c b/bin/varnishd/cache/cache_shmlog.c
index 81f5a03..19048c2 100644
--- a/bin/varnishd/cache/cache_shmlog.c
+++ b/bin/varnishd/cache/cache_shmlog.c
@@ -350,6 +350,17 @@ VSLb(struct vsl_log *vsl, enum VSL_tag_e tag, const char *fmt, ...)
va_end(ap);
}
+void
+VSLb_ts(struct vsl_log *vsl, const char *event, double first, double *pprev,
+ double now)
+{
+
+ assert(!isnan(now) && now != 0.);
+ VSLb(vsl, SLT_Timestamp, "%s: %.9f %.9f %.9f",
+ event, now, now - first, now - *pprev);
+ *pprev = now;
+}
+
/*--------------------------------------------------------------------
* Setup a VSL buffer, allocate space if none provided.
*/
diff --git a/include/tbl/vsl_tags.h b/include/tbl/vsl_tags.h
index 5f768ec..34c5c13 100644
--- a/include/tbl/vsl_tags.h
+++ b/include/tbl/vsl_tags.h
@@ -462,4 +462,21 @@ SLTM(Storage, 0, "Where object is stored",
"\t+---- Type (\"malloc\", \"file\", \"persistent\" etc.)\n"
"\n"
)
+
+SLTM(Timestamp, 0, "Timing information",
+ "Contains timing information for the Varnish worker threads.\n\n"
+ "Time stamps are issued by Varnish on certain events,"
+ " and show the absolute time of the event, the time spent since the"
+ " start of the work unit, and the time spent since the last timestamp"
+ " was logged.\n\n"
+ "The format is::\n\n"
+ "\t%s: %f %f %f\n"
+ "\t| | | |\n"
+ "\t| | | +- Time since last timestamp\n"
+ "\t| | +---- Time since start of work unit\n"
+ "\t| +------- Absolute time of event\n"
+ "\t+----------- Event label\n"
+ "\n"
+)
+
#undef NODEF_NOTICE
More information about the varnish-commit
mailing list