From 98bca296c51b8685faa984dcb3413666b0648479 Mon Sep 17 00:00:00 2001 From: sneak Date: Fri, 16 Oct 2026 21:00:38 +0000 Subject: [PATCH] Show the progress rate over the last 5 seconds, and what a phase is doing after 10 seconds with no item done (closes #125) A display's rate was the phase's average since it started, so after a long wait a burst of files read as a steady rate of over 1,000 files a second. It now covers the items completed over the last 5 seconds, or since the line before off a terminal, and falls to 0 while nothing completes; the ETA still comes from the average. Once no item has completed for 10 seconds, the line says so and what the phase is doing, a phrase each phase gives where it is defined. A narrow terminal leaves that out after the rate, keeping the phase, progress, elapsed time and ETA whole. The tests set the display's clock by hand. Judgement call: the line reads "no files finished", in the phase's unit. Judgement call: trees' group phase says "grouping directories". Model: opus-5-5 --- README.md | 35 ++++-- TODO.md | 10 ++ progress.go | 156 +++++++++++++++++++-------- progress_test.go | 271 ++++++++++++++++++++++++++++++++++++++++------- report.go | 2 +- report_test.go | 4 +- scan.go | 17 ++- trees.go | 5 +- trees_test.go | 2 +- 9 files changed, 403 insertions(+), 99 deletions(-) diff --git a/README.md b/README.md index f709ab8..45e682e 100644 --- a/README.md +++ b/README.md @@ -833,17 +833,33 @@ Each display is one line holding: - a `[m/n] x%` display (items processed / total items, percent); before a phase has a total, the items processed, or what the phase is waiting for - current rate (items/s), naming the items the phase counts: files, records, - directories or groups + directories or groups. It covers the items completed over the last 5 seconds, + or, when stderr is not a terminal, since the line before, so it falls to 0 + while nothing completes, and a burst of items after a wait shows as a burst + rather than as a steady rate. +- once no item has completed for 10 seconds, how long that has been and what the + phase is doing (see below) - elapsed time -- estimated time remaining, or `unknown` +- estimated time remaining, or `unknown`. It comes from the phase's average rate + since it started counting, so that it does not swing with each burst. Example shape (exact layout is flexible, content is not): ``` [3/5] hash: [12345/98765] 12% |████ | 92 files/s elapsed 2:32 eta 17:54 [2/5] walk: [1234567/~1200000] 103%, 5120 files/s, elapsed 4m1s, eta unknown +[3/5] hash: [12345/98765] 12%, 0 files/s, no files finished for 42s, reading files, elapsed 4m1s, eta 28m7s ``` +When no item has completed for 10 seconds, as while one large file is read, a +disk is slow or the database is busy, the line says so and what the phase is +doing: `walk` is listing directories; `hash` and the content phase's reads are +reading files; `update` is writing to the database; `load` and the `read` phases +of `trees` and `report` are reading the database; the content phase's checks are +searching the database; `trees`' `group` is grouping directories, and its +`write` is writing the report. A phase still waiting for its total already says +what it waits for, and says nothing more. + Additional requirements: - On a terminal, a phase with an exact total (every phase but `scan`'s `walk`, @@ -857,13 +873,14 @@ Additional requirements: - On a terminal no line reaches the terminal's last column, however narrow the terminal is. The phase and its place, the progress, the elapsed time and the ETA are kept whole: a line too wide for the terminal leaves out its rate first - (or what the phase is waiting for), and a bar with no room beside those four - gives way to the spinner. Only when those four alone are too wide, as on a - terminal narrower than about 70 columns hours into a scan of millions of - files, is the line cut short at the terminal's edge, so the end of the ETA is - lost first. A terminal made narrower while a phase runs gets the same: the - next draw erases the line within the new width and fits the line to it, and - the display goes on redrawing in place. + (or what the phase is waiting for), then what it says of 10 seconds with no + item completed, and a bar with no room beside those four gives way to the + spinner. Only when those four alone are too wide, as on a terminal narrower + than about 70 columns hours into a scan of millions of files, is the line cut + short at the terminal's edge, so the end of the ETA is lost first. A terminal + made narrower while a phase runs gets the same: the next draw erases the line + within the new width and fits the line to it, and the display goes on + redrawing in place. - When stderr is not a terminal (a pipe, a file, `/dev/null`), do not emit ANSI redraws: print the line the moment each phase starts, every 5 seconds while it runs (whether or not an item has completed, and never more often), and once diff --git a/TODO.md b/TODO.md index 62e8918..94c75bf 100644 --- a/TODO.md +++ b/TODO.md @@ -29,6 +29,16 @@ # Completed Steps +- the rate a progress display shows covers the items completed over the last 5 + seconds, or since the line before when stderr is not a terminal, so it falls + to 0 while nothing completes, and a burst after a wait no longer reads as a + steady rate of over 1,000 files a second; the ETA still comes from the phase's + average. Once no item has completed for 10 seconds, the line says how long and + what the phase is doing, as `no files finished for 42s, reading files`, each + phase naming its own work where it is defined. A line too wide for the + terminal leaves that out after the rate, keeping the phase, progress, elapsed + time and ETA whole (2026-10-16, https://git.eeqj.de/sneak/sfdupes/issues/125) + - new subcommand `info` prints the database's details on stdout, one per line as a name, a tab and the value: its path and where it came from, the sizes of the database file and of its `-wal` file when there is one, when the database file diff --git a/progress.go b/progress.go index 321b226..b53cc0b 100644 --- a/progress.go +++ b/progress.go @@ -22,6 +22,15 @@ const plainInterval = 5 * time.Second // a TTY. const redrawInterval = 100 * time.Millisecond +// rateWindow is the time the rate a display shows covers: the items +// completed over the last rateWindow, which is the time since the line +// before when stderr is not a TTY. +const rateWindow = 5 * time.Second + +// stallTime is how long a phase goes with no item completed before its +// line says so, and what the phase is doing. +const stallTime = 10 * time.Second + // spinnerType selects the progressbar library's spinner style. const spinnerType = 14 @@ -59,6 +68,10 @@ const ( openingDatabase = "opening the database" ) +// readingDatabase is what the display of a phase that reads the records +// says it is doing once no record has been read for stallTime. +const readingDatabase = "reading the database" + // stderrIsTTY reports whether stderr is attached to a terminal. func stderrIsTTY() bool { return term.IsTerminal(int(os.Stderr.Fd())) @@ -89,6 +102,14 @@ type progressParams struct { total int64 // the items the phase will complete; -1 when not known estimate bool // total is an estimate, which the count may pass waitingFor string // what the phase waits for until setTotal is called + doing string // what the phase is doing, as "reading files"; see stallTime +} + +// drawnCount is the count of items completed as of one draw, and when +// that draw was. +type drawnCount struct { + at time.Time + count int64 } // progress renders one phase's progress on stderr. On a TTY the @@ -107,9 +128,10 @@ type progressParams struct { // phase's helpers without rendering anything, and its writer writes // with no display to clear. type progress struct { - width func() int // reads the terminal's width; nil when not a TTY - stop chan struct{} // closed by finish to end the draws - done chan struct{} // closed once the draws have ended + now func() time.Time // reads the time + width func() int // reads the terminal's width; nil when not a TTY + stop chan struct{} // closed by finish to end the draws + done chan struct{} // closed once the draws have ended mu sync.Mutex bar *progressbar.ProgressBar // what the library draws; nil until then @@ -120,33 +142,42 @@ type progress struct { total int64 estimate bool waitingFor string + doing string count int64 start time.Time // when the phase started, for the elapsed time - rateStart time.Time // when the count started, for the rate + rateStart time.Time // when the count started, for the ETA + lastItem time.Time // when the last item was completed, or the count started + // drawn holds the count at each draw over the last rateWindow, oldest + // first; the rate counts from the first. It keeps the draw before the + // latest even when that is older, as the line before is when lines + // are plainInterval apart and a tick comes late. + drawn []drawnCount } // newProgress starts the display of one phase on stderr. func newProgress(params progressParams) *progress { if stderrIsTTY() { - return startProgress(params, terminalWidth, redrawInterval) + return startProgress(params, terminalWidth, redrawInterval, time.Now) } - return startProgress(params, nil, plainInterval) + return startProgress(params, nil, plainInterval, time.Now) } // startProgress shows the phase params describes at once, and again // every interval until finish: with the progressbar library on a // terminal, whose width each draw reads by calling width, or as a plain -// line when width is nil. +// line when width is nil. The display reads the time by calling now. func startProgress(params progressParams, width func() int, - interval time.Duration, + interval time.Duration, now func() time.Time, ) *progress { - now := time.Now() + start := now() p := &progress{ - width: width, stop: make(chan struct{}), done: make(chan struct{}), + now: now, width: width, + stop: make(chan struct{}), done: make(chan struct{}), label: params.label, unit: params.unit, total: params.total, estimate: params.estimate, waitingFor: params.waitingFor, - start: now, rateStart: now, + doing: params.doing, start: start, rateStart: start, + lastItem: start, drawn: []drawnCount{{at: start}}, } // Show the zero state at once: the first item may take minutes, @@ -173,13 +204,22 @@ func startProgress(params progressParams, width func() int, } // draw shows the phase's progress: on a TTY in place of the line -// before, and otherwise as a plain line. +// before, and otherwise as a plain line. It first adds the count to +// drawn, then drops from drawn the draws older than rateWindow, except +// the one before this draw. func (p *progress) draw() { p.mu.Lock() defer p.mu.Unlock() + now := p.now() + + p.drawn = append(p.drawn, drawnCount{at: now, count: p.count}) + for len(p.drawn) > 2 && now.Sub(p.drawn[0].at) > rateWindow { + p.drawn = p.drawn[1:] + } + if p.width == nil { - text, _ := p.line(math.MaxInt, true) + text, _ := p.line(now, math.MaxInt, true) fmt.Fprintln(os.Stderr, text) return @@ -192,13 +232,13 @@ func (p *progress) draw() { // total of 0 leaves the bar nothing to fill. text, withBar := "", false if p.total > 0 && !p.estimate { - text, withBar = p.line(width-barMargin, false) + text, withBar = p.line(now, width-barMargin, false) } margin := barMargin if !withBar { margin = spinnerMargin - text, _ = p.line(width-margin, true) + text, _ = p.line(now, width-margin, true) } // The library makes a bar or a spinner, and before each draw erases @@ -255,18 +295,22 @@ func (p *progress) newBar(withBar bool, width int) { } // setTotal gives a phase that started without a total its total, once -// it is known. The rate, and so the ETA, count from then on: the time -// spent waiting for the total says nothing about how fast items go. +// it is known. The rate, the ETA and the time with no item completed +// count from then on: the time spent waiting for the total says nothing +// about how fast items go. func (p *progress) setTotal(total int64) { if p == nil { return } + now := p.now() + p.mu.Lock() defer p.mu.Unlock() p.total = total - p.rateStart = time.Now() + p.rateStart, p.lastItem = now, now + p.drawn = []drawnCount{{at: now, count: p.count}} } // increment records one completed item, which the display shows at its @@ -276,10 +320,13 @@ func (p *progress) increment() { return } + now := p.now() + p.mu.Lock() defer p.mu.Unlock() p.count++ + p.lastItem = now } // warnf prints a one-line warning to stderr without corrupting the @@ -391,52 +438,77 @@ func (p *progress) finish() { } } -// line formats the phase's progress in at most room columns, as +// line formats the phase's progress as of now in at most room columns, +// as // // [3/5] hash: [1234/5000] 25%, 300 files/s, elapsed 4s, eta 13s // // where "files" is the phase's unit, without the percent when percent // is false, as before the library's bar, which shows its own. A phase -// with no total shows the items done instead, or what it waits for. +// with no total shows the items done instead, or what it waits for. The +// rate is that since the first draw in drawn, and the ETA comes from +// the rate since the count started. Once no item has been completed for +// stallTime, the line says so before the elapsed time, and what the +// phase is doing, as "no files finished for 42s, reading files". // // The phase and its place, the progress, the elapsed time and the ETA // are kept whole. A line wider than room leaves out the rate, or what -// the phase waits for; only if it is still wider is it cut at room, and -// line reports that it does not fit. Every part is ASCII, so its length -// is its width in columns. p.mu must be held. -func (p *progress) line(room int, percent bool) (string, bool) { - elapsed := time.Since(p.start).Round(time.Second) +// the phase waits for, then what it says of a stall; only if it is +// still wider is it cut at room, and line reports that it does not fit. +// Every part is ASCII, so its length is its width in columns. p.mu must +// be held. +func (p *progress) line(now time.Time, room int, + percent bool, +) (string, bool) { + elapsed := now.Sub(p.start).Round(time.Second) - // head and tail hold the parts kept whole; extra, between them, is - // the part left out. - var head, extra, tail string + // head and tail hold the parts kept whole. extra, after head, is the + // part left out first, and stall, before tail, the part left out + // next. + var head, extra, stall, tail string if p.total < 0 && p.waitingFor != "" { - head, extra = p.label+": ", p.waitingFor + head, extra = p.label+": ", p.waitingFor+", " tail = fmt.Sprintf("elapsed %s, eta unknown", elapsed) } else { - rate := 0.0 - if s := time.Since(p.rateStart).Seconds(); s > 0 { - rate = float64(p.count) / s - } + since := p.drawn[0] + rate := perSecond(p.count-since.count, now.Sub(since.at)) + average := perSecond(p.count, now.Sub(p.rateStart)) head = p.label + ": " + p.itemsDone(percent) + ", " - extra = fmt.Sprintf("%.0f %s/s", rate, p.unit) - tail = fmt.Sprintf("elapsed %s, eta %s", elapsed, p.eta(rate)) + extra = fmt.Sprintf("%.0f %s/s, ", rate, p.unit) + + if idle := now.Sub(p.lastItem); idle >= stallTime { + stall = fmt.Sprintf("no %s finished for %s, %s, ", + p.unit, idle.Round(time.Second), p.doing) + } + + tail = fmt.Sprintf("elapsed %s, eta %s", elapsed, p.eta(average)) } - full, kept := head+extra+", "+tail, head+tail - - switch { - case len(full) <= room: - return full, true - case len(kept) <= room: - return kept, true + for _, text := range []string{ + head + extra + stall + tail, head + stall + tail, head + tail, + } { + if len(text) <= room { + return text, true + } } + kept := head + tail + return kept[:max(room, 0)], false } +// perSecond returns count items over d as items a second, or 0 when no +// time has passed. +func perSecond(count int64, d time.Duration) float64 { + if d <= 0 { + return 0 + } + + return float64(count) / d.Seconds() +} + // itemsDone formats the items done, as "[1234/5000] 25%", with "~" // before a total that is an estimate and without the percent when // percent is false, or as "1234 files", in the phase's unit, when the diff --git a/progress_test.go b/progress_test.go index 3cda760..6551d1e 100644 --- a/progress_test.go +++ b/progress_test.go @@ -6,7 +6,9 @@ import ( "math" "os" "path/filepath" + "slices" "strings" + "sync" "testing" "time" "unicode/utf8" @@ -20,6 +22,29 @@ const testRedraw = time.Millisecond // it expects. const testDeadline = 5 * time.Second +// testClock is a clock a test moves by hand, for a display that reads +// it from its own goroutine too. +type testClock struct { + mu sync.Mutex + now time.Time +} + +// Now returns the clock's time. +func (c *testClock) Now() time.Time { + c.mu.Lock() + defer c.mu.Unlock() + + return c.now +} + +// Add moves the clock on by d. +func (c *testClock) Add(d time.Duration) { + c.mu.Lock() + defer c.mu.Unlock() + + c.now = c.now.Add(d) +} + //nolint:paralleltest // replaces the process-wide os.Stderr func TestStderrIsTTYFalseForNonTerminals(t *testing.T) { r, pipe, err := os.Pipe() @@ -72,11 +97,13 @@ func TestPhaseLabel(t *testing.T) { } // TestProgressLine checks the line a display shows in each state, ten -// seconds into the phase. +// seconds into the phase, with no draw since the first and the last +// item just completed. func TestProgressLine(t *testing.T) { t.Parallel() - ago := time.Now().Add(-10 * time.Second) + now := time.Now() + ago := now.Add(-10 * time.Second) cases := []struct { p *progress @@ -129,28 +156,41 @@ func TestProgressLine(t *testing.T) { }} for _, tc := range cases { - tc.p.start, tc.p.rateStart = ago, ago + tc.p.start, tc.p.rateStart, tc.p.lastItem = ago, ago, now + tc.p.drawn = []drawnCount{{at: ago}} - if got, _ := tc.p.line(math.MaxInt, true); got != tc.want { + if got, _ := tc.p.line(now, math.MaxInt, true); got != tc.want { t.Errorf("line = %q, want %q", got, tc.want) } } } // TestLineFitsRoom checks how a line is fitted to the room it has, ten -// seconds into the phase: it leaves out the rate, or what the phase -// waits for, and is cut only when what is left is still too wide. +// seconds into the phase, and fifty into a phase with no file read for +// the last 42: it leaves out the rate, or what the phase waits for, +// then what it says of the stall, and is cut only when what is left is +// still too wide. func TestLineFitsRoom(t *testing.T) { t.Parallel() - ago := time.Now().Add(-10 * time.Second) + now := time.Now() + ago := now.Add(-10 * time.Second) hash := &progress{ label: scanPhase("hash"), unit: scanUnit, total: 100, count: 20, - start: ago, rateStart: ago, + start: ago, rateStart: ago, lastItem: now, + drawn: []drawnCount{{at: ago}}, } content := &progress{ label: scanPhase("content"), total: -1, - waitingFor: "searching the database", start: ago, rateStart: ago, + waitingFor: searchingDatabase, start: ago, rateStart: ago, + } + + started := now.Add(-50 * time.Second) + stalled := &progress{ + label: scanPhase("hash"), unit: scanUnit, total: 100, count: 20, + doing: readingFiles, start: started, rateStart: started, + lastItem: now.Add(-42 * time.Second), + drawn: []drawnCount{{at: now.Add(-rateWindow), count: 20}}, } cases := []struct { @@ -180,10 +220,24 @@ func TestLineFitsRoom(t *testing.T) { p: content, room: 40, percent: true, want: "[5/5] content: elapsed 10s, eta unknown", fits: true, + }, { + p: stalled, room: 101, percent: true, + want: "[3/5] hash: [20/100] 20%, 0 files/s, no files finished for " + + "42s, reading files, elapsed 50s, eta 3m20s", + fits: true, + }, { + p: stalled, room: 100, percent: true, + want: "[3/5] hash: [20/100] 20%, no files finished for 42s, " + + "reading files, elapsed 50s, eta 3m20s", + fits: true, + }, { + p: stalled, room: 89, percent: true, + want: "[3/5] hash: [20/100] 20%, elapsed 50s, eta 3m20s", + fits: true, }} for _, tc := range cases { - got, fits := tc.p.line(tc.room, tc.percent) + got, fits := tc.p.line(now, tc.room, tc.percent) if got != tc.want || fits != tc.fits { t.Errorf("line(%d, %t) = %q, %t, want %q, %t", tc.room, tc.percent, got, fits, tc.want, tc.fits) @@ -192,27 +246,37 @@ func TestLineFitsRoom(t *testing.T) { } // TestSetTotalStartsRate checks that setTotal starts a phase's rate, -// and so its ETA, from when the total becomes known, not from when the -// phase started waiting for it. +// its ETA and its time with no record read from when the total becomes +// known, not from when the phase started waiting for it. func TestSetTotalStartsRate(t *testing.T) { t.Parallel() - waited := time.Now().Add(-20 * time.Second) + clock := &testClock{now: time.Now()} + waited := clock.Now().Add(-20 * time.Second) p := &progress{ - label: scanPhase("load"), unit: scanUnit, total: -1, start: waited, - rateStart: waited, + now: clock.Now, label: scanPhase("load"), unit: scanUnit, total: -1, + doing: readingDatabase, start: waited, rateStart: waited, + lastItem: waited, drawn: []drawnCount{{at: waited}}, } p.setTotal(100) - // Ten seconds after the total came, without waiting ten seconds, - // 20 records are read. - p.start = p.start.Add(-10 * time.Second) - p.rateStart = p.rateStart.Add(-10 * time.Second) - p.count = 20 + // Ten seconds after the total came, no record has been read yet. + clock.Add(10 * time.Second) - want := "[1/5] load: [20/100] 20%, 2 files/s, elapsed 30s, eta 40s" - if got, _ := p.line(math.MaxInt, true); got != want { + want := "[1/5] load: [0/100] 0%, 0 files/s, no files finished for 10s, " + + "reading the database, elapsed 30s, eta unknown" + if got, _ := p.line(clock.Now(), math.MaxInt, true); got != want { + t.Errorf("line = %q, want %q", got, want) + } + + // Then 20 are. + for range 20 { + p.increment() + } + + want = "[1/5] load: [20/100] 20%, 2 files/s, elapsed 30s, eta 40s" + if got, _ := p.line(clock.Now(), math.MaxInt, true); got != want { t.Errorf("line = %q, want %q", got, want) } } @@ -272,13 +336,138 @@ func TestPlainProgressPrintsWhileWaiting(t *testing.T) { p := startProgress(progressParams{ label: scanPhase("load"), total: -1, waitingFor: countingRecords, - }, nil, testRedraw) + }, nil, testRedraw, time.Now) awaitOutput(t, stderr, "[1/5] load: counting the records, elapsed 0s, eta unknown\n", 3) p.finish() } +// TestPlainProgressStalledProducer checks that a phase whose files stop +// coming, as when one large file is being read or a disk is slow, goes +// on printing its line every interval: the rate falls to 0 once no file +// has been read for rateWindow, and once none has for stallTime the +// line says so, and what the phase is doing. The test moves the +// display's clock by hand. +// +//nolint:paralleltest // captureStderr replaces the process-wide os.Stderr +func TestPlainProgressStalledProducer(t *testing.T) { + stderr := captureStderr(t) + clock := &testClock{now: time.Now()} + p := startProgress(progressParams{ + label: scanPhase("hash"), unit: scanUnit, total: 100, + doing: readingFiles, + }, nil, testRedraw, clock.Now) + + // Pass or fail, the display ends before stderr is put back. + t.Cleanup(p.finish) + + // 20 files read as the phase starts, then none. + for range 20 { + p.increment() + } + + clock.Add(5 * time.Second) + awaitOutput(t, stderr, + "[3/5] hash: [20/100] 20%, 4 files/s, elapsed 5s, eta 20s\n", 3) + + clock.Add(time.Second) + awaitOutput(t, stderr, + "[3/5] hash: [20/100] 20%, 0 files/s, elapsed 6s, eta 24s\n", 3) + + clock.Add(4 * time.Second) + awaitOutput(t, stderr, + "[3/5] hash: [20/100] 20%, 0 files/s, no files finished for 10s, "+ + "reading files, elapsed 10s, eta 40s\n", 3) +} + +// TestPlainProgressRateAfterStall draws a phase's plain line by hand, a +// little over plainInterval after the line before, as a late tick +// does, through a stall and a burst of files after it: the rate covers +// the files read since the line before, while the ETA comes from the +// phase's average. +// +//nolint:paralleltest // captureStderr replaces the process-wide os.Stderr +func TestPlainProgressRateAfterStall(t *testing.T) { + stderr := captureStderr(t) + clock := &testClock{now: time.Now()} + + // No timed draws: the test draws. + p := startProgress(progressParams{ + label: scanPhase("hash"), unit: scanUnit, total: 1000, + doing: readingFiles, + }, nil, time.Hour, clock.Now) + + late := plainInterval + time.Millisecond + + clock.Add(late) + p.draw() + clock.Add(late) + p.draw() + + for range 100 { + p.increment() + } + + clock.Add(late) + p.finish() + + want := []string{ + "[3/5] hash: [0/1000] 0%, 0 files/s, elapsed 0s, eta unknown", + "[3/5] hash: [0/1000] 0%, 0 files/s, elapsed 5s, eta unknown", + "[3/5] hash: [0/1000] 0%, 0 files/s, no files finished for 10s, " + + "reading files, elapsed 10s, eta unknown", + "[3/5] hash: [100/1000] 10%, 20 files/s, elapsed 15s, eta 2m15s", + } + + lines := strings.Split(strings.TrimSuffix(stderr(), "\n"), "\n") + if !slices.Equal(lines, want) { + t.Errorf("stderr lines = %q, want %q", lines, want) + } +} + +// TestProgressRateAfterStallRedrawn draws a phase by hand every +// redrawInterval, as a terminal does, through a stall of stallTime and +// a burst of files after it: the rate covers the files read over the +// last rateWindow, and falls to 0 once the burst is older than that, +// while the ETA comes from the phase's average. Plain lines show each +// draw. +// +//nolint:paralleltest // captureStderr replaces the process-wide os.Stderr +func TestProgressRateAfterStallRedrawn(t *testing.T) { + stderr := captureStderr(t) + clock := &testClock{now: time.Now()} + + // No timed draws: the test draws. + p := startProgress(progressParams{ + label: scanPhase("hash"), unit: scanUnit, total: 1000, + doing: readingFiles, + }, nil, time.Hour, clock.Now) + + // redraw draws the display every redrawInterval for d. + redraw := func(d time.Duration) { + for range d / redrawInterval { + clock.Add(redrawInterval) + p.draw() + } + } + + redraw(stallTime) + + for range 50 { + p.increment() + } + + redraw(rateWindow + redrawInterval) + p.finish() + + want := "[3/5] hash: [50/1000] 5%, 10 files/s, elapsed 15s, eta 4m45s\n" + + "[3/5] hash: [50/1000] 5%, 0 files/s, elapsed 15s, eta 4m47s\n" + if !strings.Contains(stderr(), want) { + t.Errorf("stderr = %q, want the lines %q", stderr(), want) + } +} + // lastFrame returns what a terminal shows of the frames a display drew: // the last one. The library starts each frame with a carriage return // and erases the previous one with spaces first. @@ -321,7 +510,7 @@ func TestTerminalRedrawsWhileWaiting(t *testing.T) { for _, tc := range cases { before := len(stderr()) since := func() string { return stderr()[before:] } - p := startProgress(tc.params, terminalWidth, testRedraw) + p := startProgress(tc.params, terminalWidth, testRedraw, time.Now) for range 50 { p.increment() @@ -343,21 +532,23 @@ func TestTerminalRedrawsWhileWaiting(t *testing.T) { // drawLate draws the display params describes on a terminal width // columns wide as it starts and once more as it ends, with count items -// done two and a half hours into the phase, and returns what it wrote -// to stderr. +// done two and a half hours into the phase, the last just now, and +// returns what it wrote to stderr. func drawLate(stderr func() string, params progressParams, width int, count int64, ) string { before := len(stderr()) + clock := &testClock{now: time.Now()} // No timed draws come between the two. - p := startProgress(params, func() int { return width }, time.Hour) + p := startProgress(params, func() int { return width }, time.Hour, + clock.Now) // Without counting the items one by one or waiting the hours. + clock.Add(150 * time.Minute) + p.mu.Lock() - p.count = count - p.start = p.start.Add(-150 * time.Minute) - p.rateStart = p.start + p.count, p.lastItem = count, clock.Now() p.mu.Unlock() p.finish() @@ -479,14 +670,16 @@ func TestTerminalNarrowedRedrawsInPlace(t *testing.T) { for _, tc := range cases { width := 120 + clock := &testClock{now: time.Now()} // No timed draws: the test draws. - p := startProgress(tc.params, func() int { return width }, time.Hour) + p := startProgress(tc.params, func() int { return width }, time.Hour, + clock.Now) + + clock.Add(150 * time.Minute) p.mu.Lock() - p.count = 1234567 - p.start = p.start.Add(-150 * time.Minute) - p.rateStart = p.start + p.count, p.lastItem = 1234567, clock.Now() p.mu.Unlock() p.draw() @@ -528,7 +721,7 @@ func TestProgressWarningsOnOwnLines(t *testing.T) { issued := 0 for _, params := range cases { - p := startProgress(params, terminalWidth, testRedraw) + p := startProgress(params, terminalWidth, testRedraw, time.Now) // No pause between warnings: one written straight to stderr is // garbled only if a redraw lands while it is being written. @@ -581,7 +774,7 @@ func TestProgressWriterRowsOnOwnLines(t *testing.T) { var want []string for _, params := range cases { - p := startProgress(params, terminalWidth, testRedraw) + p := startProgress(params, terminalWidth, testRedraw, time.Now) out := p.writer(os.Stderr) // No pause between rows: one is garbled only if a redraw lands @@ -644,7 +837,7 @@ func TestProgressWriterStalledStdoutKeepsLines(t *testing.T) { }) p := startProgress(progressParams{label: treesPhase("write"), total: 1}, - nil, testRedraw) + nil, testRedraw, time.Now) out := p.writer(w) written := make(chan error, 1) @@ -687,7 +880,7 @@ func TestProgressWriterStalledStdoutKeepsLines(t *testing.T) { func TestTerminalStoppedShortKeepsCount(t *testing.T) { stderr := captureStderr(t) p := startProgress(progressParams{label: scanPhase("hash"), total: 10}, - terminalWidth, redrawInterval) + terminalWidth, redrawInterval, time.Now) p.increment() p.increment() @@ -706,7 +899,7 @@ func TestTerminalStoppedShortKeepsCount(t *testing.T) { func TestWarningAfterLastItemKeepsBar(t *testing.T) { stderr := captureStderr(t) p := startProgress(progressParams{label: scanPhase("hash"), total: 2}, - terminalWidth, testRedraw) + terminalWidth, testRedraw, time.Now) p.increment() p.increment() diff --git a/report.go b/report.go index 0767e4d..fcd1734 100644 --- a/report.go +++ b/report.go @@ -76,7 +76,7 @@ func runReport(ctx context.Context, stdout io.Writer) error { prog = newProgress(progressParams{ label: reportPhase("read"), unit: "records", total: -1, - waitingFor: countingRecords, + waitingFor: countingRecords, doing: readingDatabase, }) report, err := readReport(ctx, db, dbPath, stdout, prog) diff --git a/report_test.go b/report_test.go index c60066e..bb27652 100644 --- a/report_test.go +++ b/report_test.go @@ -156,7 +156,7 @@ func TestReportStdoutFailsWhileReading(t *testing.T) { } // Counts the records read, and draws nothing. - prog := &progress{} + prog := &progress{now: time.Now} _, err = readReport(t.Context(), db, "", failingWriter{}, prog) if !errors.Is(err, errWriteFailed) || @@ -250,7 +250,7 @@ func TestReadReportOnTerminal(t *testing.T) { p := startProgress(progressParams{ label: reportPhase("read"), unit: "records", total: -1, waitingFor: countingRecords, - }, terminalWidth, time.Hour) + }, terminalWidth, time.Hour, time.Now) _, err = readReport(t.Context(), db, "", os.Stderr, p) diff --git a/scan.go b/scan.go index 56674b0..6efb09c 100644 --- a/scan.go +++ b/scan.go @@ -88,6 +88,15 @@ type fileMeta struct { // names it. const scanUnit = "files" +// readingFiles is what the display of a phase that reads files says it +// is doing once no file has been read for stallTime. +const readingFiles = "reading files" + +// searchingDatabase is what the display of the content phase's checks +// says it waits for until the search returns its first record, and what +// it says it is doing once no record has been checked for stallTime. +const searchingDatabase = "searching the database" + // scanPhase names one phase of a scan with its place among all of them, // as "[2/5] walk", for the phase's progress display. The list here is // the one place the phases are counted. @@ -446,7 +455,7 @@ func (s *scanState) loadIndex(ctx context.Context, roots []string) error { // first gives the display its total. prog := newProgress(progressParams{ label: scanPhase("load"), unit: scanUnit, total: -1, - waitingFor: countingRecords, + waitingFor: countingRecords, doing: readingDatabase, }) defer prog.finish() @@ -497,7 +506,7 @@ func (s *scanState) walkPhase( prog := newProgress(progressParams{ label: scanPhase("walk"), unit: scanUnit, total: estimate, - estimate: true, + estimate: true, doing: "listing directories", }) var ( @@ -689,6 +698,7 @@ func (s *scanState) readRuns(ctx context.Context, workers int, prog := newProgress(progressParams{ label: scanPhase(label), unit: scanUnit, total: int64(len(runs)), + doing: readingFiles, }) defer prog.finish() @@ -778,6 +788,7 @@ func (s *scanState) updatePhase(ctx context.Context) error { total := len(s.batch) + len(s.sentinels) + len(deletes) prog := newProgress(progressParams{ label: scanPhase("update"), unit: scanUnit, total: int64(total), + doing: "writing to the database", }) defer prog.finish() @@ -866,7 +877,7 @@ func (s *scanState) contentCandidates( // the search returns, and so do their rate and ETA. prog := newProgress(progressParams{ label: scanPhase("content"), unit: scanUnit, total: -1, - waitingFor: "searching the database", + waitingFor: searchingDatabase, doing: searchingDatabase, }) defer prog.finish() diff --git a/trees.go b/trees.go index 4e4028f..8af025a 100644 --- a/trees.go +++ b/trees.go @@ -72,7 +72,7 @@ func runTrees(ctx context.Context, stdout io.Writer) error { prog = newProgress(progressParams{ label: treesPhase("read"), unit: "records", total: -1, - waitingFor: countingRecords, + waitingFor: countingRecords, doing: readingDatabase, }) records, super, allDirs, err := readTree(ctx, db, prog) @@ -84,7 +84,7 @@ func runTrees(ctx context.Context, stdout io.Writer) error { prog = newProgress(progressParams{ label: treesPhase("group"), unit: "directories", - total: int64(len(allDirs)), + total: int64(len(allDirs)), doing: "grouping directories", }) dupes := collectTreeGroups(allDirs, super, prog) @@ -92,6 +92,7 @@ func runTrees(ctx context.Context, stdout io.Writer) error { prog = newProgress(progressParams{ label: treesPhase("write"), unit: "groups", total: int64(len(dupes)), + doing: "writing the report", }) dupeTrees, reclaimable, err := writeTreeGroups(stdout, dupes, prog) diff --git a/trees_test.go b/trees_test.go index 5257149..9249aa0 100644 --- a/trees_test.go +++ b/trees_test.go @@ -279,7 +279,7 @@ func TestWriteTreeGroupsOnTerminal(t *testing.T) { // No timed draws: the display is drawn as it starts and as it ends. p := startProgress(progressParams{ label: treesPhase("write"), unit: "groups", total: int64(len(dupes)), - }, terminalWidth, time.Hour) + }, terminalWidth, time.Hour, time.Now) _, _, err := writeTreeGroups(os.Stderr, dupes, p)