Skip to content

perf: compiled-runtime output flushing and match-table transcoding (1.5x) - #717

Merged
ddehilster merged 1 commit into
masterfrom
perf/compiled-runtime-output-and-matching
Aug 25, 2026
Merged

perf: compiled-runtime output flushing and match-table transcoding (1.5x)#717
ddehilster merged 1 commit into
masterfrom
perf/compiled-runtime-output-and-matching

Conversation

@ddehilster

Copy link
Copy Markdown
Member

What

Two changes to the compiled-analyzer runtime, both found by profiling rather than by reading the code.

1. Arun::out flushed the stream on every <<. NLP-ENGINE-499/505 added that so print-debugging survives a crash, with a comment saying the cost was negligible "for typical diagnostic volumes". parse-en-us writes ~6 MB across 19 files per run (a 2.35 MB out.xml), one token at a time, so it became a WriteFile plus a file-position query per write.

Durability now comes from a new Parse::flushostrs() called from Parse::finPass, so every completed pass's output is on disk if the process dies — O(passes) instead of O(writes). NLP_FLUSH_EVERY_WRITE=1 restores the old behaviour for bisecting a crash within one pass.

2. find_str_nocase rebuilt an icu::UnicodeString for every element of a match list on every call, even though every caller passes one of the static const tables emitted into the generated analyzer code. Now cached in a direct-mapped table keyed on the array address.

Profile (before)

Compiled -COMPILED run of parse-en-us, x86 RelWithDebInfo, 37.5 KB input, ~7k stack samples:

symbolself
ntdll!ZwWriteFile25.5%
ntdll!ZwQueryInformationFile13.2%
find_str_nocase (+ICU under it)~18% inclusive
Var::find + Ipair::getKey + Delt<Ipair>::getData~1%

Arun::out was 34.7% inclusive, ostream::flush 32.1%, fflush 32.0%.

That last row is worth noting: the string-keyed variable lookup (Var::find's linear list scan with _tcscmp) looks like the obvious villain when reading the generated code, but it is about 1% of runtime.

Results

Interleaved A/B, 8 runs per arm, parse-en-us. The machine had ~35% background load, so min and p25 are the meaningful columns:

minp25median
flush every write (old)17.19s17.84s19.59s
flush per pass (new)11.69s11.72s13.03s

1.47x – 1.52x.

After the fix, find_str_nocase self time went 13.4% → 4.5%. (A first attempt using std::map for that cache was a complete wash — the tree lookup cost as much as the transcoding it saved. The direct-mapped version is what paid off.)

Correctness

All 18 analyzer output files are byte-identical before and after. Only dbg.log differs, because it contains the per-pass timings.

Not in this PR

run!_chkstk is ~6% of self time. The generator emits one giant matchRule<N> per pass containing a switch over every rule, so the frame is sized for the union of all rules and every rule execution probes it. Confirmed the frames exceed a page: building with /Gs1048576 crashes with an access violation. The fix is emitting one function per rule, which is a change in the analyzer code generator — separate PR.

🤖 Generated with Claude Code

Profiling a compiled -COMPILED run of parse-en-us (x86 RelWithDebInfo,
37.5 KB input, ~7k stack samples) put ~42% of self time in file-write
syscalls and ~18% inclusive in the rule matcher's string comparison.
Neither was where reading the code suggested: the string-keyed variable
lookup (Var::find's linear list scan) is about 1% of runtime.
1. Arun::out flushed on every `<<`. NLP-ENGINE-499/505 added that so
print-debugging survives a crash, with a comment saying the cost was
negligible "for typical diagnostic volumes". parse-en-us writes ~6 MB
across 19 files per run, one token at a time, so it cost a WriteFile
plus a file-position query per write:
ntdll!ZwWriteFile 25.5% self
ntdll!ZwQueryInformationFile 13.2% self
Arun::out 34.7% inclusive
Durability now comes from Parse::flushostrs(), called from
Parse::finPass, so every completed pass's output is on disk if the
process dies. That is O(passes) instead of O(writes).
NLP_FLUSH_EVERY_WRITE=1 restores the old behaviour for bisecting a
crash within a single pass.
2. find_str_nocase rebuilt an icu::UnicodeString for every element of a
match list on every call, even though every caller passes one of the
static const tables emitted into the generated analyzer code. Cache
the UTF-16 form in a direct-mapped table keyed on the array address.
A std::map here is not cheap enough -- measured, the tree lookup cost
as much as the transcoding it saved -- so the slot is found with a
shift+mask and confirmed by comparing the array pointer and its first
element. Self time 13.4% -> 4.5%.
Measured on parse-en-us, interleaved A/B, 8 runs per arm (min/p25, the
machine had background load):
flush every write (old) 17.19s / 17.84s
flush per pass (new) 11.69s / 11.72s 1.47x - 1.52x
All 18 analyzer output files are byte-identical before and after; only
dbg.log differs, because it contains the per-pass timings.
Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
@ddehilster
ddehilster merged commit 2f72415 into masterAug 25, 2026
7 checks passed
Sign up for freeto join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

1 participant

@ddehilster