diff --git a/.github/workflows/ci.yml b/.github/workflows/ci.yml index 06bd125..61c685f 100644 --- a/.github/workflows/ci.yml +++ b/.github/workflows/ci.yml @@ -600,7 +600,7 @@ jobs: # in somebody else's file. run: | set -euo pipefail - watched='internal/format/registry.go cmd/tfg/main.go internal/gui/window/run.go internal/audit/parallel.go go.mod' + watched='internal/format/registry.go cmd/tfg/main.go internal/gui/window/run.go internal/audit/parallel.go internal/engine/parallel.go go.mod' # On a pull request there is no "before" - the field belongs to a push # - so this asked for something empty and every pull request answered # "touched". That quietly undid the decision of 2026-08-20, because diff --git a/CHANGELOG.md b/CHANGELOG.md index 6dff7c6..5ad52c9 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -58,6 +58,39 @@ because it turns other people's test suites red. ### Changed +- **Files are written over several threads, so a run of many files is several + times faster.** They used to be written one after another. + + Nothing about what you get changes. The files are byte for byte identical, + the manifest lists them in the same order, `verify` and `cleanup` behave + exactly as before, and every refusal says what it said. + + Measured on an eight core machine, variants interleaved and their order + reversed between repetitions. 240 `.png` files of 200 kB went from 2.03 to + 0.44 seconds, which is **4.6 times faster**. 80 `.zip` files of 2 MB, 2.9 + times. 240 `.docx` files of 200 kB, 2.0 times. Two thousand `.txt` files of + 4 kB, 1.4 times - with files that small the time goes into what a run does + once rather than into writing them. + + A single file is unchanged whatever its size, and the measurement says so + rather than the reasoning: at one 20 MB `.png` the two ranges overlap, so no + difference is claimed. There is nothing to write beside a single file. + + The gain follows the number of cores you have and the kind of file. Work the + processor does - drawing a picture, compressing an archive - scales best. A + run held up by the disk gains less. A handful of files was already quick and + is unaffected. + + **One thing changes if you stop a run part way.** Ctrl+C used to leave behind + the files finished so far, which were always a consecutive run of them. + Several threads means one file can be cut off while a later one is already + finished, so what survives can have a gap in it. The manifest names exactly + what is on the disk either way, which is what `verify` and `cleanup` work + from, so neither is affected. + + The progress bar counts the whole run rather than one file at a time, so its + file counter can move by more than one between redraws. + - **Producing `.png` and `.gif` files is about twice as cheap.** Working out what a file will contain used to draw the whole picture and compress it, only to throw the result away and do it again when the file was actually written. diff --git a/internal/engine/engine.go b/internal/engine/engine.go index 4c557e9..2a02fb7 100644 --- a/internal/engine/engine.go +++ b/internal/engine/engine.go @@ -1,13 +1,11 @@ package engine import ( - "bufio" "context" "crypto/sha256" "encoding/hex" "errors" "fmt" - "io" "io/fs" "os" "path/filepath" @@ -162,11 +160,25 @@ type Options struct { // OnProgress is called as the run advances. Nil means silence, which is // what every caller that has nobody to show it to should pass. // - // Called from the same goroutine doing the work, so there is no - // concurrency here to get wrong. Called often - once per write inside a - // file, not only once per finished file - so rate limiting what actually - // reaches a screen belongs to the caller. Without the writes inside a - // file, one 5 GB file would report once, at the end. + // NEVER TWO AT ONCE, though not always from the same goroutine. Until + // 2026-09-06 this promised the stronger thing - "from the same goroutine + // doing the work" - and both callers were built on it: the command line bar + // moves last and printed without a lock, and the window's throttle reads + // and writes a timestamp without one. The files are written over several + // goroutines now, so the engine serialises these calls instead. The lock + // gives happens-before, so both callers stay correct unchanged. What a + // caller may NOT do is assume the goroutine, which is why the sentence is + // here rather than only in the commit that changed it. + // + // Called often - once per write inside a file, not only once per finished + // file - so rate limiting what actually reaches a screen belongs to the + // caller. Without the writes inside a file, one 5 GB file would report + // once, at the end. + // + // With several files in flight the byte count is the whole run's, so it + // moves while any writer moves rather than tracking one file. It still + // falls back when a file fails, exactly as it did before, because a file + // that failed counts for nothing. OnProgress func(Progress) } @@ -443,6 +455,12 @@ type Progress struct { // // A manifest is returned even when the run is cut short, otherwise cleanup // has nothing to work with. +// +// The writing itself happens over several goroutines, and everything about +// that lives in parallel.go - including why, and what it measured. What stays +// here is everything a run does exactly once: the checks that decide whether +// it may start at all, and the reading back of the answers in the order the +// plan lists them. func Run(ctx context.Context, files []PlannedFile, opt Options) (*Result, error) { m := manifest.New( "testing-files-generator", version.Version, @@ -516,133 +534,58 @@ func Run(ctx context.Context, files []PlannedFile, opt Options) (*Result, error) } }() - totalBytes := TotalBytes(files) - var bytesDone int64 - - for i, f := range files { - select { - case <-ctx.Done(): - // Stop starting new files. What is already finished stays, and - // the manifest describes exactly that. - m.Run.Complete = false - return res, ctx.Err() - default: - } + // The files are written over several goroutines. Everything that runs + // beside anything else lives in parallel.go, including the measurements + // that put it there. + written := writeAll(ctx, files, opt.OutDir, newProgressGate(files, opt.OnProgress)) - // Built per file rather than once, because it closes over how far the - // run had got before this file started. Left nil when nobody is - // listening, so a run without progress allocates nothing for it. - var report func(int64) - if opt.OnProgress != nil { - report = func(inFile int64) { - opt.OnProgress(Progress{ - FilesDone: i, FilesTotal: len(files), - BytesDone: bytesDone + inFile, BytesTotal: totalBytes, - }) - } - } - - sum, err := writeOne(ctx, f, opt.OutDir, report) - if err == nil { - // Only what reached the disk. Counting a file that failed would - // have the bar claim bytes nobody can find, and on a run where - // several fail the total would arrive before the files do. - bytesDone += f.Plan.Bytes - } - if opt.OnProgress != nil { - opt.OnProgress(Progress{ - FilesDone: i + 1, FilesTotal: len(files), - BytesDone: bytesDone, BytesTotal: totalBytes, - }) - } - if err != nil { - if errors.Is(err, context.Canceled) || errors.Is(err, context.DeadlineExceeded) { - m.Run.Complete = false - return res, err + // Read back in the order the plan lists, on this goroutine alone. Two + // things rest on that and neither is tidiness: + // + // - the manifest keeps the order it has always had, which is the order + // cleanup prints to a person before deleting from it, + // - a run stopped part way names the LOWEST cancelled file rather than + // whichever writer happened to notice first, so the same interruption + // reports the same thing on every machine. + var stopped error + for i, r := range written { + switch { + case r.ok: + m.Add(entryFor(files[i], r.sha, true, nil)) + case r.err == nil: + // Never started. A cancelled run leaves these behind and they are + // neither a success nor a failure, so they get no entry - which is + // what the sequential loop did by never reaching them. + case errors.Is(r.err, context.Canceled) || errors.Is(r.err, context.DeadlineExceeded): + // A writer stopped half way through wrote nothing that survived, + // so there is nothing to record about it either. + if stopped == nil { + stopped = r.err } + default: // One file failing does not end the run. Nine thousand good // files are worth keeping, and the entry says what went wrong. res.Failures++ - m.Add(entryFor(f, "", false, err)) - continue + m.Add(entryFor(files[i], "", false, r.err)) } - m.Add(entryFor(f, sum, true, nil)) } - m.Run.Complete = true - return res, nil -} - -func writeOne(ctx context.Context, f PlannedFile, outDir string, report func(int64)) (string, error) { - final := filepath.Join(outDir, f.Name) - // The process id is in the name because two runs writing into one directory - // used to meet on it. Measured on 2026-08-03: two runs of the same target - // collided on the temporary file, one of them reported two files it could - // not produce, and the bytes of the other had already gone through the same - // handle. The name never survives the run, so nothing about it has to be - // repeatable - and the file it becomes is settled by the plan, not by this. - tmp := tempPathFor(outDir, f.Name) - - // os.Create, and O_EXCL was tried here and taken back out on 2026-08-25. - // - // The idea was sound: the check in preflight answers "this name is free" - // a few hundred lines before the write, and O_EXCL would have the - // filesystem answer it at the moment of writing instead. What it costs on - // Windows is not sound. Measured with a probe, a file created in a - // directory reached through a symbolic link: - // - // os.Create works - // O_CREATE|O_EXCL|O_WRONLY fails with "The file exists" - // - // about a file that does not exist. Go asks for the reparse point rather - // than what it points at when O_EXCL is set, so every file of a run whose - // output directory is a link fails - and this tool supports exactly that - // on purpose, because people keep fixtures on a mounted workspace or a - // scratch disk. Two guards said so within a minute of the change. - // - // The window O_EXCL would have closed is a real one and it is small: - // preflight refuses every name that is taken before the run starts, so - // what is left is somebody else creating our temporary name, with our - // process id in it, during the run. Trading a supported way of pointing - // the tool at a directory for that is the wrong way round. - fh, err := os.Create(tmp) - if err != nil { - return "", err - } - - h := sha256.New() - buffered := bufio.NewWriterSize(fh, 64<<10) - counter := &countingWriter{w: io.MultiWriter(buffered, h), report: report} - - writeErr := writeWithoutCrashing(ctx, f, counter) - if writeErr == nil { - writeErr = buffered.Flush() - } - closeErr := fh.Close() - - if writeErr != nil { - _ = os.Remove(tmp) - return "", writeErr - } - if closeErr != nil { - _ = os.Remove(tmp) - return "", closeErr + // A stopped run keeps every file that FINISHED, which may leave a hole + // where a writer was cut off. The sequential loop could only ever leave a + // contiguous prefix, so this is the one thing a person can observe that + // changed - decided by the owner on 2026-09-06, and the alternative is + // worse in a way untouchable rule 7 names: a finished file with no entry + // in the manifest is a file no command of this tool can remove. + if stopped == nil && ctx.Err() != nil { + stopped = ctx.Err() } - - // The size is the promise. A generator that missed it by a byte is a bug - // worth catching here rather than in someone's test suite, so the file - // never reaches its final name. - if counter.n != f.Plan.Bytes { - _ = os.Remove(tmp) - return "", fmt.Errorf("generator for %s produced %d B where the plan said %d B", - f.Desc.ID, counter.n, f.Plan.Bytes) + if stopped != nil { + m.Run.Complete = false + return res, stopped } - if err := os.Rename(tmp, final); err != nil { - _ = os.Remove(tmp) - return "", err - } - return hex.EncodeToString(h.Sum(nil)), nil + m.Run.Complete = true + return res, nil } func entryFor(f PlannedFile, sha string, materialized bool, failure error) manifest.File { @@ -927,22 +870,3 @@ func runID(seed int64) string { h := sha256.Sum256([]byte(fmt.Sprintf("run:%d", seed))) return "run_" + hex.EncodeToString(h[:5]) } - -type countingWriter struct { - w io.Writer - n int64 - // report, when set, is called with the running total for this file. It is - // what gives progress inside a single large file rather than only between - // files - the case where silence is worst, because one 5 GB file is one - // callback if you only count finished files. - report func(int64) -} - -func (c *countingWriter) Write(p []byte) (int, error) { - n, err := c.w.Write(p) - c.n += int64(n) - if c.report != nil { - c.report(c.n) - } - return n, err -} diff --git a/internal/engine/parallel.go b/internal/engine/parallel.go new file mode 100644 index 0000000..2d2116c --- /dev/null +++ b/internal/engine/parallel.go @@ -0,0 +1,376 @@ +// Part of package engine. See engine.go. +package engine + +import ( + "bufio" + "context" + "crypto/sha256" + "encoding/hex" + "fmt" + "io" + "os" + "path/filepath" + "runtime" + "sync" + "sync/atomic" +) + +// This file is the only place in internal/engine that runs anything beside +// anything else, and it is listed in internal/guard/concurrency_test.go with +// that reason. Keeping it to one file is the point, the same way +// internal/audit/parallel.go does: everything else in this package stays a +// plain loop, and a reader looking for the goroutines finds them here. +// +// Why it exists. Writing the files is what a run is: measured on 2026-09-06, +// after P7 stopped planning from encoding the picture twice, planning a run of +// 300 PNGs is 51 ms and writing it is 2741 ms - 2% against 98%. So the write +// loop is the whole of what is left to parallelise, and the plan is not. +// +// Measured with tools/probes/writeparallel, which writes a real planned run +// with N goroutines in ONE process - the shape this file has, rather than the +// N separate processes an earlier probe used: +// +// png 200 kB x240 W1 1.00x W2 2.05x W4 3.03x W8 4.19x W16 5.51x +// zip 2 MB x80 W1 1.00x W2 1.78x W4 2.77x W8 3.87x +// +// The question that had to be answered before any of this was written is what +// a shared heap does to it, because separate processes have one each. It does +// nothing: the same run allocates 563.0 MB at one goroutine and 562.8 MB at +// sixteen, and collects a quarter as often. The numbers, the instrument and +// the two mistakes made getting them are in +// docs/PERFORMANCE-REVIEW-2026-09-05.md section 14. +// +// What this costs, said out loud rather than left to be found. N generators +// are live at once, so the memory a run holds while writing is N times one +// generator's working set. Every generator streams - there is a guard for that +// - so that set is bounded by the format rather than by the file, and the +// largest of them hold one picture. It is still N times what it was. And the +// answers are collected before any of them reaches the manifest, which is +// forty bytes a file that the sequential loop did not need: forty megabytes at +// the millionth file, beside a plan that is already far larger. + +// widthFor is how many goroutines a run of n files gets. +// +// GOMAXPROCS rather than a number, for the reason written beside the same +// function in internal/audit: a constant would describe this machine rather +// than the one the tool is run on. Never more than there are files, so a run +// of three does not start sixteen goroutines to have thirteen of them find +// nothing to do. +// +// Measured on an SSD, and that is a limit of the measurement rather than a +// property of the answer. A run held up by a slow disk rather than by the +// processor could be worse at sixteen writers than at one, and that case is +// NOT measured - both formats measured above kept improving to the widest +// setting tried. If it turns up, it turns up as a run that is slower than it +// was, and the number to change is here. +func widthFor(n int) int { + w := runtime.GOMAXPROCS(0) + if w > n { + w = n + } + if w < 1 { + w = 1 + } + return w +} + +// fileResult is what one file came to. The zero value is a file that was never +// started, which a cancelled run leaves behind and which is neither a success +// nor a failure - it gets no manifest entry, exactly as it gets none today. +type fileResult struct { + sha string + ok bool + err error +} + +// writeAll writes every planned file, over several goroutines, and answers for +// each one at its own index. +// +// Answers by index rather than by appending, and that is not tidiness. The +// manifest is built from this slice in order afterwards, and the order of the +// manifest is what cleanup PRINTS to a person before deleting from it - there +// is a guard for that. A list assembled out of completion order holds the same +// files and offers them in an order nobody was shown. +// +// A cancelled run keeps EVERY FILE THAT FINISHED, which may leave a hole where +// a writer was stopped half way. That is the one behaviour that changes here, +// it is a decision of the owner's from 2026-09-06, and the alternative is +// worse in a way untouchable rule 7 names: a finished file with no manifest +// entry is a file no command of this tool can ever remove. internal/audit +// wants the opposite - a contiguous prefix - because a sentence about an +// interrupted verify is a sentence about a prefix, and that difference is why +// there are two pools rather than one shared one. +func writeAll(ctx context.Context, files []PlannedFile, outDir string, gate *progressGate) []fileResult { + out := make([]fileResult, len(files)) + + // next is the only thing every goroutine touches, and it is an atomic + // counter. out is written at indices no other goroutine is given, because + // the counter hands each index out exactly once. + var next atomic.Int64 + var wg sync.WaitGroup + + work := func() { + defer wg.Done() + drain(ctx, &next, files, outDir, gate, out) + } + for w := widthFor(len(files)); w > 0; w-- { + wg.Add(1) + go work() + } + wg.Wait() + + return out +} + +// drain takes files off the counter until there are none left. +// +// A function of its own rather than the body of the goroutine above, for the +// reason written beside the same split in internal/audit: a literal inside a +// loop counts one level deeper than it reads, and the shape guard asks for the +// split rather than for a larger ceiling. +func drain(ctx context.Context, next *atomic.Int64, files []PlannedFile, outDir string, gate *progressGate, out []fileResult) { + for { + i := int(next.Add(1)) - 1 + // Cancellation is asked before taking a file rather than only at the + // top of a pass, so a Ctrl+C is noticed at the next file rather than + // after every remaining one has been begun. + // + // NO MUTATION PROVES THIS LINE and that is not an oversight. Every + // generator takes the context and refuses on it too, so taking this + // question out changes nothing anybody can observe - it only has a + // stopped run create and delete a temporary file for every index it + // had left, which on a million file run is a million of them. What it + // buys is work not done, and the guard that would catch its absence + // would be a guard on a clock. + if i >= len(out) || ctx.Err() != nil { + return + } + // One of these per file, on this goroutine's own stack. How far this + // writer has already reported is the one number that cannot live in + // the gate: with several files in flight there is no such thing as + // "the file being written". + p := fileProgress{gate: gate} + sum, err := writeOne(ctx, files[i], outDir, &p) + out[i] = fileResult{sha: sum, ok: err == nil, err: err} + p.finished(files[i].Plan.Bytes, err == nil) + } +} + +// progressGate is how progress leaves a run that has several writers in it. +// +// Options.OnProgress used to promise "called from the same goroutine doing the +// work". Both callers were built on that: the command line bar moves last and +// printed with no lock, and the window's throttle reads and writes a timestamp +// with none either. The promise cannot survive this file, so what replaces it +// is a weaker one that costs those callers nothing - NEVER TWO AT ONCE. The +// lock gives happens-before, so both remain correct without a line of change. +// +// The callback runs INSIDE the lock rather than beside it. Outside, two +// callbacks could run at once and the whole point would be gone. +// +// That lock is taken once per Write INSIDE a file, not once per file, which is +// often enough to be worth pricing rather than assuming. Measured 2026-09-06 +// on gif, the most talkative generator in the tree at one call per 260 bytes: +// 319 840 callbacks in a run, over three million a second through this one +// mutex, and the timings with and without it overlap. No cost is claimed +// because none was found. +// +// A nil gate is a run nobody is watching. Every method takes a nil receiver, +// so a run without progress does no locking and allocates nothing for it. +type progressGate struct { + mu sync.Mutex + filesDone int + bytesDone int64 + filesTotal int + bytesTotal int64 + report func(Progress) +} + +func newProgressGate(files []PlannedFile, report func(Progress)) *progressGate { + if report == nil { + return nil + } + return &progressGate{ + filesTotal: len(files), + bytesTotal: TotalBytes(files), + report: report, + } +} + +// advance moves the run on by what one writer has added since it last spoke. +// +// Deltas rather than a running total, because with several files in flight +// "how far the run had got before this file started, plus what is in this +// file" describes no run at all. At one writer the numbers this produces are +// the same ones the sequential loop produced, which is what lets the guards +// that watch the bar stay as they were. +func (g *progressGate) advance(delta int64) { + if g == nil { + return + } + g.mu.Lock() + defer g.mu.Unlock() + g.bytesDone += delta + g.say() +} + +// finished is the end of one file: the delta that squares this writer's +// reporting with what the plan promised, and one more file done. +func (g *progressGate) finished(delta int64) { + if g == nil { + return + } + g.mu.Lock() + defer g.mu.Unlock() + g.bytesDone += delta + g.filesDone++ + g.say() +} + +// say hands the current position out. Called with the lock held, always. +func (g *progressGate) say() { + g.report(Progress{ + FilesDone: g.filesDone, FilesTotal: g.filesTotal, + BytesDone: g.bytesDone, BytesTotal: g.bytesTotal, + }) +} + +// fileProgress is one writer's share of the bar: the gate, and how much of +// this file it has already accounted for. +// +// It exists on the writing goroutine's stack and nowhere else, which is what +// makes the arithmetic below unshared. Everything it hands the gate is a +// delta, so the gate never has to know which file it came from. +type fileProgress struct { + gate *progressGate + reported int64 +} + +// advance is the counting writer's callback: n is the running total for this +// file, and the gate is told the difference. +func (p *fileProgress) advance(n int64) { + p.gate.advance(n - p.reported) + p.reported = n +} + +// finished squares this file up. A file that succeeded is topped up to exactly +// what the plan promised, so the bar lands on the total rather than near it. A +// file that failed gives back everything it reported, because a file that +// failed counts for nothing - the bar would otherwise claim bytes nobody can +// find. That the total can go backwards on a failed file is how it already +// behaves. What is new is only that another writer's bytes may sit in the same +// total while it happens. +func (p *fileProgress) finished(planned int64, ok bool) { + if ok { + p.gate.finished(planned - p.reported) + return + } + p.gate.finished(-p.reported) +} + +// writeOne writes one file under a temporary name and renames it only once it +// is whole, so the output directory never holds an incomplete file. That +// invariant covers the process ending - Ctrl+C, kill, a CI timeout. It does +// not cover power loss, because that would need a flush per file and ten +// thousand of those is a real cost. +// +// It lives here rather than in engine.go because it is what a worker does, and +// this file is meant to be the whole answer to "what runs beside what". +func writeOne(ctx context.Context, f PlannedFile, outDir string, p *fileProgress) (string, error) { + final := filepath.Join(outDir, f.Name) + // The process id is in the name because two runs writing into one directory + // used to meet on it. Measured on 2026-08-03: two runs of the same target + // collided on the temporary file, one of them reported two files it could + // not produce, and the bytes of the other had already gone through the same + // handle. The name never survives the run, so nothing about it has to be + // repeatable - and the file it becomes is settled by the plan, not by this. + // + // Two WRITERS of one run cannot meet on it, because planning refuses two + // files that want the same name and this name is built from that one. + tmp := tempPathFor(outDir, f.Name) + + // os.Create, and O_EXCL was tried here and taken back out on 2026-08-25. + // + // The idea was sound: the check in preflight answers "this name is free" + // a few hundred lines before the write, and O_EXCL would have the + // filesystem answer it at the moment of writing instead. What it costs on + // Windows is not sound. Measured with a probe, a file created in a + // directory reached through a symbolic link: + // + // os.Create works + // O_CREATE|O_EXCL|O_WRONLY fails with "The file exists" + // + // about a file that does not exist. Go asks for the reparse point rather + // than what it points at when O_EXCL is set, so every file of a run whose + // output directory is a link fails - and this tool supports exactly that + // on purpose, because people keep fixtures on a mounted workspace or a + // scratch disk. Two guards said so within a minute of the change. + // + // The window O_EXCL would have closed is a real one and it is small: + // preflight refuses every name that is taken before the run starts, so + // what is left is somebody else creating our temporary name, with our + // process id in it, during the run. Trading a supported way of pointing + // the tool at a directory for that is the wrong way round. + fh, err := os.Create(tmp) + if err != nil { + return "", err + } + + h := sha256.New() + buffered := bufio.NewWriterSize(fh, 64<<10) + counter := &countingWriter{w: io.MultiWriter(buffered, h)} + // Left nil when nobody is listening, so a run without progress does no + // locking at all and allocates nothing for it. + if p.gate != nil { + counter.report = p.advance + } + + writeErr := writeWithoutCrashing(ctx, f, counter) + if writeErr == nil { + writeErr = buffered.Flush() + } + closeErr := fh.Close() + + if writeErr != nil { + _ = os.Remove(tmp) + return "", writeErr + } + if closeErr != nil { + _ = os.Remove(tmp) + return "", closeErr + } + + // The size is the promise. A generator that missed it by a byte is a bug + // worth catching here rather than in someone's test suite, so the file + // never reaches its final name. + if counter.n != f.Plan.Bytes { + _ = os.Remove(tmp) + return "", fmt.Errorf("generator for %s produced %d B where the plan said %d B", + f.Desc.ID, counter.n, f.Plan.Bytes) + } + + if err := os.Rename(tmp, final); err != nil { + _ = os.Remove(tmp) + return "", err + } + return hex.EncodeToString(h.Sum(nil)), nil +} + +type countingWriter struct { + w io.Writer + n int64 + // report, when set, is called with the running total for this file. It is + // what gives progress inside a single large file rather than only between + // files - the case where silence is worst, because one 5 GB file is one + // callback if you only count finished files. + report func(int64) +} + +func (c *countingWriter) Write(p []byte) (int, error) { + n, err := c.w.Write(p) + c.n += int64(n) + if c.report != nil { + c.report(c.n) + } + return n, err +} diff --git a/internal/guard/codeshape_test.go b/internal/guard/codeshape_test.go index 14a2c0c..782b5a6 100644 --- a/internal/guard/codeshape_test.go +++ b/internal/guard/codeshape_test.go @@ -34,14 +34,20 @@ const ( // that counted comments would be a limit on explaining. Measured before // choosing: comments and blanks run 17 to 45 lines in the longest // functions, so counting them would have punished the wrong thing. - longestFunction = 79 + // Lowered from 79 on 2026-09-06: engine.Run stopped being the longest + // function in the tree when the writing went into parallel.go and what was + // left was the checks a run does once. The ratchet only tightens. + longestFunction = 75 // 503 until 2026-09-03. engine.go lost the line that told the plan budget // how big a target was, because the budget stopped needing to be told - it // takes its reference point when it is built. A ratchet goes down when work // makes it lowerable. // Lowered from 502 on 2026-09-05: preflight and the questions it asks about // names moved into their own file. The ratchet only tightens. - longestFile = 457 + // Lowered from 457 on 2026-09-06: writing a file moved out of engine.go + // into parallel.go, beside the goroutines that do it. The longest file in + // the tree is somewhere else now. + longestFile = 433 // Depth answers a different question than length, and it is the better // question of the two. A hundred line function that is flat reads top to diff --git a/internal/guard/concurrency_test.go b/internal/guard/concurrency_test.go index 7070893..7fa5b3a 100644 --- a/internal/guard/concurrency_test.go +++ b/internal/guard/concurrency_test.go @@ -54,6 +54,27 @@ var mayBeConcurrent = map[string]string{ // file and cannot fail - which is what makes the order of the answers, and // the file a refusal names, the same on every run. "internal/audit/parallel.go": "hashing the claimed files runs beside itself, and nothing else in the package does", + // Writing the files IS the run. Measured 2026-09-06, after P7 stopped + // planning from encoding the picture twice: planning 300 PNGs is 51 ms and + // writing them is 2741 ms, so the write loop is 98% of it and the plan is + // 2%. Over goroutines in one process, png 200 kB x240 goes 2.05x at two, + // 3.03x at four, 4.19x at eight and 5.51x at sixteen, and zip 2 MB x80 + // reaches 3.87x at eight - measured with tools/probes/writeparallel, which + // also answered the question that had to come first: a shared heap costs + // nothing, 563.0 MB at one goroutine against 562.8 MB at sixteen. + // + // Added 2026-09-06 and THE OWNER DECIDED IT, with two things put to them + // rather than assumed. Where the pool lives: here rather than shared with + // internal/audit, because the two need opposite behaviour when a run is + // stopped - audit a contiguous prefix, this every file that finished - and + // a shared helper would carry a flag switching the one property each of + // them rests on. And what a stopped run records: every finished file, hole + // or no hole, because a finished file with no manifest entry is a file + // untouchable rule 7 leaves nothing able to remove. + // + // Numbers, the instrument, and the two mistakes made getting them: + // docs/PERFORMANCE-REVIEW-2026-09-05.md section 14. + "internal/engine/parallel.go": "the planned files are written beside each other, and nothing else in the package does", } // Waiting on cancellation is not the same thing as running in parallel. Every diff --git a/internal/guard/crowding_test.go b/internal/guard/crowding_test.go index 00d0bde..a21d136 100644 --- a/internal/guard/crowding_test.go +++ b/internal/guard/crowding_test.go @@ -45,8 +45,10 @@ const ( // same act as editing a golden value for the same reason. // Lowered from 10 on 2026-09-05: audit.Verify dropped under sixty lines // when the per file work moved into compare. The ratchet only tightens. + // Lowered from 2 on 2026-09-06: engine.go dropped out of the crowded band + // when writing a file moved into parallel.go. crowdedFunctions = 9 - crowdedFiles = 2 + crowdedFiles = 1 ) func TestNothingIsQuietlyCreepingTowardsTheCeiling(t *testing.T) { diff --git a/internal/guard/progress_test.go b/internal/guard/progress_test.go index 4f688db..a34d279 100644 --- a/internal/guard/progress_test.go +++ b/internal/guard/progress_test.go @@ -8,6 +8,7 @@ import ( "runtime" "strings" "sync" + "sync/atomic" "testing" "github.com/donislawdev/TestingFilesGenerator/internal/cli" @@ -152,44 +153,81 @@ func TestProgressStaysOffWhenNothingIsWatching(t *testing.T) { } } -// Every report arrives on one goroutine, which is what the window's rate +// No two reports are ever in flight at once, which is what the window's rate // limiter is built on. // // throttle in internal/gui/window keeps a time.Time and reads and writes it -// without a mutex. That is correct today and it is correct for one reason -// only: Options.OnProgress documents that it is called from the goroutine -// doing the work, and Run writes its files one after another. An outside -// review read the window on its own, saw shared state with no lock, and called -// it a defect - then withdrew it on finding the contract, and pointed out that -// nothing pins the contract down. +// without a mutex, and the command line bar moves last and printed the same +// way. Both are correct for one reason: Options.OnProgress says what a caller +// may assume. An outside review read the window on its own, saw shared state +// with no lock, called it a defect, then withdrew it on finding the contract - +// and pointed out that nothing pinned the contract down. So this is the pin. // -// So this is the pin. The day somebody parallelises the write loop, the reports -// arrive from several goroutines at once and this goes red here, in the engine, -// rather than as an occasional wrong number on somebody's progress bar. +// The contract this pins is not the one it used to pin, and the change is +// the reason this comment is long. Until 2026-09-06 it read "called from the +// same goroutine doing the work", and this guard asked exactly that: one +// goroutine, counted from its stack. That promise died with the sequential +// write loop, and this guard is what said so - it went red on the first build +// that wrote files in parallel, naming six goroutines, which is what it was +// written to do. What replaces it is the weaker promise that costs both +// callers nothing: NEVER TWO AT ONCE. A lock gives happens-before just as a +// single goroutine does, so neither caller needed a line of change. +// +// Two things are asked, and the second is why this is not simply weaker than +// what it replaced: +// +// - no two callbacks overlap. A run that dropped the lock fails here. +// - MORE THAN ONE goroutine reported. Without that, a build that quietly +// went back to writing one file at a time would satisfy the first +// question by never having anything to serialise, and this guard would be +// green about a question it had stopped asking - which is the shape O118 +// names. GOMAXPROCS is raised for the duration so the question is the same +// on a one core runner as it is here. // // The goroutine is identified from its stack because Go does not offer the // number any other way. That is a thing to do in a test and nowhere else. -func TestEveryProgressReportArrivesOnOneGoroutine(t *testing.T) { +func TestNoTwoProgressReportsArriveAtOnce(t *testing.T) { dir := t.TempDir() + // Raised so several writers exist wherever this runs. widthFor asks + // GOMAXPROCS, so a runner with one hardware thread would otherwise write + // one file at a time and leave the overlap question unasked. Restored + // afterwards - nothing in this package runs in parallel with it. + defer runtime.GOMAXPROCS(runtime.GOMAXPROCS(8)) + + // inside counts callbacks in flight. Anything but one on the way in means + // two were running together, which is the defect. + var inside atomic.Int64 + var overlapped atomic.Bool + // Under a lock, because a guard that has to survive the very thing it // looks for cannot share a bare map with it. Without this, a run that did // report from several goroutines would end the test binary with "concurrent // map writes" instead of saying how many there were. var mu sync.Mutex seen := map[string]bool{} + opt := engine.Options{ OutDir: dir, Seed: 4457, Command: "test", ManifestName: engine.DefaultManifestName, OnProgress: func(engine.Progress) { + if inside.Add(1) != 1 { + overlapped.Store(true) + } mu.Lock() seen[goroutineName()] = true mu.Unlock() + // Widens the window a broken build would have to hit. Without it + // two callbacks that are genuinely concurrent can still take turns + // by luck, and a guard that needs luck to fail is one that passes + // on the runner and fails on somebody's machine. + runtime.Gosched() + inside.Add(-1) }, } // Several files, and each big enough to report from inside itself, so the // callback is reached both between files and during one. - planned, err := engine.Plan([]engine.Target{txtTarget("files", 6, 2<<20)}, opt) + planned, err := engine.Plan([]engine.Target{txtTarget("files", 32, 2<<20)}, opt) if err != nil { t.Fatalf("planning: %v", err) } @@ -198,17 +236,88 @@ func TestEveryProgressReportArrivesOnOneGoroutine(t *testing.T) { } if len(seen) == 0 { - t.Fatal("no progress arrived at all, so this proves nothing about where it arrives from") + t.Fatal("no progress arrived at all, so this proves nothing about how it arrives") } - if len(seen) != 1 { - t.Errorf("progress arrived on %d goroutines and the contract says one.\n"+ + if len(seen) < 2 { + t.Fatalf("progress arrived on %d goroutine(s), so nothing was ever serialised and "+ + "this guard did not reach the question it asks. Either the run stopped writing "+ + "files beside each other, or GOMAXPROCS could not be raised.", len(seen)) + } + if overlapped.Load() { + t.Errorf("two progress reports were in flight at once, across %d goroutines.\n"+ "Reason: the window's rate limiter reads and writes a timestamp without a lock,\n"+ - "on the strength of that contract. Two goroutines here is a race there, showing\n"+ - "up as a bar that stutters or a report that is never drawn - and only sometimes.", + "and so does the command line bar, on the strength of the contract in\n"+ + "engine.Options.OnProgress. Two at once here is a race there, showing up as a\n"+ + "bar that stutters or a report that is never drawn - and only sometimes.", len(seen)) } } +// A run over several writers still moves the bar forwards only, and still +// lands it on the totals it promised. +// +// The sequential loop got this for nothing: one file at a time, a running +// total, and the last report was the last file. With several writers the total +// is shared and the last report comes from whichever writer finished last, so +// both properties are now arithmetic that can be got wrong - a writer topping +// up by the whole file rather than by what it had not yet reported would sail +// past the total, and one that forgot to top up at all would stop short of it. +// +// Under the race detector this is also the densest contention in the suite: +// thirty two files, several writers, and a callback on every write inside each +// of them. +func TestProgressOverSeveralWritersStillReachesTheEndAndNeverGoesBack(t *testing.T) { + dir := t.TempDir() + defer runtime.GOMAXPROCS(runtime.GOMAXPROCS(8)) + + var mu sync.Mutex + var reports []engine.Progress + opt := engine.Options{ + OutDir: dir, Seed: 8821, Command: "test", + ManifestName: engine.DefaultManifestName, + OnProgress: func(p engine.Progress) { + mu.Lock() + reports = append(reports, p) + mu.Unlock() + }, + } + planned, err := engine.Plan([]engine.Target{txtTarget("files", 32, 1<<20)}, opt) + if err != nil { + t.Fatalf("planning: %v", err) + } + if _, err := engine.Run(context.Background(), planned, opt); err != nil { + t.Fatalf("the run failed: %v", err) + } + + if len(reports) < 32 { + t.Fatalf("thirty two files produced %d reports, so this guard is not looking at "+ + "a run that reported from inside its files", len(reports)) + } + last := reports[len(reports)-1] + if last.FilesDone != last.FilesTotal || last.BytesDone != last.BytesTotal { + t.Errorf("the last report said %d/%d files and %d/%d bytes, so the bar never "+ + "reaches the end it promised", last.FilesDone, last.FilesTotal, + last.BytesDone, last.BytesTotal) + } + var prevBytes int64 + var prevFiles int + for i, p := range reports { + if p.BytesDone < prevBytes { + t.Fatalf("report %d went backwards, from %d B to %d B - with several writers "+ + "sharing one total, a writer that gives back more than it added does this", + i, prevBytes, p.BytesDone) + } + if p.FilesDone < prevFiles { + t.Fatalf("report %d counted %d finished files after %d", i, p.FilesDone, prevFiles) + } + if p.BytesDone > p.BytesTotal { + t.Fatalf("report %d claimed %d B of %d B, which is more than the run will write", + i, p.BytesDone, p.BytesTotal) + } + prevBytes, prevFiles = p.BytesDone, p.FilesDone + } +} + // goroutineName is the identity of the goroutine calling it, taken from the // first line of its own stack: "goroutine 17 [running]:". There is no // supported way to ask, which is why this is confined to one guard. diff --git a/internal/guard/safety_test.go b/internal/guard/safety_test.go index ef66c28..4432eba 100644 --- a/internal/guard/safety_test.go +++ b/internal/guard/safety_test.go @@ -7,8 +7,10 @@ import ( "path/filepath" "runtime" "strings" + "sync" "testing" + "github.com/donislawdev/TestingFilesGenerator/internal/core" "github.com/donislawdev/TestingFilesGenerator/internal/engine" _ "github.com/donislawdev/TestingFilesGenerator/internal/format/all" ) @@ -157,6 +159,140 @@ func TestAnInterruptedRunLeavesNoPartialFileAndStillWritesAManifest(t *testing.T } } +// A run stopped part way names EVERY file that finished, and names nothing +// else. +// +// This is the one thing a person can observe that changed when the files +// started being written beside each other, and it is a decision of the owner's +// from 2026-09-06 rather than a consequence nobody chose. The sequential loop +// could only ever leave a contiguous prefix: file five was finished before +// file six was begun. With several writers, one can be cut off half way while +// its neighbour has already been renamed into place, so what is left on the +// disk may have a hole in it. +// +// The alternative - recording the prefix and leaving the rest - is worse in a +// way untouchable rule 7 names exactly. cleanup deletes what the manifest +// lists and nothing else, so a finished file with no entry is a file NOTHING +// in this tool can ever remove, and verify reports it for good. The same +// reasoning is why the pool here is not the one in internal/audit, which wants +// the opposite: a sentence about an interrupted verify is a sentence about a +// prefix. +// +// So the property is a two way one, and both halves matter. Every entry that +// claims a file has one, and every file on the disk has an entry. +// +// The first version of this guard PASSED WITHOUT EVER REACHING A HOLE, and +// the mutation runner is what said so. It planned four hundred files of four +// kilobytes, which every writer finishes in one pass - so no writer was ever +// cut off half way, what the run left behind was a prefix after all, and the +// mutation that puts the prefix behaviour back could not redden anything. +// A guard that names the defect and cannot meet it is the shape this project +// has recorded twice. So the plan below is built to guarantee the hole: the +// FIRST file is sixteen times the size of the rest, so a later one always +// finishes first, the cancellation always lands while file one is still being +// written, and index one is always missing from what survives. +func TestARunStoppedPartWayNamesEveryFileThatFinished(t *testing.T) { + dir := t.TempDir() + + // Raised so several writers exist wherever this runs, because with one + // writer a stopped run leaves a prefix and the hole this guard is about + // cannot occur. + defer runtime.GOMAXPROCS(runtime.GOMAXPROCS(8)) + + ctx, cancel := context.WithCancel(context.Background()) + defer cancel() + + // Cancelled from inside the run, the moment the first file is finished. + // A timer would make this a guard about how fast the machine is. + var once sync.Once + opt := engine.Options{ + OutDir: dir, Seed: 7741, Command: "test", + ManifestName: engine.DefaultManifestName, + OnProgress: func(p engine.Progress) { + if p.FilesDone >= 1 { + once.Do(cancel) + } + }, + } + // One big file and thirty one small ones, and the order is the whole + // point. Every writer starts at once, one of the small ones finishes long + // before the big one can, and the cancellation that follows cuts the big + // one off - leaving a finished file at a HIGHER index than one that never + // finished, which is the only shape a sequential loop could not produce. + sizes := append([]int64{32 << 20}, engine.Uniform(31, 2<<20)...) + planned, err := engine.Plan([]engine.Target{{ + ID: "files", Format: "txt", Sizes: sizes, + }}, opt) + if err != nil { + t.Fatalf("planning: %v", err) + } + + res, runErr := engine.Run(ctx, planned, opt) + if runErr == nil { + t.Fatal("the run was cancelled from inside itself and reported success") + } + + claimed := map[string]bool{} + for _, f := range res.Manifest.Files { + if f.Materialized { + claimed[f.Name] = true + } + } + + entries, err := os.ReadDir(dir) + if err != nil { + t.Fatalf("reading %s: %v", dir, err) + } + onDisk := map[string]bool{} + for _, e := range entries { + name := e.Name() + if name == engine.DefaultManifestName { + // The run takes this name before the first file and it holds no + // entry of its own. + continue + } + if strings.Contains(name, core.PartialMarker) { + t.Errorf("%s was left behind - a half written file that looks finished "+ + "reaches a test suite as a false truth", name) + continue + } + onDisk[name] = true + } + + // Asserted rather than assumed, and these three are what decide whether + // the comparison below means anything. Two empty sets agree with each + // other, a run that finished everything was never stopped, and a run whose + // survivors happen to be a prefix is the case this guard exists to be + // different from (O118). + if len(onDisk) == 0 { + t.Fatal("the run was stopped before it finished a single file, so there is no " + + "finished file to ask about") + } + if len(onDisk) >= len(planned) { + t.Fatalf("the run wrote all %d files before the cancellation reached it, so it "+ + "was never stopped part way", len(planned)) + } + if onDisk[planned[0].Name] { + t.Fatalf("%s is the biggest file in the run and it finished anyway, so nothing "+ + "here was cut off half way and the survivors are a prefix - which is not the "+ + "case this guard is about", planned[0].Name) + } + + for name := range onDisk { + if !claimed[name] { + t.Errorf("%s is on the disk and the manifest does not name it. cleanup deletes "+ + "what the manifest lists and nothing else, so this file is one no command "+ + "of this tool can remove", name) + } + } + for name := range claimed { + if !onDisk[name] { + t.Errorf("the manifest names %s as written and it is not there, so verify "+ + "reports a file that never existed", name) + } + } +} + func TestAFreshRunIntoAnEmptyDirectoryStillWorks(t *testing.T) { // The guards above refuse things. This one exists so that refusing // everything would not pass as success.