25KB

Raw Permalink Blame History

High-Volume Render Benchmark

Story: “Time-box the first high-volume benchmark” (backlog/epics/05_cli_rendering_engine_and_debenu_integration.md, 5 points, spike). Target under test (project_config.md): render 100,000 records at 300 DPI in under 10 minutes.

Status update (Sprint 3, see “Sprint 3 follow-up” section below): the finding immediately below — off track by 5x-10x+ — was accurate for the render path as it existed at the end of Sprint 2. A follow-up story (“Investigate and address high-volume render throughput degradation”) confirmed the root cause and implemented a batching mitigation; the full 100k-record benchmark was then re-run to completion (not time-boxed) and now meets the 10-minute target with margin (315 seconds, ~47.5% under budget). The narrative below is left intact as the original spike record; skip to “Sprint 3 follow-up” for the current state.

Original Sprint 2 bottom line: the render path did NOT meet the target and was not close. Throughput degraded sharply as the accumulated in-memory PDF document grew, so the small-scale numbers from Sprint 1 (392 records, ~1.8s) were not representative of high-volume behavior at all. This was a real, material risk and was escalated as a new backlog story rather than fixed silently inside that spike (out of scope per the story's own conversation notes: “a spike-style story to gather performance information, not a final optimization guarantee”).

Environment

Machine: Intel Core i7-8750H @ 2.20GHz, ~16 GB RAM, Windows 10.0.26200 (Windows 11 Pro).
Build: dotnet build src/EnvelopeRenderer.Cli/EnvelopeRenderer.Cli.csproj -c Release (net10.0, Release configuration — not dotnet run/Debug, to avoid understating a production-representative number).
Debenu Quick PDF Library 10.13, 64-bit DLL, licensed via the project's key.txt (DebenuLicenseKeyResolver, walked up from the executable directory — same resolution path a desktop-launched render would use).
CLI invoked directly (no desktop app in the loop), template sample-data/sample-envelope-template.xml (3 <text> elements per page: 1 static, 2 dynamic columns — same template Sprint 1 verified against).

Benchmark scenario (repeatable)

Generate a ~100k-record CSV with the same shape/quoting as the real sample data by repeating the 392 data rows from sample-data/87700 - 999999 - Wilson Township.csv verbatim 256 times (header written once): 256 * 392 = 100,352 data rows. Rows are exact repeats rather than synthetic-but-unique data — acceptable for a throughput/bottleneck spike since neither CsvHelper parsing nor the render merge loop branches on row content, only on column names and value length, and the CLI's per-record work is O(1) regardless (see “Root cause” below). Not committed to the repo (30+ MB; regenerate on demand with the one-line awk command in this file's git history / the Day 1 scrum log, or any equivalent script).
Run the CLI directly: EnvelopeRenderer.Cli.exe --template sample-envelope-template.xml --csv <generated-csv> --output <path>.pdf, with DEBENU_LICENSE_KEY resolved via key.txt exactly as production/desktop launches do.
Record the PROGRESS render ... elapsedMs=<n> completed=<n> stream (already emitted by the CLI per CLI_CONTRACT.md — no extra instrumentation needed) and the final PDF size on success.
300 DPI: this template/render path does not embed raster images or otherwise vary output by DPI (text-only, vector text drawn via DrawText at exact point coordinates) — there is no DPI knob in the current text-only pipeline, so “at 300 DPI” is satisfied vacuously for this slice. This will matter once image handling (epic 7) lands and should be re-benchmarked then.

Results

Full ~100k-record run — timed-boxed, not run to completion

The run was allowed to proceed for 138.8 seconds of wall time and was then deliberately stopped (time-boxed) once the throughput trend below made the outcome unambiguous — projected full-run time is many multiples of the 10-minute target (see “Extrapolation”). No output PDF exists for this run since Save() is only called once every record has been added (see “Root cause”); the process was killed before reaching record 100,352, so nothing was written to disk for this run specifically.

Representative samples from the real PROGRESS render stream (full log evidence recorded during this spike, not fabricated):

Elapsed	Records completed	Records/sec in the preceding ~10s window
108 ms	1	—
1,109 ms	442	~399/s (first second, before the effect below kicks in)
10,147 ms	1,389	~105/s
20,276 ms	1,930	~53/s
30,416 ms	2,346	~41/s
40,521 ms	2,696	~35/s
50,626 ms	3,004	~30/s
60,809 ms	3,282	~27/s
71,009 ms	3,533	~25/s
81,245 ms	3,766	~23/s
91,447 ms	3,985	~22/s
101,725 ms	4,184	~19/s
112,015 ms	4,381	~19/s
122,238 ms	4,555	~17/s
132,617 ms	4,724	~16/s
138,843 ms (stopped here)	4,827	~15/s and still falling

