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.

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;

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();

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,

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

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

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 {

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"

bin/varnishtest/tests/r02413.vtc

-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

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.
 

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

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 */

include/tbl/params.h

@@ -1817,7 +1817,6 @@ PARAM_BITS(
 	"-ObjProtocol,"
 	"-ObjReason,"
 	"-ObjStatus,"
-	"-VCL_trace,"
 	"-VdpAcct,"
 	"-VfpAcct,"
 	"-WorkThread",

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 */

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,

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)

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);
 

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)
 
 /*--------------------------------------------------------------------