From 7b791a78e7f050048ede1ad4ff6ce0f31db0e41c Mon Sep 17 00:00:00 2001 From: Lukasz Raczylo Date: Fri, 2 Oct 2026 01:01:13 +0100 Subject: [PATCH] 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. --- cmd/llmtest/progress.go | 104 ++++++++++++++++++++++++---- cmd/llmtest/progress_test.go | 130 +++++++++++++++++++++++++---------- 2 files changed, 184 insertions(+), 50 deletions(-) diff --git a/cmd/llmtest/progress.go b/cmd/llmtest/progress.go index 347a26f..8a3d75e 100644 --- a/cmd/llmtest/progress.go +++ b/cmd/llmtest/progress.go @@ -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) } } diff --git a/cmd/llmtest/progress_test.go b/cmd/llmtest/progress_test.go index e1f7afe..651e2f9 100644 --- a/cmd/llmtest/progress_test.go +++ b/cmd/llmtest/progress_test.go @@ -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)