internal/core/adt: several logging improvements

Replace the file prefix with a logging sequence number:
the file name was not very useful and mostly messed with
indentation. The sequence number, OTOH, allows for more
easily pinpointing the position in the log and is quite handy
for setting conditional break points. (Developer can set a
   ctx.logID == n
condition on a breakpoint after the log to stop at that
particular point in evaluation).

The Logf function now uses a strings.Builder. This should
be faster, but also results in nicer code.

Change the nesting around the Unify and Start Process
headers. This improves legibility of logs

Signed-off-by: Marcel van Lohuizen <[email protected]>
Change-Id: Ie6d67902e0c13831d390b9cd1ac097c9d007fda9
Reviewed-on: https://review.gerrithub.io/c/cue-lang/cue/+/1207550
Reviewed-by: Matthew Sackman <[email protected]>
Unity-Result: CUE porcuepine <[email protected]>
TryBot-Result: CUEcueckoo <[email protected]>

Author: mpvl

internal/core/adt/context.go

@@ -182,6 +182,7 @@ type OpContext struct {
 	IsValidator bool
 
 	// ==== Debugging ====
+	logID int // sequence number for log messages
 
 	// ErrorGraphs contains an analysis, represented as a Mermaid graph, for
 	// each node that has an error.

internal/core/adt/log.go

@@ -48,7 +48,7 @@ func (c *OpContext) Assertf(pos token.Pos, b bool, format string, args ...interf
 }
 
 func init() {
-	log.SetFlags(log.Lshortfile)
+	log.SetFlags(0)
 }
 
 var pMap = map[*Vertex]int{}
@@ -57,41 +57,43 @@ func (c *OpContext) Logf(v *Vertex, format string, args ...interface{}) {
 	if c.LogEval == 0 {
 		return
 	}
-	var prefix string
+	w := &strings.Builder{}
+
+	c.logID++
+	fmt.Fprintf(w, "%3d ", c.logID)
+
 	if c.nest > 0 {
-		prefix = strings.Repeat("... ", c.nest)
-		prefix = prefix[:len(prefix)-1]
+		for i := 0; i < c.nest; i++ {
+			w.WriteString("... ")
+		}
 	}
 
 	if v == nil {
-		s := fmt.Sprintf(prefix+format, args...)
-		_ = log.Output(2, s)
+		fmt.Fprintf(w, format, args...)
+		_ = log.Output(2, w.String())
 		return
 	}
+
 	p := pMap[v]
 	if p == 0 {
 		p = len(pMap) + 1
 		pMap[v] = p
 	}
 	disjunctInfo := c.disjunctInfo()
+	fmt.Fprintf(w, "[n:%d/%v %s%s] ",
+		p, v.Path(), c.PathToString(v.Path()), disjunctInfo)
 
-	a := append([]interface{}{
-		prefix,
-		p,
-		v.Path(),
-		c.PathToString(v.Path()),
-		disjunctInfo,
-	}, args...)
-	for i := 2; i < len(a); i++ {
-		switch x := a[i].(type) {
+	for i, a := range args {
+		switch x := a.(type) {
 		case Node:
-			a[i] = c.Str(x)
+			args[i] = c.Str(x)
 		case Feature:
-			a[i] = x.SelectorString(c)
+			args[i] = x.SelectorString(c)
 		}
 	}
-	s := fmt.Sprintf("%s [n:%d %v%s%s] "+format, a...)
-	_ = log.Output(2, s)
+	fmt.Fprintf(w, format, args...)
+
+	_ = log.Output(2, w.String())
 }
 
 // PathToString creates a pretty-printed path of the given list of features.

internal/core/adt/sched.go

@@ -369,11 +369,11 @@ func (s *scheduler) process(needs condition, mode runMode) bool {
 
 	if s.ctx.LogEval > 0 && len(s.tasks) > 0 {
 		if v := s.tasks[0].node.node; v != nil {
-			c.nest++
 			c.Logf(v, "START Process %v -- mode: %v", v.Label, mode)
+			c.nest++
 			defer func() {
-				c.Logf(v, "END Process")
 				c.nest--
+				c.Logf(v, "END Process")
 			}()
 		}
 	}

internal/core/adt/unify.go

@@ -122,11 +122,11 @@ func (n *nodeContext) scheduleConjuncts() {
 // TODO(evalv3): consider not returning a result at all.
 func (v *Vertex) unify(c *OpContext, needs condition, mode runMode) bool {
 	if c.LogEval > 0 {
-		c.nest++
 		c.Logf(v, "Unify %v", fmt.Sprintf("%p", v))
+		c.nest++
 		defer func() {
-			c.Logf(v, "END Unify")
 			c.nest--
+			c.Logf(v, "END Unify")
 		}()
 	}