diff --git a/README.md b/README.md index a007bc7..72a8bad 100644 --- a/README.md +++ b/README.md @@ -97,10 +97,11 @@ As a file `/etc/cron.d/sfdupes`: `SFDUPES_DATABASE=/path/to/db.sqlite` before the command on the same line. - `scan` writes nothing to stdout. Its stderr, appended here to `/var/log/sfdupes.log`, holds a first line naming the database (see - "Database"), a plain progress line as each phase starts and then at most every - 5 seconds, a warning for each path it skips, and the summary line (see - "Progress" and "`scan` mode"). The log grows with every scan; rotate it like - any other. + "Database"), plain progress lines naming each phase and its place among the + five, as `[2/5] walk` (one as the phase starts, one every 5 seconds while it + runs, and one as it ends), a warning for each path it skips, and the summary + line (see "Progress" and "`scan` mode"). The log grows with every scan; rotate + it like any other. - Skipped paths do not fail a scan: it still exits 0, and cron sends nothing. A scan that fails, or is stopped by `SIGINT` or `SIGTERM`, exits 1 with the reason among the last lines of the log; `tail` prints them, and cron mails @@ -492,10 +493,15 @@ operands: schedule into the same database. Records below an operand at or inside such a directory are not kept this way, since that operand's own walk verifies them. -`scan` runs **four sequential phases over the whole scan**. Parallelism lives -inside each phase; batched database writes begin during the hash phase: +`scan` runs **five sequential phases over the whole scan**. Parallelism lives +inside the walk, hash and content phases; batched database writes begin during +the hash phase: -1. **walk + stat** — enumerate the trees under all `PATH` operands concurrently +1. **load** — read the existing records. Each record under the operands is kept + in memory, by path, with its size, its mtime and whether it has hashes, for + the walk to compare each file with; the size of every other record joins the + size census. +2. **walk + stat** — enumerate the trees under all `PATH` operands concurrently with the walk worker pool: every operand seeds the shared queue, and each worker reads one directory at a time, handing discovered subdirectories back to the queue and running `lstat` on each regular file as it is discovered @@ -505,7 +511,7 @@ inside each phase; batched database writes begin during the hash phase: or busy pools. The walk builds the size census and resolves unchanged already-hashed files on the fly; every other file is carried to the hash phase as a (path, size, mtime) record. -2. **hash** — with the census complete, each carried file's size decides its +3. **hash** — with the census complete, each carried file's size decides its fate. Size-unique files are never read: new or changed ones are recorded without hashes in the update phase, unchanged unhashed ones simply keep their records. Every file with a shared size is hashed by the worker pool as @@ -521,10 +527,10 @@ inside each phase; batched database writes begin during the hash phase: **while hashing runs**, so a scan interrupted after hours keeps everything hashed so far and the next scan resumes cheaply, skipping records already written. -3. **update** — commit the final partial batch, the hash-less records for +4. **update** — commit the final partial batch, the hash-less records for size-unique new and changed files, and the deletions for records the scan did not verify (vanished files, plus paths that failed to stat or hash). -4. **content** — find every record of 10 MiB or more without a `content` hash +5. **content** — find every record of 10 MiB or more without a `content` hash whose size, `head`, and `tail` equal another record's, anywhere in the database: records from this scan and records stored by earlier scans, inside or outside the scanned operands. SQLite finds them, so only the records to @@ -578,8 +584,9 @@ files. `--workers` must be at least 1: a smaller value is a usage error, reported in one line on stderr with exit 2 before anything is scanned. All three phases are seek-bound on spinning disks, so raising `--workers` well past the core count can help on pools with many spindles. The main goroutine owns -partitioning, database writes, and progress rendering; progress display must -never block the workers. +partitioning, database writes, and the progress counts, which each progress +display draws from a goroutine of its own; progress display must never block the +workers. `scan` writes nothing to stdout. The summary line on stderr reports the files seen this run broken down by disposition, plus skips: @@ -711,40 +718,56 @@ units. Use the progress-bar library for all scan progress; rendering in the style of `pv` is the model. All progress goes to stderr. -Each phase gets its own display, rendered the moment the phase starts — a scan -must never look hung. Loading the existing-record index (`load`) and the walk -have no known totals while running: show a live count, rate, and elapsed time -(spinner-style, no percentage or ETA). The content phase's display (`content`) -starts the same way, counting the records checked while SQLite finds the files -to read and `lstat` checks them, then shows a bar once reading starts. The hash -and update phases, and the content phase's reads, have exact totals — only files -that actually need hashing appear in the hash and content totals, so their ETAs -are meaningful. Required elements for the bars with known totals: +A scan must always show that it is working and not hung. Each phase gets its own +display from the moment it starts, naming the phase and its place among the five +(`[1/5] load`, `[2/5] walk`, `[3/5] hash`, `[4/5] update`, `[5/5] content`) and +showing its progress, its elapsed time and its estimated time remaining (ETA): -- elapsed time -- estimated time remaining -- a `[m/n] x%` display (items processed / total items, percent) +- `load` counts the records first, then reads them against that count. While the + count runs, the display says it is counting the records. +- `walk` has no exact total. Its estimate is the number of records the last scan + left under the operands, known once `load` is done and shown with a `~`. Once + the walk passes the estimate, or when there are no such records, as on a first + scan, the ETA is unknown. +- `hash` and `update` have exact totals. Only files that actually need hashing + appear in the hash total, so its ETA is meaningful. +- `content` counts the records whose files it checks with `lstat`, saying it is + searching the database while SQLite finds them, then checks them against that + count. The files to read then get a display of their own, with their count as + its total. + +Each display is one line holding: + +- the phase and its place among the phases +- 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) +- elapsed time +- estimated time remaining, or `unknown` Example shape (exact layout is flexible, content is not): ``` -hash: [12345/98765] 12% |████ | 92 files/s elapsed 2:32 eta 17:54 +[3/5] hash: [12345/98765] 12%, 92 files/s, elapsed 2m32s, eta 17m54s +[2/5] walk: [1234567/~1200000] 103%, 5120 files/s, elapsed 4m1s, eta unknown ``` Additional requirements: +- On a terminal the progress-bar library draws the line behind a spinner, and + draws it again several times a second, so the elapsed time and ETA stay + current while a phase waits for its next item. - When stderr is not a terminal (a pipe, a file, `/dev/null`), do not emit ANSI - redraws: print a plain one-line progress update the moment each phase starts, - then no more often than every 5 seconds. -- Progress updates are driven from the main goroutine and must be non-blocking - with respect to the worker pool. On a terminal the spinner-style displays also - redraw on their own several times a second, so their count and elapsed time - stay current while a phase waits for its next item. + 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 + more as the phase ends. +- Progress must be non-blocking with respect to the worker pool: the main + goroutine counts the items, and each display draws them from a goroutine of + its own. - A warning printed during a phase always lands on a line of its own, never inside the progress display. -- A bar whose phase stops short of its total, as an interrupted one does, is - left as last drawn rather than filled up. +- A phase that stops short of its total, as an interrupted one does, is left + showing the count it stopped at rather than filled up. - `report` and `trees` modes need no progress display, only their stderr summaries. diff --git a/TODO.md b/TODO.md index 0c6ab0c..45fb6fc 100644 --- a/TODO.md +++ b/TODO.md @@ -29,6 +29,15 @@ # Completed Steps +- each `scan` phase's progress display names the phase and its place among the + five, as `[2/5] walk`, from the moment it starts, with its progress, elapsed + time and ETA: `load` counts the records first, the walk's total is estimated + from the records under the operands, and the content phase says it is + searching the database before it checks the files it found against their + count. On a terminal the line is drawn again several times a second; in plain + mode it is printed every 5 seconds whether or not an item completed + (2026-10-16, https://git.eeqj.de/sneak/sfdupes/issues/112) + - `scan`, `report` and `trees` first print a line on stderr naming the database they use, as an absolute path, and whether that path is the default or comes from `SFDUPES_DATABASE`; `scan` says when the database is new. README diff --git a/db.go b/db.go index ca84961..21f9bde 100644 --- a/db.go +++ b/db.go @@ -514,6 +514,18 @@ func loadDupeRows(ctx context.Context, db *sql.DB, return records, nil } +// countRecords returns the number of records in the database. +func countRecords(ctx context.Context, db *sql.DB) (int64, error) { + var n int64 + + err := db.QueryRowContext(ctx, "SELECT COUNT(*) FROM files").Scan(&n) + if err != nil { + return 0, fmt.Errorf("count records: %w", err) + } + + return n, nil +} + // loadFileMeta streams every record's path, size, mtime, and whether // it carries hashes to fn. Scan change detection needs no hash // values, and skipping the hash columns keeps the scan's in-memory @@ -572,6 +584,20 @@ JOIN ( ORDER BY size, head, tail ` +// countContentCandidates returns the number of rows of +// contentCandidatesSQL. +func countContentCandidates(ctx context.Context, db *sql.DB) (int64, error) { + var n int64 + + err := db.QueryRowContext(ctx, + "SELECT COUNT(*) FROM ("+contentCandidatesSQL+")", headTailMin).Scan(&n) + if err != nil { + return 0, fmt.Errorf("count records: %w", err) + } + + return n, nil +} + // loadContentCandidates streams the rows of contentCandidatesSQL to fn: // each record, without its content hash, and whether it has one. func loadContentCandidates(ctx context.Context, db *sql.DB, diff --git a/db_test.go b/db_test.go index 5c16b96..72ead79 100644 --- a/db_test.go +++ b/db_test.go @@ -309,8 +309,10 @@ func TestApplyChangesRoundTrip(t *testing.T) { }, } - err := applyChanges(t.Context(), db, recs, nil, - newProgress("update", 2)) + prog := newProgress(progressParams{label: "update", total: 4}) + defer prog.finish() + + err := applyChanges(t.Context(), db, recs, nil, prog) if err != nil { t.Fatalf("applyChanges: %v", err) } @@ -329,7 +331,7 @@ func TestApplyChangesRoundTrip(t *testing.T) { } err = applyChanges(t.Context(), db, []scanRec{upd}, - []string{"/a/tab\tnew\nline"}, newProgress("update", 2)) + []string{"/a/tab\tnew\nline"}, prog) if err != nil { t.Fatalf("applyChanges: %v", err) } @@ -357,8 +359,10 @@ func TestApplyChangesBatching(t *testing.T) { }) } - err := applyChanges(t.Context(), db, recs, nil, - newProgress("update", int64(n))) + prog := newProgress(progressParams{label: "update", total: int64(2 * n)}) + defer prog.finish() + + err := applyChanges(t.Context(), db, recs, nil, prog) if err != nil { t.Fatalf("applyChanges: %v", err) } @@ -372,8 +376,7 @@ func TestApplyChangesBatching(t *testing.T) { deletes = append(deletes, r.path) } - err = applyChanges(t.Context(), db, nil, deletes, - newProgress("update", int64(n))) + err = applyChanges(t.Context(), db, nil, deletes, prog) if err != nil { t.Fatalf("applyChanges deletes: %v", err) } diff --git a/progress.go b/progress.go index 79b05bb..a16875a 100644 --- a/progress.go +++ b/progress.go @@ -3,22 +3,24 @@ package main import ( "fmt" "os" + "slices" + "sync" "time" "github.com/schollz/progressbar/v3" "golang.org/x/term" ) -// plainInterval is the minimum time between progress lines when stderr -// is not a TTY. +// plainInterval is the time between progress lines while a phase runs, +// when stderr is not a TTY. const plainInterval = 5 * time.Second -// barThrottle caps how often the TTY progress bar redraws. -const barThrottle = 100 * time.Millisecond +// redrawInterval is the time between redraws of the progress display on +// a TTY. +const redrawInterval = 100 * time.Millisecond -// walkSpinnerType selects the progressbar library's spinner style used -// for the walk pass, which has no known total. -const walkSpinnerType = 14 +// spinnerType selects the progressbar library's spinner style. +const spinnerType = 14 // percentScale converts a fraction to a percentage. const percentScale = 100 @@ -28,96 +30,153 @@ func stderrIsTTY() bool { return term.IsTerminal(int(os.Stderr.Fd())) } -// progress renders one scan pass's progress on stderr. On a TTY it -// delegates to the progressbar library (spinner style when the total is -// unknown, full bar with count/percent/rate/elapsed/ETA otherwise). When -// stderr is not a TTY it emits no ANSI redraws: it prints a plain -// one-line update as the pass starts, then no more often than every -// plainInterval. -// -// All methods must be called from the main goroutine only. On a TTY -// the library also redraws a spinner from its own goroutine, several -// times a second, so its count and elapsed time stay current while a -// pass waits for its next item. A nil *progress is a valid -// no-display receiver: every method is a no-op, so batched database -// flushes during the streaming pass can reuse the update-pass helpers -// without rendering anything. -type progress struct { - label string - total int64 // -1 when unknown (walk pass) - bar *progressbar.ProgressBar - count int64 - start time.Time - last time.Time +// phaseLabel names phase with its place among phases, as "[2/5] walk". +func phaseLabel(phases []string, phase string) string { + return fmt.Sprintf("[%d/%d] %s", + slices.Index(phases, phase)+1, len(phases), phase) } -func newProgress(label string, total int64) *progress { - p := &progress{label: label, total: total, start: time.Now()} - if stderrIsTTY() { - p.bar = newBar(label, total) +// progressParams describe one phase's progress display as it starts. +type progressParams struct { + label string // the phase and its place, from phaseLabel + 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 +} - return p +// progress renders one phase's progress on stderr as one line (see +// line): the phase and its place among the phases, the items done out +// of the total, the rate, the elapsed time and the estimated time +// remaining. On a TTY the progressbar library draws the line behind a +// spinner, again every redrawInterval. When stderr is not a TTY it +// emits no ANSI redraws: it prints the line as the phase starts, every +// plainInterval while it runs, and as it ends. Either way the display +// shows the phase is alive while it waits for its next item. +// +// The redraws come from a goroutine of their own, so mu guards what +// they read. Every method must be called from the main goroutine. A +// nil *progress is a valid no-display receiver: every method is a +// no-op, so batched database flushes during the hash phase can reuse +// the update phase's helpers without rendering anything. +type progress struct { + bar *progressbar.ProgressBar // nil when stderr is not a TTY + stop chan struct{} // closed by finish to end the redraws + done chan struct{} // closed once the redraws have ended + + mu sync.Mutex + label string + total int64 + estimate bool + waitingFor string + count int64 + start time.Time // when the phase started, for the elapsed time + rateStart time.Time // when the count started, for the rate +} + +// newProgress starts the display of one phase on stderr. +func newProgress(params progressParams) *progress { + if stderrIsTTY() { + return startProgress(params, newSpinner(), redrawInterval) } - // Print the zero state at once: the first item may take minutes, - // and a pass must never look hung. - p.last = p.start - fmt.Fprintln(os.Stderr, p.plainLine()) + return startProgress(params, nil, plainInterval) +} + +// startProgress shows the phase params describes at once, on bar, or as +// a plain line when bar is nil, and again every interval until finish. +func startProgress(params progressParams, bar *progressbar.ProgressBar, + interval time.Duration, +) *progress { + now := time.Now() + p := &progress{ + bar: bar, stop: make(chan struct{}), done: make(chan struct{}), + label: params.label, total: params.total, estimate: params.estimate, + waitingFor: params.waitingFor, start: now, rateStart: now, + } + + // Show the zero state at once: the first item may take minutes, + // and a phase must never look hung. + p.draw() + + go func() { + defer close(p.done) + + ticker := time.NewTicker(interval) + defer ticker.Stop() + + for { + select { + case <-p.stop: + return + case <-ticker.C: + p.draw() + } + } + }() return p } -// newBar builds the TTY display for newProgress. -func newBar(label string, total int64) *progressbar.ProgressBar { - opts := []progressbar.Option{ +// newSpinner builds the TTY display for newProgress: the library's +// spinner, followed by the text draw gives it. +func newSpinner() *progressbar.ProgressBar { + return progressbar.NewOptions64(-1, progressbar.OptionSetWriter(os.Stderr), - progressbar.OptionSetDescription(label), - progressbar.OptionShowCount(), - progressbar.OptionShowIts(), - progressbar.OptionSetItsString("files"), - progressbar.OptionSetElapsedTime(true), - progressbar.OptionThrottle(barThrottle), - // Render at zero immediately: a phase must be visible the - // moment it starts, even before its first item completes. - progressbar.OptionSetRenderBlankState(true), - } - if total >= 0 { - opts = append(opts, - progressbar.OptionSetPredictTime(true), - progressbar.OptionShowElapsedTimeOnFinish(), - ) - } else { - opts = append(opts, - progressbar.OptionSetPredictTime(false), - progressbar.OptionSpinnerType(walkSpinnerType), - ) - } - - return progressbar.NewOptions64(total, opts...) + progressbar.OptionSpinnerType(spinnerType), + // The spinner turns at each draw, not on a timer of the + // library's own. + progressbar.OptionSetSpinnerChangeInterval(0), + // The text carries the elapsed time. + progressbar.OptionSetElapsedTime(false), + ) } -// increment records one completed item and refreshes the display. +// draw shows the phase's line: on a TTY in place of the one before, and +// otherwise as a plain line. +func (p *progress) draw() { + p.mu.Lock() + defer p.mu.Unlock() + + if p.bar == nil { + fmt.Fprintln(os.Stderr, p.line()) + + return + } + + p.bar.Describe(p.line()) +} + +// 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. +func (p *progress) setTotal(total int64) { + if p == nil { + return + } + + p.mu.Lock() + defer p.mu.Unlock() + + p.total = total + p.rateStart = time.Now() +} + +// increment records one completed item, which the display shows at its +// next draw. func (p *progress) increment() { if p == nil { return } + p.mu.Lock() + defer p.mu.Unlock() + p.count++ - if p.bar != nil { - _ = p.bar.Add(1) - - return - } - - if time.Since(p.last) >= plainInterval { - p.last = time.Now() - fmt.Fprintln(os.Stderr, p.plainLine()) - } } -// warnf prints a one-line warning to stderr without corrupting the bar. -// The whole message is escaped like a report's path columns, so a path -// holding a newline cannot split the warning. +// warnf prints a one-line warning to stderr without corrupting the +// display. The whole message is escaped like a report's path columns, +// so a path holding a newline cannot split the warning. func (p *progress) warnf(format string, args ...any) { if p == nil { return @@ -125,78 +184,98 @@ func (p *progress) warnf(format string, args ...any) { msg := escapePath(fmt.Sprintf(format, args...)) - if p.bar != nil && p.total < 0 { - // The library also redraws a spinner from its own goroutine, so - // a direct write could land inside a redraw. The bar prints the - // warning itself, just before its next redraw. - _, _ = progressbar.Bprintln(p.bar, msg) + p.mu.Lock() + defer p.mu.Unlock() + + if p.bar == nil { + fmt.Fprintln(os.Stderr, msg) return } - if p.bar != nil { - _ = p.bar.Clear() - } - - fmt.Fprintln(os.Stderr, msg) - - // The library never draws a finished bar again, so the warning for - // a pass's last item would erase it for good: draw its last frame - // again below the warning. - if p.bar != nil && p.bar.IsFinished() { - fmt.Fprint(os.Stderr, p.bar.String()) - } + // A direct write could land inside the line on the TTY. The bar + // prints the warning on a line of its own, just before its next + // draw. + _, _ = progressbar.Bprintln(p.bar, msg) } -// finish terminates the pass's display. A bar whose pass stopped short -// of its total, as an interrupted one does, is left as last drawn; the -// library's Finish would fill it up. +// finish ends the phase's display with its line as the phase ends. A +// phase stopped short of its total, as an interrupted one is, shows the +// count it stopped at. func (p *progress) finish() { if p == nil { return } + close(p.stop) + <-p.done + + p.draw() + if p.bar != nil { - if p.total >= 0 && p.count < p.total { - _ = p.bar.Exit() - } else { - _ = p.bar.Finish() - } + // Finish draws the line once more, below any warning it holds, + // and leaves it on the TTY. + _ = p.bar.Finish() fmt.Fprintln(os.Stderr) - - return } - - fmt.Fprintln(os.Stderr, p.plainLine()) } -// plainLine formats a non-TTY progress line. -func (p *progress) plainLine() string { - elapsed := time.Since(p.start) - if p.total < 0 { - return fmt.Sprintf("%s: %d files, elapsed %s", - p.label, p.count, elapsed.Round(time.Second)) - } +// line formats the phase's progress, as +// +// [3/5] hash: [1234/5000] 25%, 300 files/s, elapsed 4s, eta 13s +// +// with "~" before a total that is an estimate. A phase with no total +// shows the items done instead, or what it waits for. p.mu must be +// held. +func (p *progress) line() string { + elapsed := time.Since(p.start).Round(time.Second) - pct := float64(percentScale) - if p.total > 0 { - pct = percentScale * float64(p.count) / float64(p.total) + if p.total < 0 && p.waitingFor != "" { + return fmt.Sprintf("%s: %s, elapsed %s, eta unknown", + p.label, p.waitingFor, elapsed) } rate := 0.0 - if s := elapsed.Seconds(); s > 0 { + if s := time.Since(p.rateStart).Seconds(); s > 0 { rate = float64(p.count) / s } - eta := "?" + done := fmt.Sprintf("%d files", p.count) - if rate > 0 && p.count <= p.total { - remaining := time.Duration(float64(p.total-p.count) / rate * float64(time.Second)) - eta = remaining.Round(time.Second).String() + if p.total >= 0 { + approx := "" + if p.estimate { + approx = "~" + } + + pct := float64(percentScale) + if p.total > 0 { + pct = percentScale * float64(p.count) / float64(p.total) + } + + done = fmt.Sprintf("[%d/%s%d] %.0f%%", p.count, approx, p.total, pct) } - return fmt.Sprintf("%s: [%d/%d] %.0f%% %.0f files/s elapsed %s eta %s", - p.label, p.count, p.total, pct, rate, - elapsed.Round(time.Second), eta) + return fmt.Sprintf("%s: %s, %.0f files/s, elapsed %s, eta %s", + p.label, done, rate, elapsed, p.eta(rate)) +} + +// eta returns the time the phase has left at rate items a second, or +// "unknown": with no total, before the first item, and once the count +// passes an estimate. p.mu must be held. +func (p *progress) eta(rate float64) string { + switch { + case p.total < 0, p.estimate && p.count > p.total: + return "unknown" + case p.count >= p.total: + return "0s" + case rate <= 0: + return "unknown" + } + + remaining := time.Duration( + float64(p.total-p.count) / rate * float64(time.Second)) + + return remaining.Round(time.Second).String() } diff --git a/progress_test.go b/progress_test.go index 453fa94..7cd9182 100644 --- a/progress_test.go +++ b/progress_test.go @@ -8,9 +8,13 @@ import ( "time" ) -// spinnerIdle comfortably outlasts the 100ms interval at which the -// progressbar library redraws a spinner from its own goroutine. -const spinnerIdle = 500 * time.Millisecond +// testRedraw is the redraw interval the tests give a display, so that +// many redraws fit in a few milliseconds. +const testRedraw = time.Millisecond + +// testDeadline bounds how long a test waits for a display to draw what +// it expects. +const testDeadline = 5 * time.Second //nolint:paralleltest // replaces the process-wide os.Stderr func TestStderrIsTTYFalseForNonTerminals(t *testing.T) { @@ -54,59 +58,217 @@ func TestStderrIsTTYFalseForNonTerminals(t *testing.T) { } } -// TestNewProgressPrintsBeforeFirstItem checks that each pass shows its -// zero state the moment it starts when stderr is not a terminal, and -// that the next line still waits for plainInterval. +func TestPhaseLabel(t *testing.T) { + t.Parallel() + + phases := []string{"load", "walk", "hash"} + if got := phaseLabel(phases, "walk"); got != "[2/3] walk" { + t.Errorf("phaseLabel = %q, want %q", got, "[2/3] walk") + } +} + +// TestProgressLine checks the line a display shows in each state, ten +// seconds into the phase. +func TestProgressLine(t *testing.T) { + t.Parallel() + + ago := time.Now().Add(-10 * time.Second) + + cases := []struct { + p *progress + want string + }{{ + p: &progress{ + label: scanPhase("load"), total: -1, + waitingFor: "counting the records", + }, + want: "[1/5] load: counting the records, elapsed 10s, eta unknown", + }, { + p: &progress{label: scanPhase("hash"), total: 100, count: 20}, + want: "[3/5] hash: [20/100] 20%, 2 files/s, elapsed 10s, eta 40s", + }, { + p: &progress{label: scanPhase("hash"), total: 100}, + want: "[3/5] hash: [0/100] 0%, 0 files/s, elapsed 10s, eta unknown", + }, { + p: &progress{label: scanPhase("update"), total: 0}, + want: "[4/5] update: [0/0] 100%, 0 files/s, elapsed 10s, eta 0s", + }, { + p: &progress{ + label: scanPhase("walk"), total: 100, estimate: true, count: 20, + }, + want: "[2/5] walk: [20/~100] 20%, 2 files/s, elapsed 10s, eta 40s", + }, { + // Past the estimate the walk cannot tell how long it has left. + p: &progress{ + label: scanPhase("walk"), total: 100, estimate: true, count: 120, + }, + want: "[2/5] walk: [120/~100] 120%, 12 files/s, elapsed 10s, " + + "eta unknown", + }, { + // A first scan's walk has no estimate. + p: &progress{label: scanPhase("walk"), total: -1, count: 20}, + want: "[2/5] walk: 20 files, 2 files/s, elapsed 10s, eta unknown", + }} + + for _, tc := range cases { + tc.p.start, tc.p.rateStart = ago, ago + + if got := tc.p.line(); got != tc.want { + t.Errorf("line = %q, want %q", got, tc.want) + } + } +} + +// TestSetTotalStartsRate checks that a phase's rate, and so its ETA, +// count from when its total became known, not from when it started +// waiting for it. +func TestSetTotalStartsRate(t *testing.T) { + t.Parallel() + + p := progress{ + label: scanPhase("load"), total: 100, count: 20, + start: time.Now().Add(-20 * time.Second), + rateStart: time.Now().Add(-10 * time.Second), + } + + want := "[1/5] load: [20/100] 20%, 2 files/s, elapsed 20s, eta 40s" + if got := p.line(); got != want { + t.Errorf("line = %q, want %q", got, want) + } +} + +// TestPlainProgressPrintsAtStartAndEnd checks that when stderr is not a +// terminal a phase prints its line the moment it starts, before its +// first item, nothing for the items it completes before plainInterval +// has passed, and its line again as it ends. // //nolint:paralleltest // captureStderr replaces the process-wide os.Stderr -func TestNewProgressPrintsBeforeFirstItem(t *testing.T) { +func TestPlainProgressPrintsAtStartAndEnd(t *testing.T) { stderr := captureStderr(t) + p := newProgress(progressParams{label: scanPhase("hash"), total: 1000}) - newProgress("walk", -1).increment() - newProgress("hash", 10).increment() + for range 1000 { + p.increment() + } - want := "walk: 0 files, elapsed 0s\n" + - "hash: [0/10] 0% 0 files/s elapsed 0s eta ?\n" - if got := stderr(); got != want { - t.Errorf("stderr = %q, want %q", got, want) + p.finish() + + lines := strings.Split(strings.TrimSuffix(stderr(), "\n"), "\n") + + want := "[3/5] hash: [0/1000] 0%, 0 files/s, elapsed 0s, eta unknown" + if len(lines) != 2 || lines[0] != want || + !strings.HasPrefix(lines[1], "[3/5] hash: [1000/1000] 100%, ") { + t.Errorf("stderr lines = %q, want %q, then the line at 1000", + lines, want) } } -// newWalkSpinner returns the walk pass's terminal display, writing to -// os.Stderr whether or not it is a terminal, and stops the library's -// redraws when the test ends. -func newWalkSpinner(t *testing.T) *progress { +// TestPlainProgressPrintsWhileWaiting checks that a phase waiting with +// no completed items still prints a line every interval. +// +//nolint:paralleltest // captureStderr replaces the process-wide os.Stderr +func TestPlainProgressPrintsWhileWaiting(t *testing.T) { + stderr := captureStderr(t) + p := startProgress(progressParams{ + label: scanPhase("load"), total: -1, + waitingFor: "counting the records", + }, nil, testRedraw) + + want := "[1/5] load: counting the records, elapsed 0s, eta unknown\n" + for deadline := time.Now().Add(testDeadline); strings.Count(stderr(), + want) < 3 && time.Now().Before(deadline); { + time.Sleep(testRedraw) + } + + p.finish() + + if got := stderr(); strings.Count(got, want) < 3 { + t.Errorf("stderr = %q, want %q at least three times", got, 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. +func lastFrame(out string) string { + var shown string + + for frame := range strings.SplitSeq(out, "\r") { + if strings.TrimSpace(frame) != "" { + shown = frame + } + } + + return shown +} + +// awaitFrame waits until the last frame a terminal display drew to +// stderr shows want, and fails the test if it never does. +func awaitFrame(t *testing.T, stderr func() string, want string) { t.Helper() - p := &progress{ - label: "walk", total: -1, start: time.Now(), - bar: newBar("walk", -1), + for deadline := time.Now().Add(testDeadline); !strings.Contains( + lastFrame(stderr()), want); time.Sleep(testRedraw) { + if time.Now().After(deadline) { + t.Fatalf("terminal shows %q, want %q", lastFrame(stderr()), want) + } } - t.Cleanup(p.finish) - - return p } -// TestProgressWarningsOnOwnLines drives the terminal display of the walk -// pass through a run of warnings with no items between them, as when the -// walk meets many unreadable paths, for several of the spinner's -// redraws: every warning must land on a line of its own, never inside a -// redraw. +// TestTerminalRedrawsWhileWaiting checks that the terminal display of a +// phase, with a total or without, keeps showing the elapsed time while +// the phase waits for its next item, and shows every item completed +// before the wait. +// +//nolint:paralleltest // captureStderr replaces the process-wide os.Stderr +func TestTerminalRedrawsWhileWaiting(t *testing.T) { + stderr := captureStderr(t) + + counts := map[int64]string{-1: "50 files", 100: "[50/100]"} + + for total, count := range counts { + p := startProgress(progressParams{ + label: scanPhase("hash"), total: total, + }, newSpinner(), testRedraw) + + for range 50 { + p.increment() + } + + // An hour into the phase, without waiting an hour. + p.mu.Lock() + p.start = p.start.Add(-time.Hour) + p.mu.Unlock() + + awaitFrame(t, stderr, "elapsed 1h0m0s") + + if shown := lastFrame(stderr()); !strings.Contains(shown, count) { + t.Errorf("terminal shows %q, want %q", shown, count) + } + + p.finish() + } +} + +// TestProgressWarningsOnOwnLines drives the terminal display through a +// run of warnings with no items between them, as when the walk meets +// many unreadable paths, for many redraws: every warning must land on a +// line of its own, never inside a redraw. // //nolint:paralleltest // captureStderr replaces the process-wide os.Stderr func TestProgressWarningsOnOwnLines(t *testing.T) { stderr := captureStderr(t) - p := newWalkSpinner(t) + p := startProgress(progressParams{label: scanPhase("walk"), total: -1}, + newSpinner(), testRedraw) // No pause between warnings: one written straight to stderr is // garbled only if a redraw lands while it is being written. issued := 0 - for start := time.Now(); time.Since(start) < spinnerIdle; issued++ { + for start := time.Now(); time.Since(start) < 50*testRedraw; issued++ { p.warnf("warning") } - // The spinner prints the warnings at its next redraw. - time.Sleep(spinnerIdle) + p.finish() // A terminal shows each line as the text after its last carriage // return. @@ -129,83 +291,41 @@ func TestProgressWarningsOnOwnLines(t *testing.T) { } } -// TestSpinnerShowsCountAfterBurst checks that once a burst of items -// faster than the redraw limit is over, the walk display shows every -// item completed while it waits for the next one. +// TestTerminalStoppedShortKeepsCount checks that the terminal display +// of a phase that stops before its total, as an interrupted one does, +// is left showing the count it stopped at. // //nolint:paralleltest // captureStderr replaces the process-wide os.Stderr -func TestSpinnerShowsCountAfterBurst(t *testing.T) { +func TestTerminalStoppedShortKeepsCount(t *testing.T) { stderr := captureStderr(t) - p := newWalkSpinner(t) - - for range 50 { - p.increment() - } - - time.Sleep(spinnerIdle) - - if shown := lastFrame(stderr()); !strings.Contains(shown, "(50/-,") { - t.Errorf("terminal shows %q, want a count of 50", shown) - } -} - -// lastFrame returns what a terminal shows of the frames a bar drew: the -// last one. The library starts each frame with a carriage return and -// erases the previous one with spaces first. -func lastFrame(out string) string { - var shown string - - for frame := range strings.SplitSeq(out, "\r") { - if strings.TrimSpace(frame) != "" { - shown = frame - } - } - - return shown -} - -// TestBarStoppedShortKeepsCount checks that the terminal display of a -// pass that stops before its total, as an interrupted one does, is left -// as last drawn instead of being filled up. -// -//nolint:paralleltest // captureStderr replaces the process-wide os.Stderr -func TestBarStoppedShortKeepsCount(t *testing.T) { - stderr := captureStderr(t) - p := &progress{ - label: "hash", total: 10, start: time.Now(), - bar: newBar("hash", 10), - } + p := startProgress(progressParams{label: scanPhase("hash"), total: 10}, + newSpinner(), redrawInterval) p.increment() - - // Past the redraw limit, so the bar draws the next count. - time.Sleep(2 * barThrottle) p.increment() p.finish() - if shown := lastFrame(stderr()); !strings.Contains(shown, "(2/10,") { + if shown := lastFrame(stderr()); !strings.Contains(shown, "[2/10]") { t.Errorf("terminal shows %q, want a count of 2 of 10", shown) } } -// TestWarningAfterLastItemKeepsBar checks that a warning printed after -// a pass's last item, as for a failed read of the last file, leaves the -// pass's finished bar on the terminal below the warning. +// TestWarningAfterLastItemKeepsLine checks that a warning printed after +// a phase's last item, as for a failed read of the last file, leaves +// the phase's last line on the terminal below the warning. // //nolint:paralleltest // captureStderr replaces the process-wide os.Stderr -func TestWarningAfterLastItemKeepsBar(t *testing.T) { +func TestWarningAfterLastItemKeepsLine(t *testing.T) { stderr := captureStderr(t) - p := &progress{ - label: "hash", total: 2, start: time.Now(), - bar: newBar("hash", 2), - } + p := startProgress(progressParams{label: scanPhase("hash"), total: 2}, + newSpinner(), redrawInterval) p.increment() p.increment() p.warnf("warning") p.finish() - if shown := lastFrame(stderr()); !strings.Contains(shown, "(2/2,") { + if shown := lastFrame(stderr()); !strings.Contains(shown, "[2/2]") { t.Errorf("terminal shows %q, want a count of 2 of 2", shown) } } diff --git a/scan.go b/scan.go index e3d33ed..f9ae719 100644 --- a/scan.go +++ b/scan.go @@ -84,18 +84,26 @@ type fileMeta struct { hashed bool } -// runScan implements the scan subcommand: four sequential phases — -// walk (which stats each file as it is discovered), hash, update, -// content — that synchronize the persistent database with the -// filesystem state under the PATH operands. Only files whose size at -// least one other file shares are ever hashed: a size-unique file -// cannot be a duplicate. A file of headTailMin or more gets its content -// hash only when its size, head, and tail match another file's. Flag -// parsing and the at-least-one-operand check are done by cobra. Before -// anything else, the scan names the database on stderr, saying whether -// it is new. The scan holds the lock on the database for its whole -// run, so a second scan fails before it walks the filesystem or opens -// 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. +func scanPhase(name string) string { + return phaseLabel( + []string{"load", "walk", "hash", "update", "content"}, name) +} + +// runScan implements the scan subcommand: five sequential phases — +// load (which reads the existing records), walk (which stats each file +// as it is discovered), hash, update, content — that synchronize the +// persistent database with the filesystem state under the PATH +// operands. Only files whose size at least one other file shares are +// ever hashed: a size-unique file cannot be a duplicate. A file of +// headTailMin or more gets its content hash only when its size, head, +// and tail match another file's. Flag parsing and the +// at-least-one-operand check are done by cobra. Before anything else, +// the scan names the database on stderr, saying whether it is new. The +// scan holds the lock on the database for its whole run, so a second +// scan fails before it walks the filesystem or opens the database. // Errors are returned rather than exiting, so that the deferred close — // which takes the database out of WAL mode — always runs, and the lock // is released after it. When ctx is cancelled, as by the SIGINT or @@ -344,18 +352,18 @@ func syncScan(ctx context.Context, db *sql.DB, roots []string, } // runPhases synchronizes the database with the filesystem under roots -// in four sequential phases: walk (enumerate and stat every file, -// building a complete size census), hash (read only the new or -// changed — or previously unhashed — files whose size at least one -// other file shares, committing results in batches as they arrive), -// update (record the size-unique files without reading them, and -// delete the records the scan no longer verifies), and content (fill -// in the content hash of every record of headTailMin or more whose -// size, head, and tail match another record's). Records outside the -// roots are never touched, except that the content phase fills in -// their content hash. Operands the walk cannot start from are dropped -// first, so the records beneath them are treated as if those operands -// had not been given. +// in five sequential phases: load (read the existing records), walk +// (enumerate and stat every file, building a complete size census), +// hash (read only the new or changed — or previously unhashed — files +// whose size at least one other file shares, committing results in +// batches as they arrive), update (record the size-unique files without +// reading them, and delete the records the scan no longer verifies), +// and content (fill in the content hash of every record of headTailMin +// or more whose size, head, and tail match another record's). Records +// outside the roots are never touched, except that the content phase +// fills in their content hash. Operands the walk cannot start from are +// dropped first, so the records beneath them are treated as if those +// operands had not been given. func (s *scanState) runPhases(ctx context.Context, roots []string, workers int, oneFS bool, ) error { @@ -430,10 +438,21 @@ func (s *scanState) walkableRoots(roots []string) []string { // separately into the same database. func (s *scanState) loadIndex(ctx context.Context, roots []string) error { // Indexing tens of millions of records takes real time; without a - // display the scan looks hung before the walk begins. - prog := newProgress("load", -1) + // display the scan looks hung before the walk begins. Counting them + // first gives the display its total. + prog := newProgress(progressParams{ + label: scanPhase("load"), total: -1, + waitingFor: "counting the records", + }) defer prog.finish() + total, err := countRecords(ctx, s.db) + if err != nil { + return err + } + + prog.setTotal(total) + s.existing = make(map[string]fileMeta) return loadFileMeta(ctx, s.db, @@ -465,7 +484,16 @@ func (s *scanState) loadIndex(ctx context.Context, roots []string) error { func (s *scanState) walkPhase( events <-chan walkEvent, roots []string, ) ([]fileRec, []fileRec) { - prog := newProgress("walk", -1) + // The records the last scan left under the roots estimate how many + // files the walk will find. A first scan has none, and no estimate. + estimate := int64(len(s.existing)) + if estimate == 0 { + estimate = -1 + } + + prog := newProgress(progressParams{ + label: scanPhase("walk"), total: estimate, estimate: true, + }) var ( changed, unhashed []fileRec @@ -636,10 +664,11 @@ func (s *scanState) hashPhase(ctx context.Context, workers int) error { } // readRuns reads runs with the worker pool, one read per inode run, in -// the order given, under a progress display named label. The workers -// compute each run's hashes with hash, and each result goes to record; -// a run that fails to read is warned about and counted as skipped -// instead. The total counts actual reads, so the bar shows a real ETA. +// the order given, under the progress display of the phase named label. +// The workers compute each run's hashes with hash, and each result goes +// to record; a run that fails to read is warned about and counted as +// skipped instead. The total counts actual reads, so the display shows +// a real ETA. // // Returning early — a failed database write, or a cancelled scan — must // not strand the pool: the feeder would park forever on a full jobs @@ -653,7 +682,9 @@ func (s *scanState) readRuns(ctx context.Context, workers int, pool := startHashPool(ctx, runs, workers, hash) defer pool.stop() - prog := newProgress(label, int64(len(runs))) + prog := newProgress(progressParams{ + label: scanPhase(label), total: int64(len(runs)), + }) defer prog.finish() for range runs { @@ -740,7 +771,9 @@ func (s *scanState) updatePhase(ctx context.Context) error { s.st.removed = len(deletes) total := len(s.batch) + len(s.sentinels) + len(deletes) - prog := newProgress("update", int64(total)) + prog := newProgress(progressParams{ + label: scanPhase("update"), total: int64(total), + }) defer prog.finish() @@ -821,11 +854,22 @@ func (s *scanState) contentPhase(ctx context.Context, workers int) error { func (s *scanState) contentCandidates( ctx context.Context, ) ([]fileRec, map[string]scanRec, error) { - // The query and the checks take real time on a large database; + // The search and the checks take real time on a large database; // without a display the scan looks hung before the reads begin. - prog := newProgress("content", -1) + // Counting what the search finds first gives the checks a total. + prog := newProgress(progressParams{ + label: scanPhase("content"), total: -1, + waitingFor: "searching the database", + }) defer prog.finish() + total, err := countContentCandidates(ctx, s.db) + if err != nil { + return nil, nil, err + } + + prog.setTotal(total) + var ( toRead []fileRec first scanRec // the current group's first record @@ -849,7 +893,7 @@ func (s *scanState) contentCandidates( passed, unread = 0, nil } - err := loadContentCandidates(ctx, s.db, func(r scanRec, hashed bool) { + err = loadContentCandidates(ctx, s.db, func(r scanRec, hashed bool) { prog.increment() if r.size != first.size || r.head != first.head || r.tail != first.tail { diff --git a/scan_test.go b/scan_test.go index 778fe64..0714e5a 100644 --- a/scan_test.go +++ b/scan_test.go @@ -1586,6 +1586,69 @@ func TestScanPipeline(t *testing.T) { assertSmokeTreeGroups(t, dir, db) } +// TestScanProgressNamesEachPhase checks the plain progress lines of a +// first scan, and of a rescan of one operand holding two of the +// database's records. Each phase's first line names it with its place +// among the five: load counts the records before reading them, the +// content phase searches the database, and the walk estimates its total +// from the records under its operand, or says its ETA is unknown when +// there are none. +// +//nolint:paralleltest // captureStderr replaces the process-wide os.Stderr +func TestScanProgressNamesEachPhase(t *testing.T) { + stderr := captureStderr(t) + dir := buildSmokeTree(t) + db := openTestDB(t) + + syncTree(t, db, dir) + + first := stderr() + + syncTree(t, db, filepath.Join(dir, "a")) + + rescan := stderr()[len(first):] + load := "[1/5] load: counting the records, elapsed 0s, eta unknown" + content := "[5/5] content: searching the database, elapsed 0s, eta unknown" + cases := map[string][]string{ + first: { + load, "[2/5] walk: 0 files, 0 files/s, elapsed 0s, eta unknown", + "[3/5] hash: [0/", "[4/5] update: [0/", content, + }, + rescan: { + load, "[2/5] walk: [0/~2] 0%, 0 files/s, elapsed 0s, eta unknown", + "[3/5] hash: [0/", "[4/5] update: [0/", content, + }, + } + + for out, want := range cases { + var got []string + + for line := range strings.Lines(out) { + label, _, _ := strings.Cut(line, ":") + if len(got) == 0 || !strings.HasPrefix(got[len(got)-1], label) { + got = append(got, line) + } + } + + if len(got) != len(want) { + t.Fatalf("first lines of the phases = %q, want %q", got, want) + } + + for i := range want { + if !strings.HasPrefix(got[i], want[i]) { + t.Errorf("phase %d starts %q, want %q", i+1, got[i], want[i]) + } + } + } + + // The load phase's total is the count of the records. + loaded := fmt.Sprintf("\n[1/5] load: [%d/%d] 100%%, ", + smokeTreeFiles, smokeTreeFiles) + if !strings.Contains(rescan, loaded) { + t.Errorf("rescan stderr = %q, want %q", rescan, loaded) + } +} + func TestSyncScanUnchangedReuse(t *testing.T) { t.Parallel()