Skip to content

Query latency: do once what every query repeated; first build reports its stage instead of blocking - #1576

Merged
swapnilpaliwal-sd merged 1 commit into
0.1.3from
fix/query-latency
Sep 28, 2026
Merged

swapnilpaliwal-sd merged 1 commit into
0.1.3from
fix/query-latency

Conversation

@swapnilpaliwal-sd

@swapnilpaliwal-sd swapnilpaliwal-sd commented Sep 28, 2026 •

Copy link
Copy Markdown
Contributor

Symptom

On a 34k-line Next.js/TypeScript app, queries took 42-61 s each while the machine was busy (1-5 s idle), and agents using the tool spent the extra time on slow queries. A first query on an unindexed repository blocked for minutes with no output; under MCP past 900 s it failed with a bare "Error executing tool" (#1557).

Where the time goes (measured)

Phases per verb, median of 3, macOS, on a 34k-line React/TSX app (296 files, fresh graph). Busy = 9 of 10 cores running yes (load average 58-75). Seconds.

verb load total launch chain (node → python probe → bash ×3 → sed/tr/grep) freshness check verb process of which Soufflé of which SQLite
impact idle 0.37 0.12 0.04 0.21 0.10 0.02
impact busy 0.64 0.30 0.07 0.27 0.12 0.02
path idle 0.21 0.10 0.04 0.07 - (SQL) 0.01
path busy 0.43 0.25 0.06 0.11 - 0.01
context idle 0.30 0.10 0.04 0.17 - 0.02
context busy 0.56 0.30 0.07 0.20 - 0.02
changed idle 0.27 0.10 0.04 0.12 - 0.01
changed busy 0.74 0.32 0.10 0.32 - 0.01
changed --impact idle 0.50 0.10 0.04 0.36 0.10 (in child) 0.01
changed --impact busy 1.01 0.28 0.12 0.61 0.12 0.01
test-impact idle 0.53 0.09 0.04 0.40 0.10 (in child) -
test-impact busy 1.08 0.24 0.11 0.73 0.12 -
any query right after an edit idle 10.05 10.0 (waits for the rebuild; rebuild 7.2 s)
any query right after an edit busy 10.96 10.0 (rebuild 13.0 s, answer still from the old graph)

On this repository (3,300 files in five languages): impact 0.9-1.5 s, of which the per-query non-source scan was 0.6 s and Soufflé 0.6 s on the TypeScript graph; the freshness check was 0.2 s (one tree walk per language).

Scaling under load: the launch chain grows ~2.5x (process starts), Soufflé ~1.2x (single-threaded, it keeps its core), the verb's Python work ~1.3-2x.

What changed

  • Non-source scan cached per graph (ax_nonsource.py, out/dl/nonsource.sqlite): candidate files are statted; a file is opened only when its size or mtime moved since it was read, and searched only when its words include a name asked for. A name can match only at the start of a [\w.$-] run and end at its end or a ., which is exactly the word set stored, so the files skipped are files the search could not match. Files modified in the last 2 s are not cached; names outside [\w.$-] fall back to the full scan; any cache error falls back to the full scan. Warmed by index. AXIOMCODE_NO_SCAN_CACHE=1 scans every file.
  • Build output is not scanned: .next, .nuxt, .turbo, coverage, .cache, … (the refresher's own PRUNE_ALL). On the app with a dev build folder, impact useAdminClient dropped 190 [text] rows that were all source maps (3 pages → 2) and 338 ms → 139 ms.
  • Impact solve cache: the rules' output is keyed by the rules id, the graph export's stamps and every per-query fact file, and read back on a repeat (page 2, the same question again, changed --impact then test-impact). AXIOMCODE_NO_SOLVE_CACHE=1 runs the rules.
  • One tree walk for the freshness check of a repository in several languages (0.165 s → 0.033 s on five languages; identical file set, directories only C# prunes included).
  • bin/axiomcode recognises a verb by reading the frontend's dispatch table in-process (same source as --verbs, so still no drift) and finds its root by parameter expansion: no second bash, sed, tr, grep or dirname per query.
  • Python probe remembered by the node launchers (CLI, MCP, every hook), keyed by PATH/AXIOMCODE_PYTHON, re-probed when a candidate resolves to another file or the file changes.
  • First build never holds a call silently: under the MCP server a query with no graph starts the build in the background and answers within AXIOMCODE_BUILD_WAIT (60 s) - with the answer if it finished, else "the graph for … is being built (language 1 of 3, solve (iteration 1); 2m10s so far) … ask again"; a one-time rule compile is named as such. A query during a build reports on it instead of queueing a second build. From a shell the call waits and prints each stage as it moves. An MCP call past the server's timeout answers in words (mcp: a query made during a first index that runs past 900 s fails with a bare 'Error executing tool' #1557).

Before / after (same machine, same graph)

verb idle before idle after (first ask / repeat) busy before busy after (first ask / repeat)
impact 0.36 0.33 / 0.22 0.48-0.64 0.41-0.46 / 0.26-0.29
path 0.21 0.19 0.25-0.43 0.23-0.25
context 0.30 0.28 0.39-0.56 0.33-0.39
changed 0.27 0.22 0.55-0.74 0.56
changed --impact 0.50 0.35 1.01-1.03 0.71
test-impact 0.53 0.38 0.95-1.08 0.84
impact, this repo (5 languages) 0.9-1.35 0.50 (warm scan)
impact, app with a .next folder 0.34 0.14
query, no graph, MCP blocks for the whole build (then fails past 900 s) answers in ≤ 60 s with the stage

Launch chain alone: 0.10-0.13 s → 0.06-0.08 s idle. Busy ranges are two runs under different background load.

Equivalence (control)

41 queries - 19 impact (incl. --page 2, --tests, --json, file:line), 5 path (incl. *, --every, a no-path refusal), 3 context, changed, changed --impact, test-impact on the app with an edit, and 11 impact/path/context on this repository's five-language graph - run through the dispatcher of origin/0.1.3 and of this branch (cold caches, then warm), on the same graphs: 41/41 byte-identical, exit codes included. The only intended difference is the build-folder skip, covered by its own test with a control (a config file naming the target is still reported).

Tests

tests/latency.py (25 checks; 6 fail on 0.1.3): cached scan == full scan across edits/additions/deletions/binary/too-large/racy-mtime/dotted and odd names, and a warm query opens only candidate files; one walk == per-language walks; solve cache hit on repeat, miss on another target and on a changed config file, same answer as with caches off; build folders skipped, config kept; verb found without spawning; Python probe cached and re-probed when PATH moves; first build non-blocking under MCP with stage, a second query reports on it, the answer once done; MCP timeout message.

Ran: tests/run.py (244/246, 2 pending as before), surfaces, fastpath, directive, mcp, manifests, cli_version, engine_choice, tiers, no_symlink, indexed_tree, mcp_first, hosts, enrich_budget, multi_language, refresh - all pass.

Not changed here (refresh coordination is being reworked separately)

The largest cost on a busy machine is the post-edit wait: a query after an edit waits AXIOMCODE_FRESH_WAIT (10 s) for a rebuild that takes longer than that under load, then answers from the previous graph anyway (#1553). Suggested for that work: skip the wait when the last refresh's recorded duration (refresh.json seconds) exceeds the time left, answer at once from the previous graph with the stale-files note, and let only the query that asks for it wait. Merging the freshness check into the verb's own Python process would save one more interpreter start per query; it touches the dispatcher's gate lines, so it is left to that work too.

@swapnilpaliwal-sd

Copy link
Copy Markdown
Contributor Author

Rebased onto 0.1.3 after #1565. Three files overlapped; each keeps both changes:

Local checks on the merged scripts: tests/manifests.py ok, tests/directive.py 12 of 12, tests/surfaces.py ok. The engine-backed suites run in CI.

@swapnilpaliwal-sd
swapnilpaliwal-sd merged commit 32eee1f into 0.1.3 Sep 28, 2026
8 checks passed
@swapnilpaliwal-sd
swapnilpaliwal-sd deleted the fix/query-latency branch September 28, 2026 03:36
…ilently for a first build

Measured per phase on a 34k-line React/TypeScript app and on this repository, idle and with 9 of 10
cores busy. On a fresh graph every verb answers in 0.2-1.1 s; the time went to work repeated on every
call with the same result:

- impact opened every non-source file in the tree on every query (twice) to look for the changed
  name: 0.6 s per query here, and a dev server's build folder (.next source maps) added ~1,500 files
  and 190 noise rows. The scan is now cached per graph in out/dl/nonsource.sqlite: files are statted,
  opened only when their size or mtime moved, and searched only when their words include a name asked
  for. Build output and coverage folders (ax_fresh.PRUNE_ALL) are skipped. Warmed by `index`.
- the impact rules ran again for a question already asked (page 2, a repeat, changed --impact then
  test-impact). The solve is now keyed by the rules, the graph export and every per-query fact, and
  read back on a repeat.
- the freshness check walked the tree once per language: one walk now (0.165 s -> 0.033 s on five
  languages), the same file set.
- bin/axiomcode started a second bash, a sed, a tr, two greps and dirname per level to recognise a
  verb and find its root; it reads the frontend's dispatch table in-process now.
- the node launchers (CLI, MCP, every hook) started Python to ask where it lives on every call; the
  answer is remembered, keyed by PATH, and probed again when a candidate resolves elsewhere.
- a query with no graph blocked silently for the whole first build, and a second one queued another
  build behind it; under the MCP server past 900 s it failed with a bare tool error. Now the MCP
  server's queries start the build in the background and answer within AXIOMCODE_BUILD_WAIT seconds
  with the stage it is at; a query during a build reports on it; the shell prints the stage as it
  moves; a timed-out MCP call answers in words.

Answers are unchanged: 41 queries (impact, path, context, changed, changed --impact, test-impact)
on both repositories compared byte for byte before/after, cold and warm caches. tests/latency.py
pins each change against the slow path it replaces.

Co-authored-by: axiomcode-bot[bot] <334110751+axiomcode-bot[bot]@users.noreply.github.com>
Sign up for free to 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