diff --git a/README.md b/README.md index a007bc7..5c7459f 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,72 @@ 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` 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) +- 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 2:32 eta 17:54 +[2/5] walk: [1234567/~1200000] 103%, 5120 files/s, elapsed 4m1s, eta unknown ``` 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. A terminal made narrower while a phase runs gets the same: the + next draw erases the line within the new width and fits the line to it, and + the display goes on redrawing in place. - When stderr is not a terminal (a pipe, a file, `/dev/null`), do not emit ANSI - redraws: print 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..aec4797 100644 --- a/TODO.md +++ b/TODO.md @@ -29,6 +29,21 @@ # 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, also after the terminal is + made narrower during a phase: 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 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..596408f 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 @@ -552,26 +564,46 @@ func loadFileMeta(ctx context.Context, db *sql.DB, return nil } -// contentCandidatesSQL selects every record of at least headTailMin -// bytes whose size, head, and tail equal another record's, in each -// group (the records sharing a size, head, and tail) where at least one -// record has no content hash, with whether each record has one. 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. +// contentGroupsSQL selects each group (the records sharing a size, +// head, and tail) of records of at least headTailMin bytes that has more +// than one record and at least one record without a content hash, with +// the number of its records. +const contentGroupsSQL = ` +SELECT size, head, tail, COUNT(*) AS records +FROM files +WHERE size >= ? AND head <> '' +GROUP BY size, head, tail +HAVING COUNT(*) > 1 AND SUM(content = '') > 0 +` + +// 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 ( - SELECT size, head, tail - FROM files - WHERE size >= ? AND head <> '' - GROUP BY size, head, tail - HAVING COUNT(*) > 1 AND SUM(content = '') > 0 -) AS g USING (size, head, tail) +JOIN (` + contentGroupsSQL + `) AS g USING (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: // 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..3cc86ee 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) } @@ -382,3 +385,62 @@ func TestApplyChangesBatching(t *testing.T) { 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) + } +} diff --git a/progress.go b/progress.go index 79b05bb..57623c4 100644 --- a/progress.go +++ b/progress.go @@ -2,122 +2,272 @@ package main import ( "fmt" + "math" "os" + "slices" + "strings" + "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 + +// 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. 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. 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 -} - -func newProgress(label string, total int64) *progress { - p := &progress{label: label, total: total, start: time.Now()} - if stderrIsTTY() { - p.bar = newBar(label, total) - - return p +// terminalWidth returns the width of the terminal on stderr, or +// fallbackWidth, as the progressbar library does, when it cannot read +// one. +func terminalWidth() int { + width, _, err := term.GetSize(int(os.Stderr.Fd())) + if err != nil || width <= 0 { + return fallbackWidth } - // 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 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. +// +// The draws come from a goroutine of their own, so mu guards the fields +// below it. 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 { + 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 + widest int // the widest line bar has drawn, in columns + 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, 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 } -// newBar builds the TTY display for newProgress. -func newBar(label string, total int64) *progressbar.ProgressBar { - opts := []progressbar.Option{ - 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), - ) +// draw shows the phase's progress: on a TTY in place of the line +// before, and otherwise as a plain line. +func (p *progress) draw() { + p.mu.Lock() + defer p.mu.Unlock() + + if p.width == nil { + text, _ := p.line(math.MaxInt, true) + fmt.Fprintln(os.Stderr, text) + + return } - return progressbar.NewOptions64(total, opts...) + width := p.width() + + // A phase with an exact total gets the library's bar when its line, + // without the percent the bar shows, fits whole beside the bar. A + // total of 0 leaves the bar nothing to fill. + text, withBar := "", false + if p.total > 0 && !p.estimate { + text, withBar = p.line(width-barMargin, false) + } + + margin := barMargin + if !withBar { + margin = spinnerMargin + text, _ = p.line(width-margin, true) + } + + // The library makes a bar or a spinner, and before each draw erases + // its line with as many spaces as the widest line it has drawn. A + // display gets a new one when it turns from one to the other, as its + // line grows or the terminal is resized, and when the terminal has + // been made too narrow for that erase, which would wrap and leave a + // line behind at every draw. + if p.bar == nil || p.withBar != withBar || p.widest >= width { + p.newBar(withBar, width) + } + + if withBar { + _ = p.bar.Set64(p.count) + } + + p.bar.Describe(text) + + // The library drew the text and its margin, less the terminal's last + // column, which the margin keeps clear. + p.widest = max(p.widest, len(text)+margin-1) } -// increment records one completed item and refreshes the display. +// 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, width int) { + if p.bar != nil { + // Erase what was drawn before, short of the last column of a + // terminal that may have been made narrower since: the library's + // own erase is as wide as the widest line it drew. + blank := strings.Repeat(" ", min(p.widest, width-1)) + fmt.Fprint(os.Stderr, "\r"+blank+"\r") + } + + total := int64(-1) // the library's spinner + if withBar { + total = p.total + } + + p.bar = progressbar.NewOptions64(total, + progressbar.OptionSetWriter(os.Stderr), + progressbar.OptionSetWidth(barWidth), + 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 and the ETA. + progressbar.OptionSetElapsedTime(false), + progressbar.OptionSetPredictTime(false), + ) + p.withBar, p.widest = withBar, 0 +} + +// 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,58 +275,101 @@ 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) - - return - } + p.mu.Lock() + defer p.mu.Unlock() 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() } 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 -// 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, drawn once more as the phase ends. +// A phase stopped short of its total, as an interrupted one is, shows +// the count it stopped at rather than a full bar. func (p *progress) finish() { if p == nil { return } - if p.bar != nil { - if p.total >= 0 && p.count < p.total { - _ = p.bar.Exit() - } else { - _ = p.bar.Finish() - } + close(p.stop) + <-p.done + 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) - - return } - - fmt.Fprintln(os.Stderr, p.plainLine()) } -// plainLine formats a non-TTY progress line. -func (p *progress) plainLine() string { - elapsed := time.Since(p.start) +// 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 + } + + head = p.label + ": " + p.itemsDone(percent) + ", " + extra = fmt.Sprintf("%.0f files/s", rate) + 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 { - return fmt.Sprintf("%s: %d files, elapsed %s", - p.label, p.count, elapsed.Round(time.Second)) + return fmt.Sprintf("%d files", p.count) + } + + approx := "" + if p.estimate { + approx = "~" + } + + done := fmt.Sprintf("[%d/%s%d]", p.count, approx, p.total) + if !percent { + return done } pct := float64(percentScale) @@ -184,19 +377,24 @@ func (p *progress) plainLine() string { pct = percentScale * float64(p.count) / float64(p.total) } - rate := 0.0 - if s := elapsed.Seconds(); s > 0 { - rate = float64(p.count) / s + return fmt.Sprintf("%s %.0f%%", done, pct) +} + +// 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" } - - eta := "?" - 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() - } + remaining := time.Duration( + float64(p.total-p.count) / rate * float64(time.Second)) - 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 remaining.Round(time.Second).String() } diff --git a/progress_test.go b/progress_test.go index 453fa94..4aa707b 100644 --- a/progress_test.go +++ b/progress_test.go @@ -1,16 +1,22 @@ package main import ( + "math" "os" "path/filepath" "strings" "testing" "time" + "unicode/utf8" ) -// 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 +60,437 @@ 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. -// -//nolint:paralleltest // captureStderr replaces the process-wide os.Stderr -func TestNewProgressPrintsBeforeFirstItem(t *testing.T) { - stderr := captureStderr(t) +func TestPhaseLabel(t *testing.T) { + t.Parallel() - newProgress("walk", -1).increment() - newProgress("hash", 10).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) + phases := []string{"load", "walk", "hash"} + if got := phaseLabel(phases, "walk"); got != "[2/3] walk" { + t.Errorf("phaseLabel = %q, want %q", got, "[2/3] walk") } } -// 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 { +// 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(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() - p := &progress{ - label: "walk", total: -1, start: time.Now(), - bar: newBar("walk", -1), - } - t.Cleanup(p.finish) + deadline := time.Now().Add(testDeadline) + for strings.Count(stderr(), want) < times { + if time.Now().After(deadline) { + t.Fatalf("stderr = %q, want %q at least %d times", + stderr(), want, times) + } - return p + time.Sleep(testRedraw) + } } -// 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. +// 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) + } + } + } + } +} + +// TestTerminalNarrowedRedrawsInPlace draws a large scan's display, two +// and a half hours into the phase, on a terminal 120 columns wide, then +// makes the terminal narrower than that line and draws it again a few +// times. Nothing written after that, the erase before each redraw +// included, may reach the narrower terminal's last column: it would +// wrap, and every redraw would leave a line behind. At these widths the +// spinner stays a spinner and the bar stays a bar. +// +//nolint:paralleltest // captureStderr replaces the process-wide os.Stderr +func TestTerminalNarrowedRedrawsInPlace(t *testing.T) { + stderr := captureStderr(t) + + cases := []struct { + params progressParams + narrow int + }{ + {progressParams{label: scanPhase("walk"), total: -1}, 60}, + {progressParams{label: scanPhase("hash"), total: 9876543}, 90}, + } + + for _, tc := range cases { + width := 120 + + // No timed draws: the test draws. + p := startProgress(tc.params, func() int { return width }, time.Hour) + + p.mu.Lock() + p.count = 1234567 + p.start = p.start.Add(-150 * time.Minute) + p.rateStart = p.start + p.mu.Unlock() + + p.draw() + + width = tc.narrow + before := len(stderr()) + + p.draw() + p.draw() + p.finish() + + lines := strings.FieldsFuncSeq(stderr()[before:], func(r rune) bool { + return r == '\r' || r == '\n' + }) + + for line := range lines { + if n := utf8.RuneCountInString(line); n >= width { + t.Errorf("%d columns written on a terminal made %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 func TestProgressWarningsOnOwnLines(t *testing.T) { stderr := captureStderr(t) - p := newWalkSpinner(t) - // 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++ { - p.warnf("warning") + cases := []progressParams{ + {label: scanPhase("walk"), total: -1}, + {label: scanPhase("hash"), total: 10}, } - // The spinner prints the warnings at its next redraw. - time.Sleep(spinnerIdle) + issued := 0 + + for _, params := range cases { + p := startProgress(params, terminalWidth, testRedraw) + + // No pause between warnings: one written straight to stderr is + // garbled only if a redraw lands while it is being written. + for start := time.Now(); time.Since(start) < 50*testRedraw; issued++ { + p.warnf("warning") + } + + p.finish() + } // A terminal shows each line as the text after its last carriage // return. @@ -129,83 +513,43 @@ 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 rather than a full bar. // //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}, + terminalWidth, 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. +// a phase's last item, as for a failed read of the last file, leaves the +// phase's full bar on the terminal below the warning. // //nolint:paralleltest // captureStderr replaces the process-wide os.Stderr func TestWarningAfterLastItemKeepsBar(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}, + terminalWidth, testRedraw) p.increment() p.increment() + + awaitOutput(t, stderr, "[2/2],", 1) 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..bdb22d3 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,16 +854,28 @@ 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) + // 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() + total, err := countContentCandidates(ctx, s.db) + if err != nil { + return nil, nil, err + } + var ( - toRead []fileRec - first scanRec // the current group's first record - passed int // the current group's files that passed the check - unread []fileRec // those of them without a content hash + searching = true // no record has been returned yet + toRead []fileRec + first scanRec // the current group's first record + passed int // the current group's files that passed the check + unread []fileRec // those of them without a content hash ) recs := make(map[string]scanRec) @@ -849,7 +894,13 @@ 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) { + if searching { + searching = false + + prog.setTotal(total) + } + prog.increment() 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 } + // A search that returned no record still ends showing its count. + if searching { + prog.setTotal(total) + } + endGroup() return toRead, recs, nil 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()