[master] b3a461f Add SLT_Begin records at start of every new vxid transaction. Format: <type> <parent-vxid>
Martin Blix Grydeland
martin at varnish-cache.org
Wed May 15 14:46:13 CEST 2013
commit b3a461f3dd75353490a7c84e7142b41565f005d5
Author: Martin Blix Grydeland <martin at varnish-software.com>
Date: Thu Apr 25 13:41:54 2013 +0200
Add SLT_Begin records at start of every new vxid transaction.
Format: <type> <parent-vxid>
Add SLT_End records at the end of all vxid transactions.
Add SLT_Link records whenever one initiates a new child transation.
Format: <type-of-child> <child-vxid>
This is used by VSL api to form structured log output.
diff --git a/bin/varnishd/cache/cache_busyobj.c b/bin/varnishd/cache/cache_busyobj.c
index 5124dc4..47e61b3 100644
--- a/bin/varnishd/cache/cache_busyobj.c
+++ b/bin/varnishd/cache/cache_busyobj.c
@@ -129,7 +129,7 @@ VBO_GetBusyObj(struct worker *wrk, struct req *req)
sz = cache_param->vsl_buffer;
VSL_Setup(bo->vsl, p, sz);
bo->vsl->wid = VXID_Get(&wrk->vxid_pool) | VSL_BACKENDMARKER;
- VSLb(bo->vsl, SLT_Link, "req %u", req->vsl->wid & VSL_IDENTMASK);
+ VSLb(bo->vsl, SLT_Begin, "bereq %u", req->vsl->wid & VSL_IDENTMASK);
VSLb(req->vsl, SLT_Link, "bereq %u", bo->vsl->wid & VSL_IDENTMASK);
p += sz;
p = (void*)PRNDUP(p);
@@ -182,6 +182,7 @@ VBO_DerefBusyObj(struct worker *wrk, struct busyobj **pbo)
if (r)
return;
+ VSLb(bo->vsl, SLT_End, "%s", "");
VSL_Flush(bo->vsl, 0);
if (oc != NULL) {
diff --git a/bin/varnishd/cache/cache_esi_deliver.c b/bin/varnishd/cache/cache_esi_deliver.c
index d5cf9e6..041626f 100644
--- a/bin/varnishd/cache/cache_esi_deliver.c
+++ b/bin/varnishd/cache/cache_esi_deliver.c
@@ -60,7 +60,7 @@ ved_include(struct req *preq, const char *src, const char *host)
wrk_ws_wm = WS_Snapshot(wrk->aws); /* XXX ? */
req = SES_GetReq(wrk, preq->sp);
- VSLb(req->vsl, SLT_Link, "req %u", preq->vsl->wid & VSL_IDENTMASK);
+ VSLb(req->vsl, SLT_Begin, "esireq %u", preq->vsl->wid & VSL_IDENTMASK);
VSLb(preq->vsl, SLT_Link, "esireq %u", req->vsl->wid & VSL_IDENTMASK);
req->esi_level = preq->esi_level + 1;
@@ -114,6 +114,9 @@ ved_include(struct req *preq, const char *src, const char *host)
(void)usleep(10000);
}
+ VSLb(req->vsl, SLT_End, "%s", "");
+ req->vsl->wid = 0;
+
/* Reset the workspace */
WS_Reset(wrk->aws, wrk_ws_wm); /* XXX ? */
diff --git a/bin/varnishd/cache/cache_http1_fsm.c b/bin/varnishd/cache/cache_http1_fsm.c
index ecc3583..90ffc21 100644
--- a/bin/varnishd/cache/cache_http1_fsm.c
+++ b/bin/varnishd/cache/cache_http1_fsm.c
@@ -252,8 +252,13 @@ http1_dissect(struct worker *wrk, struct req *req)
* 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)
+ if (req->vsl->wid == 0) {
req->vsl->wid = VXID_Get(&wrk->vxid_pool) | VSL_CLIENTMARKER;
+ VSLb(req->vsl, SLT_Begin, "req %u",
+ req->sp->vxid & VSL_IDENTMASK);
+ VSL(SLT_Link, req->sp->vxid, "req %u",
+ req->vsl->wid & VSL_IDENTMASK);
+ }
/* Borrow VCL reference from worker thread */
VCL_Refresh(&wrk->vcl);
diff --git a/bin/varnishd/cache/cache_req_fsm.c b/bin/varnishd/cache/cache_req_fsm.c
index a1baa0e..07d0742 100644
--- a/bin/varnishd/cache/cache_req_fsm.c
+++ b/bin/varnishd/cache/cache_req_fsm.c
@@ -1349,6 +1349,7 @@ CNT_Request(struct worker *wrk, struct req *req)
* Nuke the VXID, cache_http1_fsm.c::http1_dissect() will
* allocate a new one when necessary.
*/
+ VSLb(req->vsl, SLT_End, "%s", "");
req->vsl->wid = 0;
}
diff --git a/bin/varnishd/cache/cache_session.c b/bin/varnishd/cache/cache_session.c
index 1630007..f117459 100644
--- a/bin/varnishd/cache/cache_session.c
+++ b/bin/varnishd/cache/cache_session.c
@@ -195,6 +195,7 @@ ses_vsl_socket(struct sess *sp, const char *lsockname)
strcpy(laddr, "-");
strcpy(lport, "-");
}
+ VSL(SLT_Begin, sp->vxid, "sess");
VSL(SLT_SessOpen, sp->vxid, "%s %s %s %s %s %.6f %d",
sp->addr, sp->port, lsockname, laddr, lport, sp->t_open, sp->fd);
}
@@ -329,6 +330,7 @@ SES_Delete(struct sess *sp, enum sess_close reason, double now)
VSL(SLT_SessClose, sp->vxid, "%s %.3f %ju %ju %ju %ju %ju %ju",
sess_close_2str(sp->reason, 0), now - sp->t_open, b->req,
b->pipe, b->pass, b->fetch, b->hdrbytes, b->bodybytes);
+ VSL(SLT_End, sp->vxid, "%s", "");
MPL_Free(pp->mpl_sess, sp);
}
@@ -383,7 +385,8 @@ SES_GetReq(struct worker *wrk, struct sess *sp)
sz = cache_param->workspace_thread;
VSL_Setup(req->vsl, p, sz);
req->vsl->wid = VXID_Get(&wrk->vxid_pool) | VSL_CLIENTMARKER;
- VSLb(req->vsl, SLT_Link, "sess %u", sp->vxid & VSL_IDENTMASK);
+ VSLb(req->vsl, SLT_Begin, "req %u", sp->vxid & VSL_IDENTMASK);
+ VSL(SLT_Link, req->sp->vxid, "req %u", req->vsl->wid & VSL_IDENTMASK);
p += sz;
p = (void*)PRNDUP(p);
@@ -417,6 +420,9 @@ SES_ReleaseReq(struct req *req)
AN(pp->pool);
CHECK_OBJ_NOTNULL(req, REQ_MAGIC);
MPL_AssertSane(req);
+ if (req->vsl->wid != 0)
+ /* Non-released VXID - assume it was from a req */
+ VSLb(req->vsl, SLT_End, "%s", "");
VSL_Flush(req->vsl, 0);
req->sp = NULL;
MPL_Free(pp->mpl_req, req);
diff --git a/include/tbl/vsl_tags.h b/include/tbl/vsl_tags.h
index 3f43bc1..25ba677 100644
--- a/include/tbl/vsl_tags.h
+++ b/include/tbl/vsl_tags.h
@@ -161,12 +161,26 @@ SLTM(VCL_Error, "", "")
SLTM(Gzip, "G(un)zip performed on object", "")
-SLTM(Link, "Linkage between different VXIDs",
- "Links this records VXID to its parent VXID\n"
- "The first field gives the type of the parent:\n"
+SLTM(Link, "Links to a child VXID",
+ "Links this VXID to any child VXID it initiates\n"
+ "The first field gives the type of the child:\n"
" req Request\n"
- " sess Session\n"
" bereq Backend request\n"
" esireq ESI subrequest\n"
- "The second field gives the VXID if the parent.\n"
+ "The second field gives the VXID of the child.\n"
+)
+
+SLTM(Begin, "Marks the start of a VXID",
+ "The first record of a VXID transaction.\n"
+ "The first field gives the type of the transaction:\n"
+ " sess Session\n"
+ " req Request\n"
+ " bereq Backend request\n"
+ " esireq ESI subrequest\n"
+ "The second field gives the VXID of the parent that initiated this"
+ " transaction. For Session transactions this field is blank.\n"
+)
+
+SLTM(End, "Marks the end of a VXID",
+ "The last record of a VXID transaction.\n"
)
More information about the varnish-commit
mailing list