Hold the build wall clock with a budget, and take the derived-read slices R732 left unmeasured

Baseline on trunk: 410.1 seconds, 610 test classes reporting. Where it goes:

The second-pass column is the point. Every module except graphitron-sakila-example is within a few seconds of where it was when the build took 706 seconds; that module alone fell from 410.6s to 93.6s, and it is what R742 bought. So the build is now flat, and an item that wants to take a big slice out of it has to find something every module pays rather than one class that is slow.

One caveat on reading that table too closely: graphitron-maven-plugin measured 39.6s, 46.1s, 30.8s and 32.0s across four runs of identical work, its integration tests forking Maven builds of their own. Treat any single figure for it as ±8s, and do not attribute a change to it without repeating the run.

GeneratorDeterminismTest is 18.99s (R742’s landed 18.13s, remeasured here) and FixtureWarningsGateTest, which is one full-fixture generator run and nothing else, is 2.862s.

JFR attributes a sample to a call site; it cannot say which statement ran, how many times, or whether one read cost 900ms or twelve reads cost 35ms each. This pass wired an env-guarded ExecuteListener onto the store’s own DSLContext, fingerprinting each statement (bind values collapsed) and dumping count, total and max at JVM exit. The recipe is at the end of this section and it is the durable part of this pass: every number below came from it, and none of them was visible in a profile.

One full-fixture generator run executes 185 statements and spends 2.55 seconds inside them. Five reads are 84% of that:

The JFR profile agrees and adds the non-store residue: over GeneratorDeterminismTest (20.80s, 1443 samples, stackdepth=1024) the store reads are 55.3% of samples, the store’s own DDL boot 7.7%, ConnectionPromoter.rebuildAssembledForConnections 4.2%, FactSink.flush 2.5%, and nothing else reaches two percent. Garbage collection is 49 pauses and about 0.3 seconds of 21, so it is not a lever and should not be looked at again.

R742 lands the multiplicity report so that the third registration is chosen from data. It ranks views by their own subtree size, which answers which read is expensive. The question a chooser actually has is a different one: if this relation were materialized, how many instantiations disappear from the reads a run performs? That is computable from the same parse, weighting each read by the milliseconds the instrument measured for it.

The answer is intent_resolved_type_binding, and it is not close. It is named in all four hot reads and removes 684 of the 1321 instantiations across them, halving every one:

Registered as a throwaway instrument, with both target classes green:

Per read, and this is the part that reorders the slices below: the defect read goes 912.3ms to 72.4ms, the two projection reads 601.0ms to 36.2ms, the key-column loop 415.6ms to 1.3ms, and the type-id read 213.6ms to 1.7ms. The registration’s own refresh costs 59ms per run, which is the whole of the new cost.

One small thing the mechanism does per refresh, which matters more as the store gets faster. Materializations decides a target’s refresh shape by asking INFORMATION_SCHEMA.COLUMNS whether it carries a graph_name column, once per registration per refresh. The instrument prices that at about 13ms a call: 26.5ms per run at R742’s two registrations, 79.9ms across five runs at three. It is 1% of a 2.55 second run and 7% of a 0.40 second one, and it grows linearly with the registry. The answer is a property of the schema and invariant for a store’s lifetime, so it wants computing once rather than per refresh. Small, but it belongs to whoever touches the materializer next, which is R746.

The metric under-predicts a registration’s value, badly, and the report should say so. Linear in instantiations removed, the projection was 1.18 seconds per run; the measurement was 2.15. Removing a windowed view from the middle of a tree removes its subtree’s re-evaluation per instantiation, which a linear model cannot see. R742 argues for a generous ceiling on the grounds that the metric over-approximates a relation’s cost; as a predictor of a registration’s saving it under-approximates, and a chooser who trusts the linear reading will decline registrations worth taking.

intent_resolved_type_binding_live reads intent_bound_table, which reads intent_spelled_table, which is a registered target. Materializations.refresh iterates the registry in source_view_name order, and intent_resolved_type_binding_live sorts before intent_spelled_table_live, so the binding target is refilled from a spelling target that is still empty. R746 predicted exactly this and called it the first thing a third registration would want.

