engine: implement fine profiling

internal/engine/arithmetic.go

@@ -7,6 +7,8 @@ import (
 )
 
 func (e Engine) add(ctx ExecutionContext, left, right types.Value) (types.Value, error) {
+	defer e.profiler.Enter("add").Exit()
+
 	if left == nil || right == nil {
 		return nil, fmt.Errorf("cannot add %T and %T", left, right)
 	}
@@ -22,6 +24,8 @@ func (e Engine) add(ctx ExecutionContext, left, right types.Value) (types.Value,
 }
 
 func (e Engine) sub(ctx ExecutionContext, left, right types.Value) (types.Value, error) {
+	defer e.profiler.Enter("sub").Exit()
+
 	if left == nil || right == nil {
 		return nil, fmt.Errorf("cannot subtract %T and %T", left, right)
 	}
@@ -37,6 +41,8 @@ func (e Engine) sub(ctx ExecutionContext, left, right types.Value) (types.Value,
 }
 
 func (e Engine) mul(ctx ExecutionContext, left, right types.Value) (types.Value, error) {
+	defer e.profiler.Enter("mul").Exit()
+
 	if left == nil || right == nil {
 		return nil, fmt.Errorf("cannot multiplicate %T and %T", left, right)
 	}
@@ -52,6 +58,8 @@ func (e Engine) mul(ctx ExecutionContext, left, right types.Value) (types.Value,
 }
 
 func (e Engine) div(ctx ExecutionContext, left, right types.Value) (types.Value, error) {
+	defer e.profiler.Enter("div").Exit()
+
 	if left == nil || right == nil {
 		return nil, fmt.Errorf("cannot divide %T and %T", left, right)
 	}
@@ -67,6 +75,8 @@ func (e Engine) div(ctx ExecutionContext, left, right types.Value) (types.Value,
 }
 
 func (e Engine) mod(ctx ExecutionContext, left, right types.Value) (types.Value, error) {
+	defer e.profiler.Enter("mod").Exit()
+
 	if left == nil || right == nil {
 		return nil, fmt.Errorf("cannot modulo %T and %T", left, right)
 	}
@@ -82,6 +92,8 @@ func (e Engine) mod(ctx ExecutionContext, left, right types.Value) (types.Value,
 }
 
 func (e Engine) pow(ctx ExecutionContext, left, right types.Value) (types.Value, error) {
+	defer e.profiler.Enter("pow").Exit()
+
 	if left == nil || right == nil {
 		return nil, fmt.Errorf("cannot exponentiate %T and %T", left, right)
 	}

internal/engine/builtin.go

@@ -16,34 +16,33 @@ import (
 	"github.com/xqueries/xdb/internal/engine/types"
 )
 
-var (
-	// suppress warnings, TODO: remove
-	_ = builtinCount
-	_ = builtinUCase
-	_ = builtinLCase
-	_ = builtinMin
-	_ = builtinMax
-)
-
 // builtinNow returns a new date value, containing the timestamp provided by the
 // given timeProvider.
-func builtinNow(tp timeProvider) (types.DateValue, error) {
+func (e Engine) builtinNow(tp timeProvider) (types.DateValue, error) {
+	defer e.profiler.Enter("now").Exit()
+
 	return types.NewDate(tp()), nil
 }
 
-func builtinRand(rp randomProvider) (types.IntegerValue, error) {
+func (e Engine) builtinRand(rp randomProvider) (types.IntegerValue, error) {
+	defer e.profiler.Enter("rand").Exit()
+
 	return types.NewInteger(rp()), nil
 }
 
 // builtinCount returns a new integral value, representing the count of the
 // passed in values.
-func builtinCount(args ...types.Value) (types.IntegerValue, error) {
+func (e Engine) builtinCount(args ...types.Value) (types.IntegerValue, error) {
+	defer e.profiler.Enter("count").Exit()
+
 	return types.NewInteger(int64(len(args))), nil
 }
 
 // builtinUCase maps all passed in string values to new string values with the
 // internal string value folded to upper case.
-func builtinUCase(args ...types.StringValue) ([]types.StringValue, error) {
+func (e Engine) builtinUCase(args ...types.StringValue) ([]types.StringValue, error) {
+	defer e.profiler.Enter("ucase").Exit()
+
 	var output []types.StringValue
 	for _, arg := range args {
 		output = append(output, types.StringValue{Value: strings.ToUpper(arg.Value)})
@@ -53,7 +52,9 @@ func builtinUCase(args ...types.StringValue) ([]types.StringValue, error) {
 
 // builtinLCase maps all passed in string values to new string values with the
 // internal string value folded to lower case.
-func builtinLCase(args ...types.StringValue) ([]types.StringValue, error) {
+func (e Engine) builtinLCase(args ...types.StringValue) ([]types.StringValue, error) {
+	defer e.profiler.Enter("lcase").Exit()
+
 	var output []types.StringValue
 	for _, arg := range args {
 		output = append(output, types.StringValue{Value: strings.ToLower(arg.Value)})
@@ -63,7 +64,9 @@ func builtinLCase(args ...types.StringValue) ([]types.StringValue, error) {
 
 // builtinMax returns the largest value out of all passed in values. The largest
 // value is determined by comparing one element to all others.
-func builtinMax(args ...types.Value) (types.Value, error) {
+func (e Engine) builtinMax(args ...types.Value) (types.Value, error) {
+	defer e.profiler.Enter("max").Exit()
+
 	if len(args) == 0 {
 		return nil, nil
 	}
@@ -92,7 +95,9 @@ func builtinMax(args ...types.Value) (types.Value, error) {
 
 // builtinMin returns the smallest value out of all passed in values. The
 // smallest value is determined by comparing one element to all others.
-func builtinMin(args ...types.Value) (types.Value, error) {
+func (e Engine) builtinMin(args ...types.Value) (types.Value, error) {
+	defer e.profiler.Enter("min").Exit()
+
 	if len(args) == 0 {
 		return nil, nil
 	}

internal/engine/compare.go

@@ -21,7 +21,7 @@ const (
 // as left<right. If left and right cannot be compared, e.g. because they have
 // different types, cmpUncomparable will be returned.
 func (e Engine) cmp(left, right types.Value) cmpResult {
-	defer e.profiler.Enter(EvtCompare).Exit()
+	defer e.profiler.Enter("cmp").Exit()
 
 	// types must be equal
 	if !right.Is(left.Type()) {
@@ -49,27 +49,37 @@ func (e Engine) cmp(left, right types.Value) cmpResult {
 // eq checks if left and right are equal. If left and right can't be compared
 // according to (Engine).cmp, false is returned.
 func (e Engine) eq(left, right types.Value) bool {
+	defer e.profiler.Enter("eq").Exit()
+
 	return e.cmp(left, right) == cmpEqual
 }
 
 // lt checks if the left value is less than the right value. For the <= (less
 // than or equal) relation, see (Engine).lteq.
 func (e Engine) lt(left, right types.Value) bool {
+	defer e.profiler.Enter("lt").Exit()
+
 	return e.cmp(left, right) == cmpLessThan
 }
 
 // gt checks if the left value is less than the right value. For the >= (greater
 // than or equal) relation, see (Engine).gteq.
 func (e Engine) gt(left, right types.Value) bool {
+	defer e.profiler.Enter("gt").Exit()
+
 	return e.lt(right, left)
 }
 
 // lteq checks if the left value is smaller than or equal to the right value.
 func (e Engine) lteq(left, right types.Value) bool {
+	defer e.profiler.Enter("lteq").Exit()
+
 	return e.eq(left, right) || e.lt(left, right)
 }
 
 // gteq checks if the right value is smaller than or equal to the left value.
 func (e Engine) gteq(left, right types.Value) bool {
+	defer e.profiler.Enter("gteq").Exit()
+
 	return e.eq(left, right) || e.gt(left, right)
 }

internal/engine/engine.go

@@ -46,13 +46,16 @@ func New(dbFile *storage.DBFile, opts ...Option) (Engine, error) {
 // Evaluate evaluates the given command. This may mutate the state of the
 // database, and changes may occur to the database file.
 func (e Engine) Evaluate(cmd command.Command) (table.Table, error) {
-	defer e.profiler.Enter(EvtEvaluate).Exit()
-
 	_ = e.eq
 	_ = e.lt
 	_ = e.gt
 	_ = e.lteq
 	_ = e.gteq
+	_ = e.builtinCount
+	_ = e.builtinUCase
+	_ = e.builtinLCase
+	_ = e.builtinMin
+	_ = e.builtinMax
 
 	ctx := newEmptyExecutionContext()
 
@@ -77,5 +80,7 @@ func (e Engine) Closed() bool {
 
 // Close closes the underlying database file.
 func (e Engine) Close() error {
+	defer e.profiler.Enter("close").Exit()
+
 	return e.dbFile.Close()
 }

internal/engine/evaluate.go

@@ -122,6 +122,8 @@ func (e Engine) evaluateProjection(ctx ExecutionContext, proj command.Project) (
 }
 
 func (e Engine) evaluateValues(ctx ExecutionContext, v command.Values) (tbl table.Table, err error) {
+	defer e.profiler.Enter("values").Exit()
+
 	var colCnt int
 	for _, values := range v.Values {
 		rowValues := make([]types.Value, len(values))
@@ -149,7 +151,7 @@ func (e Engine) evaluateValues(ctx ExecutionContext, v command.Values) (tbl tabl
 }
 
 func (e Engine) evaluateScan(ctx ExecutionContext, s command.Scan) (table.Table, error) {
-	defer e.profiler.Enter(EvtFullTableScan(s.Table.QualifiedName())).Exit()
+	defer e.profiler.Enter("scan").Exit()
 
 	switch tbl := s.Table.(type) {
 	case command.SimpleTable:

internal/engine/function.go

@@ -7,9 +7,9 @@ import (
 func (e Engine) evaluateFunction(ctx ExecutionContext, fn types.FunctionValue) (types.Value, error) {
 	switch fn.Name {
 	case "NOW":
-		return builtinNow(e.timeProvider)
+		return e.builtinNow(e.timeProvider)
 	case "RANDOM":
-		return builtinRand(e.randomProvider)
+		return e.builtinRand(e.randomProvider)
 	}
 	return nil, ErrNoSuchFunction(fn.Name)
 }

internal/engine/profile/profile.go

@@ -5,6 +5,7 @@ import (
 	"fmt"
 	"sort"
 	"strings"
+	"text/tabwriter"
 	"time"
 )
 
@@ -16,9 +17,10 @@ type Profile struct {
 
 func (p Profile) String() string {
 	var buf bytes.Buffer
+	w := tabwriter.NewWriter(&buf, 5, 4, 3, ' ', tabwriter.AlignRight)
 
 	evts := p.Events
-	sort.Slice(evts, func(i, j int) bool { return strings.Compare(evts[i].Object.String(), evts[j].Object.String()) < 0 })
+	sort.Slice(evts, func(i, j int) bool { return strings.Compare(evts[i].Name, evts[j].Name) < 0 })
 
 	firstEvt, lastEvt := evts[0], evts[0]
 	for _, evt := range evts {
@@ -30,31 +32,29 @@ func (p Profile) String() string {
 		}
 	}
 
-	startTime := firstEvt.Start
-	endTime := lastEvt.Start.Add(lastEvt.Duration)
-
-	_, _ = fmt.Fprintf(&buf, "Profile\n\tfrom %v\n\tto   %v\n\ttook %v\n", fmtTime(startTime), fmtTime(endTime), endTime.Sub(startTime))
-	_, _ = fmt.Fprintf(&buf, "Events (%v):\n", len(evts))
-
 	buckets := make(map[string][]Event)
 	for _, evt := range evts {
-		str := evt.Object.String()
-		buckets[str] = append(buckets[str], evt)
+		buckets[evt.Name] = append(buckets[evt.Name], evt)
 	}
 
-	for bucket, bucketEvts := range buckets {
-		_, _ = fmt.Fprintf(&buf, "\t%v (%v events)\n", bucket, len(bucketEvts))
+	_, _ = fmt.Fprintf(w, "%v\t\t%v\t%v\t%v\t\n", "event", "min", "avg", "max")
+	for _, bucketEvts := range buckets {
 		totalDuration := 0 * time.Second
+		minBucketDur := bucketEvts[0].Duration
+		maxBucketDur := bucketEvts[0].Duration
 		for _, bucketEvt := range bucketEvts {
 			totalDuration += bucketEvt.Duration
-			_, _ = fmt.Fprintf(&buf, "\t\t- %v took %v\n", fmtTime(bucketEvt.Start), bucketEvt.Duration)
+			if bucketEvt.Duration < minBucketDur {
+				minBucketDur = bucketEvt.Duration
+			}
+			if bucketEvt.Duration > maxBucketDur {
+				maxBucketDur = bucketEvt.Duration
+			}
 		}
-		_, _ = fmt.Fprintf(&buf, "\t\taverage %v, total %v\n", totalDuration/time.Duration(len(bucketEvts)), totalDuration)
+		avgBucketDur := totalDuration / time.Duration(len(bucketEvts))
+		_, _ = fmt.Fprintf(w, "%v\t\t%v\t%v\t%v\t\n", bucketEvts[0].Name, minBucketDur, avgBucketDur, maxBucketDur)
 	}
 
+	_ = w.Flush()
 	return buf.String()
 }
-
-func fmtTime(t time.Time) string {
-	return t.Format(time.RFC3339Nano)
-}