internal/core/adt: delay stringifying nodes in errors via fmt.Stringer

Particularly given that OpContext.Str ends up calling debug.NodeString,
which is relatively expensive to call when creating many errors.
Thousands of errors can easily be created when disjunctions are used.

Two of the projects which still see high memory usage see a reduction
of about 3% in allocated objects or space.
Automata sees a mild saving in CPU cost, as it spent 3% of CPU there.

                │     old     │                 new                  │
                │   sec/op    │   sec/op     vs base                 │
    VetAutomata   551.1m ± 3%   525.1m ± 4%  -4.72% (p=0.034 n=8+10)

                │     old      │                  new                  │
                │     B/op     │     B/op      vs base                 │
    VetAutomata   627.1Mi ± 0%   609.6Mi ± 0%  -2.78% (p=0.000 n=8+10)

                │     old     │                 new                  │
                │  allocs/op  │  allocs/op   vs base                 │
    VetAutomata   4.442M ± 0%   4.436M ± 0%  -0.14% (p=0.000 n=8+10)

               │    old     │             new             │
               │   sec/op   │   sec/op    vs base         │
    VetCaascad   4.482 ± 2%   4.427 ± 2%  ~ (p=0.721 n=8)

               │     old      │                new                 │
               │     B/op     │     B/op      vs base              │
    VetCaascad   3.318Gi ± 0%   3.302Gi ± 0%  -0.50% (p=0.000 n=8)

               │     old     │                new                │
               │  allocs/op  │  allocs/op   vs base              │
    VetCaascad   12.85M ± 0%   12.49M ± 0%  -2.80% (p=0.000 n=8)

Move OpContext.Str to OpContext.String, and add the new fmt.Stringer
implementation in place of the old OpContext.Str. This way, the majority
of callers, which just need to stringify a node for formatting inside
an error via %s, can stay as they are. It also makes sense for the
longer method name to be the one that does the work upfront.

Note that some error messages change due to the use of a shallow copy
and the delayed printing of the copied value. We used to print the value
upfront, before it was fully evaluated, whereas we print it a bit later
now, once e.g. `1 & 1` has become `1`, and `if true` has been removed.

Updates #3334.

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

Author: mvdan

cue/testdata/builtins/validators.txtar

@@ -555,15 +555,6 @@ Result:
 diff old new
 --- old
 +++ new
-@@ -31,7 +31,7 @@
-     ./issue3418.cue:10:16
-     ./issue3418.cue:10:18
-     ./issue3418.cue:11:5
--issue3474.structValidator.failAfter.A: invalid value {C:true,B*:if true true} (does not satisfy struct.MaxFields(1)): len(fields) > MaxFields(1) (2 > 1):
-+issue3474.structValidator.failAfter.A: invalid value {C:true,B:true} (does not satisfy struct.MaxFields(1)): len(fields) > MaxFields(1) (2 > 1):
-     ./issue3474.cue:12:5
-     ./issue3474.cue:12:22
-     ./issue3474.cue:13:5
 @@ -51,6 +51,11 @@
      ./issue3474.cue:53:5
      ./issue3474.cue:53:12
