Show the progress rate over the last 5 seconds, and where a phase waits after 10 seconds with no item done (closes #125)

The rate was the phase's average, so a burst after a long wait read as
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; the ETA still
comes from the average. Once no item has completed for 10 seconds, the
rate gives way to "stalled" and where the phase waits, as "stalled
disk/db": disk, db, out (stdout) or cpu, or two of them. A line too
wide for the terminal loses its bar first, then its rate or those
words, so the phase, progress, elapsed time and ETA stay whole. The
content phase's last partial batch is now written under a display of
its own. The tests set the display's clock by hand.

Deviation: the stall words hold no time and name where the phase waits, not what it does.
Judgement call: trees' group phase, which works in memory, says "cpu".

Model: opus-5-5

README.md

@@ -799,7 +799,8 @@ A scan has five phases (`[1/5] load`, `[2/5] walk`, `[3/5] hash`,
   `head`, and `tail`, without fetching the records. It then says it is searching
   the database until SQLite returns the first record; the checks, and their rate
   and ETA, start there. The files to read then get a display of their own, with
-  their count as its total.
+  their count as its total, and so does the writing of the last of their records
+  to the database, with the count of those records as its total.
 
 `trees` has four phases (`[1/4] open`, `[2/4] read`, `[3/4] group`,
 `[4/4] write`, see "`trees` mode"):
@@ -833,17 +834,36 @@ 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, the
+  word `stalled` and where the phase waits take the rate's place (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/45678] 27%, stalled disk/db, elapsed 4m30s, eta 12m9s
 ```
 
+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 `stalled` and where the
+phase waits in place of the rate, which would read 0: `disk` for files, `db` for
+the database, `out` for stdout, and two of them, as `disk/db`, for a phase that
+may wait on either. `walk` says `disk`. `hash` and the content phase's reads say
+`disk/db`, as they read files and write their records to the database between
+them, and so do the content phase's checks, which `lstat` each record's file as
+the database search returns it. `load`, `update`, the content phase's last write
+and the `read` phase of `trees` say `db`. `trees`' `write` says `out`, and its
+`group`, which works in memory, says `cpu`. The `read` phase of `report` writes
+the report while it reads the records, so it says `db/out`. 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`,
@@ -855,15 +875,18 @@ Additional requirements:
   times a second, so its elapsed time keeps moving while a phase waits for its
   next item.
 - 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
+  terminal is. A line too wide for the terminal first loses its bar, which gives
-  ETA are kept whole: a line too wide for the terminal leaves out its rate first
+  way to the spinner, then its rate, the words of a stalled phase, or what the
-  (or what the phase is waiting for), and a bar with no room beside those four
+  phase is waiting for. The phase and its place, the progress, the elapsed time
-  gives way to the spinner. Only when those four alone are too wide, as on a
+  and the ETA are kept whole. On an 80-column terminal, a stalled line at counts
-  terminal narrower than about 70 columns hours into a scan of millions of
+  and times like those of the stalled line in the example above keeps its words
-  files, is the line cut short at the terminal's edge, so the end of the ETA is
+  whole in every phase; where the words and the ETA do not both fit, as at
-  lost first. A terminal made narrower while a phase runs gets the same: the
+  millions of files and times in hours, the words give way. Only when those four
-  next draw erases the line within the new width and fits the line to it, and
+  alone are too wide, as on a terminal narrower than about 70 columns hours into
-  the display goes on redrawing in place.
+  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

TODO.md

@@ -29,6 +29,20 @@
 
 # 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 word `stalled` and
+  where the phase waits take the rate's place, as `stalled disk/db`: `disk`,
+  `db`, `out` for stdout or `cpu`, or two of them for a phase that may wait on
+  either, each phase giving its word where it is defined. A line too wide for
+  the terminal loses its bar first, then its rate or those words, so the phase,
+  progress, elapsed time and ETA stay whole; on an 80-column terminal the words
+  fit beside them in an ordinary scan. The content phase's last partial batch is
+  now written under a display of its own (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

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 it has stalled, and where it waits, in place of the rate.
+const stallTime = 10 * time.Second
+
 // spinnerType selects the progressbar library's spinner style.
 const spinnerType = 14
 
@@ -89,6 +98,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
+	stalledOn  string // where the phase waits, as "disk/db"; 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,6 +124,7 @@ type progressParams struct {
 // phase's helpers without rendering anything, and its writer writes
 // with no display to clear.
 type progress struct {
+	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
@@ -120,33 +138,42 @@ type progress struct {
 	total      int64
 	estimate   bool
 	waitingFor string
+	stalledOn  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,
+		stalledOn: params.stalledOn, start: start, rateStart: start,
+		lastItem: start, drawn: []drawnCount{{at: start}},
 	}
 
 	// Show the zero state at once: the first item may take minutes,
@@ -173,32 +200,42 @@ 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)
+		fmt.Fprintln(os.Stderr, p.line(now, math.MaxInt, true))
-		fmt.Fprintln(os.Stderr, text)
 
 		return
 	}
 
 	width := p.width()
 
-	// A phase with an exact total gets the library's bar when its line,
+	// A phase with an exact total gets the library's bar when its whole
-	// without the percent the bar shows, fits whole beside the bar. A
+	// line, without the percent the bar shows, fits beside the bar: the
-	// total of 0 leaves the bar nothing to fill.
+	// bar gives way before any part of the line. A 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 = p.line(now, math.MaxInt, false)
+		withBar = len(text) <= width-barMargin
 	}
 
 	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 +292,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
+// it is known. The rate, the ETA and the time with no item completed
-// spent waiting for the total says nothing about how fast items go.
+// 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 +317,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,50 +435,68 @@ 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 rate, which would read 0, gives way to the word
+// "stalled" and where the phase waits, as "stalled disk/db".
 //
 // 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
+// are kept whole. A line wider than room leaves out the rate, the words
-// the phase waits for; only if it is still wider is it cut at room, and
+// of a stalled phase, or what the phase waits for; only if it is still
-// line reports that it does not fit. Every part is ASCII, so its length
+// wider is it cut at room. Every part is ASCII, so its length is its
-// is its width in columns. p.mu must be held.
+// width in columns. p.mu must be held.
-func (p *progress) line(room int, percent bool) (string, bool) {
+func (p *progress) line(now time.Time, room int, percent bool) string {
-	elapsed := time.Since(p.start).Round(time.Second)
+	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
 
 	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
+		since := p.drawn[0]
-		if s := time.Since(p.rateStart).Seconds(); s > 0 {
+		rate := perSecond(p.count-since.count, now.Sub(since.at))
-			rate = float64(p.count) / s
+		average := perSecond(p.count, now.Sub(p.rateStart))
-		}
 
 		head = p.label + ": " + p.itemsDone(percent) + ", "
-		extra = fmt.Sprintf("%.0f %s/s", rate, p.unit)
+		extra = fmt.Sprintf("%.0f %s/s, ", rate, p.unit)
-		tail = fmt.Sprintf("elapsed %s, eta %s", elapsed, p.eta(rate))
+		tail = fmt.Sprintf("elapsed %s, eta %s", elapsed, p.eta(average))
+
+		if now.Sub(p.lastItem) >= stallTime {
+			extra = "stalled " + p.stalledOn + ", "
+		}
 	}
 
-	full, kept := head+extra+", "+tail, head+tail
+	full, kept := head+extra+tail, head+tail
 
 	switch {
 	case len(full) <= room:
-		return full, true
+		return full
 	case len(kept) <= room:
-		return kept, true
+		return kept
 	}
 
-	return kept[:max(room, 0)], false
+	return kept[:max(room, 0)]
+}
+
+// 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 "~"

progress_test.go

@@ -6,7 +6,9 @@ import (
 	"math"
 	"os"
 	"path/filepath"
+	"slices"
 	"strings"
+	"sync"
 	"testing"
 	"time"
 	"unicode/utf8"
@@ -20,6 +22,33 @@ const testRedraw = time.Millisecond
 // it expects.
 const testDeadline = 5 * time.Second
 
+// hashStalledOn is where the hash phase says it waits once it has
+// stalled, as readRuns gives it.
+const hashStalledOn = "disk/db"
+
+// 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 +101,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,90 +160,120 @@ 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
+// seconds into the phase, and fifty into a phase with no file read for
-// waits for, and is cut only when what is left is still too wide.
+// the last 42: it leaves out the rate, what the phase waits for, or the
+// words of a stalled phase, 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,
 	}
 
+	started := now.Add(-50 * time.Second)
+	stalled := &progress{
+		label: scanPhase("hash"), unit: scanUnit, total: 100, count: 20,
+		stalledOn: hashStalledOn, start: started, rateStart: started,
+		lastItem: now.Add(-42 * time.Second),
+		drawn:    []drawnCount{{at: now.Add(-rateWindow), count: 20}},
+	}
+
 	cases := []struct {
 		p       *progress
 		room    int
 		percent bool
 		want    string
-		fits    bool
 	}{{
 		p: hash, room: 57, percent: true,
 		want: "[3/5] hash: [20/100] 20%, 2 files/s, elapsed 10s, eta 40s",
-		fits: true,
 	}, {
 		p: hash, room: 56, percent: true,
 		want: "[3/5] hash: [20/100] 20%, elapsed 10s, eta 40s",
-		fits: true,
 	}, {
 		p: hash, room: 45, percent: true,
 		want: "[3/5] hash: [20/100] 20%, elapsed 10s, eta 40",
-		fits: false,
 	}, {
 		// Before the library's bar, which shows the percent.
 		p: hash, room: 57, percent: false,
 		want: "[3/5] hash: [20/100], 2 files/s, elapsed 10s, eta 40s",
-		fits: true,
 	}, {
 		p: content, room: 40, percent: true,
 		want: "[5/5] content: elapsed 10s, eta unknown",
-		fits: true,
+	}, {
+		p: stalled, room: 65, percent: true,
+		want: "[3/5] hash: [20/100] 20%, stalled disk/db, elapsed 50s, " +
+			"eta 3m20s",
+	}, {
+		p: stalled, room: 64, percent: true,
+		want: "[3/5] hash: [20/100] 20%, elapsed 50s, eta 3m20s",
 	}}
 
 	for _, tc := range cases {
-		got, fits := tc.p.line(tc.room, tc.percent)
+		if got := tc.p.line(now, tc.room, tc.percent); got != tc.want {
-		if got != tc.want || fits != tc.fits {
+			t.Errorf("line(%d, %t) = %q, want %q",
-			t.Errorf("line(%d, %t) = %q, %t, want %q, %t",
+				tc.room, tc.percent, got, tc.want)
-				tc.room, tc.percent, got, fits, tc.want, tc.fits)
 		}
 	}
 }
 
 // TestSetTotalStartsRate checks that setTotal starts a phase's rate,
-// and so its ETA, from when the total becomes known, not from when the
+// its ETA and its time with no record read from when the total becomes
-// phase started waiting for it.
+// known, not from when the phase started waiting for it: after 20
+// seconds of waiting for the total, the phase has not stalled 5 seconds
+// after it, and has 10 seconds after it with no record read.
 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,
+		now: clock.Now, label: scanPhase("load"), unit: scanUnit, total: -1,
-		rateStart: waited,
+		stalledOn: "db", start: waited, rateStart: waited,
+		lastItem: waited, drawn: []drawnCount{{at: waited}},
 	}
 
 	p.setTotal(100)
 
