ivy: add a rudimentary tracing functionality to the interpreter

Add a ")debug trace" special command to enable execution tracing.
If it's set to 1, it traces calls to user-defined operators.
If it's set to 2 or highter, it traces all operators.

The output is very simple and can get noisy fast, but should still
be helpful. I've wanted this for a long time.

Internally, this required the type of the debug map to change from
boolean to integer, but that makes no real difference outside,
and not much inside.

Example:

% ivy
)debug
cpu	0
panic	0
parse	0
tokens	0
trace	0
types	0
For trace: 1 traces user-defined only, 2 traces all operators

op fac n = n < 1: 1; n*fac n-1

)debug trace 1

fac 3
	> fac (3)
	| > fac (2)
	| | > fac (1)
	| | | > fac (0)
6

)debug trace 2

fac 3
	> fac (3)
	| > (3) < (1)
	| > (3) - (1)
	| > fac (2)
	| | > (2) < (1)
	| | > (2) - (1)
	| | > fac (1)
	| | | > (1) < (1)
	| | | > (1) - (1)
	| | | > fac (0)
	| | | | > (0) < (1)
	| | | > (1) * (1)
	| | > (2) * (1)
	| > (3) * (2)
6

op a gcd b =
	a == b: a
	a > b: b gcd a-b
	a gcd b-a

8 gcd 2
	> (8) gcd (2)
	| > (8) == (2)
	| > (8) > (2)
	| > (8) - (2)
	| > (2) gcd (6)
	| | > (2) == (6)
	| | > (2) > (6)
	| | > (6) - (2)
	| | > (2) gcd (4)
	| | | > (2) == (4)
	| | | > (2) > (4)
	| | | > (4) - (2)
	| | | > (2) gcd (2)
	| | | | > (2) == (2)
2

config/config.go

@@ -23,6 +23,7 @@ var DebugFlags = [...]string{
 	"panic",
 	"parse",
 	"tokens",
+	"trace",
 	"types",
 }
 