What R746 did not predict is the symptom, and it is worse than the quiet wrong answer that item expects. The build fails, confidently, blaming the schema author:

Nothing is wrong with that schema. A materializer ordering bug arrives at the author as an instruction to change their own SDL, which is the worst available failure mode for a performance mechanism. The 11.61s above was measured by renaming the source view so it sorts last, which is a measurement trick and not a fix.

Two consequences for R746, and both are that item’s business rather than work for this one. Its priority: 4 looks wrong now that it gates the largest measured saving left in the store. And its closing claim that it "is not a performance item at all" is true of the registry as it stands and false of the registry anyone will want next. R746 entered Spec under another session while this pass was running, so both are recorded in its body as arguments for its Spec pass to weigh rather than applied over it; the priority field is untouched.

The gate that should catch it cannot yet exercise it, and that is a third consequence. FactSchemaGateTest.everyMaterializedTargetEqualsItsRule is the case that holds a target against its rule. R742’s Done gate found it vacuous, both registered relations yielding zero rows in its fixture, and R742’s rework has since given it real rows, so it would now report a target populated from an empty predecessor. What it still cannot reach is the ordering itself: its fixture carries two registrations that do not depend on each other, which is the very property that makes ordering unnecessary today. Closing that wants a fixture registration whose view reads another registration’s target, and this pass’s failure text is the concrete case such a fixture has to fail on before R746’s sort is in place.

Added by the In Review gate on the diagnostics-drain budget-overrun item, since shipped, which landed intent_resolved_type_binding as a meta_materialize registration at 272ef13 for the language server’s diagnostics drain, together with a second registration of intent_field_column_scope. So the slice above, the one this item measured as worth more than everything else in it combined, is on trunk. It arrived from the language-server side rather than from the build-wall-clock side, and its reason row argues the drain’s arithmetic rather than this item’s.

Two things follow for this item’s Spec pass. The 18.99s to 11.61s on GeneratorDeterminismTest and the 2.55s to 0.40s of store time per run are now trunk’s baseline rather than an available win, so the ordering of the remaining slices was computed against a store that no longer exists and wants re-deriving from fresh numbers. And the block this item recorded is gone: the refresh order is no longer the registry’s source_view_name order but a topological one over meta_materialize_dependency, derived at boot by no.sikt.graphitron.model.derive.MaterializeDependencies, which is exactly the case that landed here, intent_field_column_scope_live reading the binding’s target while sorting ahead of it alphabetically.

The per-refresh INFORMATION_SCHEMA.COLUMNS probe this item priced is untouched and has grown rather than shrunk. Materializations still asks the catalog whether each target carries a graph_name column once per registration per refresh, and the registry now holds six registrations rather than the three that number was taken at.

Slice 3 below was promoted to first by the second pass. This pass measured it and it is worth nothing.

Start with the premise. The slice says the DDL declares "zero `CREATE INDEX`", which is true and reads as a store with no indexes. The store has 260: H2 creates a primary-key index for each of the 143 keys and a constraint index for each of the 117 foreign keys that needed one. What the store lacks is an index on a column that leads no key, which is a much smaller claim.

Then the measurement. The join predicates on the two materialized targets are uniform enough to index exactly: intent_spelled_table is joined on (graph_name, spelling) at all six of its sites, and intent_argmapping_pair on (graph_name, type_name, field_name) at ten and (graph_name, site, use_site, position) at six. Three indexes cover every one of them. With all three in place, GeneratorDeterminismTest measured 18.42s and 19.98s against a baseline of 18.99s and 20.80s, and FixtureWarningsGateTest 2.973s and 2.628s against 2.862s. There is no effect to find.

The reading, offered as the best available rather than as proven: after R742 the remaining cost is per-instantiation plan overhead, not per-row comparison. The relations these joins reach are small (sql_table 71 rows, sql_column 251 in the plugin’s own store), and an index on a 71-row table saves nothing against a plan instantiated 765 times. Value.compareToNotNullable staying the top JFR leaf frame at 11.3% is consistent with this and is not evidence against it: comparisons are what a plan does, and there are a great many cheap plans rather than a few expensive scans. The write-side worry the second pass raised about indexes is moot, the slice having no read-side win to trade against it.

