Fixup for #1591.

- Keep more metrics than just the minimal duration.

- Change default &min-time to 1s.

- Don't allow unitless value as &min-time.

- Rename &on-run to &on-run-end, and &min-iters to &min-runs.

cmd/mvelvdoc/main.go

@@ -0,0 +1,48 @@
+package main
+
+import (
+	"log"
+	"os"
+	"path/filepath"
+	"strings"
+)
+
+func main() {
+	for _, goFile := range os.Args[1:] {
+		bs, err := os.ReadFile(goFile)
+		handleErr("read file:", err)
+
+		var goLines, elvLines []string
+
+		lines := strings.Split(string(bs), "\n")
+		for i := 0; i < len(lines); i++ {
+			if !strings.HasPrefix(lines[i], "//elvdoc:") {
+				goLines = append(goLines, lines[i])
+				continue
+			}
+			if len(elvLines) > 0 {
+				elvLines = append(elvLines, "")
+			}
+			elvLines = append(elvLines, "#"+lines[i][2:])
+			i++
+			for i < len(lines) && strings.HasPrefix(lines[i], "//") {
+				elvLines = append(elvLines, "#"+lines[i][2:])
+				i++
+			}
+			i--
+		}
+
+		os.WriteFile(goFile, []byte(strings.Join(goLines, "\n")), 0o644)
+		if len(elvLines) > 0 {
+			elvFile := goFile[:len(goFile)-len(filepath.Ext(goFile))] + ".d.elv"
+			elvLines = append(elvLines, "")
+			os.WriteFile(elvFile, []byte(strings.Join(elvLines, "\n")), 0o644)
+		}
+	}
+}
+
+func handleErr(s string, err error) {
+	if err != nil {
+		log.Fatalln(s, err)
+	}
+}

pkg/elvdoc/elvdoc.go

@@ -0,0 +1,83 @@
+// Package elvdoc implements extraction of elvdoc, in-source documentation of
+// Elvish variables and functions.
+package elvdoc
+
+import (
+	"bufio"
+	"io"
+	"regexp"
+	"strings"
+)
+
+var (
+	// Groups:
+	// 1. Name
+	// 2. Signature (part inside ||)
+	fnRegexp = regexp.MustCompile(`^fn +([^ ]+) +\{(?:\|([^|]*)\|)?`)
+	// Groups:
+	// 1. Name
+	varRegexp = regexp.MustCompile(`^var +([^ ]+)`)
+)
+
+// Extract extracts elvdoc from Elvish source.
+func Extract(r io.Reader) (fnDocs, varDocs map[string]string, err error) {
+	fnDocs = make(map[string]string)
+	varDocs = make(map[string]string)
+
+	scanner := bufio.NewScanner(r)
+	var commentLines []string
+	for scanner.Scan() {
+		line := scanner.Text()
+		if strings.HasPrefix(line, "# ") {
+			commentLines = append(commentLines, line)
+			continue
+		}
+		if m := fnRegexp.FindStringSubmatch(line); m != nil {
+			name, sig := m[1], m[2]
+			var sb strings.Builder
+			writeUsage(&sb, name, sig)
+			if len(commentLines) > 0 {
+				sb.WriteByte('\n')
+				writeCommentContent(&sb, commentLines)
+			}
+			fnDocs[name] = sb.String()
+		} else if m := varRegexp.FindStringSubmatch(line); m != nil {
+			name := m[1]
+			var sb strings.Builder
+			writeCommentContent(&sb, commentLines)
+			varDocs[name] = sb.String()
+		}
+		commentLines = commentLines[:0]
+	}
+
+	return fnDocs, varDocs, scanner.Err()
+}
+
+func writeUsage(sb *strings.Builder, name, sig string) {
+	sb.WriteString("```elvish\n")
+	sb.WriteString(name)
+	for _, field := range strings.Fields(sig) {
+		sb.WriteByte(' ')
+		if strings.HasPrefix(field, "&") {
+			sb.WriteString(field)
+		} else if strings.HasPrefix(field, "@") {
+			sb.WriteString("$" + field[1:] + "...")
+		} else {
+			sb.WriteString("$" + field)
+		}
+	}
+	sb.WriteString("\n```\n")
+}
+
+func writeCommentContent(sb *strings.Builder, lines []string) string {
+	for _, line := range lines {
+		// Every line starts with "# "
+		sb.WriteString(line[2:])
+		sb.WriteByte('\n')
+	}
+	return sb.String()
+}
+
+func Format(r io.Reader, w io.Writer) error {
+	return nil
+}

