[master] 51e13a4 Allocate request VXID only when it's needed and delay all logging until it's been allocated.
Martin Blix Grydeland
martin at varnish-software.com
Tue Sep 9 14:29:15 CEST 2014
commit 51e13a4a5e3940c29730ed65aa0b7b482ba21e61
Author: Martin Blix Grydeland <martin at varnish-software.com>
Date: Mon Sep 1 13:52:53 2014 +0200
Allocate request VXID only when it's needed and delay all logging
until it's been allocated.
This patch delays the VXID allocation until the time we know that we
will actually be logging anything for this request (not completely all
whitespace noise). This keeps the code in one place only (plus the ESI
mock request handling), instead of separated between the linger wait,
cache acceptor and pipelining code paths.
Coincidentally fixes the logging of timestamps problem in #1588.
Test case by daghf.
Fixes: #1581 #1588
diff --git a/bin/varnishd/cache/cache_esi_deliver.c b/bin/varnishd/cache/cache_esi_deliver.c
index 55c8901..d272bfc 100644
--- a/bin/varnishd/cache/cache_esi_deliver.c
+++ b/bin/varnishd/cache/cache_esi_deliver.c
@@ -62,7 +62,8 @@ ved_include(struct req *preq, const char *src, const char *host)
req = SES_GetReq(wrk, preq->sp);
req->req_body_status = REQ_BODY_NONE;
- AN(req->vsl->wid & VSL_CLIENTMARKER);
+ AZ(req->vsl->wid);
+ req->vsl->wid = VXID_Get(wrk, VSL_CLIENTMARKER);
VSLb(req->vsl, SLT_Begin, "req %u esi", VXID(preq->vsl->wid));
VSLb(preq->vsl, SLT_Link, "req %u esi", VXID(req->vsl->wid));
req->esi_level = preq->esi_level + 1;
diff --git a/bin/varnishd/cache/cache_fetch.c b/bin/varnishd/cache/cache_fetch.c
index ba547ca..1011946 100644
--- a/bin/varnishd/cache/cache_fetch.c
+++ b/bin/varnishd/cache/cache_fetch.c
@@ -889,8 +889,8 @@ VBF_Fetch(struct worker *wrk, struct req *req, struct objcore *oc,
bo = VBO_GetBusyObj(wrk, req);
CHECK_OBJ_NOTNULL(bo, BUSYOBJ_MAGIC);
- VSLb(bo->vsl, SLT_Begin, "bereq %u %s ", VXID(req->vsl->wid), how);
- VSLb(req->vsl, SLT_Link, "bereq %u %s ", VXID(bo->vsl->wid), how);
+ VSLb(bo->vsl, SLT_Begin, "bereq %u %s", VXID(req->vsl->wid), how);
+ VSLb(req->vsl, SLT_Link, "bereq %u %s", VXID(bo->vsl->wid), how);
THR_SetBusyobj(bo);
diff --git a/bin/varnishd/cache/cache_http1_fsm.c b/bin/varnishd/cache/cache_http1_fsm.c
index 23bec6c..bd80c79 100644
--- a/bin/varnishd/cache/cache_http1_fsm.c
+++ b/bin/varnishd/cache/cache_http1_fsm.c
@@ -121,9 +121,9 @@ http1_wait(struct sess *sp, struct worker *wrk, struct req *req)
if (hs == HTTP1_COMPLETE) {
/* Got it, run with it */
if (isnan(req->t_first))
- VSLb_ts_req(req, "Start", now);
- VSLb_ts_req(req, "Req", now);
- req->t_req = req->t_prev;
+ req->t_first = now;
+ if (isnan(req->t_req))
+ req->t_req = now;
req->acct.req_hdrbytes += Tlen(req->htc->rxbuf);
return (REQ_FSM_MORE);
} else if (hs == HTTP1_ERROR_EOF) {
@@ -150,8 +150,8 @@ http1_wait(struct sess *sp, struct worker *wrk, struct req *req)
} else {
/* Working on it */
if (isnan(req->t_first))
- /* Timestamp Start on first byte received */
- VSLb_ts_req(req, "Start", now);
+ /* Record first byte received time stamp */
+ req->t_first = now;
when = sp->t_idle + cache_param->timeout_req;
tmo = (int)(1e3 * (when - now));
if (when < now || tmo == 0) {
@@ -238,13 +238,7 @@ http1_cleanup(struct sess *sp, struct worker *wrk, struct req *req)
if (HTTP1_Reinit(req->htc) == HTTP1_COMPLETE) {
AZ(req->vsl->wid);
- req->vsl->wid = VXID_Get(wrk, VSL_CLIENTMARKER);
- VSLb(req->vsl, SLT_Begin, "req %u rxreq", VXID(req->sp->vxid));
- VSL(SLT_Link, req->sp->vxid, "req %u rxreq",
- VXID(req->vsl->wid));
- VSLb_ts_req(req, "Start", sp->t_idle);
- VSLb_ts_req(req, "Req", sp->t_idle);
- req->t_req = req->t_prev;
+ req->t_first = req->t_req = sp->t_idle;
wrk->stats.sess_pipeline++;
req->acct.req_hdrbytes += Tlen(req->htc->rxbuf);
return (SESS_DONE_RET_START);
@@ -270,16 +264,17 @@ http1_dissect(struct worker *wrk, struct req *req)
CHECK_OBJ_NOTNULL(wrk, WORKER_MAGIC);
CHECK_OBJ_NOTNULL(req, REQ_MAGIC);
- /*
- * Cache_req_fsm zeros the vxid once a requests is processed.
- * Allocate a new one only now that we know will need it.
- */
- if (req->vsl->wid == 0) {
- req->vsl->wid = VXID_Get(wrk, VSL_CLIENTMARKER);
- VSLb(req->vsl, SLT_Begin, "req %u rxreq", VXID(req->sp->vxid));
- VSL(SLT_Link, req->sp->vxid, "req %u rxreq",
- VXID(req->vsl->wid));
- }
+ /* Allocate a new vxid now that we know we'll need it. */
+ AZ(req->vsl->wid);
+ req->vsl->wid = VXID_Get(wrk, VSL_CLIENTMARKER);
+
+ VSLb(req->vsl, SLT_Begin, "req %u rxreq", VXID(req->sp->vxid));
+ VSL(SLT_Link, req->sp->vxid, "req %u rxreq", VXID(req->vsl->wid));
+ AZ(isnan(req->t_first)); /* First byte timestamp set by http1_wait */
+ AZ(isnan(req->t_req)); /* Complete req rcvd set by http1_wait */
+ req->t_prev = req->t_first;
+ VSLb_ts_req(req, "Start", req->t_first);
+ VSLb_ts_req(req, "Req", req->t_req);
/* Borrow VCL reference from worker thread */
VCL_Refresh(&wrk->vcl);
diff --git a/bin/varnishd/cache/cache_session.c b/bin/varnishd/cache/cache_session.c
index 3b22ce7..bd48b45 100644
--- a/bin/varnishd/cache/cache_session.c
+++ b/bin/varnishd/cache/cache_session.c
@@ -133,9 +133,6 @@ ses_sess_pool_task(struct worker *wrk, void *arg)
req = SES_GetReq(wrk, sp);
CHECK_OBJ_NOTNULL(req, REQ_MAGIC);
- AN(req->vsl->wid & VSL_CLIENTMARKER);
- VSLb(req->vsl, SLT_Begin, "req %u rxreq", VXID(sp->vxid));
- VSL(SLT_Link, sp->vxid, "req %u rxreq", VXID(req->vsl->wid));
sp->sess_step = S_STP_NEWREQ;
ses_req_pool_task(wrk, req);
@@ -362,7 +359,6 @@ SES_GetReq(struct worker *wrk, struct sess *sp)
sz = cache_param->vsl_buffer;
VSL_Setup(req->vsl, p, sz);
- req->vsl->wid = VXID_Get(wrk, VSL_CLIENTMARKER);
p += sz;
p = (void*)PRNDUP(p);
diff --git a/bin/varnishtest/tests/r01581.vtc b/bin/varnishtest/tests/r01581.vtc
new file mode 100644
index 0000000..f04eb0e
--- /dev/null
+++ b/bin/varnishtest/tests/r01581.vtc
@@ -0,0 +1,23 @@
+varnishtest "Duplcate SLT_Begin"
+
+server s1 {
+ rxreq
+ txresp
+} -start
+
+varnish v1 -vcl+backend {
+} -start
+
+logexpect l1 -v v1 -g request {
+ expect 0 1001 Begin
+ expect * = ReqStart
+ expect * = End
+} -start
+
+client c1 {
+ delay 0.1
+ send "GET / HTTP/1.1\r\nHost: example.com\r\n\r\n"
+ rxresp
+} -run
+
+logexpect l1 -wait
More information about the varnish-commit
mailing list