Keep the negative result. It is the second time this item has aimed at indexes on a reading of a profile leaf frame, and the finding is that this store’s cost has not been row volume since R742.

The violation is real and it is worse than this item describes. StoreNodeTables.read loops bindings(...) and calls keyColumns(...) inside the loop, 12 times per run on this fixture, and it is the second-largest call site in the JFR profile at 11.4%. It also calls tableRef(...) in the same loop, which issues three more reads per node type (sql_table joined to sql_schema, then sql_column, then sql_primary_key joined through sql_constraint_column to sql_column). Four reads per node type, not the one this item names.

And after the registration above, the whole intent_resolved_node_key_column loop costs 1.3 milliseconds per run: 60 reads across five runs, 6.7ms total, 0.2ms at the worst. The 380ms this slice would have recovered is recovered by the registration instead, and taking both does not take it twice.

So this stops being a performance slice and becomes purely what this item wanted it for: the worked violation behind the "batch by key set, never loop by key" enforcer, with a method whose own javadoc asserts what its body contradicts. Spec it on those grounds and quote 1.3ms, not 380ms.

Shipped at 452c497, re-measured at 821890c, split out as its own item because it was one line of DDL and touched nothing else here. The wire spelling left storage: every file column and the diagnostic view hold paths, the two boundaries whose protocol names a document by URI render one at their own edge, and the CREATE ALIAS carrying inline Java source went with them, so no store boot runs javac any more.

Kept here as the datum this item’s flat module table asks for, not as remaining work. The statement was 64.5ms of a 212ms boot on the sandbox that found it, seven times the next most expensive, and it never amortised, each store paying its own compilation (four warm alias-only boots in one JVM: 85.9, 65.9, 62.9, 51.1ms). Re-measured on a faster sandbox at landing: 28.8ms of a 159.5ms boot, so 18.6ms and 11.7% off every boot, and 387s to 349s end to end on a full green mvn install -Plocal-db. It was consumer-facing as well, every graphitron:generate, language-server session and MCP server start paying it once.

This item carries the extension as "smaller than a slice" at the end of the unmeasured list. It is measured now, and it is one module rather than three.

The first reading of this was wrong and is worth keeping as the method lesson. Giving graphitron-model, graphitron-lsp and graphitron-mcp the same junit-platform.properties graphitron already has took two full builds from 367.4s to 310.8s and 317.7s, both green, and the three modules' spans appeared to account for 34.6s of it. Those spans are not a usable instrument on a 4 vCPU sandbox. Over five runs of identical work graphitron-maven-plugin spanned 30.8s to 46.1s and graphitron-model 37.7s to 113.9s, so an 11-second "win" inside one pair of runs is noise wearing a number.

A clean per-module A/B, mvn test -pl :<module> with the arms alternated and repeated, says:

graphitron-model is worth more alone than the three were credited with together, and that fits what the module is: its test cost is almost entirely per-case store boots, 152 of them, each an independent in-memory database, which is the shape concurrency helps. That row stands.

The other two rows are an artifact and the real figures are large. Once graphitron-model’s properties file landed it began riding along in that module’s test-jar, which `graphitron-lsp and graphitron-mcp both consume at test scope, so both arms of their A/B ran parallel and the test compared parallel against parallel. Re-measured with the entry stripped from the installed test-jar and the arms alternated: graphitron-lsp 33.4/33.0s against 50.1/50.8s, −17.5s, and graphitron-mcp 26.9/28.1s against 35.0s, −7.5s. So test parallelism is worth about 25 seconds in those two modules after all, it is already in effect, and it arrives through a channel neither module’s pom mentions. R764 carries the mechanism and what to do about it.

Two traps to know before re-running this, both of which produce the same false "nothing". Removing a junit-platform.properties from src/test/resources does not remove the copy Maven already put in target/test-classes. And for any module that depends on another module’s test-jar, the file can arrive from that jar instead, in which case a -pl A/B varies nothing at all. Check the installed test-jars of the upstream modules, not just the module under test.

The remaining caution stands unchanged: green runs are not thread safety. graphitron’s own properties file documents the process-global hazard and carries `@Isolated on the two classes that trip it, and nothing measured here establishes that graphitron-model has no such state; what is established is that every case there owns its own store.

