Compiler-test compiles: SKC_TIME_PHASES misses ~90% of the time (fixed stdlib-load cost)

[mbouaziz]

Timing the compiler tests with SKC_TIME_PHASES

Now that SKC_TIME_PHASES (#1291/#1292) is in main, I profiled the compiler test suite by compiling every test file with it set. The headline: SKC_TIME_PHASES accounts for only ~10% of a test compile — the other ~90% is a fixed, uninstrumented per-invocation cost (loading the stdlib sklib).

Method

Each valid test compiled exactly as the harness does — skc -O0 --no-inline --export-function-as <Module>.main=skip_main -o <bin> <file>.sk — with SKC_TIME_PHASES=1, capturing the ##TIME## lines. All 896/896 valid tests compiled successfully (parallel run, coverage check). Per-compile figures below are from a single-threaded run (no contention) over a stratified 12-file sample; every file landed within 4831–4941 ms regardless of its content, so the numbers are highly stable. Measured on this dev box (20 cores) with the stage1 release skc; absolute ms will differ on CI hardware, but the proportions won't.

Result: ~90% of a compile is untimed

	per compile
Total skc wall	~4870 ms
Sum of all SKC_TIME_PHASES phases	~493 ms (~10%)
Untimed	~4377 ms (~90%)

The instrumented phases (the ~10% we can currently see), single-threaded means:

phase	ms	% of instrumented
native/link (clang++)	184	37%
frontend+ir (createIR)	112	23%
native/compile	97	20%
native/write_asm_files	50	10%
native/create_asm_graph	48	10%
native/merge_asm_graph	0.7	—
native/create_asm_symbols	0.5	—
outer/makeOuter	0.01	—

What the untimed ~4.4s is

It's a fixed cost paid on every skc invocation, independent of the input — an empty fun main(): void { void } compiles in the same ~4.87s. strace pins it down:

• skc opens libstd.sklib (2×) and zero prelude .sk sources — so it loads the precompiled stdlib, it does not recompile the prelude.
• strace -c shows only ~0.18s in syscalls (mostly wait4 on the clang++ link). The ~4.4s is CPU-bound userspace work — deserializing/materializing the stdlib into the compiler's SKStore context, plus parse/name/type of the input.

Note this also means the frontend+ir label (from #1292) overstates what it captures: it wraps IR generation (~112 ms); the real frontend/stdlib cost happens before it and is untimed.

Scale across the suite

At ~4.87s/compile, single-threaded subprocess mode:

• 896 valid tests ≈ 73 min; with the 823 invalid tests, 1719 compiles ≈ 140 min.
• Of that, the fixed stdlib-load overhead (~4.4s × 1719) is ≈ 126 min of redundant work — the same stdlib materialized from scratch 1719 times.

This is exactly the cost the unified @exptest harness (#1289) removes by compiling all tests into one binary (the stdlib is loaded once). It's also why the old per-test subprocess path was slow.

Takeaways

1. SKC_TIME_PHASES is currently blind to ~90% of compile time. The stdlib-load/materialization and the parse/name/type frontend aren't wrapped in runCompilerPhase. Extending the instrumentation to cover them (and splitting frontend+ir into real frontend vs IR-gen) would make the profiler actually point at where time goes.
2. sklib load/materialization (~4.4s) is the single highest-leverage compiler-perf target. It dominates every compile and every non-unified test run. Worth a dedicated look at why deserializing a 1.6 MB sklib costs seconds of CPU.
3. Within the codegen/link phases that are timed, native/link (clang++) and native/compile are the largest — but they're a rounding error next to the stdlib load.

Raw per-file ##TIME## data available if useful.

🤖 Generated with Claude Code

[mbouaziz]

Found the blind spot: type-checking the stdlib is ~64% of every compile

Following up on the ~90% that SKC_TIME_PHASES couldn't see. I instrumented it and re-measured — the untimed time is now fully attributed.

Why it was invisible, and how it's instrumented now

The whole frontend runs as per-key reactive computations inside SKStore's engine, not as wrapped function calls — compile() writes all 109 stdlib sources into input dirs and context.update() pushes them through the eager-dir chain parse → name → type → outer → backend. None of that is a runCompilerPhase call, so it was dark.

The fix is a single per-dir hook in Context.updateWithStatus: each reactive arrow firing is exactly one dir's whole dirty-key batch, so it emits one ##TIME## dir/<name> line per stage (~tens of lines, not thousands). Plus two compiler-side wraps: the pre-update() sklib JSON decode, and context.update() itself as a cross-check bound.

Where a compile actually goes

Per-compile, single-threaded, near-identical across all test files (~4.6–4.9s total):

stage	ms	% of compile
type-checking (dir//typing/)	~3150	~64%
backend (dir//backendsink/ = IR-gen + codegen + link)	~505	~11%
naming (dir//namingclasses/ + namingfuns/ + …)	~410	~8%
outer IST (dir//outerdefs/)	~245	~5%
parsing (dir//astandaccessedenvvarscache/)	~180	~4%
sklib JSON decode (frontend/sklib-decode, pre-update)	~60	~1%
startup + writeFiles + misc (still untimed)	~350	~7%

Cross-check: the dir/* stages sum to update/total (~4530 ms), and dir//backendsink/ equals the previously-timed frontend+ir + native/* phases combined — so no double-counting. Coverage went from ~10% → ~93% of a compile.

Two things this also exposed: the old frontend+ir and outer/makeOuter wraps were near-useless — the real work is in dir//typing/ and dir//outerdefs/; the labels were on the wrong calls.

Takeaway

The stdlib is re-type-checked from source on every single compile (~3.15s), and that dominates everything. Across a subprocess test run (~1719 compiles) that's ~90 minutes spent re-typing the same stdlib — exactly what the unified @exptest harness (#1289) amortizes by loading it once. The compiler-side win would be a genuinely precompiled typed sklib (cache the typed defs) instead of re-typing the embedded source each run; dir//typing/ is the single highest-leverage target in the compiler.

Instrumentation is on branch time-phases-frontend (3-file diff) if it's worth upstreaming to make SKC_TIME_PHASES cover the frontend by default.

🤖 Generated with Claude Code