@@ -40,7 +41,8 @@ type Config struct {
 	origin      int
 	bigOrigin   *big.Int
 	seed        int64
-	debug       [len(DebugFlags)]bool
+	debug       [len(DebugFlags)]int
+	traceLevel  int
 	source      rand.Source
 	random      *rand.Rand
 	randLock    sync.Mutex
@@ -153,22 +155,31 @@ func (c *Config) FloatFormat() (verb byte, prec int, ok bool) {
 	return c.formatVerb, c.formatPrec, c.formatFloat
 }
 
-// Debug returns the value of the specified boolean debugging flag.
-func (c *Config) Debug(flag string) bool {
+// Debug returns the value of the specified debugging flag, -1 if the
+// flag is unknown.
+func (c *Config) Debug(flag string) int {
 	for i, f := range DebugFlags {
 		if f == flag {
 			return c.debug[i]
 		}
 	}
-	return false
+	return -1
+}
+
+// Tracing reports whether the tracing level is set at or above level.
+func (c *Config) Tracing(level int) bool {
+	return c.traceLevel >= level
 }
 
 // SetDebug sets the value of the specified boolean debugging flag.
 // It returns false if the flag is unknown.
-func (c *Config) SetDebug(flag string, state bool) bool {
+func (c *Config) SetDebug(flag string, state int) bool {
 	c.init()
 	for i, f := range DebugFlags {
 		if f == flag {
+			if flag == "trace" {
+				c.traceLevel = state
+			}
 			c.debug[i] = state
 			return true
 		}

exec/context.go

@@ -114,6 +114,17 @@ func (c *Context) pop() {
 	c.stack = c.stack[:len(c.stack)-n]
 }
 
+var indent = "| "
+
+// TraceIndent returns an indentation marker showing the depth of the stack.
+func (c *Context) TraceIndent() string {
+	n := 2 * len(c.frameSizes)
+	if len(indent) < n {
+		indent = strings.Repeat("| ", n+10)
+	}
+	return indent[:n]
+}
+
 // Eval evaluates a list of expressions.
 func (c *Context) Eval(exprs []value.Expr) []value.Value {
 	var values []value.Value
@@ -131,39 +142,47 @@ func (c *Context) EvalUnary(op string, right value.Value) value.Value {
 	if len(op) > 1 {
 		switch op[len(op)-1] {
 		case '/':
+			value.TraceUnary(c, 2, op, right)
 			return value.Reduce(c, op[:len(op)-1], right)
 		case '\\':
+			value.TraceUnary(c, 2, op, right)
 			return value.Scan(c, op[:len(op)-1], right)
 		case '%':
 			if len(op) > 2 {
 				switch op[len(op)-2] {
 				case '/':
+					value.TraceUnary(c, 2, op, right)
 					return value.ReduceFirst(c, op[:len(op)-2], right)
 				case '\\':
+					value.TraceUnary(c, 2, op, right)
 					return value.ScanFirst(c, op[:len(op)-2], right)
 				}
 			}
 		case '@':
+			value.TraceUnary(c, 2, op, right)
 			return value.Each(c, op, right)
 		}
 	}
-	fn := c.Unary(op)
+	fn, userDefined := c.unary(op)
 	if fn == nil {
 		value.Errorf("unary %q not implemented", op)
 	}
+	if userDefined {
+		value.TraceUnary(c, 1, op, right)
+	}
 	return fn.EvalUnary(c, right)
 }
 
-func (c *Context) Unary(op string) value.UnaryOp {
+func (c *Context) unary(op string) (fn value.UnaryOp, userDefined bool) {
 	userFn := c.UnaryFn[op]
 	if userFn != nil {
-		return userFn
+		return userFn, true
 	}
 	builtin := value.UnaryOps[op]
 	if builtin != nil {
-		return builtin
+		return builtin, false
 	}
-	return nil
+	return nil, false
 }
 
 func (c *Context) UserDefined(op string, isBinary bool) bool {
@@ -180,32 +199,38 @@ func (c *Context) EvalBinary(left value.Value, op string, right value.Value) val
 	if op == "==" || op == "!=" {
 		v, ok := value.EvalCharEqual(left, op == "==", right)
 		if ok {
+			value.TraceBinary(c, 2, left, op, right) // Only trace if we've done it.
 			return v
 		}
 	}
 	if strings.Trim(op, "@") != op {
+		value.TraceBinary(c, 2, left, op, right)
 		return value.BinaryEach(c, left, op, right)
 	}
 	if strings.Contains(op, ".") {
+		value.TraceBinary(c, 2, left, op, right)
 		return value.Product(c, left, op, right)
 	}
-	fn := c.Binary(op)
+	fn, userDefined := c.binary(op)
 	if fn == nil {
 		value.Errorf("binary %q not implemented", op)
 	}
+	if userDefined {
+		value.TraceBinary(c, 1, left, op, right)
+	}
 	return fn.EvalBinary(c, left, right)
 }
 
-func (c *Context) Binary(op string) value.BinaryOp {
+func (c *Context) binary(op string) (fn value.BinaryOp, userDefined bool) {
 	user := c.BinaryFn[op]
 	if user != nil {
-		return user
+		return user, true
 	}
 	builtin := value.BinaryOps[op]
 	if builtin != nil {
-		return builtin
+		return builtin, false
 	}
-	return nil
+	return nil, false
 }
 
 // Define defines the function and installs it. It also performs

ivy.go

@@ -78,7 +78,7 @@ func main() {
 
 	if len(*debugFlag) > 0 {
 		for _, debug := range strings.Split(*debugFlag, ",") {
-			if !conf.SetDebug(debug, true) {
+			if !conf.SetDebug(debug, 1) {
 				fmt.Fprintf(os.Stderr, "ivy: unknown debug flag %q\n", debug)
 				os.Exit(2)
 			}

parse/function.go

@@ -149,7 +149,7 @@ func (p *Parser) functionDefn() {
 	p.context.Define(fn)
 	funcVars(fn)
 	succeeded = true
-	if p.context.Config().Debug("parse") {
+	if p.context.Config().Debug("parse") > 0 {
 		p.Printf("op %s %s %s = %s\n", fn.Left.ProgString(), fn.Name, fn.Right.ProgString(), tree(fn.Body))
 	}
 }

parse/parse.go

@@ -215,7 +215,7 @@ func (p *Parser) expressionList() ([]value.Expr, bool) {
 	default:
 		p.errorf("unexpected %s", tok)
 	}
-	if len(exprs) > 0 && p.context.Config().Debug("parse") {
+	if len(exprs) > 0 && p.context.Config().Debug("parse") > 0 {
 		p.Println(tree(exprs))
 	}
 	return exprs, ok

parse/special.go

@@ -180,26 +180,27 @@ Switch:
 	case "debug":
 		if p.peek().Type == scan.EOF {
 			for _, f := range config.DebugFlags {
-				p.Printf("%s\t%d\n", f, truth(conf.Debug(f)))
+				p.Printf("%s\t%d\n", f, conf.Debug(f))
 			}
+			p.Println("For trace: 1 traces user-defined only, 2 traces all operators")
 			break Switch
 		}
 		name := p.need(scan.Identifier).Text
+		val := conf.Debug(name)
+		if val < 0 {
+			p.Println("no such debug flag:", name)
+			break Switch
+		}
 		if p.peek().Type == scan.EOF {
 			// Toggle the value
-			if !conf.SetDebug(name, !conf.Debug(name)) {
-				p.Println("no such debug flag:", name)
-			}
-			if conf.Debug(name) {
-				p.Println("1")
-			} else {
-				p.Println("0")
+			conf.SetDebug(name, truth(val == 0))
+			p.Println(conf.Debug(name))
+		} else {
+			number := p.nextDecimalNumber()
+			if number < 0 {
+				p.Println("illegal value")
 			}
-			break
-		}
-		number := p.nextDecimalNumber()
-		if !conf.SetDebug(name, number != 0) {
-			p.Println("no such debug flag:", name)
+			conf.SetDebug(name, number)
 		}
 	case "demo":
 		p.need(scan.EOF)
@@ -443,7 +444,7 @@ func (p *Parser) runUntilError(name string) error {
 				continue
 			}
 			p.context.AssignGlobal("_", val)
-			fmt.Fprintf(p.context.Config().Output(), "%v\n", val.Sprint(p.context.Config()))
+			p.Println(val.Sprint(p.context.Config()))
 		}
 		if !ok {
 			return io.EOF

run/run.go

@@ -50,7 +50,7 @@ func Run(p *parse.Parser, context value.Context, interactive bool) (success bool
 	conf := context.Config()
 	writer := conf.Output()
 	defer func() {
-		if conf.Debug("panic") {
+		if conf.Debug("panic") > 0 {
 			return
 		}
 		err := recover()
@@ -95,7 +95,7 @@ func Run(p *parse.Parser, context value.Context, interactive bool) (success bool
 			return true
 		}
 		if interactive {
-			if exprs != nil && conf.Debug("cpu") {
+			if exprs != nil && conf.Debug("cpu") > 0 {
 				if real, _, _ := conf.CPUTime(); real != 0 {
 					fmt.Printf("(%s)\n", conf.PrintCPUTime())
 				}
@@ -139,7 +139,7 @@ func printValues(conf *config.Config, writer io.Writer, values []value.Value) bo
 	if len(values) == 0 {
 		return false
 	}
-	if conf.Debug("types") {
+	if conf.Debug("types") > 0 {
 		for i, v := range values {
 			if i > 0 {
 				fmt.Fprint(writer, ",")

scan/scan.go

@@ -177,7 +177,7 @@ func (l *Scanner) emit(t Type) stateFn {
 	}
 	text := l.input[l.start:l.pos]
 	config := l.context.Config()
-	if config.Debug("tokens") {
+	if config.Debug("tokens") > 0 {
 		fmt.Fprintf(config.Output(), "%s:%d: emit %s\n", l.name, l.line, Token{t, l.line, text})
 	}
 	l.token = Token{t, l.line, text}

value/context.go

@@ -60,4 +60,7 @@ type Context interface {
 
 	// UserDefined reports whether the specified op is user-defined.
 	UserDefined(op string, isBinary bool) bool
+
+	// TraceIndent returns an indentation marker showing the depth of the stack.
+	TraceIndent() string
 }

value/eval.go

@@ -5,6 +5,7 @@
 package value
 
 import (
+	"fmt"
 	"iter"
 	"math/big"
 	"runtime"
@@ -39,6 +40,20 @@ type unaryOp struct {
 	fn          [numType]unaryFn
 }
 
+// TraceUnary prints a trace line for a unary operator.
+func TraceUnary(c Context, level int, op string, v Value) {
+	if c.Config().Tracing(level) {
+		fmt.Fprintf(c.Config().ErrOutput(), "\t%s> %s %s\n", c.TraceIndent(), op, v)
+	}
+}
+
+// TraceBinary prints a trace line for a binary operator.
+func TraceBinary(c Context, level int, u Value, op string, v Value) {
+	if c.Config().Tracing(level) {
+		fmt.Fprintf(c.Config().ErrOutput(), "\t%s> %s %s %s\n", c.TraceIndent(), u, op, v)
+	}
+}
+
 func (op *unaryOp) EvalUnary(c Context, v Value) Value {
 	which := whichType(v)
 	fn := op.fn[which]
@@ -53,6 +68,9 @@ func (op *unaryOp) EvalUnary(c Context, v Value) Value {
 		}
 		Errorf("unary %s not implemented on type %s", op.name, which)
 	}
+	if c.Config().Tracing(2) {
+		fmt.Printf("\t%s> %s %s\n", c.TraceIndent(), op.name, v)
+	}
 	return fn(c, v)
 }
 
@@ -105,6 +123,9 @@ func (op *binaryOp) EvalBinary(c Context, u, v Value) Value {
 		}
 		Errorf("binary %s not implemented on type %s", op.name, whichV)
 	}
+	if conf.Tracing(2) {
+		fmt.Printf("\t%s> %s %s %s\n", c.TraceIndent(), u, op.name, v)
+	}
 	return fn(c, u, v)
 }
 

value/unary.go

@@ -152,12 +152,12 @@ func bigFloatRand(c Context, f *big.Float) Value {
 	max.Add(max, bigIntOne.Int) // big.Int.Rand is [0,n)
 	// Now pick a random integer from [0 to max)
 	config.LockRandom()
-	rand := big.NewInt(0).Rand(c.Config().Random(), max)
+	rand := big.NewInt(0).Rand(config.Random(), max)
 	config.UnlockRandom()
 	// Make it a float and normalize it.
 	x := big.NewFloat(0).SetInt(rand)
 	x.Quo(x, big.NewFloat(0).SetInt(max))
-	// Finally, scale it up to [0,v).
+	// Finally, scale it up to [0, f).
 	x.Mul(x, f)
 	return BigFloat{x}
 }