The recipes at the end of this item still apply. This one is new and is what produced every number above.

Add an env-guarded ExecuteListener where the store builds its DSLContext (GraphitronModelStore’s constructor), recording each statement’s wall clock against a fingerprint of its SQL with string literals collapsed, and dump the ranking from a shutdown hook. Two details are load-bearing. Dump to a file named by PID rather than to stderr: a Maven build has at least two JVMs executing store statements, the build’s own and each surefire fork, and a fork’s stderr after the test run is lost. And read the two dumps as different subjects, because they are: the Maven JVM’s covers the module’s `graphitron:generate executions, which is the write side, and the fork’s covers the tests, which is the read side. Conflating them is how the census below looks like a read cost.

Same instrument on the Maven JVM, over graphitron-sakila-example’s five `graphitron:generate executions: 1346 statements and 13.3 seconds inside them, of which the jvm_ family’s deletes and merges are about 8.1 seconds, 62%. On a second run under heavier load the same set was 12.6 of 15.5 seconds, 81%. The single most expensive statement outside the census is one derivation insert into intent_type_backing_class, at 1.87 seconds across six executions.

R685 already owns this and should not be re-specced. What it does not carry is this half of the number: R685 measures the scan (516ms of the 648ms each classpath scan costs) and the row count (87% of everything the store holds), and the store-write cost of those same rows is the 62% above. Worth adding there as evidence. One more figure for the same item: the persisted store the plugin leaves behind is 845 MB for 418,192 rows, of which about 400,000 are the census.

Recorded because it is a negative result and the next person should not pay for it twice. The question was whether the census, which is written enumeratively and mostly serves the editor, is also read enumeratively on the build path, which would have made a read-side cut available on top of R685’s width cut. It is not. Fourteen views depend transitively on the jvm_ family, and every one the generator reads (intent_field_producer_method, intent_type_backing_seed, intent_resolved_node_key_projection, intent_field_accessor_hop, intent_argmapping_projection_defect) reaches the census through a join on a graphitron_ or graphql_ relation, so it is already anchored to the names the schema wrote. The enumerative readers are the editor’s and the MCP server’s. There is no build-path read to narrow, and the write cost above stays the whole of the census’s contribution to build wall clock. The row-share figures the dig produced went to R685, whose case they strengthen.

The dig did turn up one thing, and it is a correctness hazard rather than a win: the census’s transitive closure view intent_class_assignable does not return on a real census, filed as R760 with a validated rewrite. It costs no wall clock today precisely because nothing reads it, so it is not a slice of this item; it is on this list only so that a later pass measuring the census does not rediscover it as a mystery hang.

Pushing the same question one level further did find a write-side lever, filed as R762, and it is larger than anything left on this list. Anchored is not the same as shallow: the reads being anchored to a written class name is exactly what makes the depth of the census optional. Two of the nine jvm_ relations carry the enumerative load at 11,851 rows, the other seven are 405,374 rows and 97% of the census, and every read of those seven pins a class name that is already in the document. One class’s members resolve from the classfile in about 0.1 ms, so the depth is a storage choice. Against the 8.1 seconds of jvm_ writes above, and on a measured row-to-time proportionality, that is where the census’s contribution to build wall clock actually sits. It belongs to R762 and R685 rather than here, and it wants an end-to-end measurement after the change rather than a projection from the proportionality.