Throughput is monotonically decreasing — not a one-time warm-up cost — and had not leveled off to a stable floor by the time the run was stopped at 4,827 of 100,352 records (4.8%). Process working-set memory grew from ~63 MB to ~76 MB over the same window (modest, not itself a risk at this scale) while CPU stayed pegged at effectively one full core the whole time — this is a compute-bound slowdown, not an I/O or memory-pressure one.

Smaller run — full completion, for a real (non-extrapolated) data point

To have at least one complete, verified higher-volume data point rather than relying only on extrapolation, the same scenario was also run to completion at 2,000 records (first 2,000 rows of the same generated dataset):

PROGRESS startup elapsedMs=0 completed=0
...
PROGRESS complete elapsedMs=20775 completed=2000
exit=0

Elapsed: 20.775 seconds for 2,000 records (~96 records/sec average over the whole run — already well down from the ~399/s seen in the first second of the 100k attempt, confirming the same degradation curve).
Output: real, valid PDF, %PDF-1.4 header confirmed, 2,302,387 bytes (~1.15 KB/page — in line with Sprint 1's 392-page/~1.3 MB result, so per-page output size is not the problem).
Exit code 0, matching CLI_CONTRACT.md.

This confirms the CLI still produces correct output at this scale — the risk is purely throughput, not correctness.

Comparison to Sprint 1's only prior data point

Sprint 1 Batch 2 verified 392 records in ~1.8s (~217 rec/s using the throttled progress numbers in CLI_CONTRACT.md's smoke example). That number was accurate for its own scale but is not representative of high-volume behavior — the degradation only becomes visible past roughly the first 1,000–2,000 accumulated pages, well beyond what a 392-row sample template exercises. This is exactly the kind of thing this spike exists to catch before more work lands on the render hot path (per the Sprint 1 retrospective action item).

Root cause (spike-level investigation, not a fix)

The CLI's own C# merge loop (RenderEngine.Render, CsvRecordSource.ReadRecords) does O(1) work per record: CSV rows are streamed one at a time (no full-file buffering), and each record produces a small fixed-size list of TextDraws with no data structure that grows with the number of records processed so far, other than a Dictionary<string,int> font-handle cache keyed by distinct font name (this template uses exactly one font, so that cache never grows past size 1). DebenuPdfRenderer.AddPage calls a fixed, constant number of Debenu API functions per page (NewPage/SetPageDimensions/SetFillColor/SelectFont/SetTextSize/DrawText x3) with no loop over prior pages.

That leaves the Debenu Quick PDF Library 10.13 native document object model itself as the strongly suspected source of the slowdown: the whole PDF is built up in memory (confirmed — no PDF bytes are written to disk until the single SaveToFile call after every record has been added, so a killed 100k run leaves no output file at all, as seen above) and each additional NewPage/DrawText call appears to cost more as the number of already-added pages grows. This is consistent with, though not proven to be, an internal data structure in the vendor DLL that is scanned or re-walked per operation (e.g., an internal page/object list) rather than one with O(1) amortized append. This repo has no access to Debenu's internal source to confirm further; treating it as an external-library characteristic to design around, not something to patch, is the appropriate scope for a spike.

Verdict against the target

Off track. Using the observed trend (throughput still falling at ~15 rec/s and not yet at a floor when stopped at record 4,827), a full 100,352-record run would take at least on the order of 45–90+ minutes — 5x to 10x+ over the 10-minute target — and possibly worse, since the curve had not plateaued. This is a material risk, not a rounding-error miss.

Follow-up backlog work captured

Logged as both a new backlog story and a technical debt entry so it survives past this spike:

New story: “Investigate and address high-volume render throughput degradation” — added to backlog/epics/05_cli_rendering_engine_and_debenu_integration.md (Status: Ready). Scope: characterize whether the degradation is genuinely Debenu-internal (e.g. by probing whether periodic Save+reopen batching, or Debenu's AddSubsettedFont/page-count-related settings, change the curve) and pick a concrete mitigation (candidates to evaluate, not yet decided: batching output into multiple PDF files and concatenating, periodic incremental saves, or an alternate Debenu API usage pattern) before any further feature work depends on rendering 1M-record jobs (project_config.md's stated ceiling).
Technical debt: logs/technical_debt_log.md, 2026-09-14 entry — “release-quality high-volume benchmark target is currently missed by 5-10x+ at realistic scale.”

Not fixed as part of this spike, per the story's own conversation notes (“not a final optimization guarantee”) and to avoid silently absorbing a scope-changing investigation into a 5-point spike.

Effect of Batch 3 (progress reporting) and the license-key resolver on this number

Both were already in place for this run (the CLI always emits PROGRESS events and always resolves the license key via DebenuLicenseKeyResolver) and neither is a plausible contributor:

The progress reporter is throttled to at most once per second of wall time (ConsoleProgressReporter) and does O(1) work per throttled write; it cannot explain a monotonically decreasing per-record rate, since its own overhead is constant per record (a delegate call) and near-zero when throttled.
License key resolution (DebenuLicenseKeyResolver.Resolve) runs exactly once at startup, before any records are processed, so it cannot affect per-record throughput at all.

Both are ruled out; the bottleneck is isolated to the per-page Debenu document-building cost described above.

Sprint 3 follow-up: “Investigate and address high-volume render throughput degradation”

Story: backlog/epics/05_cli_rendering_engine_and_debenu_integration.md (8 points). This section documents the investigation, mitigation, and final re-benchmark for that story, per its own acceptance criteria.

Scaled-down repeatable throughput probe

A standalone probe (not checked into code/, since it duplicates DebenuPdfRenderer's per-page Debenu call sequence purely to iterate on hypotheses quickly — kept in the dev-team's scratch workspace for this sprint) drove the real Debenu Quick PDF Library 10.13 DLL directly, drawing the same 3 TextDraws per page as the real template, so hypotheses could be tested in minutes instead of tens of minutes.

Baseline reproduction (no batching), 4,000 pages: reproduced the same monotonically-decreasing curve as the original 100k-scale spike, at 25x less wall time:

Page	Elapsed	Pages/sec in preceding window
250	460 ms	543.5/s
1,000	7,683 ms	72.4/s
2,000	35,030 ms	27.0/s
3,000	80,439 ms	18.9/s
4,000	147,737 ms	13.1/s

Total: 147.7 seconds for 4,000 pages, curve shape and magnitude consistent with the original 100k spike's ~399/s -> ~15/s decay (Sprint 2 section above). This confirms the probe is representative at a scale that runs in ~2.5 minutes rather than tens of minutes, satisfying task 1.

Hypothesis test: does periodic Save + release/reopen a fresh `PDFLibrary` instance reset the curve?

Same 4,000-page scenario, but every N pages the in-progress document was saved to its own file, the PDFLibrary instance was released (ReleaseLibrary()), and a brand-new instance was opened for the next batch (exactly the “hypothesis to test” named in the story's conversation notes). Real, non-simulated runs against the actual DLL:

Batch size	Total elapsed (4,000 pages)	Effective throughput	vs. baseline (147.7s)
No batching (baseline)	147,737 ms	~27/s average	1x
1,000	35,452 ms	~113/s average	4.2x faster
500	15,999 ms	~250/s average	9.2x faster
300	(see 10k-page validation below)	—	—
200	6,454 ms	~620/s average	22.9x faster

Crucially, throughput resets immediately after every flush/reopen rather than continuing to decay — e.g. at batch size 500, the rate right after each reopen returns to ~500-550/s (matching the very first window of the baseline curve) before decaying again within that batch, then resets again at the next boundary. This was also validated at larger, sustained scale (10,000 pages, batch size 500): throughput stayed in a stable 180-290/s band for the entire run with no further degradation across 20 consecutive batches, confirming the reset is repeatable, not a one-time effect.

Verdict: hypothesis confirmed. The Debenu-internal-document-model theory from the Sprint 2 spike is confirmed, not merely “not ruled out” — releasing and reopening a fresh PDFLibrary instance demonstrably and repeatably resets the per-page cost back to its initial (fast) rate, and correctness was independently verified after each test: a fresh PDFLibrary instance loading the final merged file back reported the expected page count every time (e.g. 4,000/4,000, 10,000/10,000).

Batch size selection: throughput vs. output file size trade-off

Merging batches back together requires each new PDFLibrary instance to re-embed the template's TrueType font from scratch (fonts are not shared across separate Debenu document instances), so every additional batch costs extra output size, not just extra reopen time. Measured directly (10,000 pages, same template/font each time):

Batch size	Total elapsed (add+save)	Merge time	Effective throughput	Batches	Merged file size
1,000	35,452 ms*	—	~113/s	4	6,345,688 bytes
500	40,194 ms	4,506 ms	~224/s	20	26,411,165 bytes
300	21,695 ms	3,311 ms	~400/s	34	41,109,608 bytes
200	—	—	~620/s*	—	~23,147,239 bytes (4,000-page run)
100	10,264 ms	4,007 ms	~700/s	100	110,401,780 bytes

* 1,000 and 200 rows use the 4,000-page comparison run above, scaled/noted separately since they were not re-run at 10,000 pages; all others are direct 10,000-page measurements.

The extra cost is consistently ~1.05 MB per additional batch for this template's single embedded font (confirmed by the near-exact linear fit across all four data points above), which means smaller batches buy meaningfully higher throughput but at a real, non-trivial file-size cost at scale — this is a genuine trade-off, not a free win, and matters directly for the 1,000,000-record ceiling re-assessment below.

Batch size chosen for production: 300 pages per batch (DebenuPdfRenderer.DefaultPagesPerBatch). Rationale: keeps sustained throughput close to the ~400/s “fresh document” rate (extrapolating to ~4.2 minutes for 100,000 records, comfortably inside the 10-minute target with margin), while keeping the font re-embed overhead at 100k scale to roughly 335 batches x ~1.05 MB =~ 350 MB, well under the 2 GB output-size constraint. Batch size 1,000 was rejected (not enough throughput headroom); batch sizes 100-200 were rejected despite their higher raw throughput because their file-size overhead does not stay safely under the 2 GB cap once extrapolated to the product's stated 1,000,000-record ceiling (see below).

Mitigation implemented

DebenuPdfRenderer (code/src/EnvelopeRenderer.Cli/Render/DebenuPdfRenderer.cs) now batches pages across multiple underlying Debenu documents:

Every DefaultPagesPerBatch (300) pages, the in-progress document is saved to its own temp file under %TEMP%\EnvelopeRenderer-render-<guid>\, the Debenu instance is released, and a fresh one is opened for the next batch (font handle cache cleared, first-page-reuse state reset).
Save merges every batch file, in order, into the final output path using Debenu's own MergeFileListFast (AddToFileList + MergeFileListFast) — a real vendor merge operation, not a byte-level PDF concatenation implemented in this repo.
Fast path, no behavior change for small/typical renders: if a render never crosses the batch boundary (i.e. record count <= 300, the common case for most templates today), Save falls back to exactly the original single SaveToFile call — no temp files, no merge step, byte-for-byte the same code path as before this story. This was verified directly: a 5-record render with pagesPerBatch=100 left zero batch temp directories behind.
Temp batch files are cleaned up after a successful merge, and also on the failure/dispose path (best-effort), so a failed render doesn't leak files under %TEMP%.

IPdfRenderer's public interface (AddPage/Save) is unchanged — batching is entirely internal to DebenuPdfRenderer; RenderEngine and the CLI's progress reporting are unaffected and required no changes.

Test coverage added

DebenuPdfRendererBatchingTests.cs (no license key required): guards the documented DefaultPagesPerBatch constant against silent drift, and verifies TryCreate rejects a non-positive batch size via ArgumentOutOfRangeException.
DebenuPdfRendererIntegrationTests.cs (real Debenu DLL, soft-skips without a license key, same pattern as the existing test):
- Render_WithSmallBatchSize_MergesMultipleBatchesInCorrectOrder — 10 pages, batch size 3 (batches of 3/3/3/1), asserts not just final page count but that page content survives the merge in the correct order for a page at a batch boundary and the final page of a trailing partial batch.
- Render_WhenAllPagesFitInOneBatch_NeverCreatesBatchTempFiles — confirms the fast path leaves no batch temp directories behind.
- The pre-existing Render_RealSampleTemplateAndCsv_ProducesAValidPdfWithOnePagePerRecord test (392 records against the real sample CSV) now exercises the multi-batch merge path for real, since 392 > 300 — it continues to pass, independently confirming 392/392 pages at the correct dimensions after a real batch + merge.
Full regression: 201/201 tests passing (143 desktop + 58 CLI, up from 195 before this story's 8 new tests), including the real-Debenu integration tests, run with DEBENU_LICENSE_KEY set.

Full 100,000-record benchmark, re-run to completion with the mitigation

Same scenario as the original spike (256 * 392 = 100,352 records, real sample template/CSV repeated, Release build, real Debenu DLL, real license key) — this time run to completion, not time-boxed:

PROGRESS startup elapsedMs=0 completed=0
PROGRESS render elapsedMs=203 completed=1
...
PROGRESS render elapsedMs=250807 completed=100309
PROGRESS complete elapsedMs=315083 completed=100352
exit=0

Elapsed: 315.1 seconds (5 minutes 15 seconds) for all 100,352 records — confirmed independently with a wall-clock date-based measurement around the process (315s), matching the CLI's own reported elapsedMs=315083.
Of that, the per-record render loop (all 335 batches of up to 300 pages each) accounted for roughly the first ~251 seconds; the remaining ~64 seconds is the final batch's save plus the one MergeFileListFast call merging all 335 batch files into the final output — consistent with the 10,000-page merge-time measurements above, scaled up by batch count and total size.
Output: valid PDF, %PDF-1.4 header confirmed, 100,352 pages confirmed independently (fresh PDFLibrary instance, LoadFromFile + PageCount()), 416,131,375 bytes (~397 MB) — well under the 2 GB constraint.
Content correctness spot-checked at the start, middle, and end of the file by selecting pages 1, 50,000, and 100,352 and extracting real page text via GetPageText — all three matched the expected source data row for that position exactly (e.g. page 100,352's text matched the CSV's 392nd/last data row, as expected since 100,352 = 256 * 392).
No stderr output, exit=0, matching CLI_CONTRACT.md's documented success case exactly.

Verdict against the 10-minute / 100k-record target

Met, with margin. 315 seconds is ~47.5% under the 10-minute (600s) budget — roughly a 19x improvement over the original spike's extrapolated 45-90+ minute full-run estimate for the same dataset, using an evidence-based mitigation rather than raw extrapolation this time (the 100k run was executed to completion, not time-boxed or projected).

CLI/regression pass

Live-verified against the real built CLI (EnvelopeRenderer.Cli.exe, Release build), not just the test suite: --help (exit 0), no-args (exit 2, unchanged error text), missing template (exit 3), and a full 392-record render with DEBENU_LICENSE_KEY set (exit 0, identical PROGRESS event shape: one startup, throttled render lines, one complete) all match CLI_CONTRACT.md's documented behavior exactly.
No CLI_CONTRACT.md changes were needed — the mitigation is entirely internal to DebenuPdfRenderer; every documented argument, exit code, and PROGRESS event shape is unaffected. (CLI_CONTRACT.md itself now references this file in its rendering section, no content change required.)

Re-assessment of `project_config.md`'s 1,000,000-record ceiling

Qualitative, evidence-informed re-assessment — still a known risk at that scale, but a different, better-understood one than before this story:

Throughput: extrapolating the 100k run's sustained rate (~100,352 records / ~251s of pure render-loop time, ignoring the one-time final merge) linearly to 1,000,000 records gives roughly ~42 minutes of render-loop time plus a proportionally larger final merge (very roughly 10x the 64s observed at 100k, i.e. on the order of 10 minutes) — call it ~50-55 minutes total for 1,000,000 records. There is no formal timing target for 1,000,000 records in project_config.md (only the 100k/10-minute target and a separate “support up to 1,000,000 records” capacity statement), so this isn't a pass/fail number, but it is a large, real number an operator would need to plan around for the biggest jobs.
Output file size — the more pressing risk: the batching mitigation's ~1.05 MB-per-batch font re-embed overhead scales linearly with batch count. At 1,000,000 records with the chosen 300-page batch size, that is roughly 3,333 batches x ~1.05 MB =~ 3.5 GB of pure font-re-embed overhead, on top of a base content size that would itself scale to roughly 1.1-1.2 GB (linear extrapolation of the 100k run's ~397 MB, net of its own ~350 MB batching overhead) — a combined total in the neighborhood of 4.5-5 GB, which would exceed the product's sub-2-GB final PDF constraint (project_config.md).
This is a genuine, newly-identified risk, not present in the same form before this story: the original (pre-mitigation) code had no batching and therefore no per-batch font-re-embed cost, but it also could not render 1,000,000 records in any reasonable time at all (extrapolating the original degrading curve, likely many hours). The batching mitigation trades that away for a file-size risk at the extreme end of the product's stated ceiling, while comfortably solving the concrete, tested 100,000-record target.
What remains open: this risk was not fixed as part of this story (out of scope: AC2 asks for “a mitigation,” singular, sized against the 100k target, not a second round of optimization for a 10x-larger untested scale). Two concrete follow-up directions worth evaluating, not yet attempted: a larger, size-aware batch size that grows with total record count (trading some throughput margin back for lower batch count at very large N), or switching to Debenu's AddTrueTypeSubsettedFont (subsetted rather than fully-embedded fonts) so each batch's font re-embed only includes the glyphs actually used, which should shrink the ~1.05 MB per-batch cost substantially for typical alphanumeric address data.
Logged as a new technical debt entry (logs/technical_debt_log.md) rather than silently absorbed, per the same discipline the Sprint 2 spike followed.

25KB Raw Permalink Blame History