-	// Ten seconds after the total came, without waiting ten seconds,
+	clock.Add(5 * time.Second)
-	// 20 records are read.
-	p.start = p.start.Add(-10 * time.Second)
-	p.rateStart = p.rateStart.Add(-10 * time.Second)
-	p.count = 20
 
-	want := "[1/5] load: [20/100] 20%, 2 files/s, elapsed 30s, eta 40s"
+	want := "[1/5] load: [0/100] 0%, 0 files/s, elapsed 25s, eta unknown"
-	if got, _ := p.line(math.MaxInt, true); got != want {
+	if got := p.line(clock.Now(), math.MaxInt, true); got != want {
+		t.Errorf("line = %q, want %q", got, want)
+	}
+
+	clock.Add(5 * time.Second)
+
+	want = "[1/5] load: [0/100] 0%, stalled db, 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 records are read.
+	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 +333,137 @@ 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 the phase has stalled, and where it waits, in place of the
+// rate. 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,
+		stalledOn: hashStalledOn,
+	}, 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%, stalled disk/db, 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,
+		stalledOn: hashStalledOn,
+	}, 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%, stalled disk/db, 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,
+		stalledOn: hashStalledOn,
+	}, 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 +506,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 +528,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
+// done two and a half hours into the phase, the last just now, and
-// to stderr.
+// 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.count, p.lastItem = count, clock.Now()
-	p.start = p.start.Add(-150 * time.Minute)
-	p.rateStart = p.start
 	p.mu.Unlock()
 
 	p.finish()
