diff --git a/README.md b/README.md index f709ab8..4273341 100644 --- a/README.md +++ b/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,20 @@ 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 - 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. + terminal is. A line too wide for the terminal first loses its bar, which gives + way to the spinner, then its rate, the words of a stalled phase, or what the + phase is waiting for. The phase and its place, the progress, the elapsed time + and the ETA are kept whole. On an 80-column terminal, at counts like those of + the stalled line in the example above, a stalled line keeps its words whenever + the elapsed time and the ETA are both in minutes, except in the content + phase's checks and reads. Their lines are the widest, and at most times in + minutes they lose the words. Where the words and the ETA do not both fit, as + at millions of files and times in hours, the words give way. 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..b814411 100644 --- a/TODO.md +++ b/TODO.md @@ -29,6 +29,22 @@ # 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, at counts + like those of README's example, the content phase's checks and reads lose + those words at most times in minutes, and every other phase keeps them + whenever the elapsed time and the ETA are both in minutes. 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 diff --git a/progress.go b/progress.go index 321b226..6802825 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 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,9 +124,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 +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, text) + fmt.Fprintln(os.Stderr, p.line(now, math.MaxInt, true)) return } width := p.width() - // A phase with an exact total gets the library's bar when its line, - // without the percent the bar shows, fits whole beside the bar. A - // total of 0 leaves the bar nothing to fill. + // A phase with an exact total gets the library's bar when its whole + // line, without the percent the bar shows, fits beside the bar: the + // 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 -// 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 +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 -// 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) +// are kept whole. A line wider than room leaves out the rate, the words +// of a stalled phase, or what the phase waits for; only if it is still +// wider is it cut at room. 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 { + 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 - 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) + 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 "~" diff --git a/progress_test.go b/progress_test.go index 3cda760..1c65053 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,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 -// 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, 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.want || fits != tc.fits { - t.Errorf("line(%d, %t) = %q, %t, want %q, %t", - tc.room, tc.percent, got, fits, tc.want, tc.fits) + if got := tc.p.line(now, tc.room, tc.percent); got != tc.want { + t.Errorf("line(%d, %t) = %q, want %q", + tc.room, tc.percent, got, tc.want) } } } // 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: 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, - rateStart: waited, + now: clock.Now, label: scanPhase("load"), unit: scanUnit, total: -1, + 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, - // 20 records are read. - p.start = p.start.Add(-10 * time.Second) - p.rateStart = p.rateStart.Add(-10 * time.Second) - p.count = 20 + clock.Add(5 * 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, elapsed 25s, eta unknown" + 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 -// 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() @@ -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.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 +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() diff --git a/report.go b/report.go index 0767e4d..a3396fe 100644 --- a/report.go +++ b/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) 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..642055b 100644 --- a/scan.go +++ b/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() diff --git a/trees.go b/trees.go index 4e4028f..77275a5 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, 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) 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)