pkg/eval/builtin_fn_misc.go

@@ -5,7 +5,10 @@ package eval
 import (
 	"errors"
 	"fmt"
+	"math"
+	"math/big"
 	"net"
+	"strconv"
 	"sync"
 	"time"
 
@@ -16,10 +19,8 @@ import (
 )
 
 var (
-	ErrNegativeSleepDuration    = errors.New("sleep duration must be >= zero")
-	ErrInvalidSleepDuration     = errors.New("invalid sleep duration")
-	ErrInvalidBenchmarkDuration = errors.New("benchmark duration must be > zero")
-	ErrInvalidBenchmarkIter     = errors.New("benchmark iterations must be > zero")
+	ErrNegativeSleepDuration = errors.New("sleep duration must be >= zero")
+	ErrInvalidSleepDuration  = errors.New("invalid sleep duration")
 )
 
 // Builtins that have not been put into their own groups go here.
@@ -38,9 +39,9 @@ func init() {
 		"deprecate": deprecate,
 
 		// Time
-		"benchmark": benchmark,
 		"sleep":     sleep,
 		"time":      timeCmd,
+		"benchmark": benchmark,
 
 		"-ifaddrs": _ifaddrs,
 	})
@@ -535,118 +536,95 @@ func timeCmd(fm *Frame, opts timeOpt, f Callable) error {
 //elvdoc:fn benchmark
 //
 // ```elvish
-// benchmark &min-iters=5 &min-time=10s &on-run=$nil &on-end=$nil $callable
+// benchmark &min-runs=5 &min-time=1s &on-end=$nil &on-run-end=$nil $callable
 // ```
 //
-// Runs `$callable` one or more times and call `$on-end` with the shortest
-// duration as a number in seconds. If `&on-end` is `$nil` (the default) print
-// the duration in human-readable form; e.g., 1.000564042s.
+// Runs `$callable` repeatedly, and reports statistics about how long each run
+// takes.
 //
-// If `$callable` throws an exception, the exception is propagated after the
-// `&on-end` (or default) printing is done.
+// If the `&on-end` callback is not given, `benchmark` prints the average,
+// standard deviation, minimum and maximum of the time it took to run
+// `$callback`, and the number of runs. If the `&on-end` callback is given,
+// `benchmark` instead calls it with a map containing these metrics, keyed by
+// `avg`, `stddev`, `min`, `max` and `runs`. Each duration value (i.e. all
+// except `runs`) is given as the number of seconds.
 //
-// If `$on-end` throws an exception, it is propagated, unless `$callable` has
-// already thrown an exception.
+// The number of runs is controlled by `&min-runs` and `&min-time`. The
+// `$callable` is run at least `&min-runs` times, **and** when the total
+// duration is at least `&min-time`.
+//
+// The `&min-runs` option must be a non-negative integer within the range of the
+// machine word.
+//
+// The `&min-time` option must be a string representing a non-negative duration,
+// specified as a sequence of decimal numbers with a unit suffix (the numbers
+// may have fractional parts), such as "300ms", "1.5h" and "1h45m7s". Valid time
+// units are "ns", "us" (or "µs"), "ms", "s", "m", "h".
+//
+// If `&on-run-end` is given, it is called after each call to `$callable`, with
+// the time that call took, given as the number of seconds.
 //
-// The `&min-iters` option defines the minimum number of iterations to execute
-// regardless of the total run time. The default is five. The number of
-// iterations must be greater than zero.
+// If `$callable` throws an exception, `benchmark` terminates and propagates the
+// exception after the `&on-end` callback (or the default printing behavior)
+// finishes. The duration of the call that throws an exception is not passed to
+// `&on-run-end`, nor is it included when calculating the statistics for
+// `&on-end`. If the first call to `$callable` throws an exception and `&on-end`
+// is `$nil`, nothing is printed and any `&on-end` callback is not called.
 //
-// The `&min-time` option defines the minimum duration to run the benchmark. The
-// default is ten seconds. The duration can be a simple
-// [number](language.html#number) (with optional fractional part) without an
-// explicit unit suffix -- in which case the unit is seconds. The duration can
-// also be a string written as a sequence of decimal numbers, each with optional
-// fraction, plus a unit suffix. For example, "300ms", "1.5h" or "1h45m7s".
-// Valid time units are "ns", "us" (or "µs"), "ms", "s", "m", "h". The duration
-// must be greater than or equal to zero.
+// If `&on-run-end` is given and throws an exception, `benchmark` terminates and
+// propagates the exception after the `&on-end` callback (or the default
+// printing behavior) finishes, unless `$callable` has already thrown an
+// exception
 //
-// Note: A given execution must satisfy both the `&min-iters` and `&min-time`
-// constraints.
+// If `&on-end` throws an exception, the exception is propagated, unless
+// `$callable` or `&on-run-end` has already thrown an exception.
 //
 // Example:
 //
 // ```elvish-transcript
-// ~> var run-times = []
-// ~> benchmark &min-time=40s &min-iters=3 ^
-//      &on-run={|x| set run-times = [$@run-times $x] } ^
-//      &on-end={|x| echo "fastest "$x } { sleep 10s }
-// fastest 10.000564042
-// ~> pprint $run-times
-// [
-//  (num 10.003042292)
-//  (num 10.000564042)
-//  (num 10.001751125)
-//  (num 10.001130667)
-// ]
+// ~> benchmark { }
+// 98ns ± 382ns (min 0s, max 210.417µs, 10119226 runs)
+// ~> benchmark &on-end={|m| put $m[avg]} { }
+// ▶ (num 9.8e-08)
+// ~> benchmark &on-run-end={|d| echo $d} { sleep 0.3 }
+// 0.301123625
+// 0.30123775
+// 0.30119075
+// 0.300629166
+// 0.301260333
+// 301.088324ms ± 234.298µs (min 300.629166ms, max 301.260333ms, 5 runs)
 // ```
 //
 // @cf time
 
-type benchmarkOpt struct {
+type benchmarkOpts struct {
 	OnEnd    Callable
-	OnRun    Callable
-	MinIters string
+	OnRunEnd Callable
+	MinRuns  int
 	MinTime  string
-	minIters int
 	minTime  time.Duration
 }
 
-const (
-	defaultMinIters = 5
-	defaultMinTime  = time.Duration(10 * time.Second)
-)
-
-func (o *benchmarkOpt) SetDefaultOptions() {
-	o.minIters = defaultMinIters
-	o.minTime = defaultMinTime
-}
-
-func benchmark(fm *Frame, opts benchmarkOpt, f Callable) error {
-	if err := parseBenchmarkOpts(&opts); err != nil {
-		return err
-	}
-	shortestDuration, err := runBenchmark(fm, opts, f)
-	if opts.OnEnd == nil {
-		_, errOut := fmt.Fprintln(fm.ByteOutput(), shortestDuration)
-		if err == nil {
-			err = errOut
-		}
-	} else {
-		newFm := fm.Fork("on-end callback of benchmark")
-		errOut := opts.OnEnd.Call(newFm, []any{shortestDuration.Seconds()}, NoOpts)
-		if err == nil {
-			err = errOut
-		}
-	}
-	return err
+func (o *benchmarkOpts) SetDefaultOptions() {
+	o.MinRuns = 5
+	o.minTime = time.Second
 }
 
-func parseBenchmarkOpts(opts *benchmarkOpt) error {
-	if opts.MinIters != "" {
-		if err := vals.ScanToGo(opts.MinIters, &opts.minIters); err != nil {
-			return ErrInvalidBenchmarkIter
-		}
-		if opts.minIters <= 0 {
-			return ErrInvalidBenchmarkIter
-		}
+func (opts *benchmarkOpts) parse() error {
+	if opts.MinRuns < 0 {
+		return errs.BadValue{What: "min-runs option",
+			Valid: "non-negative integer", Actual: strconv.Itoa(opts.MinRuns)}
 	}
 
 	if opts.MinTime != "" {
-		var d time.Duration
-		var f float64
-		if err := vals.ScanToGo(opts.MinTime, &f); err == nil {
-			// It is a simple number we treat as a (fractional) number of seconds.
-			d = time.Duration(f * float64(time.Second))
-		} else {
-			// See if it is a duration string rather than a simple number.
-			d, err = time.ParseDuration(opts.MinTime)
-			if err != nil {
-				return ErrInvalidBenchmarkDuration
-			}
+		d, err := time.ParseDuration(opts.MinTime)
+		if err != nil {
+			return errs.BadValue{What: "min-time option",
+				Valid: "duration string", Actual: parse.Quote(opts.MinTime)}
 		}
 		if d < 0 {
-			return ErrInvalidBenchmarkDuration
+			return errs.BadValue{What: "min-time option",
+				Valid: "non-negative duration", Actual: parse.Quote(opts.MinTime)}
 		}
 		opts.minTime = d
 	}
@@ -654,35 +632,92 @@ func parseBenchmarkOpts(opts *benchmarkOpt) error {
 	return nil
 }
 
-var TimeNow = time.Now // so unit testing can stub it
+// TimeNow is a reference to [time.Now] that can be overridden in tests.
+var TimeNow = time.Now
 
-func runBenchmark(fm *Frame, opts benchmarkOpt, f Callable) (time.Duration, error) {
-	var totalTime time.Duration
-	var shortestDuration time.Duration = 1<<63 - 1
-	for iter := 1; ; iter++ {
+func benchmark(fm *Frame, opts benchmarkOpts, f Callable) error {
+	if err := opts.parse(); err != nil {
+		return err
+	}
+
+	// Standard deviation is calculated using https://en.wikipedia.org/wiki/Algorithms_for_calculating_variance#Welford's_online_algorithm
+	var (
+		min   = time.Duration(math.MaxInt64)
+		max   = time.Duration(math.MinInt64)
+		runs  int64
+		total time.Duration
+		m2    float64
+		err   error
+	)
+	for {
 		t0 := TimeNow()
-		err := f.Call(fm, NoArgs, NoOpts)
-		t1 := TimeNow()
+		err = f.Call(fm, NoArgs, NoOpts)
 		if err != nil {
-			return 0, err
+			break
+		}
+		dt := TimeNow().Sub(t0)
+
+		if min > dt {
+			min = dt
+		}
+		if max < dt {
+			max = dt
 		}
-		dt := t1.Sub(t0)
-		if dt < shortestDuration {
-			shortestDuration = dt
+		var oldDelta float64
+		if runs > 0 {
+			oldDelta = float64(dt) - float64(total)/float64(runs)
 		}
-		if opts.OnRun != nil {
-			newFm := fm.Fork("on-run callback of benchmark")
-			err := opts.OnRun.Call(newFm, []any{dt.Seconds()}, NoOpts)
+		runs++
+		total += dt
+		if runs > 0 {
+			newDelta := float64(dt) - float64(total)/float64(runs)
+			m2 += oldDelta * newDelta
+		}
+
+		if opts.OnRunEnd != nil {
+			newFm := fm.Fork("on-run-end callback of benchmark")
+			err = opts.OnRunEnd.Call(newFm, []any{dt.Seconds()}, NoOpts)
 			if err != nil {
-				return 0, err
+				break
 			}
 		}
-		totalTime += dt
-		if iter >= opts.minIters && totalTime >= opts.minTime {
+
+		if runs >= int64(opts.MinRuns) && total >= opts.minTime {
 			break
 		}
 	}
-	return shortestDuration, nil
+
+	if runs == 0 {
+		return err
+	}
+
+	avg := total / time.Duration(runs)
+	stddev := time.Duration(math.Sqrt(m2 / float64(runs)))
+	if opts.OnEnd == nil {
+		_, errOut := fmt.Fprintf(fm.ByteOutput(),
+			"%v ± %v (min %v, max %v, %d runs)\n", avg, stddev, min, max, runs)
+		if err == nil {
+			err = errOut
+		}
+	} else {
+		stats := vals.MakeMap(
+			"avg", avg.Seconds(), "stddev", stddev.Seconds(),
+			"min", min.Seconds(), "max", max.Seconds(), "runs", int64ToElv(runs))
+		newFm := fm.Fork("on-end callback of benchmark")
+		errOnEnd := opts.OnEnd.Call(newFm, []any{stats}, NoOpts)
+		if err == nil {
+			err = errOnEnd
+		}
+	}
+	return err
+}
+
+func int64ToElv(i int64) any {
+	if i <= int64(math.MaxInt) {
+		return int(i)
+	} else {
+		return big.NewInt(i)
+	}
 }
 
 //elvdoc:fn -ifaddrs

pkg/eval/builtin_fn_misc_test.go

@@ -101,45 +101,92 @@ func TestTime(t *testing.T) {
 }
 
 func TestBenchmark(t *testing.T) {
-	var currentSeconds int64 = 1
-	var double bool = false
+	var ticks []int64
 	testutil.Set(t, &TimeNow, func() time.Time {
-		if double {
-			double = false
-			currentSeconds *= 2
-		} else {
-			double = true
+		if len(ticks) == 0 {
+			panic("mock TimeNow called more than len(ticks)")
 		}
-		return time.Unix(currentSeconds, 0)
+		v := ticks[0]
+		ticks = ticks[1:]
+		return time.Unix(v, 0)
 	})
+	setupTicks := func(ts ...int64) func(*Evaler) {
+		return func(_ *Evaler) { ticks = ts }
+	}
 
 	Test(t,
-		That("benchmark &min-time=abc { nop }").Throws(ErrInvalidBenchmarkDuration),
-		That("benchmark &min-time=0x  { nop }").Throws(ErrInvalidBenchmarkDuration),
-		That("benchmark &min-time=-1s { nop }").Throws(ErrInvalidBenchmarkDuration),
-		That("benchmark &min-iters=a  { nop }").Throws(ErrInvalidBenchmarkIter),
-		That("benchmark &min-iters=0  { nop }").Throws(ErrInvalidBenchmarkIter),
-		That("benchmark &min-iters=-1  { nop }").Throws(ErrInvalidBenchmarkIter),
-		That("benchmark { fail body }").Throws(FailError{"body"}).Prints("0s\n"),
-		That("benchmark &on-run={|x| fail on-run } { nop }").
-			WithSetup(func(_ *Evaler) { currentSeconds = 1 }).
-			Throws(FailError{"on-run"}).
-			Prints("0s\n"),
-		That("benchmark &min-time=0 { nop }").
-			WithSetup(func(_ *Evaler) { currentSeconds = 1 }).
-			Prints("1s\n"),
-		That("benchmark &min-iters=1 &min-time=10s "+
-			"&on-end={|x| printf '%.0fs\n' $x } "+
-			"&on-run={|x| printf '%.0fs\n' $x } { nop }").
-			WithSetup(func(_ *Evaler) { currentSeconds = 1 }).
-			Prints("1s\n2s\n4s\n8s\n1s\n"),
-		That("benchmark &min-iters=3 &min-time=0 "+
-			"&on-end={|x| printf '%.0fs\n' $x } "+
-			"&on-run={|x| printf '%.0fs\n' $x } { nop }").
-			WithSetup(func(_ *Evaler) { currentSeconds = 1 }).
-			Prints("1s\n2s\n4s\n1s\n"),
-
-		thatOutputErrorIsBubbled("benchmark { }"),
+		// Default output
+		That("benchmark &min-runs=2 &min-time=2s { }").
+			WithSetup(setupTicks(0, 1, 1, 3)).
+			Prints("1.5s ± 500ms (min 1s, max 2s, 2 runs)\n"),
+		// &on-end callback
+		That(
+			"var f = {|m| put $m[avg] $m[stddev] $m[min] $m[max] $m[runs]}",
+			"benchmark &min-runs=2 &min-time=2s &on-end=$f { }").
+			WithSetup(setupTicks(0, 1, 1, 3)).
+			Puts(1.5, 0.5, 1.0, 2.0, 2),
+
+		// &min-runs determining number of runs
+		That("benchmark &min-runs=4 &min-time=0s &on-end={|m| put $m[runs]} { }").
+			WithSetup(setupTicks(0, 1, 1, 3, 3, 4, 4, 6)).
+			Puts(4),
+		// &min-time determining number of runs
+		That("benchmark &min-runs=0 &min-time=10s &on-end={|m| put $m[runs]} { }").
+			WithSetup(setupTicks(0, 1, 1, 6, 6, 11)).
+			Puts(3),
+
+		// &on-run-end
+		That("benchmark &min-runs=3 &on-run-end=$put~ &on-end={|m| } { }").
+			WithSetup(setupTicks(0, 1, 1, 3, 3, 4)).
+			Puts(1.0, 2.0, 1.0),
+
+		// $callable throws exception
+		That(
+			"var i = 0",
+			"benchmark { set i = (+ $i 1); if (== $i 3) { fail failure } }").
+			WithSetup(setupTicks(0, 1, 1, 3, 3)).
+			Throws(FailError{"failure"}).
+			Prints("1.5s ± 500ms (min 1s, max 2s, 2 runs)\n"),
+		// $callable throws exception on first run
+		That("benchmark { fail failure }").
+			WithSetup(setupTicks(0)).
+			Throws(FailError{"failure"}).
+			Prints( /* nothing */ ""),
+		That("benchmark &on-end=$put~ { fail failure }").
+			WithSetup(setupTicks(0)).
+			Throws(FailError{"failure"}).
+			Puts( /* nothing */ ),
+
+		// &on-run-end throws exception
+		That("benchmark &on-run-end={|_| fail failure } { }").
+			WithSetup(setupTicks(0, 1)).
+			Throws(FailError{"failure"}).
+			Prints("1s ± 0s (min 1s, max 1s, 1 runs)\n"),
+
+		// &on-run throws exception
+		That("benchmark &min-runs=2 &min-time=0s &on-end={|_| fail failure } { }").
+			WithSetup(setupTicks(0, 1, 1, 3)).
+			Throws(FailError{"failure"}),
+
+		// Option errors
+		That("benchmark &min-runs=-1 { }").
+			Throws(errs.BadValue{What: "min-runs option",
+				Valid: "non-negative integer", Actual: "-1"}),
+		That("benchmark &min-time=abc { }").
+			Throws(errs.BadValue{What: "min-time option",
+				Valid: "duration string", Actual: "abc"}),
+		That("benchmark &min-time=-1s { }").
+			Throws(errs.BadValue{What: "min-time option",
+				Valid: "non-negative duration", Actual: "-1s"}),
+
+		// Test that output error is bubbled. We can't use
+		// testOutputErrorIsBubbled here, since the mock TimeNow requires setup.
+		That("benchmark &min-runs=0 &min-time=0s { } >&-").
+			WithSetup(setupTicks(0, 1)).
+			Throws(os.ErrInvalid),
+		That("benchmark &min-runs=0 &min-time=0s &on-end=$put~ { } >&-").
+			WithSetup(setupTicks(0, 1)).
+			Throws(ErrPortDoesNotSupportValueOutput),
 	)
 }