Performance Part 4
This commit is contained in:
@@ -4,4 +4,4 @@
|
||||
server.url=http://localhost:8787
|
||||
# Stamped by manage-ac.sh (stamp_cli_version) from ac-code-server's agenticcode.version
|
||||
# at build time. "dev" means this jar wasn't built via manage-ac.sh.
|
||||
version=286
|
||||
version=294
|
||||
|
||||
@@ -1,6 +1,8 @@
|
||||
package com.agenticcode.codeserver.service;
|
||||
|
||||
import com.agenticcode.neo4jstore.graph.*;
|
||||
import com.agenticcode.parsercore.ast.model.AstEdge;
|
||||
import com.agenticcode.parsercore.ast.model.AstNode;
|
||||
import com.agenticcode.parsercore.ast.model.LocMetrics;
|
||||
import com.agenticcode.parsercore.ast.model.NodeType;
|
||||
import com.agenticcode.parsercore.ast.spi.CoarseScanner;
|
||||
@@ -15,12 +17,11 @@ import com.agenticcode.parsernatural.NaturalLineCounter;
|
||||
import com.agenticcode.parsernatural.NaturalParser;
|
||||
import io.smallrye.mutiny.Uni;
|
||||
import jakarta.enterprise.context.ApplicationScoped;
|
||||
import org.eclipse.microprofile.config.inject.ConfigProperty;
|
||||
import org.jspecify.annotations.Nullable;
|
||||
|
||||
import java.util.Collection;
|
||||
import java.util.List;
|
||||
import java.util.Map;
|
||||
import java.util.Set;
|
||||
import java.util.*;
|
||||
import java.util.stream.Collectors;
|
||||
|
||||
/**
|
||||
* Parses a source file with the language-specific parser and persists the resulting
|
||||
@@ -39,8 +40,46 @@ public class AstIngestService {
|
||||
private final LineCounter javaLineCounter = new JavaLineCounter();
|
||||
private final LineCounter naturalLineCounter = new NaturalLineCounter();
|
||||
|
||||
public AstIngestService(GraphRepository graphRepository) {
|
||||
/**
|
||||
* Item 179 (DIAGNOSTIC): when false, {@link NodeType#COMMENT} nodes and their {@code DOCUMENTS}
|
||||
* edges are dropped just before persist. Comments are 45.8 % of the `upms` node population and
|
||||
* 60.4 % of everything {@code merge-nodes} processes, and this switch exists to measure what
|
||||
* that actually costs. It is deliberately a config property and not a query parameter: it is an
|
||||
* experiment, not a feature, so it gets no REST or CLI surface.
|
||||
*
|
||||
* <p>Turning it off makes a full parse emit no comments, so a reconciling run <em>deletes</em>
|
||||
* the existing ones — the first run after a flip therefore pays a one-time sweep and must not be
|
||||
* used as a measurement. Compare steady-state runs only.
|
||||
*/
|
||||
private final boolean commentsEnabled;
|
||||
|
||||
public AstIngestService(GraphRepository graphRepository,
|
||||
@ConfigProperty(name = "agenticcode.ingest.comments.enabled",
|
||||
defaultValue = "true") boolean commentsEnabled) {
|
||||
this.graphRepository = graphRepository;
|
||||
this.commentsEnabled = commentsEnabled;
|
||||
}
|
||||
|
||||
/**
|
||||
* Item 179: strips comment nodes and the edges touching them. Applied at the persist seam rather
|
||||
* than in the parsers, so the parse cost stays in both arms of the A/B and the delta isolates
|
||||
* persist — which is the whole question, since finalize never touches a comment node.
|
||||
*/
|
||||
private LanguageParser.ParseResult stripComments(LanguageParser.ParseResult result) {
|
||||
Set<UUID> commentIds = result.nodes().stream()
|
||||
.filter(n -> n.type() == NodeType.COMMENT)
|
||||
.map(AstNode::id)
|
||||
.collect(Collectors.toSet());
|
||||
if (commentIds.isEmpty()) {
|
||||
return result;
|
||||
}
|
||||
List<AstNode> nodes = result.nodes().stream()
|
||||
.filter(n -> n.type() != NodeType.COMMENT)
|
||||
.toList();
|
||||
List<AstEdge> edges = result.edges().stream()
|
||||
.filter(e -> !commentIds.contains(e.sourceId()) && !commentIds.contains(e.targetId()))
|
||||
.toList();
|
||||
return new LanguageParser.ParseResult(nodes, edges);
|
||||
}
|
||||
|
||||
/**
|
||||
@@ -121,7 +160,8 @@ public class AstIngestService {
|
||||
* for a coarse Tier-1 scan.
|
||||
*/
|
||||
public Uni<Void> persist(String project, LanguageParser.ParseResult result, boolean reconcile) {
|
||||
return graphRepository.persist(project, result, reconcile).replaceWithVoid();
|
||||
return graphRepository.persist(project, commentsEnabled ? result : stripComments(result),
|
||||
reconcile).replaceWithVoid();
|
||||
}
|
||||
|
||||
/**
|
||||
@@ -138,7 +178,10 @@ public class AstIngestService {
|
||||
* coarse Tier-1 scan.
|
||||
*/
|
||||
public Uni<Void> persistBatch(String project, List<LanguageParser.ParseResult> results, boolean reconcile) {
|
||||
return graphRepository.persistBatch(project, results, reconcile).replaceWithVoid();
|
||||
List<LanguageParser.ParseResult> effective = commentsEnabled
|
||||
? results
|
||||
: results.stream().map(this::stripComments).toList();
|
||||
return graphRepository.persistBatch(project, effective, reconcile).replaceWithVoid();
|
||||
}
|
||||
|
||||
/**
|
||||
|
||||
@@ -3,7 +3,7 @@ quarkus.http.port=8787
|
||||
# AgenticCode's own release counter (not the Maven project version) — bump this by hand for each
|
||||
# release. Single source of truth for the startup log line, GET /api/version, and the OpenAPI
|
||||
# info version (referenced below via property expression, not duplicated).
|
||||
agenticcode.version=286
|
||||
agenticcode.version=294
|
||||
# OpenAPI / Swagger UI (item 48) — the generated spec is the contract the web-UI TS client
|
||||
# is generated against. Served at /q/openapi (yaml/json); Swagger UI at /q/swagger-ui in dev.
|
||||
mp.openapi.extensions.smallrye.info.title=AgenticCode API
|
||||
@@ -40,3 +40,7 @@ agenticcode.ingest.batch-size=200
|
||||
%prod.quarkus.neo4j.uri=${NEO4J_URI:bolt://neo4j:7687}
|
||||
%prod.quarkus.neo4j.authentication.username=${NEO4J_USER:neo4j}
|
||||
%prod.quarkus.neo4j.authentication.password=${NEO4J_PASSWORD}
|
||||
# Item 179 (DIAGNOSTIC): set to false to drop COMMENT nodes and their DOCUMENTS edges just before
|
||||
# persist. Comments are 45.8 % of the upms node population; this exists to measure what they cost.
|
||||
# Not a feature — no REST parameter and no CLI flag. Leave true for normal operation.
|
||||
agenticcode.ingest.comments.enabled=true
|
||||
|
||||
@@ -112,11 +112,26 @@ Two instrumentation layers, both aimed at the same question — *where does the
|
||||
enrichment steps under Cypher `PROFILE` and logs the five heaviest operators of every step slower
|
||||
than 5 s. Diagnostic only — it answers "is this step matching or writing?", which the step timing
|
||||
alone cannot. Measured overhead on `upms`: none worth reporting (908 s vs 905 s).
|
||||
* **Build-time diagnostic:** `agenticcode.ingest.comments.enabled=false` drops `COMMENT` nodes and
|
||||
their `DOCUMENTS` edges just before persist. It exists to measure what comments cost (item 179:
|
||||
~17 % of a deep refresh) and is **not** a supported operating mode — with it off, `/comments`
|
||||
answers empty. It is a property, not a request parameter, so it needs a rebuild and cannot be set
|
||||
per run.
|
||||
|
||||
What that measured, so nobody re-derives it: an `upms` deep refresh is ~310 s persist and ~600 s
|
||||
enrichment; the five field-resolution steps are 88 % of the latter and every one of them is dominated
|
||||
by *matching*, not writing — `resolve-bare-included` spends 273 M database hits to produce 43 753
|
||||
rows. See roadmap item 156.
|
||||
What that measured, so nobody re-derives it. The figures below are **current** (2026-09-06, two clean
|
||||
runs, roadmap item 175); the campaign of items 153-175 took an `upms` deep refresh from **1 225 s to
|
||||
301 s**, so any older number quoted elsewhere is stale by a factor of four.
|
||||
|
||||
| | now |
|
||||
|---------------------------------|-------------------------------------------------------------------------------------------------------------------|
|
||||
| deep refresh `upms`, end to end | **301 s** (run-to-run spread 3.7 %) |
|
||||
| persist | ~149 s — `merge-edges` 47.6 s, `commit` 34.1 s, `merge-nodes` 24.0 s |
|
||||
| finalize | ~137 s — `resolve-field-placeholder` W/R 43.4 s, `link-args-to-params` 23.7 s, `resolve-bare-included` W/R 37.9 s |
|
||||
| parsing | ~9 s (interleaved with persist) |
|
||||
|
||||
The original diagnosis still holds and is why those steps shrank: the five field-resolution steps
|
||||
were dominated by *matching*, not writing — `resolve-bare-included` once spent 273 M database hits to
|
||||
produce 43 753 rows. See roadmap items 156 and 175, and item 179 for what comment nodes cost.
|
||||
|
||||
## `limit`/`offset` work on some endpoints and are silently ignored on others
|
||||
|
||||
|
||||
@@ -5473,3 +5473,128 @@ reproduced the bug.)*
|
||||
|
||||
**Historical `commit` values in these docs are not comparable with the ones printed from here on** —
|
||||
they were the sum of all three parts. Noted in the javadoc as well.
|
||||
|
||||
## Closing the performance campaign (items 173-175) — 2026-09-06
|
||||
|
||||
- [x] **173. Where the deep refresh stands after items 153-172, and what is left** (written 2026-09-06)
|
||||
|
||||
Deep refresh of `upms`: **1 225 s -> 301 s (-75 %)** (item 175, two clean runs: 301 s / 290 s). Nine reformulations
|
||||
landed, two narrow indexes
|
||||
were kept, five investigations produced no lever and are recorded so nobody repeats them.
|
||||
|
||||
**Where the time sits now.** Re-measured 2026-09-06 (item 175) with **two full
|
||||
`rebuild-and-refresh.sh upms` cycles**, no instrumentation attached, both figures from the runs' own
|
||||
log lines: **run 1 = 301 s, run 2 = 290 s** (spread 3.7 %; run 2 is the faster one because it starts
|
||||
against an already resolved graph). Both columns below are run 1 / run 2.
|
||||
|
||||
| persist (148.7 / 139.0 s) | | finalize (136.8 / 135.1 s) | |
|
||||
|---|---|---|---|
|
||||
| `merge-edges` | 47.6 / 45.9 s | `resolve-field-placeholder` WRITES | 23.8 / 23.9 s |
|
||||
| `commit` | 34.1 / 29.2 s | `link-args-to-params` | 23.7 / 23.2 s |
|
||||
| `merge-nodes` | 24.0 / 22.9 s | `resolve-bare-included` WRITES | 20.7 / 20.2 s |
|
||||
| `merge-positional-nodes` | 13.3 / 14.2 s | `resolve-field-placeholder` READS | 19.6 / 19.3 s |
|
||||
| `merge-nodes-copy` | 7.8 / 7.0 s | `resolve-bare-included` READS | 17.2 / 17.0 s |
|
||||
| `sweep-*` (3 steps) | 9.6 / 9.1 s | `delete-resolved-placeholders` | 7.1 / 7.1 s |
|
||||
| `reap-*-edges` (3 steps) | 8.3 / 7.4 s | `stamp-unresolved-placeholders` | 4.3 / 4.2 s |
|
||||
| `prepare` + `tx-open` | 1.2 / 1.1 s | remaining 44 steps | < 2.6 s each |
|
||||
|
||||
Parsing is only ~9 s: parse and persist are interleaved, so the refresh is essentially persist plus
|
||||
finalize in equal halves. The estimates this table previously carried held up well at step level
|
||||
(every one within ~1 s of the measurement); only the two totals were off, ~162 s / ~140 s against a
|
||||
measured 148.7 s / 136.8 s.
|
||||
|
||||
**Already investigated without a lever — do not re-open without a new idea:** `merge-edges` (166,
|
||||
the Eager costs ~5 %, removing it would freeze the property model), `resolve-field-placeholder` (168,
|
||||
write-bound: 2.6 M property writes in 45 s), `commit` (170, measured as genuine commit I/O once the
|
||||
residual was split), `merge-nodes` (171, two suspicions both refuted), `link-args-to-params` (172,
|
||||
seek-count-bound; the one index that helps costs 15 s to save 10).
|
||||
|
||||
**Candidates for a next attempt**, honestly ranked by what is actually known:
|
||||
|
||||
1. ~~**Fewer, larger persist batches.**~~ **Measured and rejected 2026-09-06 (item 174) --- see below.**
|
||||
The fixed per-batch cost is ~70 ms, so halving the batch count would save ~1.1 s out of 331 s.
|
||||
2. **`delete-resolved-placeholders` (7.2 s)** and the other sub-5 s finalize steps. Small, and the
|
||||
effort-to-payoff ratio is now clearly worse than it was at item 153.
|
||||
3. **Nothing on the read side.** After items 163/167/169 the field resolvers are seek-bound, and
|
||||
item 172 showed the only index that would cut seeks costs more than it saves.
|
||||
|
||||
**What is NOT worth doing**, so the next person does not spend a run finding out: raising the page
|
||||
cache (item 166 measured 11.2 MB read over an entire refresh against a 2.9 GB store — the cache is
|
||||
not the constraint), and any further whole-graph index (item 172: write cost depends on how many
|
||||
*written* nodes touch the index, not on index size).
|
||||
|
||||
**Method notes worth keeping**, each of them learned the hard way today: db-hits systematically
|
||||
mislead on seek-heavy and MERGE-heavy work — measure the clock as well; a single refresh is not a
|
||||
verdict, always check a step you did not change before believing a delta; and a read-only measurement
|
||||
against an already resolved graph short-circuits the field resolvers and flatters every prediction.
|
||||
|
||||
**Housekeeping still open:** commit `d6924a1` is a pure deletion of `CypherQueries.java` (the file was
|
||||
destroyed by a patch script and restored from `56314d5`), and `CypherQueries.java` /
|
||||
`GraphRepository.java` contain mojibake bytes that make `grep` treat them as binary, so recursive
|
||||
searches silently skip them. *(Two further points listed here on 2026-09-06 — the half-staged
|
||||
`CypherQueries.java` and item 161's "not yet measured" title — were resolved the same day.)*
|
||||
|
||||
- [x] **174. Larger persist batches --- measured, no lever (2026-09-06)**
|
||||
|
||||
Item 173 listed "fewer, larger persist batches" as the only remaining idea with a plausible
|
||||
mechanism. It was measured before it was attempted, and the mechanism does not exist. **No code
|
||||
change; `agenticcode.ingest.batch-size` stays at 200.**
|
||||
|
||||
**How it was measured.** One deep refresh of `upms` at batch size 200 (32 batches, 6 311 files),
|
||||
with the `PersistStats` instrumentation from item 170 and a sampler polling
|
||||
`SHOW TRANSACTIONS YIELD estimatedUsedHeapMemory` on the Neo4j side every ~3.8 s. The run took
|
||||
331 s rather than the 302 s baseline; the sampler spawns a `cypher-shell` JVM per sample and
|
||||
accounts for that ~10 %. Timings below are from the run's own log lines, not from the wall clock.
|
||||
|
||||
**The fixed per-batch cost is ~64 ms.** Summed over all 32 batches: `prepare` 1.2 s, `tx-open`
|
||||
0.008 s, `unattributed` 0.000 s --- 37 ms per batch of genuinely fixed work. The only other fixed
|
||||
component is the commit floor, visible on the batches that wrote nothing at all (`commit` 25-28 ms).
|
||||
Going from 200 to 400 files removes 16 batches, i.e. **~1.0 s of ~300 s (0.3 %)** --- inside
|
||||
run-to-run noise, which item 175 measured at 3.7 %. Everything else in persist scales with the data
|
||||
written; per-label figures are in item 175's table.
|
||||
|
||||
**Correction (item 175).** The persist figures first written here came from the sampler run and were
|
||||
inflated by it: persist 159.3 s instead of 148.7 s (+7 %), and the persist/finalize split was given
|
||||
as 159 s / 163 s when it is really ~149 s / ~137 s --- the sampler cost finalize ~19 %. The per-label
|
||||
numbers above were withdrawn for the same reason. **The conclusion is unaffected and in fact slightly
|
||||
stronger:** the fixed per-batch cost is 64 ms, not 70 ms.
|
||||
|
||||
**The earlier batch-400 failure was blamed on the wrong limit.** Item 173 recorded that the attempt
|
||||
"failed on `dbms.memory.transaction.total.max`". That attribution was unfounded and is withdrawn:
|
||||
the measured peak Neo4j transaction heap at batch size 200 is **313 MB against a 1.40 GiB limit**
|
||||
(default 70 % of the 2 GiB Neo4j heap), i.e. 4.5x headroom --- Neo4j was never the binding
|
||||
constraint. The likelier constraint is the *server* JVM: `JDK_JAVA_OPTIONS=-Xmx2500m`, and the run
|
||||
logs show it sitting at **2 219 / 2 500 MB (89 %)** throughout, with a whole batch of parsed ASTs
|
||||
held in memory before persisting. The original failure log is gone (the server container has since
|
||||
restarted), so this is the likely cause, not a proven one. Either way the upside does not justify
|
||||
finding out.
|
||||
|
||||
**Where persist time actually goes.** Persist is ~149 s and finalize ~137 s (item 175) --- parsing is
|
||||
only ~9 s, because parse and persist are interleaved. Persist is therefore still half the refresh,
|
||||
but all of it is per-row write work in `merge-edges` / `merge-nodes` / `commit`, all three of which
|
||||
are already recorded as investigated without a lever (items 166, 171, 170).
|
||||
|
||||
- [x] **175. Closing measurement of the performance campaign (2026-09-06)**
|
||||
|
||||
Every figure in item 173's table was an estimate carried over from mid-campaign runs, and item 174
|
||||
had published persist figures taken from a sampler-perturbed run. Both are now replaced by
|
||||
measurements from **two full `rebuild-and-refresh.sh upms` cycles** run back to back with nothing
|
||||
else touching the stack. **Docs only, no code change.**
|
||||
|
||||
| | run 1 | run 2 |
|
||||
|---|---|---|
|
||||
| deep refresh, end to end | **301 s** | **290 s** |
|
||||
| persist (32 batches) | 148.7 s | 139.0 s |
|
||||
| finalize (51 steps) | 136.8 s | 135.1 s |
|
||||
|
||||
**Run-to-run spread is 3.7 %**, and it is not noise: run 2 starts against a graph the preceding run
|
||||
already resolved, so the field resolvers find less to do. Any future A/B has to compare a first run
|
||||
with a first run. Take **301 s** as the campaign's closing figure, since that is the condition every
|
||||
earlier baseline was measured under.
|
||||
|
||||
**The old estimates were better than expected at step level** --- every single step in item 173's
|
||||
table came within ~1 s of its measurement (`merge-edges` 46.1 estimated vs 47.6 measured,
|
||||
`link-args-to-params` 23.6 vs 23.7, `resolve-bare-included` R+W 38.1 vs 37.9). Only the two totals
|
||||
were wrong, and the sampler run's figures in item 174 were wrong by more (+7 % persist, +19 %
|
||||
finalize). **Instrumentation that polls the database distorts finalize far more than persist** --- worth
|
||||
remembering before attaching a sampler to a run whose timings are meant to be quoted.
|
||||
|
||||
@@ -415,128 +415,116 @@ after probing and are recorded at the end, so nobody re-files them.
|
||||
|
||||
## Ingest performance
|
||||
|
||||
- [ ] **175. Closing measurement of the performance campaign (2026-09-06)**
|
||||
- [ ] **180. The `DOCUMENTS` edge carries two strings and nothing else — 20.2 % of all edges**
|
||||
(found 2026-09-07 while measuring item 179)
|
||||
|
||||
Every figure in item 173's table was an estimate carried over from mid-campaign runs, and item 174
|
||||
had published persist figures taken from a sampler-perturbed run. Both are now replaced by
|
||||
measurements from **two full `rebuild-and-refresh.sh upms` cycles** run back to back with nothing
|
||||
else touching the stack. **Docs only, no code change.**
|
||||
**The finding.** `MODULE_COMMENTS` is the only query that touches comments, and it finds them by
|
||||
`sourceFile`, **not** by traversal — its own javadoc says so. The `DOCUMENTS` edge appears there
|
||||
once, as an `OPTIONAL MATCH`, purely to fill two scalars in the response:
|
||||
|
||||
| | run 1 | run 2 |
|
||||
```cypher
|
||||
MATCH (c:AstNode {type:'COMMENT', project:$project, sourceFile: m.sourceFile})
|
||||
OPTIONAL MATCH (c)-[:DOCUMENTS]->(t:AstNode)
|
||||
RETURN ..., t.name AS target, t.type AS targetType
|
||||
```
|
||||
|
||||
`DOCUMENTS` occurs **zero times** in `GraphRepository` and nowhere else in `CypherQueries`.
|
||||
Nothing traverses it in either direction. So **430 075 relationships — 20.2 % of the entire edge
|
||||
population of `upms` — exist to carry two strings into one endpoint.** That is a modelling error
|
||||
regardless of what it costs.
|
||||
|
||||
**Lever A — replace the edge with two properties.** `targetName` and `targetType` on the `COMMENT`
|
||||
node, set at parse time, where `CommentBlocks.documentedNode(targets, startLine, endLine)` already
|
||||
computes the target. Measured cost of the edges (item 179's A/B removes exactly these edges from
|
||||
`merge-edges` and nothing else):
|
||||
|
||||
| | pair 1 | pair 2 |
|
||||
|---|---|---|
|
||||
| deep refresh, end to end | **301 s** | **290 s** |
|
||||
| persist (32 batches) | 148.7 s | 139.0 s |
|
||||
| finalize (51 steps) | 136.8 s | 135.1 s |
|
||||
| `DOCUMENTS` edges | 4.9 s | 8.0 s |
|
||||
| comment nodes (`merge-nodes`) | 18.4 s | 27.2 s |
|
||||
|
||||
**Run-to-run spread is 3.7 %**, and it is not noise: run 2 starts against a graph the preceding run
|
||||
already resolved, so the field resolvers find less to do. Any future A/B has to compare a first run
|
||||
with a first run. Take **301 s** as the campaign's closing figure, since that is the condition every
|
||||
earlier baseline was measured under.
|
||||
Removes 430 075 relationship merges and ~860 k endpoint index seeks, makes `MODULE_COMMENTS`
|
||||
*faster* (two property reads instead of an `OPTIONAL MATCH`), and costs **no fidelity**: same
|
||||
nodes, same text, same line numbers, same response shape, no API change, no test rewrite.
|
||||
Work needed: parser sets the two properties; `MODULE_COMMENTS` drops the `OPTIONAL MATCH`;
|
||||
`DOCUMENTS` removed from `EdgeType` (or deprecated); a reap for the existing edges on first
|
||||
refresh.
|
||||
|
||||
**The old estimates were better than expected at step level** --- every single step in item 173's
|
||||
table came within ~1 s of its measurement (`merge-edges` 46.1 estimated vs 47.6 measured,
|
||||
`link-args-to-params` 23.6 vs 23.7, `resolve-bare-included` R+W 38.1 vs 37.9). Only the two totals
|
||||
were wrong, and the sampler run's figures in item 174 were wrong by more (+7 % persist, +19 %
|
||||
finalize). **Instrumentation that polls the database distorts finalize far more than persist** --- worth
|
||||
remembering before attaching a sampler to a run whose timings are meant to be quoted.
|
||||
**What it gives up:** a comment is then no longer reachable from the declaration it documents in
|
||||
Cypher. Nothing does that today, but a future "show me the comments on this field" would go by
|
||||
`(sourceFile, line range)` or want an index on `targetName`.
|
||||
|
||||
- [ ] **174. Larger persist batches --- measured, no lever (2026-09-06)**
|
||||
**Lever B — one `COMMENT` node per documented target** (430 075 -> 105 160; comments attach to
|
||||
only 105 160 distinct targets, mean 4.1, and 61 716 targets have exactly one). This is the larger
|
||||
half of the cost, but all 17.6 MB of comment text stays, so it saves the per-node overhead and not
|
||||
the writes — realistically 10-15 s of the measured 18-27 s. It costs the `/comments` response
|
||||
shape, its tests, and per-block node identity.
|
||||
|
||||
Item 173 listed "fewer, larger persist batches" as the only remaining idea with a plausible
|
||||
mechanism. It was measured before it was attempted, and the mechanism does not exist. **No code
|
||||
change; `agenticcode.ingest.batch-size` stays at 200.**
|
||||
**Recommendation: do A, leave B.** A is a strict improvement — less data, less work, a faster
|
||||
query, nothing given up — and worth doing even at zero time saved. B trades real fidelity for a
|
||||
few seconds and should wait until someone needs them. Caveat on A's number: part of the 5-8 s is
|
||||
the endpoint seeks, so the realised saving may land at the lower end.
|
||||
|
||||
**How it was measured.** One deep refresh of `upms` at batch size 200 (32 batches, 6 311 files),
|
||||
with the `PersistStats` instrumentation from item 170 and a sampler polling
|
||||
`SHOW TRANSACTIONS YIELD estimatedUsedHeapMemory` on the Neo4j side every ~3.8 s. The run took
|
||||
331 s rather than the 302 s baseline; the sampler spawns a `cypher-shell` JVM per sample and
|
||||
accounts for that ~10 %. Timings below are from the run's own log lines, not from the wall clock.
|
||||
See item 179 for the measurement and the method (reversed arm order, ratios rather than seconds).
|
||||
|
||||
**The fixed per-batch cost is ~64 ms.** Summed over all 32 batches: `prepare` 1.2 s, `tx-open`
|
||||
0.008 s, `unattributed` 0.000 s --- 37 ms per batch of genuinely fixed work. The only other fixed
|
||||
component is the commit floor, visible on the batches that wrote nothing at all (`commit` 25-28 ms).
|
||||
Going from 200 to 400 files removes 16 batches, i.e. **~1.0 s of ~300 s (0.3 %)** --- inside
|
||||
run-to-run noise, which item 175 measured at 3.7 %. Everything else in persist scales with the data
|
||||
written; per-label figures are in item 175's table.
|
||||
|
||||
**Correction (item 175).** The persist figures first written here came from the sampler run and were
|
||||
inflated by it: persist 159.3 s instead of 148.7 s (+7 %), and the persist/finalize split was given
|
||||
as 159 s / 163 s when it is really ~149 s / ~137 s --- the sampler cost finalize ~19 %. The per-label
|
||||
numbers above were withdrawn for the same reason. **The conclusion is unaffected and in fact slightly
|
||||
stronger:** the fixed per-batch cost is 64 ms, not 70 ms.
|
||||
- [x] **179. What comment nodes cost: measured, 17 % of a deep refresh** (2026-09-07)
|
||||
|
||||
**The earlier batch-400 failure was blamed on the wrong limit.** Item 173 recorded that the attempt
|
||||
"failed on `dbms.memory.transaction.total.max`". That attribution was unfounded and is withdrawn:
|
||||
the measured peak Neo4j transaction heap at batch size 200 is **313 MB against a 1.40 GiB limit**
|
||||
(default 70 % of the 2 GiB Neo4j heap), i.e. 4.5x headroom --- Neo4j was never the binding
|
||||
constraint. The likelier constraint is the *server* JVM: `JDK_JAVA_OPTIONS=-Xmx2500m`, and the run
|
||||
logs show it sitting at **2 219 / 2 500 MB (89 %)** throughout, with a whole batch of parsed ASTs
|
||||
held in memory before persisting. The original failure log is gone (the server container has since
|
||||
restarted), so this is the likely cause, not a proven one. Either way the upside does not justify
|
||||
finding out.
|
||||
Item 141 made comments graph data. They are now **45.8 % of the `upms` node population**
|
||||
(430 075 of 938 746) and **60.4 % of everything `merge-nodes` processes**, plus 430 075
|
||||
`DOCUMENTS` edges — 20.2 % of all edges, and 17.6 MB of text, the largest write payload in
|
||||
persist. This measures what that costs. **No model change was made**; comments stay exactly as
|
||||
they are.
|
||||
|
||||
**Where persist time actually goes.** Persist is ~149 s and finalize ~137 s (item 175) --- parsing is
|
||||
only ~9 s, because parse and persist are interleaved. Persist is therefore still half the refresh,
|
||||
but all of it is per-row write work in `merge-edges` / `merge-nodes` / `commit`, all three of which
|
||||
are already recorded as investigated without a lever (items 166, 171, 170).
|
||||
**Instrument.** `agenticcode.ingest.comments.enabled` (default `true`) on `AstIngestService`,
|
||||
applied in both `persist` and `persistBatch` — the single-file path would otherwise have kept
|
||||
comments while the batch path dropped them. Filtering happens at the **persist seam, not in the
|
||||
parser**, so parse cost stays in both arms and the delta isolates persist. Deliberately a config
|
||||
property and not a query parameter: an experiment gets no REST or CLI surface.
|
||||
|
||||
- [ ] **173. Where the deep refresh stands after items 153-172, and what is left** (written 2026-09-06)
|
||||
**Two pairs were needed, and the second one is why this entry is trustworthy.**
|
||||
|
||||
Deep refresh of `upms`: **1 225 s -> 301 s (-75 %)** (item 175, two clean runs: 301 s / 290 s). Nine reformulations
|
||||
landed, two narrow indexes
|
||||
were kept, five investigations produced no lever and are recorded so nobody repeats them.
|
||||
| OFF as % of ON | pair 1 (OFF ran first) | pair 2 (ON ran first) |
|
||||
|---|---|---|
|
||||
| **persist** | **77 %** | **77 %** |
|
||||
| `merge-nodes` | 33 % | 31 % |
|
||||
| `merge-edges` | 91 % | 87 % |
|
||||
| `commit` | 82 % | 88 % |
|
||||
| finalize | 121 % *(artefact)* | 84 % |
|
||||
| refresh total | 98 % *(contaminated)* | **83 %** |
|
||||
|
||||
**Where the time sits now.** Re-measured 2026-09-06 (item 175) with **two full
|
||||
`rebuild-and-refresh.sh upms` cycles**, no instrumentation attached, both figures from the runs' own
|
||||
log lines: **run 1 = 301 s, run 2 = 290 s** (spread 3.7 %; run 2 is the faster one because it starts
|
||||
against an already resolved graph). Both columns below are run 1 / run 2.
|
||||
**Result: comments cost ~17 % of a deep refresh**, of which persist is the larger and
|
||||
best-established part at 23 %. `merge-nodes` drops to roughly a third, matching the 60.4 % share
|
||||
of what that statement processes. Finalize also benefits (84 %) — fewer nodes, less to scan —
|
||||
which was not predicted.
|
||||
|
||||
| persist (148.7 / 139.0 s) | | finalize (136.8 / 135.1 s) | |
|
||||
|---|---|---|---|
|
||||
| `merge-edges` | 47.6 / 45.9 s | `resolve-field-placeholder` WRITES | 23.8 / 23.9 s |
|
||||
| `commit` | 34.1 / 29.2 s | `link-args-to-params` | 23.7 / 23.2 s |
|
||||
| `merge-nodes` | 24.0 / 22.9 s | `resolve-bare-included` WRITES | 20.7 / 20.2 s |
|
||||
| `merge-positional-nodes` | 13.3 / 14.2 s | `resolve-field-placeholder` READS | 19.6 / 19.3 s |
|
||||
| `merge-nodes-copy` | 7.8 / 7.0 s | `resolve-bare-included` READS | 17.2 / 17.0 s |
|
||||
| `sweep-*` (3 steps) | 9.6 / 9.1 s | `delete-resolved-placeholders` | 7.1 / 7.1 s |
|
||||
| `reap-*-edges` (3 steps) | 8.3 / 7.4 s | `stamp-unresolved-placeholders` | 4.3 / 4.2 s |
|
||||
| `prepare` + `tx-open` | 1.2 / 1.1 s | remaining 44 steps | < 2.6 s each |
|
||||
**The prediction was wrong, and low.** 25-30 s was estimated from proportional arithmetic; the
|
||||
real figure is 40-75 s depending on machine speed. The node/edge counts, by contrast, were
|
||||
predicted exactly (938 746 -> 508 671, 2 123 868 -> 1 693 793), which is what made the timings
|
||||
worth reading at all — the filter was verified before the clock was.
|
||||
|
||||
Parsing is only ~9 s: parse and persist are interleaved, so the refresh is essentially persist plus
|
||||
finalize in equal halves. The estimates this table previously carried held up well at step level
|
||||
(every one within ~1 s of the measurement); only the two totals were off, ~162 s / ~140 s against a
|
||||
measured 148.7 s / 136.8 s.
|
||||
**The cold-first-run artefact — the reason arm order must be reversed.** Pair 1 showed finalize
|
||||
*21 % slower* without comments, concentrated in `link-args-to-params` at 47.4 s against 27.5 s.
|
||||
That step provably cannot see a comment node: comments carry **exactly one edge type,
|
||||
`DOCUMENTS`**, no `CONTAINS` and no incoming edges at all, while the step traverses `CONTAINS` and
|
||||
seeks on `(project, sourceFile, paramPosition)`. Reversing the order settled it — in pair 2 the
|
||||
step is 25.6 s vs 27.9 s, i.e. equal. **The 47.4 s was the first measured run of the session, not
|
||||
the comment-less arm.** Any future A/B here must run both orders, or discard its first run.
|
||||
|
||||
**Already investigated without a lever — do not re-open without a new idea:** `merge-edges` (166,
|
||||
the Eager costs ~5 %, removing it would freeze the property model), `resolve-field-placeholder` (168,
|
||||
write-bound: 2.6 M property writes in 45 s), `commit` (170, measured as genuine commit I/O once the
|
||||
residual was split), `merge-nodes` (171, two suspicions both refuted), `link-args-to-params` (172,
|
||||
seek-count-bound; the one index that helps costs 15 s to save 10).
|
||||
**Ratios, not seconds.** The machine ran ~25 % slower during pair 2 (load average 3.8 -> 6.7 on 8
|
||||
cores, a VirtualBox VM alone at 163 % CPU), so absolute seconds were not comparable across pairs
|
||||
— but the persist ratio came out at 77 % in *both*. Expressing an A/B as a ratio of arm to arm
|
||||
within one run cancels machine drift; this is the method to use when the host cannot be quiesced.
|
||||
|
||||
**Candidates for a next attempt**, honestly ranked by what is actually known:
|
||||
**If someone wants to spend this 17 %:** the obvious shape is one `COMMENT` node per documented
|
||||
target instead of per block — 430 075 -> **105 160** nodes, since comments attach to only 105 160
|
||||
distinct targets (mean 4.1 each, 61 716 targets have exactly one). That should capture most of the
|
||||
persist saving while keeping comments queryable, at the cost of reworking `/comments`, its
|
||||
response shape and its tests. Not attempted.
|
||||
|
||||
1. ~~**Fewer, larger persist batches.**~~ **Measured and rejected 2026-09-06 (item 174) --- see below.**
|
||||
The fixed per-batch cost is ~70 ms, so halving the batch count would save ~1.1 s out of 331 s.
|
||||
2. **`delete-resolved-placeholders` (7.2 s)** and the other sub-5 s finalize steps. Small, and the
|
||||
effort-to-payoff ratio is now clearly worse than it was at item 153.
|
||||
3. **Nothing on the read side.** After items 163/167/169 the field resolvers are seek-bound, and
|
||||
item 172 showed the only index that would cut seeks costs more than it saves.
|
||||
**Raw data** (durable, outside the repo): `/home/ingo/ac-measurements/item179/` and `item179b/` —
|
||||
per-arm server logs, counts, and run logs with load averages.
|
||||
|
||||
**What is NOT worth doing**, so the next person does not spend a run finding out: raising the page
|
||||
cache (item 166 measured 11.2 MB read over an entire refresh against a 2.9 GB store — the cache is
|
||||
not the constraint), and any further whole-graph index (item 172: write cost depends on how many
|
||||
*written* nodes touch the index, not on index size).
|
||||
|
||||
**Method notes worth keeping**, each of them learned the hard way today: db-hits systematically
|
||||
mislead on seek-heavy and MERGE-heavy work — measure the clock as well; a single refresh is not a
|
||||
verdict, always check a step you did not change before believing a delta; and a read-only measurement
|
||||
against an already resolved graph short-circuits the field resolvers and flatters every prediction.
|
||||
|
||||
**Housekeeping still open:** commit `d6924a1` is a pure deletion of `CypherQueries.java` (the file was
|
||||
destroyed by a patch script and restored from `56314d5`); `CypherQueries.java` is partly staged (`MM`)
|
||||
as a side effect of that restore; item 161 below still carries "not yet measured" in its title although
|
||||
it was measured; and `CypherQueries.java` / `GraphRepository.java` contain mojibake bytes that make
|
||||
`grep` treat them as binary, so recursive searches silently skip them.
|
||||
|
||||
- [ ] **156. The five field-resolution steps expand wide and filter late** (measured
|
||||
2026-09-05 with `refresh?profile=true`, item 155)
|
||||
|
||||
Reference in New Issue
Block a user