feat(cli): show progress bar with elapsed time and ETA

A terminal gets a bar that rewrites in place. A piped log gets a line every 25 tests or every minute. The line shows the error count when a call has failed.
2026-10-12 00:45:19 +00:00 · 2026-10-02 01:01:13 +01:00
parent 6934d4df84
commit 7b791a78e7
2 changed files with 184 additions and 50 deletions
@@ -4,7 +4,9 @@ import (
 	"fmt"
 	"io"
 	"os"
+	"strings"
 	"sync"
+	"time"

 	"github.com/lukaszraczylo/llm-testbench/internal/runner"
 )
@@ -13,24 +15,40 @@ import (
 // line. A piped log stays readable without one line per request.
 const pipedProgressEvery = 25

+// pipedProgressInterval also forces a piped line after this much time, so
+// a run of slow models still logs progress between the count-based lines.
+const pipedProgressInterval = time.Minute
+
+// barWidth is the number of cells in the terminal progress bar.
+const barWidth = 30
+
+const (
+	barFilled = "\u2588"
+	barEmpty  = "\u2591"
+)
+
 // stderrProgressReporter implements runner.ProgressReporter, writing a
-// self-updating "test N of M" counter to w (os.Stderr in production).
+// progress bar with elapsed time and ETA to w (os.Stderr in production).
 // Run's stdout stays pipeable (table/markdown/json only): all progress
 // goes here instead.
 //
-// When w is a terminal the counter rewrites itself in place with a
-// carriage return. When w is piped (a log file), rewriting would produce
-// one unreadable blob, so it prints a plain line every pipedProgressEvery
-// completions plus the final one.
+// When w is a terminal the bar rewrites itself in place with a carriage
+// return. When w is piped (a log file), rewriting would produce one
+// unreadable blob, so it prints a plain line every pipedProgressEvery
+// completions or pipedProgressInterval, plus the final one.
 type stderrProgressReporter struct {
-	w     io.Writer
-	mu    sync.Mutex
-	isTTY bool
+	w         io.Writer
+	now       func() time.Time
+	start     time.Time
+	lastPrint time.Time
+	mu        sync.Mutex
+	errors    int
+	isTTY     bool
 }

 // newStderrProgressReporter builds a stderrProgressReporter writing to w.
 func newStderrProgressReporter(w io.Writer) *stderrProgressReporter {
-	return &stderrProgressReporter{w: w, isTTY: isTerminal(w)}
+	return &stderrProgressReporter{w: w, isTTY: isTerminal(w), now: time.Now}
 }

 // isTerminal reports whether w is a character device (an interactive
@@ -51,6 +69,8 @@ func isTerminal(w io.Writer) bool {
 func (r *stderrProgressReporter) ReportStart(totalTests, totalModels, concurrency int) {
 	r.mu.Lock()
 	defer r.mu.Unlock()
+	r.start = r.now()
+	r.lastPrint = r.start
 	// A write failure on this side-channel progress stream (a closed pipe,
 	// a full/broken stderr) is not actionable and must not abort the run
 	// that produces the actual report on stdout.
@@ -61,22 +81,80 @@ func (r *stderrProgressReporter) ReportStart(totalTests, totalModels, concurrenc
 // ReportDone implements runner.ProgressReporter. Safe for concurrent calls
 // from up to Config.Concurrency goroutines at once: the mutex serializes
 // writes so concurrent completions cannot interleave mid-line.
-func (r *stderrProgressReporter) ReportDone(done, total int, _ runner.Result) {
+func (r *stderrProgressReporter) ReportDone(done, total int, res runner.Result) {
 	r.mu.Lock()
 	defer r.mu.Unlock()

+	if res.Err != nil {
+		r.errors++
+	}
+	now := r.now()
+	elapsed := now.Sub(r.start)
+
 	if r.isTTY {
 		// \r returns to the line start, \x1b[K clears any longer previous
 		// text; the final completion ends the line so later output starts
 		// clean.
-		_, _ = fmt.Fprintf(r.w, "\rtest %d of %d\x1b[K", done, total)
+		_, _ = fmt.Fprintf(r.w, "\r%s\x1b[K", r.statusLine(done, total, elapsed, true))
 		if done == total {
 			_, _ = fmt.Fprintln(r.w)
 		}
 		return
 	}

-	if done%pipedProgressEvery == 0 || done == total {
-		_, _ = fmt.Fprintf(r.w, "test %d of %d\n", done, total)
+	if done%pipedProgressEvery == 0 || done == total || now.Sub(r.lastPrint) >= pipedProgressInterval {
+		r.lastPrint = now
+		_, _ = fmt.Fprintln(r.w, r.statusLine(done, total, elapsed, false))
+	}
+}
+
+// statusLine renders the progress text; withBar adds the bar for terminals.
+func (r *stderrProgressReporter) statusLine(done, total int, elapsed time.Duration, withBar bool) string {
+	pct := 0
+	if total > 0 {
+		pct = done * 100 / total
+	}
+	var b strings.Builder
+	if withBar {
+		filled := 0
+		if total > 0 {
+			filled = done * barWidth / total
+		}
+		b.WriteString(strings.Repeat(barFilled, filled) + strings.Repeat(barEmpty, barWidth-filled) + " ")
+	}
+	fmt.Fprintf(&b, "%3d%% %d/%d  elapsed %s", pct, done, total, formatDuration(elapsed))
+	if done < total {
+		fmt.Fprintf(&b, "  ETA %s", formatETA(done, total, elapsed))
+	}
+	if r.errors > 0 {
+		fmt.Fprintf(&b, "  errors %d", r.errors)
+	}
+	return b.String()
+}
+
+// formatETA extrapolates the remaining time from the average completion
+// rate so far; "~" marks it as an estimate and "--" means no data yet.
+// Jobs vary widely in duration, so it is rough, especially early on.
+func formatETA(done, total int, elapsed time.Duration) string {
+	if done <= 0 {
+		return "--"
+	}
+	remaining := time.Duration(float64(elapsed) / float64(done) * float64(total-done))
+	return "~" + formatDuration(remaining)
+}
+
+// formatDuration renders d rounded to seconds as 45s, 12m04s or 1h02m.
+func formatDuration(d time.Duration) string {
+	d = d.Round(time.Second)
+	h := int(d / time.Hour)
+	m := int(d % time.Hour / time.Minute)
+	sec := int(d % time.Minute / time.Second)
+	switch {
+	case h > 0:
+		return fmt.Sprintf("%dh%02dm", h, m)
+	case m > 0:
+		return fmt.Sprintf("%dm%02ds", m, sec)
+	default:
+		return fmt.Sprintf("%ds", sec)
 	}
 }
@@ -2,10 +2,12 @@ package main

 import (
 	"bytes"
+	"errors"
 	"regexp"
 	"strings"
 	"sync"
 	"testing"
+	"time"

 	"github.com/lukaszraczylo/llm-testbench/internal/eval"
 	"github.com/lukaszraczylo/llm-testbench/internal/runner"
@@ -24,9 +26,26 @@ func TestStderrProgressReporter_ReportStart(t *testing.T) {
 	}
 }

+// fakeClock advances only when told, so elapsed/ETA are exact.
+type fakeClock struct{ t time.Time }
+
+func (c *fakeClock) now() time.Time { return c.t }
+
+func newTestReporter(buf *bytes.Buffer, tty bool) (*stderrProgressReporter, *fakeClock) {
+	clk := &fakeClock{t: time.Unix(1_000_000, 0)}
+	r := newStderrProgressReporter(buf)
+	r.isTTY = tty
+	r.now = clk.now
+	r.ReportStart(10, 1, 1)
+	buf.Reset()
+	return r, clk
+}
+
+var okResult = runner.Result{Model: "m", TestID: "t", Score: eval.Score{Value: 1}}
+
 // A bytes.Buffer is not a character device, so newStderrProgressReporter
 // selects piped mode: a plain line every pipedProgressEvery completions
-// plus the final one, nothing else.
+// (or pipedProgressInterval), plus the final one.
 func TestStderrProgressReporter_ReportDone_Piped(t *testing.T) {
 	tests := []struct {
 		name  string
@@ -35,17 +54,16 @@ func TestStderrProgressReporter_ReportDone_Piped(t *testing.T) {
 		total int
 	}{
 		{name: "intermediate completion stays silent", done: 3, total: 10, want: ""},
-		{name: "final completion always prints", done: 10, total: 10, want: "test 10 of 10\n"},
-		{name: "every pipedProgressEvery-th completion prints", done: pipedProgressEvery, total: 100, want: "test 25 of 100\n"},
-		{name: "multiple of pipedProgressEvery prints", done: 2 * pipedProgressEvery, total: 100, want: "test 50 of 100\n"},
+		{name: "final completion always prints", done: 10, total: 10, want: "100% 10/10  elapsed 10s\n"},
+		{name: "every pipedProgressEvery-th completion prints", done: pipedProgressEvery, total: 100, want: " 25% 25/100  elapsed 10s  ETA ~30s\n"},
 		{name: "off-interval completion stays silent", done: 2*pipedProgressEvery + 1, total: 100, want: ""},
 	}
 	for _, tt := range tests {
 		t.Run(tt.name, func(t *testing.T) {
 			var buf bytes.Buffer
-			r := newStderrProgressReporter(&buf)
-			r.ReportDone(tt.done, tt.total, runner.Result{Model: "m", TestID: "t", Score: eval.Score{Value: 1}})
-
+			r, clk := newTestReporter(&buf, false)
+			clk.t = clk.t.Add(10 * time.Second)
+			r.ReportDone(tt.done, tt.total, okResult)
 			if got := buf.String(); got != tt.want {
 				t.Errorf("ReportDone(%d, %d) output = %q, want %q", tt.done, tt.total, got, tt.want)
 			}
@@ -53,39 +71,77 @@ func TestStderrProgressReporter_ReportDone_Piped(t *testing.T) {
 	}
 }

-// TTY mode rewrites one counter line in place; the test forces isTTY since
-// a bytes.Buffer can never be a terminal.
+func TestStderrProgressReporter_ReportDone_PipedTimeBasedLine(t *testing.T) {
+	var buf bytes.Buffer
+	r, clk := newTestReporter(&buf, false)
+	clk.t = clk.t.Add(pipedProgressInterval - time.Second)
+	r.ReportDone(1, 10, okResult)
+	if buf.Len() != 0 {
+		t.Fatalf("printed before the interval: %q", buf.String())
+	}
+	clk.t = clk.t.Add(2 * time.Second)
+	r.ReportDone(2, 10, okResult)
+	if !strings.Contains(buf.String(), "2/10") {
+		t.Errorf("no time-based line after the interval, got %q", buf.String())
+	}
+}
+
+// TTY mode rewrites one bar line in place; the test forces isTTY since a
+// bytes.Buffer can never be a terminal.
 func TestStderrProgressReporter_ReportDone_TTY(t *testing.T) {
-	tests := []struct {
-		name  string
-		want  string
-		done  int
-		total int
-	}{
-		{name: "intermediate rewrites in place without a newline", done: 3, total: 10, want: "\rtest 3 of 10\x1b[K"},
-		{name: "final completion ends the line", done: 10, total: 10, want: "\rtest 10 of 10\x1b[K\n"},
-	}
-	for _, tt := range tests {
-		t.Run(tt.name, func(t *testing.T) {
-			var buf bytes.Buffer
-			r := newStderrProgressReporter(&buf)
-			r.isTTY = true
-			r.ReportDone(tt.done, tt.total, runner.Result{Model: "m", TestID: "t", Score: eval.Score{Value: 1}})
+	var buf bytes.Buffer
+	r, clk := newTestReporter(&buf, true)
+	clk.t = clk.t.Add(30 * time.Second)

-			if got := buf.String(); got != tt.want {
-				t.Errorf("ReportDone(%d, %d) output = %q, want %q", tt.done, tt.total, got, tt.want)
-			}
-		})
+	r.ReportDone(5, 10, okResult)
+	want := "\r" + strings.Repeat(barFilled, 15) + strings.Repeat(barEmpty, 15) + "  50% 5/10  elapsed 30s  ETA ~30s\x1b[K"
+	if got := buf.String(); got != want {
+		t.Errorf("mid-run output = %q, want %q", got, want)
+	}
+
+	buf.Reset()
+	r.ReportDone(10, 10, okResult)
+	want = "\r" + strings.Repeat(barFilled, barWidth) + " 100% 10/10  elapsed 30s\x1b[K\n"
+	if got := buf.String(); got != want {
+		t.Errorf("final output = %q, want %q (full bar, no ETA, line ended)", got, want)
 	}
 }

-// TestStderrProgressReporter_ReportDone_ConcurrencySafe writes many
-// concurrent ReportDone calls (as Runner.Run's goroutines would) and
-// verifies no write interleaved mid-line - the reporter's own mutex must
-// serialize writes, not just the counter.
+func TestStderrProgressReporter_CountsErrors(t *testing.T) {
+	var buf bytes.Buffer
+	r, _ := newTestReporter(&buf, false)
+	r.ReportDone(1, 2, runner.Result{Err: errors.New("boom")})
+	r.ReportDone(2, 2, okResult)
+	if got := buf.String(); !strings.Contains(got, "errors 1") {
+		t.Errorf("output = %q, want an errors count of 1", got)
+	}
+}
+
+func TestFormatDuration(t *testing.T) {
+	tests := map[time.Duration]string{
+		0:                                     "0s",
+		44*time.Second + 600*time.Millisecond: "45s",
+		12*time.Minute + 4*time.Second:        "12m04s",
+		time.Hour + 2*time.Minute + 30*time.Second: "1h02m",
+	}
+	for in, want := range tests {
+		if got := formatDuration(in); got != want {
+			t.Errorf("formatDuration(%v) = %q, want %q", in, got, want)
+		}
+	}
+}
+
+func TestFormatETA_NoDataYet(t *testing.T) {
+	if got := formatETA(0, 10, time.Minute); got != "--" {
+		t.Errorf("formatETA with nothing done = %q, want --", got)
+	}
+}
+
+// Concurrent ReportDone calls (as Runner.Run's goroutines would) must not
+// interleave mid-line: the reporter's own mutex serializes the writes.
 func TestStderrProgressReporter_ReportDone_ConcurrencySafe(t *testing.T) {
 	var buf bytes.Buffer
-	r := newStderrProgressReporter(&buf)
+	r, _ := newTestReporter(&buf, false)

 	const n = 2 * pipedProgressEvery
 	var wg sync.WaitGroup
@@ -93,18 +149,18 @@ func TestStderrProgressReporter_ReportDone_ConcurrencySafe(t *testing.T) {
 		wg.Add(1)
 		go func(i int) {
 			defer wg.Done()
-			r.ReportDone(i, n, runner.Result{Model: "m", TestID: "t", Score: eval.Score{Value: 1}})
+			r.ReportDone(i, n, okResult)
 		}(i)
 	}
 	wg.Wait()

-	// In piped mode exactly the 25th and 50th completions print.
+	// Completion order is arbitrary, so the 25th and 50th calls to arrive
+	// print: exactly two lines.
 	lines := strings.Split(strings.TrimRight(buf.String(), "\n"), "\n")
 	if len(lines) != 2 {
 		t.Fatalf("got %d lines (%q), want 2 (a corrupted/interleaved write would change the count)", len(lines), buf.String())
 	}
-
-	linePattern := regexp.MustCompile(`^test \d+ of \d+$`)
+	linePattern := regexp.MustCompile(`^\s*\d+% \d+/\d+  elapsed \d+s(  ETA ~\d+s)?$`)
 	for _, line := range lines {
 		if !linePattern.MatchString(line) {
 			t.Errorf("malformed or interleaved line: %q", line)