The first two are the cheapest things on this list by a wide margin, neither needs the third and neither needs this item’s guardrail. The second has since landed directly against trunk, for one module rather than the three first credited, at a reproducible 21 seconds; the first is filed as its own item at 42.7 seconds and is what a Spec pass should take first. Quote those two figures separately rather than adding them: they were measured with different instruments, on trunks twenty commits apart, and the combined 96-second figure an earlier draft of this section carried came from whole-build spans that the parallelism entry below shows are too noisy on this hardware to carry a sum.

In the order the numbers argue for, and every one of them is now measured rather than bounded.

Trunk baseline: 11m47s, 5919 tests in 604 classes. Where it goes, by module wall clock:

R732 did its work: graphitron is 79.4s against the 181.2s it started from, and ColumnMatchShadowTest is 8.96s against the 74 to 120s that motivated the item. The three slices below that target graphitron and graphitron-mcp are now aimed at 16% of the build between them.

graphitron-sakila-example is where the build now is, and inside it two classes are almost all of it: GeneratorDeterminismTest at 240.5s across 2 test methods, and FixtureWarningsGateTest at 56.8s across 1. Neither is slow because it is a slow test. Both run GraphQLRewriteGenerator over the full fixture schema, four times and once respectively, and one such run costs about 57 seconds. The build pays for six of them. So the subject is not the test tier at all: it is the generator’s own hot path, which means every consumer pays it on every build of theirs, and the build is merely the place we can see it.

JFR over one run (FixtureWarningsGateTest in isolation, 60.49s, 5470 samples, stackdepth=1024 because the default 64 truncates every stack below the H2 frames and hides the caller):

97.4% of samples are inside H2 evaluating a query. Attributed to the deepest no.sikt frame, five call sites are 95.7% of the run:

EXPLAIN ANALYZE on the first of those, inside the real populated store: one query scans about 2.57 million rows to return a handful of defect rows, and intent_spelled_table is expanded at 469 separate plan nodes within it.

Both were applied as throwaway instruments to get numbers, not as proposed final code. A full mvn install -Plocal-db was green on both, all 5919 tests, and reproduced on a second run.

So about 122 seconds for the batched read and a further 69 for the index, 191 seconds of a 706 second build between them, and GeneratorDeterminismTest goes 240.5s to 86.2s while FixtureWarningsGateTest goes 56.8s to 20.6s. The index’s end-to-end share is smaller than its read-side share for the reason the write-side paragraph below gives.

The batched read. StoreNodeTables.read loops for (var binding : bindings(...)) and calls keyColumns(...) inside the loop, so it reads intent_resolved_node_key_column once per node type, 31 times over the fixture schema. That view is a DENSE_RANK() OVER (PARTITION BY graph_name, type_name) over a three-arm union, and a window sees its whole partition whatever predicate the reader applies outside it, so each of the 31 reads paid the entire view. This is the same defect R732 fixed in ColumnMatchShadowTest, found this time in the generator rather than in a test. The change is one query grouped with fetchGroups, 19 lines across the method and its two helpers.

Worth naming precisely, because it is the argument for an enforcer rather than a fix: the method’s own javadoc already says it "reads the whole population rather than a requested subset …​ the query is one pass per relation either way". The prose was right and the code did not match it, and nothing checked.

The index. The fact store’s DDL declares 140 tables, 56 views, 161 primary keys and zero CREATE INDEX. The spelling-resolution join in intent_spelled_table matches sql_table.table_name_upper, a generated column with nothing behind it, so it scans sql_table every time, and that view is expanded hundreds of times per query. A single CREATE INDEX ... ON sql_table (source_name, table_name_upper) takes the generator run from 46.90s to 23.49s.

The index is not free, and this is the part the first pass did not anticipate. Capture writes the whole catalog, so an index is maintained on every insert. Timing the five graphitron:generate executions alone (mvn generate-sources -pl :graphitron-sakila-example -Plocal-db): 1m06.7s without the index, 1m31.0s with it, so about 24s on the write side in that module, and `+graphitron-maven-plugin` moves 37.6s to 45.9s for the same reason. The net across the build is strongly positive because five of the six full-fixture generator runs happen in tests, which read and do not write. But it means each candidate index has to be measured on both sides, and a broad "index the hot columns" sweep is not the shape of the work.