@@ -589,15 +580,6 @@ diff old new
        _a: (_|_){
          // [incomplete] issue2098.incomplete1._a: invalid value [] (does not satisfy list.MinItems(1)): len(list) < MinItems(1) (0 < 1):
          //     ./in.cue:112:6
-@@ -209,7 +212,7 @@
-       failAfter: (_|_){
-         // [eval]
-         A: (_|_){
--          // [eval] issue3474.structValidator.failAfter.A: invalid value {C:true,B*:if true true} (does not satisfy struct.MaxFields(1)): len(fields) > MaxFields(1) (2 > 1):
-+          // [eval] issue3474.structValidator.failAfter.A: invalid value {C:true,B:true} (does not satisfy struct.MaxFields(1)): len(fields) > MaxFields(1) (2 > 1):
-           //     ./issue3474.cue:12:5
-           //     ./issue3474.cue:12:22
-           //     ./issue3474.cue:13:5
 @@ -270,6 +273,11 @@
            //     ./issue3474.cue:53:5
            //     ./issue3474.cue:53:12
@@ -677,7 +659,7 @@ issue3418.t4.x: invalid value "foo" (does not satisfy matchN): conflicting value
     ./issue3418.cue:10:16
     ./issue3418.cue:10:18
     ./issue3418.cue:11:5
-issue3474.structValidator.failAfter.A: invalid value {C:true,B*:if true true} (does not satisfy struct.MaxFields(1)): len(fields) > MaxFields(1) (2 > 1):
+issue3474.structValidator.failAfter.A: invalid value {C:true,B:true} (does not satisfy struct.MaxFields(1)): len(fields) > MaxFields(1) (2 > 1):
     ./issue3474.cue:12:5
     ./issue3474.cue:12:22
     ./issue3474.cue:13:5
@@ -855,7 +837,7 @@ Result:
       failAfter: (_|_){
         // [eval]
         A: (_|_){
-          // [eval] issue3474.structValidator.failAfter.A: invalid value {C:true,B*:if true true} (does not satisfy struct.MaxFields(1)): len(fields) > MaxFields(1) (2 > 1):
+          // [eval] issue3474.structValidator.failAfter.A: invalid value {C:true,B:true} (does not satisfy struct.MaxFields(1)): len(fields) > MaxFields(1) (2 > 1):
           //     ./issue3474.cue:12:5
           //     ./issue3474.cue:12:22
           //     ./issue3474.cue:13:5

cue/testdata/definitions/fields.txtar

@@ -866,7 +866,7 @@ diff old new
 -    ./validators.cue:18:6
 -    ./validators.cue:23:5
      ./validators.cue:24:5
--validator.open.data: invalid value {trailingComma:_|_(validator.open.data.trailingComma: field not allowed),#x:{trailingComma?:"all"}} (does not satisfy matchN): 0 matched, expected 1:
+-validator.open.data: invalid value {trailingComma:_|_(validator.open.data.trailingComma: field not allowed),#x:_|_(validator.open.data.trailingComma: field not allowed)} (does not satisfy matchN): 0 matched, expected 1:
 -    ./validators.cue:10:3
 -    ./validators.cue:10:10
 -    ./validators.cue:13:8
@@ -1206,7 +1206,7 @@ diff old new
          }
        }
 -      data: (_|_){
--        // [eval] validator.open.data: invalid value {trailingComma:_|_(validator.open.data.trailingComma: field not allowed),#x:{trailingComma?:"all"}} (does not satisfy matchN): 0 matched, expected 1:
+-        // [eval] validator.open.data: invalid value {trailingComma:_|_(validator.open.data.trailingComma: field not allowed),#x:_|_(validator.open.data.trailingComma: field not allowed)} (does not satisfy matchN): 0 matched, expected 1:
 -        //     ./validators.cue:10:3
 -        //     ./validators.cue:10:10
 -        //     ./validators.cue:13:8
@@ -1318,7 +1318,7 @@ validator.keepClosed.x.c: field not allowed:
     ./validators.cue:18:6
     ./validators.cue:23:5
     ./validators.cue:24:5
-validator.open.data: invalid value {trailingComma:_|_(validator.open.data.trailingComma: field not allowed),#x:{trailingComma?:"all"}} (does not satisfy matchN): 0 matched, expected 1:
+validator.open.data: invalid value {trailingComma:_|_(validator.open.data.trailingComma: field not allowed),#x:_|_(validator.open.data.trailingComma: field not allowed)} (does not satisfy matchN): 0 matched, expected 1:
     ./validators.cue:10:3
     ./validators.cue:10:10
     ./validators.cue:13:8
@@ -1811,7 +1811,7 @@ Result:
         }
       }
       data: (_|_){
-        // [eval] validator.open.data: invalid value {trailingComma:_|_(validator.open.data.trailingComma: field not allowed),#x:{trailingComma?:"all"}} (does not satisfy matchN): 0 matched, expected 1:
+        // [eval] validator.open.data: invalid value {trailingComma:_|_(validator.open.data.trailingComma: field not allowed),#x:_|_(validator.open.data.trailingComma: field not allowed)} (does not satisfy matchN): 0 matched, expected 1:
         //     ./validators.cue:10:3
         //     ./validators.cue:10:10
         //     ./validators.cue:13:8

cue/testdata/disjunctions/elimination.txtar

@@ -1842,15 +1842,6 @@ diff old new
    disambiguateClosed: (struct){
      b: (#struct){ |((#struct){
          x: (bool){ true }
-@@ -181,7 +127,7 @@
-             x: ((null|struct)){ |((struct){
-                 a: (struct){
-                   b: (_|_){
--                    // [incomplete] nestedNonMonotonic.incomplete.b.n2.p1.x.a.b: invalid value {c:1 & 1 & 1,d:1 & 1 & 1} (does not satisfy struct.MinFields(3)): len(fields) < MinFields(3) (2 < 3):
-+                    // [incomplete] nestedNonMonotonic.incomplete.b.n2.p1.x.a.b: invalid value {c:1,d:1} (does not satisfy struct.MinFields(3)): len(fields) < MinFields(3) (2 < 3):
-                     //     ./in.cue:138:15
-                     //     ./in.cue:124:15
-                     //     ./in.cue:125:12
 @@ -349,10 +295,6 @@
        #type: (#struct){
          fieldName: ((string|struct)){ |((string){ string }, (#struct){
@@ -2905,7 +2896,7 @@ Result:
             x: ((null|struct)){ |((struct){
                 a: (struct){
                   b: (_|_){
-                    // [incomplete] nestedNonMonotonic.incomplete.b.n2.p1.x.a.b: invalid value {c:1 & 1 & 1,d:1 & 1 & 1} (does not satisfy struct.MinFields(3)): len(fields) < MinFields(3) (2 < 3):
+                    // [incomplete] nestedNonMonotonic.incomplete.b.n2.p1.x.a.b: invalid value {c:1,d:1} (does not satisfy struct.MinFields(3)): len(fields) < MinFields(3) (2 < 3):
                     //     ./in.cue:138:15
                     //     ./in.cue:124:15
                     //     ./in.cue:125:12

cue/types_test.go

@@ -2890,7 +2890,7 @@ func TestValueLookup(t *testing.T) {
 				t.Errorf("exists: got %v; want %v", got, tc.notExists)
 			}
 
-			got := cue.ValueCtx(v).Str(cue.ValueVertex(v))
+			got := cue.ValueCtx(v).String(cue.ValueVertex(v))
 			if tc.str == "" {
 				t.Fatalf("str empty, got %q", got)
 			}

internal/core/adt/context.go

@@ -1448,14 +1448,26 @@ func (c *OpContext) newList(src ast.Node, parent *Vertex) *Vertex {
 	return c.newInlineVertex(parent, &ListMarker{})
 }
 
-// Str reports a debug string of x.
-func (c *OpContext) Str(x Node) string {
+// String reports a string of x, for use in errors or debugging.
+// Use [OpContext.Str] instead for %s format arguments, as it delays the work.
+func (c *OpContext) String(x Node) string {
 	if c.Format == nil {
 		return fmt.Sprintf("%T", x)
 	}
 	return c.Format(c.Runtime, x)
 }
 
+type stringerFunc func() string
+
+func (f stringerFunc) String() string { return f() }
+
+// Str reports a string of x via a [fmt.Stringer], for use in errors or debugging.
+func (c *OpContext) Str(x Node) fmt.Stringer {
+	return stringerFunc(func() string {
+		return c.String(x)
+	})
+}
+
 // NewList returns a new list for the given values.
 func (c *OpContext) NewList(values ...Value) *Vertex {
 	// TODO: consider making this a literal list instead.

internal/core/adt/errors.go

@@ -380,6 +380,21 @@ func (c *OpContext) NewPosf(p token.Pos, format string, args ...interface{}) *Va
 		switch x := arg.(type) {
 		case Node:
 			a = appendNodePositions(a, x)
+			// Wrap nodes in a [fmt.Stringer] which delays the call to
+			// [OpContext.Str] until the error needs to be rendered.
+			// This helps avoid work, as in many cases,
+			// errors are created but never shown to the user.
+			//
+			// A Vertex will set an error as its BaseValue via a Bottom node,
+			// which might be this error we are creating.
+			// Using the Vertex directly could then lead to endless recursion.
+			// Make a shallow copy to avoid that.
+			if v, ok := x.(*Vertex); ok {
+				// TODO(perf): we could join this allocation with the creation
+				// of the stringer below.
+				vcopy := *v
+				x = &vcopy
+			}
 			args[i] = c.Str(x)
 		case ast.Node:
 			// TODO: ideally the core evaluator should not depend on higher

internal/core/adt/expr.go

@@ -1897,6 +1897,8 @@ func validateWithBuiltin(call *CallContext) *Bottom {
 		return b
 	}
 	// failed:
+	// TODO(mvdan): building this buffer should be part of the error format and arguments,
+	// e.g. any logic needed here can be wrapped in an [fmt.Stringer].
 	var buf bytes.Buffer
 	buf.WriteString(b.qualifiedName(c))
 
@@ -1909,7 +1911,7 @@ func validateWithBuiltin(call *CallContext) *Bottom {
 			if i > 0 {
 				_, _ = buf.WriteString(", ")
 			}
-			buf.WriteString(c.Str(a))
+			buf.WriteString(c.String(a))
 		}
 		buf.WriteString(")")
 	}