internal/core/adt: avoid more allocations when LogEval is disabled

Benchmarking Judson's private project in Unity with benchcmd as follows:

    benchcmd -n 6 ExportJudsonOpendef bash -c 'CUE_DEBUG=opendef cue export -t variant=test -t shard=0 -e files ./structure >/dev/null'

I'm using CUE_DEBUG=opendef as closedness tracking causes significantly
worse performance due to https://cuelang.org/issue/3881,
to the point that measuring enough data points for comparing benchmark
results would take tens of minutes.

The results are however promising, as his CPU profile showed
that garbage collection was about 30% of CPU usage overall,
and the memory profile showed that a good portion of those allocations
came from Logf calls which aren't meant to do anything by default:

                        │    old     │               new                │
                        │   sec/op   │   sec/op    vs base              │
    ExportJudsonOpendef   9.800 ± 2%   9.158 ± 4%  -6.55% (p=0.002 n=6)

                        │     old     │             new              │
                        │ user-sec/op │ user-sec/op  vs base         │
    ExportJudsonOpendef   18.05 ± 14%   17.48 ± 11%  ~ (p=0.818 n=6)

                        │     old     │             new              │
                        │ sys-sec/op  │ sys-sec/op   vs base         │
    ExportJudsonOpendef   1.315 ± 10%   1.328 ± 16%  ~ (p=0.937 n=6)

                        │      old       │               new               │
                        │ peak-RSS-bytes │ peak-RSS-bytes  vs base         │
    ExportJudsonOpendef     9.831Gi ± 5%     9.699Gi ± 6%  ~ (p=0.394 n=6)

Signed-off-by: Daniel Martí <[email protected]>
Change-Id: I42b925c90a5baf02bbaca4af745357af1b477ade
Reviewed-on: https://review.gerrithub.io/c/cue-lang/cue/+/1213383
Unity-Result: CUE porcuepine <[email protected]>
TryBot-Result: CUEcueckoo <[email protected]>
Reviewed-by: Marcel van Lohuizen <[email protected]>

Author: mvdan

Diff for: internal/core/adt/log.go

@@ -69,6 +69,8 @@ func (c *OpContext) Un(s nestString, id int) {
 // The first argument must be the function name.
 func (c *OpContext) Indentf(v *Vertex, format string, args ...any) (s nestString, id int) {
 	if c.LogEval == 0 {
+		// The Go compiler as of 1.24 is not very clever with no-op function calls;
+		// any arguments passed to ...args above escape to the heap and allocate.
 		panic("avoid calling OpContext.Indentf when logging is disabled to prevent overhead")
 	}
 	name := strings.Split(format, "(")[0]
@@ -101,7 +103,9 @@ func (c *OpContext) RewriteArgs(args ...interface{}) {
 
 func (c *OpContext) Logf(v *Vertex, format string, args ...interface{}) {
 	if c.LogEval == 0 {
-		return
+		// The Go compiler as of 1.24 is not very clever with no-op function calls;
+		// any arguments passed to ...args above escape to the heap and allocate.
+		panic("avoid calling OpContext.Logf when logging is disabled to prevent overhead")
 	}
 	w := &strings.Builder{}
 
@@ -218,7 +222,9 @@ func (n *nodeContext) logDoDisjunct() *disjunctInfo {
 
 	d.disjunctID = int(c.stats.Disjuncts)
 
-	n.Logf("====== Do DISJUNCT %v & %v ======", d.lhs, d.rhs)
+	if n.ctx.LogEval > 0 {
+		n.Logf("====== Do DISJUNCT %v & %v ======", d.lhs, d.rhs)
+	}
 
 	return d
 }

Diff for: internal/core/adt/states.go

@@ -260,7 +260,9 @@ var schedConfig = taskContext{
 func stateCompletions(s *scheduler) condition {
 	x := s.completed
 	v := s.node.node
-	s.node.Logf("=== stateCompletions: %v  %v", v.Label, s.completed)
+	if s.node.ctx.LogEval > 0 {
+		s.node.Logf("=== stateCompletions: %v  %v", v.Label, s.completed)
+	}
 	if x.meets(allAncestorsProcessed) {
 		x |= conditionsUsingCounters &^ s.provided
 		// If we have a pending or constraint arc, a sub arc may still cause the

Diff for: internal/core/adt/tasks.go

@@ -109,7 +109,9 @@ func processResolver(ctx *OpContext, t *task, mode runMode) {
 	}
 	arc = arc.DerefNonDisjunct()
 
-	ctx.Logf(t.node.node, "RESOLVED %v to %v %v", r, arc.Label, fmt.Sprintf("%p", arc))
+	if ctx.LogEval > 0 {
+		ctx.Logf(t.node.node, "RESOLVED %v to %v %v", r, arc.Label, fmt.Sprintf("%p", arc))
+	}
 	// TODO: consider moving after markCycle or removing.
 	d := arc.DerefDisjunct()
 

Diff for: internal/core/adt/unify.go

@@ -761,7 +761,9 @@ func (v *Vertex) lookup(c *OpContext, pos token.Pos, f Feature, flags combinedFl
 
 	v = v.DerefValue()
 
-	c.Logf(c.vertex, "LOOKUP %v", f)
+	if c.LogEval > 0 {
+		c.Logf(c.vertex, "LOOKUP %v", f)
+	}
 
 	state := v.getState(c)
 	if state != nil {