[PATCH 2/2] 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
Mon Sep 1 14:02:36 CEST 2014
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
---
bin/varnishd/cache/cache_esi_deliver.c | 3 ++-
bin/varnishd/cache/cache_fetch.c | 4 ++--
bin/varnishd/cache/cache_http1_fsm.c | 39 +++++++++++++++-------------------
bin/varnishd/cache/cache_session.c | 4 ----
bin/varnishtest/tests/r01581.vtc | 23 ++++++++++++++++++++
5 files changed, 44 insertions(+), 29 deletions(-)
create mode 100644 bin/varnishtest/tests/r01581.vtc
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 001cd79..77c1e8c 100644
--- a/bin/varnishd/cache/cache_fetch.c
+++ b/bin/varnishd/cache/cache_fetch.c
@@ -822,8 +822,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 b0c5299..98b3dcf 100644
--- a/bin/varnishd/cache/cache_http1_fsm.c
+++ b/bin/varnishd/cache/cache_http1_fsm.c
@@ -122,9 +122,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) {
@@ -151,8 +151,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) {
@@ -239,13 +239,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);
@@ -305,16 +299,17 @@ 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, 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
--
2.1.0
More information about the varnish-dev
mailing list