From 2f6e48d441365068b2a379cca4e253f8511520bf Mon Sep 17 00:00:00 2001 From: DonislawDev Date: Sun, 6 Sep 2026 08:41:25 +0200 Subject: [PATCH] perf: the files of a run are written over several threads Writing the files is what a run is. After planning stopped encoding the picture twice, planning a run of 300 PNGs is 51 ms and writing it is 2741 ms, so the write loop was all that was left to parallelise. Measured end to end on built binaries, variants interleaved and their order reversed between repetitions. 240 png files of 200 kB go from 2.03 s to 0.44 s, which is 4.62x. zip 2.88x, docx 2.03x, and two thousand txt files of 4 kB 1.39x - files that small spend their time in what a run does once, and that stays serial. One file of any size is unchanged, and the measurement says so rather than the reasoning: the two ranges overlap there. The bytes do not move, and that was checked rather than argued. All 23 formats compared between the two binaries at ten combinations of size and seed each, 48 malformed recipes through two commands character for character with their exit codes, and the manifest of the same run identical block for block including the order. Everything that runs beside anything else is in one new file, listed in the concurrency gate with its reason, and the race detector is run for it. The whole suite under -race finds zero races. Two things a person can observe. OnProgress no longer promises which goroutine it is called from. It promises never two at once, which the engine gives with a lock. Both callers move unguarded state on the strength of that contract and neither needed a line of change. The lock was priced on the most talkative generator in the tree rather than assumed to be free: 319 840 callbacks in one run through one mutex, ranges overlap, no cost claimed. A run stopped part way now names every file that finished, which can leave a gap where a writer was cut off. Recording only the leading run of them would leave a finished file with no manifest entry, and untouchable rule 7 makes that a file nothing here can remove. Co-Authored-By: Claude Opus 5 --- .github/workflows/ci.yml | 2 +- CHANGELOG.md | 33 +++ internal/engine/engine.go | 208 +++++----------- internal/engine/parallel.go | 376 +++++++++++++++++++++++++++++ internal/guard/codeshape_test.go | 10 +- internal/guard/concurrency_test.go | 21 ++ internal/guard/crowding_test.go | 4 +- internal/guard/progress_test.go | 143 +++++++++-- internal/guard/safety_test.go | 136 +++++++++++ 9 files changed, 770 insertions(+), 163 deletions(-) create mode 100644 internal/engine/parallel.go 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.