@@ -413,6 +600,85 @@ func TestTerminalLinesKeepETA(t *testing.T) {
 	}
 }
 
+// TestTerminalStalledLines draws every phase's line on an 80-column
+// terminal once the phase has stalled, its last item done 42 seconds
+// before. At an ordinary scan's counts and times, 12345 of 45678 items
+// done four and a half minutes in, the line shows where the phase waits
+// whole, beside the phase, progress, elapsed time and ETA. At a large
+// scan's, 1234567 of 9876543 two and a half hours in, those four still
+// show whole, as the words give way first where they do not fit.
+//
+//nolint:paralleltest // captureStderr replaces the process-wide os.Stderr
+func TestTerminalStalledLines(t *testing.T) {
+	stderr := captureStderr(t)
+
+	// drawStalled draws the display params describes as it starts and
+	// once more as it ends, with count of total items done elapsed into
+	// the phase, and returns what the terminal shows.
+	drawStalled := func(params progressParams, total, count int64,
+		elapsed time.Duration,
+	) string {
+		before := len(stderr())
+		clock := &testClock{now: time.Now()}
+		params.total = total
+
+		// No timed draws come between the two.
+		p := startProgress(params, func() int { return 80 }, time.Hour,
+			clock.Now)
+
+		clock.Add(elapsed - 42*time.Second)
+
+		p.mu.Lock()
+		p.count, p.lastItem = count, clock.Now()
+		p.mu.Unlock()
+
+		clock.Add(42 * time.Second)
+		p.finish()
+
+		return lastFrame(stderr()[before:])
+	}
+
+	phases := []progressParams{
+		{label: scanPhase("load"), stalledOn: "db"},
+		{label: scanPhase("walk"), estimate: true, stalledOn: "disk"},
+		{label: scanPhase("hash"), stalledOn: hashStalledOn},
+		{label: scanPhase("update"), stalledOn: "db"},
+		// The content phase's checks and reads, then its last write.
+		{label: scanPhase("content"), stalledOn: "disk/db"},
+		{label: scanPhase("content"), stalledOn: "db"},
+		{label: treesPhase("read"), stalledOn: "db"},
+		{label: treesPhase("group"), stalledOn: "cpu"},
+		{label: treesPhase("write"), stalledOn: "out"},
+		{label: reportPhase("read"), stalledOn: "db/out"},
+	}
+
+	for _, params := range phases {
+		approx := ""
+		if params.estimate {
+			approx = "~"
+		}
+
+		shown := drawStalled(params, 45678, 12345,
+			4*time.Minute+30*time.Second)
+		want := params.label + ": [12345/" + approx + "45678] 27%, stalled " +
+			params.stalledOn + ", elapsed 4m30s, eta 12m9s"
+
+		if !strings.Contains(shown, want) {
+			t.Errorf("terminal shows %q, want %q", shown, want)
+		}
+
+		shown = drawStalled(params, 9876543, 1234567, 150*time.Minute)
+		for _, want := range []string{
+			params.label + ": [1234567/" + approx + "9876543] 12%, ",
+			", elapsed 2h30m0s, eta 17h30m0s",
+		} {
+			if !strings.Contains(shown, want) {
+				t.Errorf("terminal shows %q, want %q", shown, want)
+			}
+		}
+	}
+}
+
 // TestTerminalLinesFitWidth draws a large scan's bar display and a small
 // scan's, two and a half hours into the phase, on terminals from 120
 // columns down to 40, and checks that every line stays clear of the
