[master] f6ef5927b Add (be)req.trace and feature +trace to control generation of VCL_trace logs
Nils Goroll
nils.goroll at uplex.de
Mon May 8 14:53:03 UTC 2023
commit f6ef5927bca7a5bb05cd67674c0e26f233852648
Author: Nils Goroll <nils.goroll at uplex.de>
Date: Tue Nov 8 16:15:54 2022 +0100
Add (be)req.trace and feature +trace to control generation of VCL_trace logs
To potentially emit VCL_trace VSL records, we called VPI_count() from
VGC for, in the extreme, every line of VCL.
For a normal setup, VPI_count() would call into VSL only to find out
that VCL_trace is masked and not have any effect.
Issuing two additional function calls for each line of VCL obviously
is something we should avoid unless there is a real benefit.
To avoid the overhead, we move the check for the tracing flag to VGC
and decorate it with UNLIKELY(), which has no effect for now but is
expected to become a branch prediction hint soon.
This should bring the cost down close to zero.
Being at it, we also add VCL control over tracing through req.trace
and bereq.trace. req.trace gets initialized from feature +trace, and
bereq.trace inherits the value from req.trace. For now, tracing of the
housekeeping subs vcl_init and vcl_fini can only be controlled through
feature +trace.
diff --git a/bin/varnishd/cache/cache_req_fsm.c b/bin/varnishd/cache/cache_req_fsm.c
index 5313268b3..fabddba5b 100644
--- a/bin/varnishd/cache/cache_req_fsm.c
+++ b/bin/varnishd/cache/cache_req_fsm.c
@@ -891,6 +891,7 @@ cnt_recv_prep(struct req *req, const char *ci)
req->hash_ignore_vary = 0;
req->client_identity = NULL;
req->storage = NULL;
+ req->trace = FEATURE(FEATURE_TRACE);
}
req->is_hit = 0;
diff --git a/bin/varnishd/cache/cache_vcl.c b/bin/varnishd/cache/cache_vcl.c
index 0f3245c8c..ad811c4eb 100644
--- a/bin/varnishd/cache/cache_vcl.c
+++ b/bin/varnishd/cache/cache_vcl.c
@@ -93,6 +93,7 @@ VCL_Bo2Ctx(struct vrt_ctx *ctx, struct busyobj *bo)
ctx->ws = bo->ws;
ctx->vpi = bo->wrk->vpi;
ctx->vpi->handling = 0;
+ ctx->vpi->trace = bo->trace;
}
void
@@ -116,6 +117,7 @@ VCL_Req2Ctx(struct vrt_ctx *ctx, struct req *req)
ctx->ws = req->ws;
ctx->vpi = req->wrk->vpi;
ctx->vpi->handling = 0;
+ ctx->vpi->trace = req->trace;
}
/*--------------------------------------------------------------------*/
@@ -128,6 +130,7 @@ VCL_Get_CliCtx(int msg)
INIT_OBJ(&ctx_cli, VRT_CTX_MAGIC);
INIT_OBJ(&wrk_vpi_cli, WRK_VPI_MAGIC);
ctx_cli.vpi = &wrk_vpi_cli;
+ wrk_vpi_cli.trace = FEATURE(FEATURE_TRACE);
ctx_cli.now = VTIM_real();
if (msg) {
ctx_cli.msg = VSB_new_auto();
diff --git a/bin/varnishd/cache/cache_vpi.c b/bin/varnishd/cache/cache_vpi.c
index 0d8e792bf..9b3b3db1c 100644
--- a/bin/varnishd/cache/cache_vpi.c
+++ b/bin/varnishd/cache/cache_vpi.c
@@ -62,14 +62,13 @@ VPI_wrk_init(struct worker *wrk, void *p, size_t spc)
}
void
-VPI_count(VRT_CTX, unsigned u)
+VPI_trace(VRT_CTX, unsigned u)
{
CHECK_OBJ_NOTNULL(ctx, VRT_CTX_MAGIC);
CHECK_OBJ_NOTNULL(ctx->vcl, VCL_MAGIC);
CHECK_OBJ_NOTNULL(ctx->vcl->conf, VCL_CONF_MAGIC);
assert(u < ctx->vcl->conf->nref);
- ctx->vpi->ref = u;
if (ctx->vsl != NULL)
VSLb(ctx->vsl, SLT_VCL_trace, "%s %u %u.%u.%u",
ctx->vcl->loaded_name, u, ctx->vcl->conf->ref[u].source,
diff --git a/bin/varnishd/cache/cache_vrt.c b/bin/varnishd/cache/cache_vrt.c
index cc4f1bffb..d8630d347 100644
--- a/bin/varnishd/cache/cache_vrt.c
+++ b/bin/varnishd/cache/cache_vrt.c
@@ -658,6 +658,15 @@ VRT_handled(VRT_CTX)
return (ctx->vpi->handling);
}
+/* the trace value is cached in the VPI for efficiency */
+VCL_VOID
+VRT_trace(VRT_CTX, VCL_BOOL a)
+{
+ CHECK_OBJ_NOTNULL(ctx, VRT_CTX_MAGIC);
+ AN(ctx->vpi);
+ ctx->vpi->trace = a;
+}
+
/*--------------------------------------------------------------------*/
VCL_VOID
diff --git a/bin/varnishd/cache/cache_vrt_var.c b/bin/varnishd/cache/cache_vrt_var.c
index fe4f8a81e..2bd56b71a 100644
--- a/bin/varnishd/cache/cache_vrt_var.c
+++ b/bin/varnishd/cache/cache_vrt_var.c
@@ -301,6 +301,23 @@ VRT_r_beresp_uncacheable(VRT_CTX)
return (ctx->bo->uncacheable);
}
+VCL_VOID
+VRT_l_req_trace(VRT_CTX, VCL_BOOL a)
+{
+ CHECK_OBJ_NOTNULL(ctx, VRT_CTX_MAGIC);
+ CHECK_OBJ_NOTNULL(ctx->req, REQ_MAGIC);
+ ctx->req->trace = a;
+ VRT_trace(ctx, a);
+}
+VCL_VOID
+VRT_l_bereq_trace(VRT_CTX, VCL_BOOL a)
+{
+ CHECK_OBJ_NOTNULL(ctx, VRT_CTX_MAGIC);
+ CHECK_OBJ_NOTNULL(ctx->bo, BUSYOBJ_MAGIC);
+ ctx->bo->trace = a;
+ VRT_trace(ctx, a);
+}
+
/*--------------------------------------------------------------------*/
VCL_BYTES
diff --git a/bin/varnishtest/tests/c00005.vtc b/bin/varnishtest/tests/c00005.vtc
index 255f42232..4520088c7 100644
--- a/bin/varnishtest/tests/c00005.vtc
+++ b/bin/varnishtest/tests/c00005.vtc
@@ -9,7 +9,7 @@ server s1 {
txresp -body "2222\n"
} -start
-varnish v1 -arg "-p vsl_mask=+VCL_trace"
+varnish v1 -arg "-p feature=+trace"
varnish v1 -errvcl {Name acl1 must have type 'acl'.} {
sub vcl_recv {
diff --git a/bin/varnishtest/tests/c00054.vtc b/bin/varnishtest/tests/c00054.vtc
index 266cc13a8..420386b89 100644
--- a/bin/varnishtest/tests/c00054.vtc
+++ b/bin/varnishtest/tests/c00054.vtc
@@ -9,7 +9,7 @@ server s1 {
varnish v1 -vcl+backend {} -start
varnish v1 -cliok "param.show vsl_mask"
-varnish v1 -cliok "param.set vsl_mask +VCL_trace"
+varnish v1 -cliok "param.set vsl_mask -VCL_trace"
varnish v1 -cliok "param.show vsl_mask"
varnish v1 -cliok "param.set vsl_mask -WorkThread,-TTL"
varnish v1 -cliok "param.show vsl_mask"
diff --git a/bin/varnishtest/tests/r02413.vtc b/bin/varnishtest/tests/r02413.vtc
index 15ed32fe5..ba85102b1 100644
--- a/bin/varnishtest/tests/r02413.vtc
+++ b/bin/varnishtest/tests/r02413.vtc
@@ -1,11 +1,11 @@
-varnishtest "Test vcl_trace"
+varnishtest "Test feature trace"
server s1 {
rxreq
txresp
} -start
-varnish v1 -arg "-p vsl_mask=+VCL_trace" -vcl+backend {
+varnish v1 -arg "-p feature=+trace" -vcl+backend {
sub vcl_deliver {
set resp.http.vcl = "vclA";
}
@@ -18,6 +18,7 @@ varnish v1 -vcl+backend {
if (req.http.vcl == "vcl1") {
return (vcl(vclA));
}
+ set req.trace = false;
}
sub vcl_deliver {
set resp.http.vcl = "vcl2";
@@ -28,16 +29,24 @@ varnish v1 -cliok "vcl.label vclB vcl2"
varnish v1 -cliok "vcl.list"
logexpect l1 -v v1 -g raw {
+ expect * 1002 VCL_call "BACKEND_FETCH"
+ expect 0 1002 VCL_trace {^vcl1 \d+ \d+\.\d+\.\d+$}
expect * 1001 VCL_call "RECV"
expect 0 1001 VCL_trace {^vcl2 \d+ \d+\.\d+\.\d+$}
expect * 1001 VCL_call "RECV"
expect 0 1001 VCL_trace {^vcl1 \d+ \d+\.\d+\.\d+$}
+ expect * 1003 VCL_call "DELIVER"
+ expect 0 1003 RespHeader {^vcl: vcl2}
} -start
client c1 {
txreq -hdr "vcl: vcl1"
rxresp
expect resp.http.vcl == vclA
+
+ txreq
+ rxresp
+ expect resp.http.vcl == vcl2
} -run
logexpect l1 -wait
diff --git a/doc/changes.rst b/doc/changes.rst
index c9c8d1d00..e30c24924 100644
--- a/doc/changes.rst
+++ b/doc/changes.rst
@@ -38,6 +38,19 @@ Varnish Cache NEXT (2023-09-15)
.. PLEASE keep this roughly in commit order as shown by git-log / tig
(new to old)
+* VCL tracing now needs to be explicitly activated by setting the
+ ``req.trace`` or ``bereq.trace`` VCL variables, which are
+ initialized from the ``feature +trace`` flag. Only if the trace
+ variables are set will ``VCL_trace`` log records be generated.
+
+ Consequently, ``VCL_trace`` has been removed from the default
+ ``vsl_mask``, so any trace records will be emitted by
+ default. ``vsl_mask`` can still be used to filter ``VCL_trace``
+ records.
+
+ To trace ``vcl_init {}`` and ``vcl_fini {}``, set the ``feature
+ +trace`` flag while the vcl is loaded/discarded.
+
* Varnish Delivery Processors (VDPs) are now also properly closed for
error conditions, avoiding potential minor memory leaks.
diff --git a/doc/sphinx/reference/vcl_var.rst b/doc/sphinx/reference/vcl_var.rst
index edb9761bb..b8a28c453 100644
--- a/doc/sphinx/reference/vcl_var.rst
+++ b/doc/sphinx/reference/vcl_var.rst
@@ -451,6 +451,23 @@ req.time
across restarts.
+.. _req.trace:
+
+req.trace
+
+ Type: BOOL
+
+ Readable from: client
+
+ Writable from: client
+
+ Controls if ``VCL_trace`` VSL records are emitted for the current
+ request, see :ref:`vsl(7)`.
+
+ Defaults to the setting of the ``feature trace`` parameter,
+ see :ref:`varnishd(1)`. Does not get reset by a rollback.
+
+
.. _req.transport:
req.transport
@@ -794,6 +811,23 @@ bereq.time
remains constant across retries.
+.. _bereq.trace:
+
+bereq.trace
+
+ Type: BOOL
+
+ Readable from: backend
+
+ Writable from: backend
+
+ Controls if ``VCL_trace`` VSL records are emitted for the current
+ request, see :ref:`vsl(7)`.
+
+ Inherits the value of ``req.trace`` when the backend request
+ is created. Does not get reset by a rollback.
+
+
.. _bereq.uncacheable:
bereq.uncacheable
diff --git a/include/tbl/feature_bits.h b/include/tbl/feature_bits.h
index 68ae39839..1ff2a361f 100644
--- a/include/tbl/feature_bits.h
+++ b/include/tbl/feature_bits.h
@@ -86,6 +86,11 @@ FEATURE_BIT(BUSY_STATS_RATE, busy_stats_rate,
"Make busy workers comply with thread_stats_rate."
)
+FEATURE_BIT(TRACE, trace,
+ "Enable VCL tracing by default (enable (be)req.trace). "
+ "Required for tracing vcl_init / vcl_fini"
+)
+
#undef FEATURE_BIT
/*lint -restore */
diff --git a/include/tbl/params.h b/include/tbl/params.h
index f5fb58695..fcf47e31c 100644
--- a/include/tbl/params.h
+++ b/include/tbl/params.h
@@ -1817,7 +1817,6 @@ PARAM_BITS(
"-ObjProtocol,"
"-ObjReason,"
"-ObjStatus,"
- "-VCL_trace,"
"-VdpAcct,"
"-VfpAcct,"
"-WorkThread",
diff --git a/include/tbl/req_bereq_flags.h b/include/tbl/req_bereq_flags.h
index 36f868d2a..1cbde5d12 100644
--- a/include/tbl/req_bereq_flags.h
+++ b/include/tbl/req_bereq_flags.h
@@ -34,6 +34,7 @@
/* lower, vcl_r, vcl_w, doc */
REQ_BEREQ_FLAG(is_hitmiss, 1, 0, "")
REQ_BEREQ_FLAG(is_hitpass, 1, 0, "")
+REQ_BEREQ_FLAG(trace, 1, 0, "")
#undef REQ_BEREQ_FLAG
/*lint -restore */
diff --git a/include/vcc_interface.h b/include/vcc_interface.h
index 83ef7f096..529ab9ed1 100644
--- a/include/vcc_interface.h
+++ b/include/vcc_interface.h
@@ -60,11 +60,16 @@ struct wrk_vpi {
unsigned magic;
#define WRK_VPI_MAGIC 0xaa3d3df3
unsigned handling;
+ unsigned trace; // caches (be)req.trace
unsigned ref; // index into (struct vpi_ref)[]
};
-
-void VPI_count(VRT_CTX, unsigned);
+#define VPI_count(ctx, max, u) \
+ do { \
+ assert(u < max); \
+ (ctx)->vpi->ref = u; \
+ } while(0)
+void VPI_trace(VRT_CTX, unsigned);
void VPI_vcl_fini(VRT_CTX);
int VPI_Vmod_Init(VRT_CTX, struct vmod **hdl, unsigned nbr, void *ptr, int len,
diff --git a/include/vdef.h b/include/vdef.h
index faa4877c4..36e4fa854 100644
--- a/include/vdef.h
+++ b/include/vdef.h
@@ -257,3 +257,7 @@ typedef struct {
#define Tcheck(t) do { (void)pdiff((t).b, (t).e); } while (0)
#define Tlen(t) (pdiff((t).b, (t).e))
+
+/* #3020 dummy definitions until PR is merged*/
+#define LIKELY(x) (x)
+#define UNLIKELY(x) (x)
diff --git a/include/vrt.h b/include/vrt.h
index 68a2ff5a5..9dd7f044b 100644
--- a/include/vrt.h
+++ b/include/vrt.h
@@ -59,6 +59,7 @@
*
* NEXT (2023-09-15)
* [cache_filter.h] struct vdp gained priv1 member
+ * VRT_trace() added
* 17.0 (2023-03-15)
* VXID is 64 bit
* [cache.h] http_GetRange() changed
@@ -676,6 +677,7 @@ VCL_VOID VRT_UnsetHdr(VRT_CTX, VCL_HEADER);
VCL_VOID VRT_SetHdr(VRT_CTX, VCL_HEADER, const char *pfx, VCL_STRANDS);
VCL_VOID VRT_handling(VRT_CTX, unsigned hand);
unsigned VRT_handled(VRT_CTX);
+VCL_VOID VRT_trace(VRT_CTX, VCL_BOOL);
VCL_VOID VRT_fail(VRT_CTX, const char *fmt, ...) v_printflike_(2,3);
VCL_VOID VRT_hashdata(VRT_CTX, VCL_STRANDS);
diff --git a/lib/libvcc/vcc_parse.c b/lib/libvcc/vcc_parse.c
index cd9832569..f579e2d0b 100644
--- a/lib/libvcc/vcc_parse.c
+++ b/lib/libvcc/vcc_parse.c
@@ -47,9 +47,11 @@ static void vcc_Compound(struct vcc *tl);
tl->indent -= INDENT; \
} while (0)
-#define C(tl, sep) do { \
- Fb(tl, 1, "VPI_count(ctx, %u)%s\n", ++tl->cnt, sep); \
- tl->t->cnt = tl->cnt; \
+#define C(tl, sep) do { \
+ Fb(tl, 1, "VPI_count(ctx, VGC_NREFS, %u)%s\n", ++tl->cnt, sep); \
+ Fb(tl, 1, "if (UNLIKELY(ctx->vpi->trace)) VPI_trace(ctx, %u)%s\n", \
+ tl->cnt, sep); \
+ tl->t->cnt = tl->cnt; \
} while (0)
/*--------------------------------------------------------------------
More information about the varnish-commit
mailing list