Add a contrib profiler that reports where a workload spends its time

Merged
CH
9h ago
+1467-231

The existing contrib tools each show part of the picture: validate prints raw per-instance times, trace follows one instance, and perf reads CPU counters on Linux but exits when they are unavailable. None of them shows how a workload splits between compilation and evaluation, or which keywords make compilation expensive.

This PR adds contrib/profiler, which profiles a schema against a set of instances and writes one JSON report. It replaces contrib/perf, whose cold and warm hardware counters it covers, so there is a single program. It uses only the public compiler and evaluator APIs and only builds with BLAZE_CONTRIB=ON. Nothing under src/ changes.

sourcemeta_blaze_contrib_profiler --output report.json \
  benchmark/e2e/geojson/schema.json benchmark/e2e/geojson/instances.jsonl

This is the first step of a larger profiling effort. It measures everything that is possible from outside the library. Later PRs would add optional, compile-time-gated hooks inside the compiler for the costs that cannot be separated from outside today:

  • unevaluated dependency analysis
  • reference planning
  • postprocessing
  • before and after instruction counts

Those would only go in if the numbers from this tool show they are worth it.

What it measures

  • Compilation. It times bundling, framing and the compile body separately, mirroring the convenience compile() overload. It also counts the template's instructions by type. A wrapper around default_schema_compiler gives each keyword a call count, inclusive time and self time, and the report includes the wrapper's own overhead.
  • Evaluation. It runs a cold pass, warm passes timed per instance, and warm passes timed as a whole, each summarised with min, max, mean, p50, p95 and p99. Results are cross-checked so the measurement never changes an answer.
  • Trace steps (--trace-steps). A separate callback pass counts steps by instruction type. A coverage block flags what the callback cannot see, such as the children of AssertionObjectPropertiesSimple and five Control* instructions.
  • Hardware counters (Linux). It reads cycles, instructions, branches, branch misses, cache references and cache misses for each phase. Elsewhere, the report says why the counters are unavailable and the run continues.

The report also records the timer's resolution and bias, and adds a note when samples are too small to trust. Anything not measured is null, never 0.

Example

These are numbers for benchmark/e2e/geojson (500 instances, FastValidation) from one run on an M-series Mac:

  • Compilation took 4.9 ms: 2.3 ms bundling, 0.9 ms framing and 1.7 ms compile body. It produced 411 template instructions.
  • type dominated self time with 308 calls and 0.36 ms. properties and oneOf are large only inclusively.
  • Keyword timing added about 13 µs to a 1.28 ms compile body, roughly 1%.
  • Evaluation averaged 4.8 µs per instance. The warm p50 was 167 ns and the warm p99 185 µs; the cold p99 was 317 µs.

Replacing contrib/perf

The profiler's counter code started from contrib/perf and fixes the issues it had:

  • A counter labelled "branch predictions" actually measured branch instructions.
  • Ratios could divide by zero.
  • A counter that failed to open ended the program.
  • PERF_EVENT_IOC_RESET does not reset the enabled and running times, so each phase now takes its own baseline.

Two other existing issues turned up but are left alone here, as they are outside this PR's scope:

  • contrib/validate crashes with an uncaught exception when a schema has a $ref that cannot be resolved.
  • contrib/trace.cc is not clang-formatted.

I can send either fix separately if wanted.

Verification

I ran the profiler by hand on macOS arm64, and on Linux with gcc 13 and with clang 18 under ASan. The runs covered the geojson workload, valid and invalid instances, an empty instances file, a schema that fails to compile, and bad arguments. Each report was checked for consistency: the phases add up and the keyword accounting balances.

Not yet verified:

  • Real hardware counter values. My Docker environment has no PMU, so I tested the counter code with software events instead.

Whole-pass and per-instance timing added no overhead measurable above run-to-run noise.