@@ -455,7 +721,7 @@ func TestTerminalLinesFitWidth(t *testing.T) {
 // times. Nothing written after that, the erase before each redraw
 // included, may reach the narrower terminal's last column: it would
 // wrap, and every redraw would leave a line behind. At these widths the
-// spinner stays a spinner and the bar stays a bar.
+// spinner stays a spinner and the bar gives way to the spinner.
 //
 //nolint:paralleltest // captureStderr replaces the process-wide os.Stderr
 func TestTerminalNarrowedRedrawsInPlace(t *testing.T) {
@@ -479,14 +745,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.count, p.lastItem = 1234567, clock.Now()
-		p.start = p.start.Add(-150 * time.Minute)
-		p.rateStart = p.start
 		p.mu.Unlock()
 
 		p.draw()
@@ -528,7 +796,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 +849,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 +912,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 +955,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 +974,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()

report.go

@@ -74,9 +74,11 @@ func runReport(ctx context.Context, stdout io.Writer) error {
 
 	defer func() { _ = db.Close() }()
 
+	// The read phase writes the report to stdout while it reads the
+	// records, so it may wait on either.
 	prog = newProgress(progressParams{
 		label: reportPhase("read"), unit: "records", total: -1,
-		waitingFor: countingRecords,
+		waitingFor: countingRecords, stalledOn: "db/out",
 	})
 	report, err := readReport(ctx, db, dbPath, stdout, prog)
 

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)
 

scan.go

@@ -446,7 +446,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, stalledOn: "db",
 	})
 	defer prog.finish()
 
