[4.0] f941069 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:54:33 CEST 2014
commit f94106987fcdd958c1daf4cec6186da980c8ac82
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
Conflicts:
bin/varnishd/cache/cache_esi_deliver.c
bin/varnishd/cache/cache_fetch.c
bin/varnishd/cache/cache_http1_fsm.c
bin/varnishd/cache/cache_session.c
diff --git a/bin/varnishd/cache/cache_esi_deliver.c b/bin/varnishd/cache/cache_esi_deliver.c
index ee1b0e5..fee1240 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->vxid_pool) | VSL_CLIENTMARKER;
VSLb(req->vsl, SLT_Begin, "req %u esi", preq->vsl->wid & VSL_IDENTMASK);
VSLb(preq->vsl, SLT_Link, "req %u esi", req->vsl->wid & VSL_IDENTMASK);
req->esi_level = preq->esi_level + 1;
diff --git a/bin/varnishd/cache/cache_fetch.c b/bin/varnishd/cache/cache_fetch.c
index a768170..3d1fbfe 100644
--- a/bin/varnishd/cache/cache_fetch.c
+++ b/bin/varnishd/cache/cache_fetch.c
@@ -873,9 +873,9 @@ VBF_Fetch(struct worker *wrk, struct req *req, struct objcore *oc,
default: WRONG("Wrong fetch mode");
}
- VSLb(bo->vsl, SLT_Begin, "bereq %u %s ",
+ VSLb(bo->vsl, SLT_Begin, "bereq %u %s",
req->vsl->wid & VSL_IDENTMASK, how);
- VSLb(req->vsl, SLT_Link, "bereq %u %s ",
+ VSLb(req->vsl, SLT_Link, "bereq %u %s",
bo->vsl->wid & VSL_IDENTMASK, how);
bo->refcount = 2;
diff --git a/bin/varnishd/cache/cache_http1_fsm.c b/bin/varnishd/cache/cache_http1_fsm.c
index 454ec28..31b65e2 100644
--- a/bin/varnishd/cache/cache_http1_fsm.c
+++ b/bin/varnishd/cache/cache_http1_fsm.c
@@ -123,9 +123,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) {
@@ -152,8 +152,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) {
@@ -245,14 +245,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->vxid_pool) | VSL_CLIENTMARKER;
- VSLb(req->vsl, SLT_Begin, "req %u rxreq",
- req->sp->vxid & VSL_IDENTMASK);
- VSL(SLT_Link, req->sp->vxid, "req %u rxreq",
- req->vsl->wid & VSL_IDENTMASK);
- 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);
@@ -312,17 +305,19 @@ http1_dissect(struct worker *wrk, struct req *req)
memset(&req->h1, 0, sizeof req->h1);
- /*
- * 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->vxid_pool) | VSL_CLIENTMARKER;
- VSLb(req->vsl, SLT_Begin, "req %u rxreq",
- req->sp->vxid & VSL_IDENTMASK);
- VSL(SLT_Link, req->sp->vxid, "req %u rxreq",
- req->vsl->wid & VSL_IDENTMASK);
- }
+ /* Allocate a new vxid now that we know we'll need it. */
+ AZ(req->vsl->wid);
+ req->vsl->wid = VXID_Get(&wrk->vxid_pool) | VSL_CLIENTMARKER;
+
+ VSLb(req->vsl, SLT_Begin, "req %u rxreq",
+ req->sp->vxid & VSL_IDENTMASK);
+ VSL(SLT_Link, req->sp->vxid, "req %u rxreq",
+ req->vsl->wid & VSL_IDENTMASK);
+ 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 c938b98..7291a98 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", sp->vxid & VSL_IDENTMASK);
- VSL(SLT_Link, sp->vxid, "req %u rxreq", req->vsl->wid & VSL_IDENTMASK);
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->vxid_pool) | 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