1 Commits
Author SHA1 Message Date
clawbot a9b69e911b scan: show each phase as N of M, with progress, elapsed time and ETA, also while it waits (closes #112)
check / check (push) Waiting to run
Every scan display now names its phase and its place among the five,
as "[2/5] walk", with its progress, rate, elapsed time and ETA. load
counts the records first; the walk estimates its total from the
records under the operands; the content phase adds up the sizes of the
matching groups and says it is searching until the first record
returns. Each display is drawn from its own goroutine: several times a
second on a terminal, every 5 seconds in plain mode.

On a terminal a phase with an exact total draws its line before the
library's bar when there is room, and any other a spinner before the
line. A line too wide drops its rate, then its bar; it is cut only when
the phase, progress, elapsed time and ETA alone do not fit.

Judgement call: load and the content checks draw the bar too, once their totals are known.
Judgement call: the bar is 10 columns wide, not the width the line leaves.

Model: opus-5-5
2026-10-16 15:47:17 +00:00
8 changed files with 1051 additions and 312 deletions
+70 -33
View File
@@ -97,10 +97,11 @@ As a file `/etc/cron.d/sfdupes`:
`SFDUPES_DATABASE=/path/to/db.sqlite` before the command on the same line. `SFDUPES_DATABASE=/path/to/db.sqlite` before the command on the same line.
- `scan` writes nothing to stdout. Its stderr, appended here to - `scan` writes nothing to stdout. Its stderr, appended here to
`/var/log/sfdupes.log`, holds a first line naming the database (see `/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 "Database"), plain progress lines naming each phase and its place among the
5 seconds, a warning for each path it skips, and the summary line (see five, as `[2/5] walk` (one as the phase starts, one every 5 seconds while it
"Progress" and "`scan` mode"). The log grows with every scan; rotate it like runs, and one as it ends), a warning for each path it skips, and the summary
any other. 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 - 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 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 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 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. 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 `scan` runs **five sequential phases over the whole scan**. Parallelism lives
inside each phase; batched database writes begin during the hash phase: 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 with the walk worker pool: every operand seeds the shared queue, and each
worker reads one directory at a time, handing discovered subdirectories back 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 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 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 already-hashed files on the fly; every other file is carried to the hash
phase as a (path, size, mtime) record. 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 fate. Size-unique files are never read: new or changed ones are recorded
without hashes in the update phase, unchanged unhashed ones simply keep 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 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 **while hashing runs**, so a scan interrupted after hours keeps everything
hashed so far and the next scan resumes cheaply, skipping records already hashed so far and the next scan resumes cheaply, skipping records already
written. 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 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). 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 whose size, `head`, and `tail` equal another record's, anywhere in the
database: records from this scan and records stored by earlier scans, inside 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 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 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 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 core count can help on pools with many spindles. The main goroutine owns
partitioning, database writes, and progress rendering; progress display must partitioning, database writes, and the progress counts, which each progress
never block the workers. 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 `scan` writes nothing to stdout. The summary line on stderr reports the files
seen this run broken down by disposition, plus skips: seen this run broken down by disposition, plus skips:
@@ -711,40 +718,70 @@ units.
Use the progress-bar library for all scan progress; rendering in the style of Use the progress-bar library for all scan progress; rendering in the style of
`pv` is the model. All progress goes to stderr. `pv` is the model. All progress goes to stderr.
Each phase gets its own display, rendered the moment the phase starts — a scan A scan must always show that it is working and not hung. Each phase gets its own
must never look hung. Loading the existing-record index (`load`) and the walk display from the moment it starts, naming the phase and its place among the five
have no known totals while running: show a live count, rate, and elapsed time (`[1/5] load`, `[2/5] walk`, `[3/5] hash`, `[4/5] update`, `[5/5] content`) and
(spinner-style, no percentage or ETA). The content phase's display (`content`) showing its progress, its elapsed time and its estimated time remaining (ETA):
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:
- elapsed time - `load` counts the records first, then reads them against that count. While the
- estimated time remaining count runs, the display says it is counting the records.
- a `[m/n] x%` display (items processed / total items, percent) - `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` first counts the records whose files it checks with `lstat`, which
SQLite does by adding up the number of records with each matching size,
`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.
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) - current rate (items/s)
- elapsed time
- estimated time remaining, or `unknown`
Example shape (exact layout is flexible, content is not): 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 2:32 eta 17:54
[2/5] walk: [1234567/~1200000] 103%, 5120 files/s, elapsed 4m1s, eta unknown
``` ```
Additional requirements: Additional requirements:
- On a terminal, a phase with an exact total (every phase but `walk`, once it
has counted what it will do) is drawn as its line followed by the progress-bar
library's bar, 10 columns wide, which shows the percent in place of the line's
own. Any other phase, and a phase whose bar has no room, is drawn as the
library's spinner followed by its line. Each display is drawn again several
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.
- When stderr is not a terminal (a pipe, a file, `/dev/null`), do not emit ANSI - 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, redraws: print the line the moment each phase starts, every 5 seconds while it
then no more often than every 5 seconds. runs (whether or not an item has completed, and never more often), and once
- Progress updates are driven from the main goroutine and must be non-blocking more as the phase ends.
with respect to the worker pool. On a terminal the spinner-style displays also - Progress must be non-blocking with respect to the worker pool: the main
redraw on their own several times a second, so their count and elapsed time goroutine counts the items, and each display draws them from a goroutine of
stay current while a phase waits for its next item. its own.
- A warning printed during a phase always lands on a line of its own, never - A warning printed during a phase always lands on a line of its own, never
inside the progress display. inside the progress display.
- A bar whose phase stops short of its total, as an interrupted one does, is - A phase that stops short of its total, as an interrupted one does, is left
left as last drawn rather than filled up. showing the count it stopped at rather than filled up.
- `report` and `trees` modes need no progress display, only their stderr - `report` and `trees` modes need no progress display, only their stderr
summaries. summaries.
+15
View File
@@ -29,6 +29,21 @@
# Completed Steps # 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 counts the records
it checks from SQLite's grouping alone, then says it is searching the database
until the first one is returned. On a terminal a phase with an exact total
draws its line followed by the library's bar, and any other a spinner followed
by the line; every display is drawn again several times a second. No line
reaches the terminal's last column, however narrow: a line too wide leaves out
its rate, then its bar, keeping the phase, progress, elapsed time and ETA
whole, and is cut short only when those alone do not fit, as below about 70
columns late in a large scan. In plain mode the line 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 - `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 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 from `SFDUPES_DATABASE`; `scan` says when the database is new. README
+45 -13
View File
@@ -514,6 +514,18 @@ func loadDupeRows(ctx context.Context, db *sql.DB,
return records, nil 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 // loadFileMeta streams every record's path, size, mtime, and whether
// it carries hashes to fn. Scan change detection needs no hash // it carries hashes to fn. Scan change detection needs no hash
// values, and skipping the hash columns keeps the scan's in-memory // values, and skipping the hash columns keeps the scan's in-memory
@@ -552,26 +564,46 @@ func loadFileMeta(ctx context.Context, db *sql.DB,
return nil return nil
} }
// contentCandidatesSQL selects every record of at least headTailMin // contentGroupsSQL selects each group (the records sharing a size,
// bytes whose size, head, and tail equal another record's, in each // head, and tail) of records of at least headTailMin bytes that has more
// group (the records sharing a size, head, and tail) where at least one // than one record and at least one record without a content hash, with
// record has no content hash, with whether each record has one. SQLite // the number of its records.
// does the grouping, so no other record's hashes are loaded into const contentGroupsSQL = `
// memory; the rows come ordered by size, head, and tail, so each SELECT size, head, tail, COUNT(*) AS records
// group's rows arrive together.
const contentCandidatesSQL = `
SELECT f.path, f.size, f.mtime, f.mtime_nsec, f.head, f.tail, f.content <> ''
FROM files AS f
JOIN (
SELECT size, head, tail
FROM files FROM files
WHERE size >= ? AND head <> '' WHERE size >= ? AND head <> ''
GROUP BY size, head, tail GROUP BY size, head, tail
HAVING COUNT(*) > 1 AND SUM(content = '') > 0 HAVING COUNT(*) > 1 AND SUM(content = '') > 0
) AS g USING (size, head, tail) `
// contentCandidatesSQL selects every record of the groups
// contentGroupsSQL selects, with whether each record has a content
// hash. SQLite does the grouping, so no other record's hashes are
// loaded into memory; the rows come ordered by size, head, and tail, so
// each group's rows arrive together.
const contentCandidatesSQL = `
SELECT f.path, f.size, f.mtime, f.mtime_nsec, f.head, f.tail, f.content <> ''
FROM files AS f
JOIN (` + contentGroupsSQL + `) AS g USING (size, head, tail)
ORDER BY size, head, tail ORDER BY size, head, tail
` `
// countContentCandidates returns the number of rows of
// contentCandidatesSQL, adding up the records of the groups
// contentGroupsSQL selects, so it neither joins nor sorts.
func countContentCandidates(ctx context.Context, db *sql.DB) (int64, error) {
var n int64
err := db.QueryRowContext(ctx,
"SELECT COALESCE(SUM(records), 0) FROM ("+contentGroupsSQL+")",
headTailMin).Scan(&n)
if err != nil {
return 0, fmt.Errorf("count content candidates: %w", err)
}
return n, nil
}
// loadContentCandidates streams the rows of contentCandidatesSQL to fn: // loadContentCandidates streams the rows of contentCandidatesSQL to fn:
// each record, without its content hash, and whether it has one. // each record, without its content hash, and whether it has one.
func loadContentCandidates(ctx context.Context, db *sql.DB, func loadContentCandidates(ctx context.Context, db *sql.DB,
+69 -7
View File
@@ -309,8 +309,10 @@ func TestApplyChangesRoundTrip(t *testing.T) {
}, },
} }
err := applyChanges(t.Context(), db, recs, nil, prog := newProgress(progressParams{label: "update", total: 4})
newProgress("update", 2)) defer prog.finish()
err := applyChanges(t.Context(), db, recs, nil, prog)
if err != nil { if err != nil {
t.Fatalf("applyChanges: %v", err) t.Fatalf("applyChanges: %v", err)
} }
@@ -329,7 +331,7 @@ func TestApplyChangesRoundTrip(t *testing.T) {
} }
err = applyChanges(t.Context(), db, []scanRec{upd}, err = applyChanges(t.Context(), db, []scanRec{upd},
[]string{"/a/tab\tnew\nline"}, newProgress("update", 2)) []string{"/a/tab\tnew\nline"}, prog)
if err != nil { if err != nil {
t.Fatalf("applyChanges: %v", err) t.Fatalf("applyChanges: %v", err)
} }
@@ -357,8 +359,10 @@ func TestApplyChangesBatching(t *testing.T) {
}) })
} }
err := applyChanges(t.Context(), db, recs, nil, prog := newProgress(progressParams{label: "update", total: int64(2 * n)})
newProgress("update", int64(n))) defer prog.finish()
err := applyChanges(t.Context(), db, recs, nil, prog)
if err != nil { if err != nil {
t.Fatalf("applyChanges: %v", err) t.Fatalf("applyChanges: %v", err)
} }
@@ -372,8 +376,7 @@ func TestApplyChangesBatching(t *testing.T) {
deletes = append(deletes, r.path) deletes = append(deletes, r.path)
} }
err = applyChanges(t.Context(), db, nil, deletes, err = applyChanges(t.Context(), db, nil, deletes, prog)
newProgress("update", int64(n)))
if err != nil { if err != nil {
t.Fatalf("applyChanges deletes: %v", err) t.Fatalf("applyChanges deletes: %v", err)
} }
@@ -382,3 +385,62 @@ func TestApplyChangesBatching(t *testing.T) {
t.Fatalf("records = %d, want 0", len(got)) t.Fatalf("records = %d, want 0", len(got))
} }
} }
// TestCountContentCandidates checks that countContentCandidates counts
// the records the content phase's search returns: those of each group
// of two or more records of headTailMin or more with a head, where at
// least one has no content hash.
func TestCountContentCandidates(t *testing.T) {
t.Parallel()
db := openTestDB(t)
// Each group's records: size, head, and content, one per record.
groups := []struct {
size int64
head string
contents []string
}{
{headTailMin, "h", []string{"", "c", "c"}}, // returned
{headTailMin + 1, "h", []string{"", ""}}, // returned
{headTailMin + 2, "h", []string{"c", "c"}}, // all hashed
{headTailMin + 3, "h", []string{""}}, // one record
{headTailMin - 1, "h", []string{"", ""}}, // too small
{headTailMin + 4, "", []string{"", ""}}, // no head
}
var recs []scanRec
for _, g := range groups {
for _, content := range g.contents {
recs = append(recs, scanRec{
size: g.size, mtime: time.Unix(1, 0), head: g.head,
tail: "t", content: content,
path: fmt.Sprintf("/r/%d", len(recs)),
})
}
}
err := applyChanges(t.Context(), db, recs, nil, nil)
if err != nil {
t.Fatalf("applyChanges: %v", err)
}
got, err := countContentCandidates(t.Context(), db)
if err != nil {
t.Fatalf("countContentCandidates: %v", err)
}
var returned int64
err = loadContentCandidates(t.Context(), db,
func(scanRec, bool) { returned++ })
if err != nil {
t.Fatalf("loadContentCandidates: %v", err)
}
if got != 5 || returned != 5 {
t.Errorf("count = %d, records returned = %d, want 5 and 5",
got, returned)
}
}
+295 -111
View File
@@ -2,122 +2,258 @@ package main
import ( import (
"fmt" "fmt"
"math"
"os" "os"
"slices"
"sync"
"time" "time"
"github.com/schollz/progressbar/v3" "github.com/schollz/progressbar/v3"
"golang.org/x/term" "golang.org/x/term"
) )
// plainInterval is the minimum time between progress lines when stderr // plainInterval is the time between progress lines while a phase runs,
// is not a TTY. // when stderr is not a TTY.
const plainInterval = 5 * time.Second const plainInterval = 5 * time.Second
// barThrottle caps how often the TTY progress bar redraws. // redrawInterval is the time between redraws of the progress display on
const barThrottle = 100 * time.Millisecond // a TTY.
const redrawInterval = 100 * time.Millisecond
// walkSpinnerType selects the progressbar library's spinner style used // spinnerType selects the progressbar library's spinner style.
// for the walk pass, which has no known total. const spinnerType = 14
const walkSpinnerType = 14
// barWidth is the width of the progressbar library's bar between its
// two ends, as in the example line in README "Progress".
const barWidth = 10
// percentScale converts a fraction to a percentage. // percentScale converts a fraction to a percentage.
const percentScale = 100 const percentScale = 100
// fallbackWidth is the width taken for a terminal whose width cannot be
// read, as the progressbar library takes it.
const fallbackWidth = 80
// spinnerMargin is the columns of a spinner's line besides its text:
// the spinner and the three spaces the library draws around the text,
// and the terminal's last column, which every line stays clear of so
// that no terminal wraps it.
const spinnerMargin = 5
// barMargin is the columns of a bar's line besides its text: the
// percent and the bar the library draws after the text, the spaces
// around them, and the terminal's last column.
const barMargin = barWidth + 11
// stderrIsTTY reports whether stderr is attached to a terminal. // stderrIsTTY reports whether stderr is attached to a terminal.
func stderrIsTTY() bool { func stderrIsTTY() bool {
return term.IsTerminal(int(os.Stderr.Fd())) return term.IsTerminal(int(os.Stderr.Fd()))
} }
// progress renders one scan pass's progress on stderr. On a TTY it // terminalWidth returns the width of the terminal on stderr, or
// delegates to the progressbar library (spinner style when the total is // fallbackWidth, as the progressbar library does, when it cannot read
// unknown, full bar with count/percent/rate/elapsed/ETA otherwise). When // one.
// stderr is not a TTY it emits no ANSI redraws: it prints a plain func terminalWidth() int {
// one-line update as the pass starts, then no more often than every width, _, err := term.GetSize(int(os.Stderr.Fd()))
// plainInterval. if err != nil || width <= 0 {
return fallbackWidth
}
return width
}
// 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)
}
// 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
}
// progress renders one phase's progress on stderr. On a TTY the
// progressbar library draws line, fitted to the terminal's width: after
// the library's spinner, or, for a phase with an exact total, before the
// library's bar when the terminal has room for the bar beside it. It is
// drawn again every redrawInterval, so its elapsed time keeps moving
// while the phase waits for its next item. When stderr is not a TTY it
// emits no ANSI redraws: it prints line as the phase starts, every
// plainInterval while it runs, and as it ends.
// //
// All methods must be called from the main goroutine only. On a TTY // The draws come from a goroutine of their own, so mu guards the fields
// the library also redraws a spinner from its own goroutine, several // below it. Every method must be called from the main goroutine. A nil
// times a second, so its count and elapsed time stay current while a // *progress is a valid no-display receiver: every method is a no-op, so
// pass waits for its next item. A nil *progress is a valid // batched database flushes during the hash phase can reuse the update
// no-display receiver: every method is a no-op, so batched database // phase's helpers without rendering anything.
// flushes during the streaming pass can reuse the update-pass helpers
// without rendering anything.
type progress struct { 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
mu sync.Mutex
bar *progressbar.ProgressBar // what the library draws; nil until then
withBar bool // bar is the library's bar, not its spinner
label string label string
total int64 // -1 when unknown (walk pass) total int64
bar *progressbar.ProgressBar estimate bool
waitingFor string
count int64 count int64
start time.Time start time.Time // when the phase started, for the elapsed time
last time.Time rateStart time.Time // when the count started, for the rate
} }
func newProgress(label string, total int64) *progress { // newProgress starts the display of one phase on stderr.
p := &progress{label: label, total: total, start: time.Now()} func newProgress(params progressParams) *progress {
if stderrIsTTY() { if stderrIsTTY() {
p.bar = newBar(label, total) return startProgress(params, terminalWidth, redrawInterval)
}
return startProgress(params, nil, plainInterval)
}
// 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.
func startProgress(params progressParams, width func() int,
interval time.Duration,
) *progress {
now := time.Now()
p := &progress{
width: width, 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 return p
} }
// Print the zero state at once: the first item may take minutes, // draw shows the phase's progress: on a TTY in place of the line
// and a pass must never look hung. // before, and otherwise as a plain line.
p.last = p.start func (p *progress) draw() {
fmt.Fprintln(os.Stderr, p.plainLine()) p.mu.Lock()
defer p.mu.Unlock()
return p if p.width == nil {
text, _ := p.line(math.MaxInt, true)
fmt.Fprintln(os.Stderr, text)
return
} }
// newBar builds the TTY display for newProgress. width := p.width()
func newBar(label string, total int64) *progressbar.ProgressBar {
opts := []progressbar.Option{ // 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.
text, withBar := "", false
if p.total > 0 && !p.estimate {
text, withBar = p.line(width-barMargin, false)
}
if !withBar {
text, _ = p.line(width-spinnerMargin, true)
}
// The library makes a bar or a spinner. A display that turns from
// one to the other, as its line grows or the terminal is resized,
// gets a new one.
if p.bar == nil || p.withBar != withBar {
p.newBar(withBar)
}
if withBar {
_ = p.bar.Set64(p.count)
}
p.bar.Describe(text)
}
// newBar has the library make what draw draws: a bar for the phase's
// total when withBar is set, and a spinner when not. Either shows the
// text draw gives it, and nothing of its own besides the spinner, or
// the bar and its percent. p.mu must be held.
func (p *progress) newBar(withBar bool) {
if p.bar != nil {
// Erase what was drawn before.
_ = p.bar.Clear()
}
total := int64(-1) // the library's spinner
if withBar {
total = p.total
}
p.bar = progressbar.NewOptions64(total,
progressbar.OptionSetWriter(os.Stderr), progressbar.OptionSetWriter(os.Stderr),
progressbar.OptionSetDescription(label), progressbar.OptionSetWidth(barWidth),
progressbar.OptionShowCount(), progressbar.OptionSpinnerType(spinnerType),
progressbar.OptionShowIts(), // The spinner turns at each draw, not on a timer of the
progressbar.OptionSetItsString("files"), // library's own.
progressbar.OptionSetElapsedTime(true), progressbar.OptionSetSpinnerChangeInterval(0),
progressbar.OptionThrottle(barThrottle), // The text carries the elapsed time and the ETA.
// Render at zero immediately: a phase must be visible the progressbar.OptionSetElapsedTime(false),
// 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.OptionSetPredictTime(false),
progressbar.OptionSpinnerType(walkSpinnerType),
) )
p.withBar = withBar
} }
return progressbar.NewOptions64(total, opts...) // 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
} }
// increment records one completed item and refreshes the display. 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() { func (p *progress) increment() {
if p == nil { if p == nil {
return return
} }
p.mu.Lock()
defer p.mu.Unlock()
p.count++ p.count++
if p.bar != nil {
_ = p.bar.Add(1)
return
} }
if time.Since(p.last) >= plainInterval { // warnf prints a one-line warning to stderr without corrupting the
p.last = time.Now() // display. The whole message is escaped like a report's path columns,
fmt.Fprintln(os.Stderr, p.plainLine()) // so a path holding a newline cannot split the warning.
}
}
// 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.
func (p *progress) warnf(format string, args ...any) { func (p *progress) warnf(format string, args ...any) {
if p == nil { if p == nil {
return return
@@ -125,58 +261,101 @@ func (p *progress) warnf(format string, args ...any) {
msg := escapePath(fmt.Sprintf(format, args...)) msg := escapePath(fmt.Sprintf(format, args...))
if p.bar != nil && p.total < 0 { p.mu.Lock()
// The library also redraws a spinner from its own goroutine, so defer p.mu.Unlock()
// a direct write could land inside a redraw. The bar prints the
// warning itself, just before its next redraw.
_, _ = progressbar.Bprintln(p.bar, msg)
return
}
if p.bar != nil { if p.bar != nil {
// The warning takes the display's line; the next draw shows
// the display again, on the line below.
_ = p.bar.Clear() _ = p.bar.Clear()
} }
fmt.Fprintln(os.Stderr, msg) 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())
}
} }
// finish terminates the pass's display. A bar whose pass stopped short // finish ends the phase's display, drawn once more as the phase ends.
// of its total, as an interrupted one does, is left as last drawn; the // A phase stopped short of its total, as an interrupted one is, shows
// library's Finish would fill it up. // the count it stopped at rather than a full bar.
func (p *progress) finish() { func (p *progress) finish() {
if p == nil { if p == nil {
return return
} }
if p.bar != nil { close(p.stop)
if p.total >= 0 && p.count < p.total { <-p.done
_ = p.bar.Exit()
} else {
_ = p.bar.Finish()
}
p.draw()
if p.width != nil {
// The display stays on the TTY as drawn; what follows starts
// on a line of its own.
fmt.Fprintln(os.Stderr) fmt.Fprintln(os.Stderr)
}
return
} }
fmt.Fprintln(os.Stderr, p.plainLine()) // line formats the phase's progress in at most room columns, as
//
// [3/5] hash: [1234/5000] 25%, 300 files/s, elapsed 4s, eta 13s
//
// 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.
//
// 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)
// 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
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
} }
// plainLine formats a non-TTY progress line. head = p.label + ": " + p.itemsDone(percent) + ", "
func (p *progress) plainLine() string { extra = fmt.Sprintf("%.0f files/s", rate)
elapsed := time.Since(p.start) tail = fmt.Sprintf("elapsed %s, eta %s", elapsed, p.eta(rate))
}
full, kept := head+extra+", "+tail, head+tail
switch {
case len(full) <= room:
return full, true
case len(kept) <= room:
return kept, true
}
return kept[:max(room, 0)], false
}
// itemsDone formats the items done, as "[1234/5000] 25%", with "~"
// before a total that is an estimate and without the percent when
// percent is false, or as "1234 files" when the phase has no total.
// p.mu must be held.
func (p *progress) itemsDone(percent bool) string {
if p.total < 0 { if p.total < 0 {
return fmt.Sprintf("%s: %d files, elapsed %s", return fmt.Sprintf("%d files", p.count)
p.label, p.count, elapsed.Round(time.Second)) }
approx := ""
if p.estimate {
approx = "~"
}
done := fmt.Sprintf("[%d/%s%d]", p.count, approx, p.total)
if !percent {
return done
} }
pct := float64(percentScale) pct := float64(percentScale)
@@ -184,19 +363,24 @@ func (p *progress) plainLine() string {
pct = percentScale * float64(p.count) / float64(p.total) pct = percentScale * float64(p.count) / float64(p.total)
} }
rate := 0.0 return fmt.Sprintf("%s %.0f%%", done, pct)
if s := elapsed.Seconds(); s > 0 {
rate = float64(p.count) / s
} }
eta := "?" // 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
if rate > 0 && p.count <= p.total { // passes an estimate. p.mu must be held.
remaining := time.Duration(float64(p.total-p.count) / rate * float64(time.Second)) func (p *progress) eta(rate float64) string {
eta = remaining.Round(time.Second).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"
} }
return fmt.Sprintf("%s: [%d/%d] %.0f%% %.0f files/s elapsed %s eta %s", remaining := time.Duration(
p.label, p.count, p.total, pct, rate, float64(p.total-p.count) / rate * float64(time.Second))
elapsed.Round(time.Second), eta)
return remaining.Round(time.Second).String()
} }
+382 -92
View File
@@ -1,16 +1,22 @@
package main package main
import ( import (
"math"
"os" "os"
"path/filepath" "path/filepath"
"strings" "strings"
"testing" "testing"
"time" "time"
"unicode/utf8"
) )
// spinnerIdle comfortably outlasts the 100ms interval at which the // testRedraw is the redraw interval the tests give a display, so that
// progressbar library redraws a spinner from its own goroutine. // many redraws fit in a few milliseconds.
const spinnerIdle = 500 * time.Millisecond 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 //nolint:paralleltest // replaces the process-wide os.Stderr
func TestStderrIsTTYFalseForNonTerminals(t *testing.T) { func TestStderrIsTTYFalseForNonTerminals(t *testing.T) {
@@ -54,59 +60,383 @@ func TestStderrIsTTYFalseForNonTerminals(t *testing.T) {
} }
} }
// TestNewProgressPrintsBeforeFirstItem checks that each pass shows its func TestPhaseLabel(t *testing.T) {
// zero state the moment it starts when stderr is not a terminal, and t.Parallel()
// that the next line still waits for plainInterval.
//
//nolint:paralleltest // captureStderr replaces the process-wide os.Stderr
func TestNewProgressPrintsBeforeFirstItem(t *testing.T) {
stderr := captureStderr(t)
newProgress("walk", -1).increment() phases := []string{"load", "walk", "hash"}
newProgress("hash", 10).increment() if got := phaseLabel(phases, "walk"); got != "[2/3] walk" {
t.Errorf("phaseLabel = %q, want %q", got, "[2/3] walk")
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)
} }
} }
// newWalkSpinner returns the walk pass's terminal display, writing to // TestProgressLine checks the line a display shows in each state, ten
// os.Stderr whether or not it is a terminal, and stops the library's // seconds into the phase.
// redraws when the test ends. func TestProgressLine(t *testing.T) {
func newWalkSpinner(t *testing.T) *progress { 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(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.
func TestLineFitsRoom(t *testing.T) {
t.Parallel()
ago := time.Now().Add(-10 * time.Second)
hash := &progress{
label: scanPhase("hash"), total: 100, count: 20,
start: ago, rateStart: ago,
}
content := &progress{
label: scanPhase("content"), total: -1,
waitingFor: "searching the database", start: ago, rateStart: ago,
}
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,
}}
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)
}
}
}
// 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.
func TestSetTotalStartsRate(t *testing.T) {
t.Parallel()
waited := time.Now().Add(-20 * time.Second)
p := &progress{
label: scanPhase("load"), total: -1, start: waited, rateStart: 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
want := "[1/5] load: [20/100] 20%, 2 files/s, elapsed 30s, eta 40s"
if got, _ := p.line(math.MaxInt, true); got != want {
t.Errorf("line = %q, want %q", got, want)
}
}
// awaitOutput waits until stderr holds want at least times times, and
// fails the test if it never does.
func awaitOutput(t *testing.T, stderr func() string, want string,
times int,
) {
t.Helper() t.Helper()
p := &progress{ deadline := time.Now().Add(testDeadline)
label: "walk", total: -1, start: time.Now(), for strings.Count(stderr(), want) < times {
bar: newBar("walk", -1), if time.Now().After(deadline) {
} t.Fatalf("stderr = %q, want %q at least %d times",
t.Cleanup(p.finish) stderr(), want, times)
return p
} }
// TestProgressWarningsOnOwnLines drives the terminal display of the walk time.Sleep(testRedraw)
// 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. // 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 TestPlainProgressPrintsAtStartAndEnd(t *testing.T) {
stderr := captureStderr(t)
p := newProgress(progressParams{label: scanPhase("hash"), total: 1000})
for range 1000 {
p.increment()
}
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)
}
}
// 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)
awaitOutput(t, stderr,
"[1/5] load: counting the records, elapsed 0s, eta unknown\n", 3)
p.finish()
}
// 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
}
// TestTerminalRedrawsWhileWaiting checks that the terminal display of a
// phase, spinner or bar, keeps being drawn while the phase waits for its
// next item, with the elapsed time as of now, and shows every item
// completed before the wait. stderr is not a terminal here, so the
// displays take it to be fallbackWidth wide.
//
//nolint:paralleltest // captureStderr replaces the process-wide os.Stderr
func TestTerminalRedrawsWhileWaiting(t *testing.T) {
stderr := captureStderr(t)
cases := []struct {
params progressParams
want string // how the line shows a count of 50
}{
{progressParams{label: scanPhase("walk"), total: -1}, "50 files,"},
{progressParams{label: scanPhase("hash"), total: 100}, "[50/100],"},
}
for _, tc := range cases {
before := len(stderr())
since := func() string { return stderr()[before:] }
p := startProgress(tc.params, terminalWidth, 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()
awaitOutput(t, since, "elapsed 1h0m0s", 1)
p.finish()
if shown := lastFrame(since()); !strings.Contains(shown, tc.want) {
t.Errorf("terminal shows %q, want %q", shown, tc.want)
}
}
}
// 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.
func drawLate(stderr func() string, params progressParams, width int,
count int64,
) string {
before := len(stderr())
// No timed draws come between the two.
p := startProgress(params, func() int { return width }, time.Hour)
// Without counting the items one by one or waiting the hours.
p.mu.Lock()
p.count = count
p.start = p.start.Add(-150 * time.Minute)
p.rateStart = p.start
p.mu.Unlock()
p.finish()
return stderr()[before:]
}
// TestTerminalLinesKeepETA checks the line each display shows on an
// 80-column terminal at a large scan's counts and times: the rate is
// left out, so that the elapsed time and the ETA stay whole.
//
//nolint:paralleltest // captureStderr replaces the process-wide os.Stderr
func TestTerminalLinesKeepETA(t *testing.T) {
stderr := captureStderr(t)
cases := []struct {
params progressParams
want string
}{{
// Past its estimate, the walk cannot tell how long it has left.
params: progressParams{
label: scanPhase("walk"), total: 1200000, estimate: true,
},
want: "[2/5] walk: [1234567/~1200000] 103%, elapsed 2h30m0s, " +
"eta unknown",
}, {
params: progressParams{label: scanPhase("hash"), total: 9876543},
want: "[3/5] hash: [1234567/9876543] 12%, elapsed 2h30m0s, " +
"eta 17h30m0s",
}, {
params: progressParams{label: scanPhase("content"), total: 9876543},
want: "[5/5] content: [1234567/9876543] 12%, elapsed 2h30m0s, " +
"eta 17h30m0s",
}}
for _, tc := range cases {
out := drawLate(stderr, tc.params, 80, 1234567)
if shown := lastFrame(out); !strings.Contains(shown, tc.want) {
t.Errorf("terminal shows %q, want %q", shown, tc.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
// terminal's last column. A line that reaches it wraps, and every
// redraw then leaves a line behind. The bar is drawn where it has room,
// as at 120 columns, and left out where it has none.
//
//nolint:paralleltest // captureStderr replaces the process-wide os.Stderr
func TestTerminalLinesFitWidth(t *testing.T) {
stderr := captureStderr(t)
for _, width := range []int{120, 100, 80, 72, 60, 50, 40} {
for _, total := range []int64{9876543, 20000} {
params := progressParams{label: scanPhase("content"), total: total}
out := drawLate(stderr, params, width, total/8)
if width == 120 && !strings.Contains(out, "% |") {
t.Errorf("no bar on a terminal %d wide: %q", width, out)
}
lines := strings.FieldsFuncSeq(out, func(r rune) bool {
return r == '\r' || r == '\n'
})
for line := range lines {
if n := utf8.RuneCountInString(line); n >= width {
t.Errorf("a line of %d columns on a terminal %d wide: %q",
n, width, line)
}
}
}
}
}
// TestProgressWarningsOnOwnLines drives the terminal displays, spinner
// and bar, 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 //nolint:paralleltest // captureStderr replaces the process-wide os.Stderr
func TestProgressWarningsOnOwnLines(t *testing.T) { func TestProgressWarningsOnOwnLines(t *testing.T) {
stderr := captureStderr(t) stderr := captureStderr(t)
p := newWalkSpinner(t)
cases := []progressParams{
{label: scanPhase("walk"), total: -1},
{label: scanPhase("hash"), total: 10},
}
issued := 0
for _, params := range cases {
p := startProgress(params, terminalWidth, testRedraw)
// No pause between warnings: one written straight to stderr is // No pause between warnings: one written straight to stderr is
// garbled only if a redraw lands while it is being written. // garbled only if a redraw lands while it is being written.
issued := 0 for start := time.Now(); time.Since(start) < 50*testRedraw; issued++ {
for start := time.Now(); time.Since(start) < spinnerIdle; issued++ {
p.warnf("warning") p.warnf("warning")
} }
// The spinner prints the warnings at its next redraw. p.finish()
time.Sleep(spinnerIdle) }
// A terminal shows each line as the text after its last carriage // A terminal shows each line as the text after its last carriage
// return. // return.
@@ -129,83 +459,43 @@ func TestProgressWarningsOnOwnLines(t *testing.T) {
} }
} }
// TestSpinnerShowsCountAfterBurst checks that once a burst of items // TestTerminalStoppedShortKeepsCount checks that the terminal display
// faster than the redraw limit is over, the walk display shows every // of a phase that stops before its total, as an interrupted one does,
// item completed while it waits for the next one. // is left showing the count it stopped at rather than a full bar.
// //
//nolint:paralleltest // captureStderr replaces the process-wide os.Stderr //nolint:paralleltest // captureStderr replaces the process-wide os.Stderr
func TestSpinnerShowsCountAfterBurst(t *testing.T) { func TestTerminalStoppedShortKeepsCount(t *testing.T) {
stderr := captureStderr(t) stderr := captureStderr(t)
p := newWalkSpinner(t) p := startProgress(progressParams{label: scanPhase("hash"), total: 10},
terminalWidth, redrawInterval)
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.increment() p.increment()
// Past the redraw limit, so the bar draws the next count.
time.Sleep(2 * barThrottle)
p.increment() p.increment()
p.finish() 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) t.Errorf("terminal shows %q, want a count of 2 of 10", shown)
} }
} }
// TestWarningAfterLastItemKeepsBar checks that a warning printed after // TestWarningAfterLastItemKeepsBar checks that a warning printed after
// a pass's last item, as for a failed read of the last file, leaves the // a phase's last item, as for a failed read of the last file, leaves the
// pass's finished bar on the terminal below the warning. // phase's full bar on the terminal below the warning.
// //
//nolint:paralleltest // captureStderr replaces the process-wide os.Stderr //nolint:paralleltest // captureStderr replaces the process-wide os.Stderr
func TestWarningAfterLastItemKeepsBar(t *testing.T) { func TestWarningAfterLastItemKeepsBar(t *testing.T) {
stderr := captureStderr(t) stderr := captureStderr(t)
p := &progress{ p := startProgress(progressParams{label: scanPhase("hash"), total: 2},
label: "hash", total: 2, start: time.Now(), terminalWidth, testRedraw)
bar: newBar("hash", 2),
}
p.increment() p.increment()
p.increment() p.increment()
awaitOutput(t, stderr, "[2/2],", 1)
p.warnf("warning") p.warnf("warning")
p.finish() 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) t.Errorf("terminal shows %q, want a count of 2 of 2", shown)
} }
} }
+92 -36
View File
@@ -84,18 +84,26 @@ type fileMeta struct {
hashed bool hashed bool
} }
// runScan implements the scan subcommand: four sequential phases — // scanPhase names one phase of a scan with its place among all of them,
// walk (which stats each file as it is discovered), hash, update, // as "[2/5] walk", for the phase's progress display. The list here is
// content — that synchronize the persistent database with the // the one place the phases are counted.
// filesystem state under the PATH operands. Only files whose size at func scanPhase(name string) string {
// least one other file shares are ever hashed: a size-unique file return phaseLabel(
// cannot be a duplicate. A file of headTailMin or more gets its content []string{"load", "walk", "hash", "update", "content"}, name)
// 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 // runScan implements the scan subcommand: five sequential phases —
// it is new. The scan holds the lock on the database for its whole // load (which reads the existing records), walk (which stats each file
// run, so a second scan fails before it walks the filesystem or opens // as it is discovered), hash, update, content — that synchronize the
// the database. // 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 — // Errors are returned rather than exiting, so that the deferred close —
// which takes the database out of WAL mode — always runs, and the lock // 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 // 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 // runPhases synchronizes the database with the filesystem under roots
// in four sequential phases: walk (enumerate and stat every file, // in five sequential phases: load (read the existing records), walk
// building a complete size census), hash (read only the new or // (enumerate and stat every file, building a complete size census),
// changed — or previously unhashed — files whose size at least one // hash (read only the new or changed — or previously unhashed — files
// other file shares, committing results in batches as they arrive), // whose size at least one other file shares, committing results in
// update (record the size-unique files without reading them, and // batches as they arrive), update (record the size-unique files without
// delete the records the scan no longer verifies), and content (fill // reading them, and delete the records the scan no longer verifies),
// in the content hash of every record of headTailMin or more whose // and content (fill in the content hash of every record of headTailMin
// size, head, and tail match another record's). Records outside the // or more whose size, head, and tail match another record's). Records
// roots are never touched, except that the content phase fills in // outside the roots are never touched, except that the content phase
// their content hash. Operands the walk cannot start from are dropped // fills in their content hash. Operands the walk cannot start from are
// first, so the records beneath them are treated as if those operands // dropped first, so the records beneath them are treated as if those
// had not been given. // operands had not been given.
func (s *scanState) runPhases(ctx context.Context, roots []string, func (s *scanState) runPhases(ctx context.Context, roots []string,
workers int, oneFS bool, workers int, oneFS bool,
) error { ) error {
@@ -430,10 +438,21 @@ func (s *scanState) walkableRoots(roots []string) []string {
// separately into the same database. // separately into the same database.
func (s *scanState) loadIndex(ctx context.Context, roots []string) error { func (s *scanState) loadIndex(ctx context.Context, roots []string) error {
// Indexing tens of millions of records takes real time; without a // Indexing tens of millions of records takes real time; without a
// display the scan looks hung before the walk begins. // display the scan looks hung before the walk begins. Counting them
prog := newProgress("load", -1) // first gives the display its total.
prog := newProgress(progressParams{
label: scanPhase("load"), total: -1,
waitingFor: "counting the records",
})
defer prog.finish() defer prog.finish()
total, err := countRecords(ctx, s.db)
if err != nil {
return err
}
prog.setTotal(total)
s.existing = make(map[string]fileMeta) s.existing = make(map[string]fileMeta)
return loadFileMeta(ctx, s.db, return loadFileMeta(ctx, s.db,
@@ -465,7 +484,16 @@ func (s *scanState) loadIndex(ctx context.Context, roots []string) error {
func (s *scanState) walkPhase( func (s *scanState) walkPhase(
events <-chan walkEvent, roots []string, events <-chan walkEvent, roots []string,
) ([]fileRec, []fileRec) { ) ([]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 ( var (
changed, unhashed []fileRec 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 // readRuns reads runs with the worker pool, one read per inode run, in
// the order given, under a progress display named label. The workers // the order given, under the progress display of the phase named label.
// compute each run's hashes with hash, and each result goes to record; // The workers compute each run's hashes with hash, and each result goes
// a run that fails to read is warned about and counted as skipped // to record; a run that fails to read is warned about and counted as
// instead. The total counts actual reads, so the bar shows a real ETA. // 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 // Returning early — a failed database write, or a cancelled scan — must
// not strand the pool: the feeder would park forever on a full jobs // 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) pool := startHashPool(ctx, runs, workers, hash)
defer pool.stop() defer pool.stop()
prog := newProgress(label, int64(len(runs))) prog := newProgress(progressParams{
label: scanPhase(label), total: int64(len(runs)),
})
defer prog.finish() defer prog.finish()
for range runs { for range runs {
@@ -740,7 +771,9 @@ func (s *scanState) updatePhase(ctx context.Context) error {
s.st.removed = len(deletes) s.st.removed = len(deletes)
total := len(s.batch) + len(s.sentinels) + 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() defer prog.finish()
@@ -821,12 +854,24 @@ func (s *scanState) contentPhase(ctx context.Context, workers int) error {
func (s *scanState) contentCandidates( func (s *scanState) contentCandidates(
ctx context.Context, ctx context.Context,
) ([]fileRec, map[string]scanRec, error) { ) ([]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. // without a display the scan looks hung before the reads begin.
prog := newProgress("content", -1) // 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.
prog := newProgress(progressParams{
label: scanPhase("content"), total: -1,
waitingFor: "searching the database",
})
defer prog.finish() defer prog.finish()
total, err := countContentCandidates(ctx, s.db)
if err != nil {
return nil, nil, err
}
var ( var (
searching = true // no record has been returned yet
toRead []fileRec toRead []fileRec
first scanRec // the current group's first record first scanRec // the current group's first record
passed int // the current group's files that passed the check passed int // the current group's files that passed the check
@@ -849,7 +894,13 @@ func (s *scanState) contentCandidates(
passed, unread = 0, nil passed, unread = 0, nil
} }
err := loadContentCandidates(ctx, s.db, func(r scanRec, hashed bool) { err = loadContentCandidates(ctx, s.db, func(r scanRec, hashed bool) {
if searching {
searching = false
prog.setTotal(total)
}
prog.increment() prog.increment()
if r.size != first.size || r.head != first.head || r.tail != first.tail { if r.size != first.size || r.head != first.head || r.tail != first.tail {
@@ -880,6 +931,11 @@ func (s *scanState) contentCandidates(
return nil, nil, err return nil, nil, err
} }
// A search that returned no record still ends showing its count.
if searching {
prog.setTotal(total)
}
endGroup() endGroup()
return toRead, recs, nil return toRead, recs, nil
+63
View File
@@ -1586,6 +1586,69 @@ func TestScanPipeline(t *testing.T) {
assertSmokeTreeGroups(t, dir, db) 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) { func TestSyncScanUnchangedReuse(t *testing.T) {
t.Parallel() t.Parallel()