@@ -497,7 +497,7 @@ func (s *scanState) walkPhase(
 
 	prog := newProgress(progressParams{
 		label: scanPhase("walk"), unit: scanUnit, total: estimate,
-		estimate: true,
+		estimate: true, stalledOn: "disk",
 	})
 
 	var (
@@ -687,8 +687,11 @@ func (s *scanState) readRuns(ctx context.Context, workers int,
 	pool := startHashPool(ctx, runs, workers, hash)
 	defer pool.stop()
 
+	// Between results the phase may wait on a file being read or on a
+	// batch of records being written.
 	prog := newProgress(progressParams{
 		label: scanPhase(label), unit: scanUnit, total: int64(len(runs)),
+		stalledOn: "disk/db",
 	})
 	defer prog.finish()
 
@@ -778,6 +781,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),
+		stalledOn: "db",
 	})
 
 	defer prog.finish()
@@ -840,7 +844,15 @@ func (s *scanState) contentPhase(ctx context.Context, workers int) error {
 		return err
 	}
 
-	return applyChanges(ctx, s.db, s.batch, nil, nil)
+	// The last partial batch is written under a display of its own, as
+	// the update phase writes the hash phase's.
+	prog := newProgress(progressParams{
+		label: scanPhase("content"), unit: scanUnit,
+		total: int64(len(s.batch)), stalledOn: "db",
+	})
+	defer prog.finish()
+
+	return applyChanges(ctx, s.db, s.batch, nil, prog)
 }
 
 // contentCandidates returns the files the content phase reads, and
@@ -863,10 +875,11 @@ func (s *scanState) contentCandidates(
 	// without a display the scan looks hung before the reads begin.
 	// The display says it is searching until SQLite returns the first
 	// record. The checks start there, against a count of the records
-	// the search returns, and so do their rate and ETA.
+	// the search returns, and so do their rate and ETA. Between records
+	// they may wait on a file's lstat or on the search.
 	prog := newProgress(progressParams{
 		label: scanPhase("content"), unit: scanUnit, total: -1,
-		waitingFor: "searching the database",
+		waitingFor: "searching the database", stalledOn: "disk/db",
 	})
 	defer prog.finish()
 

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, stalledOn: "db",
 	})
 	records, super, allDirs, err := readTree(ctx, db, prog)
 
@@ -82,9 +82,11 @@ func runTrees(ctx context.Context, stdout io.Writer) error {
 		return fmt.Errorf("database %s: %w", dbPath, err)
 	}
 
+	// Grouping works in memory, so it waits on nothing but the
+	// processor.
 	prog = newProgress(progressParams{
 		label: treesPhase("group"), unit: "directories",
-		total: int64(len(allDirs)),
+		total: int64(len(allDirs)), stalledOn: "cpu",
 	})
 	dupes := collectTreeGroups(allDirs, super, prog)
 
@@ -92,6 +94,7 @@ func runTrees(ctx context.Context, stdout io.Writer) error {
 
 	prog = newProgress(progressParams{
 		label: treesPhase("write"), unit: "groups", total: int64(len(dupes)),
+		stalledOn: "out",
 	})
 	dupeTrees, reclaimable, err := writeTreeGroups(stdout, dupes, prog)
 

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)