From 9677ecb39f8d8ec4a56bd68dd3d066e16058f049 Mon Sep 17 00:00:00 2001 From: Adam Wright Date: Fri, 18 Sep 2026 03:23:36 +0000 Subject: [PATCH] Run react-to-me preprocessing in two rounds, and correct the latency record **The change.** `ReactToMeGraphBuilder` overrides `preprocess` and ran all four calls back to back. The base class deliberately overlaps what it can, with a comment about the round trip it saves and a test pinning it -- and the profile both the chat UI and the answer endpoint actually use discarded that, with no test noticing. Only the dependencies force an order: language detection reads the raw input and needs nothing from the rephraser, while safety and intent both read the rephrased text and so follow it but not each other. Both already ran regardless of the safety verdict, so overlapping them changes no behaviour. Measured A/B in both orders, to rule out drift flattering whichever ran second. Preprocessing 5.1s -> 2.6s at the median; first answer token 13.1s -> 11.4s. Across the tracked question set, first token p50 12.0s -> 9.6s. **The tail is the honest caveat.** Sequential waits for a+b, where noise averages out; concurrent waits for max(a,b), where it does not. On the four-question repeated measure the p90 advantage was nil (14.57s against 14.60s) even though the median improved. On the fifteen-question set p90 did improve, 14.5s -> 12.2s. The median gain is consistent; the tail gain is not, and should not be claimed. **The record was wrong.** This contract told the website team the first token arrives "around 36 seconds". It came from one question and does not reproduce: collection routing narrowed retrieval, and preprocessing was never the ~16s recorded -- it was 5.1s before this change and is 2.6s after. The spec and the contract now carry the distribution, measured through the served HTTP path as well as the graph, and name the answer model's own 6.1s time-to-first-token as the largest block left. Co-Authored-By: Claude Opus 5 --- .../contracts/answer_endpoint.md | 54 ++++--- specs/010-search-page-answers/spec.md | 67 +++++---- specs/010-search-page-answers/tasks.md | 3 +- src/agent/profiles/react_to_me.py | 40 ++++-- tests/agent/test_preprocess_concurrency.py | 132 +++++++++++++++++- 5 files changed, 233 insertions(+), 63 deletions(-) diff --git a/specs/010-search-page-answers/contracts/answer_endpoint.md b/specs/010-search-page-answers/contracts/answer_endpoint.md index ce78bb5f..2de2cdc9 100644 --- a/specs/010-search-page-answers/contracts/answer_endpoint.md +++ b/specs/010-search-page-answers/contracts/answer_endpoint.md @@ -92,30 +92,48 @@ the same question, that is a defect. ## Budget -| | first increment promises | measured today | +Measured 2026-09-18 over the fifteen tracked sweep questions, two runs each, warm +process, `gpt-4o-mini` at temperature 0. + +| | first increment promises | measured | |---|---|---| -| first token | **nothing** | ~20-36s: the answer starts only after four preprocessing calls and a retrieval | -| complete | **nothing** | p50 15.2s, p90 22.4s, max 31.5s end to end | -| streaming | **yes** | 1,168 token events for one answer | +| first token | **nothing** | p50 **9.6s**, p90 12.2s, max 14.0s (n=26) | +| complete | **nothing** | p50 **10.4s**, p90 18.1s, max 21.8s (n=30) | +| streaming | **yes** | ~700-1,200 token events for one answer | + +Through the served HTTP endpoint rather than the graph, on a four-question subset: +first token p50 10.8s, p90 12.2s. + +**An earlier version of this contract said the first token arrives "around 36 +seconds". That was wrong** -- it came from a single question, and it has not been +reproducible since. Two things changed underneath it: collection routing narrowed +retrieval to the sources a question actually needs, and the four preprocessing +calls now run in two rounds instead of four. Preprocessing is 2.6s of the total, +not the ~16s previously recorded. -**The first increment makes no latency promise, deliberately.** Two seconds was in an -earlier draft of this contract; building the streaming surface showed the answer's -first token arrives around 36 seconds, because nothing of it exists until the -rephrase, safety, language and intent calls and a retrieval have all finished. -Streaming improves the last part and does nothing about the first. +**The first increment still makes no latency promise**, and ten seconds is still +far from the two an AI overview is reported to take. But design the panel for ten +seconds, not thirty: the gap between those is the difference between a brief wait +and an abandoned page. -Design the panel for that: it must be able to show nothing for a long time, and to be -absent entirely. Do not build a spinner that implies an imminent answer, and do not -let the search results wait on it (FR-009). +Four of the thirty runs produce no answer token at all. Those are the two +deliberately unsafe questions, which return `nothing_found` in about 4.5s with an +empty body. A panel must handle "nothing, quickly" as a normal outcome. A naive measurement reports 3.0s to first token. That token is the rephraser's. -Retrieval is one part and no longer the obvious first target. It dominates the heavy -questions -- about 12.5s of a 27s answer -- and scales with *queries x collections*. Query expansion turns one question into five -queries (2.4s, one LLM call) and each runs against every collection, so cutting -queries is a lever of the same size as cutting collections. Only the latter has a -spec. See [009](../../009-collection-routing/spec.md), and note that it is one lever -rather than the whole of it. +**Where the time goes now**, at the median of a four-question repeated measure: + +| phase | seconds | +|---|---| +| preprocessing (rephrase \| language, then safety \| intent) | 2.6 | +| query expansion and retrieval | 2.3 | +| retrieval finishing to the answer's first token | 6.1 | + +The largest block is no longer retrieval or preprocessing: it is the answer model's +own time to first token with a retrieved context. Collection routing +([009](../../009-collection-routing/spec.md)) already did most of the work on +retrieval -- the 12.5s figure recorded here before it landed no longer reproduces. One measurement worth keeping in view for anyone optimising this: the async retrieval path is **not faster than the sync one** here -- 12.5s against 10.9s on the diff --git a/specs/010-search-page-answers/spec.md b/specs/010-search-page-answers/spec.md index 21eb1b18..47926c99 100644 --- a/specs/010-search-page-answers/spec.md +++ b/specs/010-search-page-answers/spec.md @@ -18,22 +18,30 @@ Measured on 2026-09-17, beta, Release97 bundle, `gpt-4o-mini`, warm process: Across all fifteen tracked questions, not one question twice: +Re-measured 2026-09-18, two runs of each tracked question: + | | | |---|---| -| Whole answer | min **6.7s**, p50 **15.2s**, p90 **22.4s**, max **31.5s** | -| Retrieval step, heavy reactome question | ~12.5s of a 27s answer | -| Retrieval step, userguide question | a fraction of a 12.8s answer | -| Query expansion | 2.4s, one LLM call, producing 4 variants + the original | -| Graph construction | 51.5s, once at startup | - -*An earlier draft of this spec quoted "25.4s and 32.2s" as the headline. That was two -runs of one question, and that question is near the maximum -- roughly twice the p50. -Corrected on 2026-09-17 after measuring the distribution.* +| First answer token | min **2.8s**, p50 **9.6s**, p90 **12.2s**, max **14.0s** (n=26) | +| Whole answer | min **3.4s**, p50 **10.4s**, p90 **18.1s**, max **21.8s** (n=30) | +| Preprocessing | 2.6s, in two rounds of two calls | +| Query expansion and retrieval | 2.3s | +| Retrieval end to first answer token | 6.1s -- now the largest single block | +| Graph construction | ~70s, once at startup | + +*This table has been wrong twice. It first quoted "25.4s and 32.2s", which was two +runs of one question near the maximum. It then quoted p50 15.2s for the whole answer +and ~36s to the first token; neither reproduces now, because collection routing +(spec 009) narrowed retrieval and preprocessing went from four sequential calls to +two rounds. Re-measure after any retrieval or preprocessing change rather than +quoting these.* A Google AI overview is generally reported to arrive in one to two seconds -- an -assumption here, not a measurement of ours. At a p50 of fifteen seconds, a panel on -the search results page is still spinning long after a person has read the ordinary -results, so the conclusion survives the correction even though the number did not. +assumption here, not a measurement of ours. At a p50 of just under ten seconds to the +first token, a panel on the search results page is still empty long after a person +has read the ordinary results. The gap has closed by more than half since this spec +was written and the conclusion still holds, which is the point worth keeping: the +requirement was never about a specific number. This is not a polish problem. It decides whether the feature works, so it is stated here as a requirement rather than discovered during implementation. @@ -65,18 +73,18 @@ disproved that, and the requirement changed rather than the measurement. Measured 2026-09-17 by streaming `astream_events` and grouping by `run_id`: -| at | tokens | what it is | -|---|---|---| -| 5.4s | 17 | rephrase | -| 9.0s | 12 | safety check | -| 12.6s | 1 | language detection | -| 16.1s | 6 | intent classifier | -| 19.8s | 80 | query expansion | -| **36.1s** | **1,189** | **the answer** | +| phase | seconds at the median | +|---|---| +| preprocessing -- rephrase \| language, then safety \| intent | 2.6 | +| query expansion and retrieval | 2.3 | +| retrieval end to the answer's first token | **6.1** | +| first answer token | **9.6** | -**Nothing of the answer exists until four sequential preprocessing calls and a -retrieval have finished.** Streaming makes the last 16 seconds pleasant and does -nothing about the first 36. A panel would show an empty box and then fill quickly. +**Nothing of the answer exists until preprocessing and a retrieval have finished**, +but that is now under five seconds rather than the twenty this spec previously +recorded. The largest remaining block is the answer model's own time to first token +against a retrieved context, which streaming does not help and nothing here +addresses. A naive measurement reports 3.0s, because the first streamed token of any kind belongs to the rephraser. That number is wrong in the most flattering direction, and @@ -88,12 +96,13 @@ handshake and every failure path against it, none of which depend on how fast it What would have to change for FR-005a, in the order the measurement suggests: -1. **The four preprocessing calls**, ~16s for 36 tokens between them, all before - retrieval starts. Whether they must be sequential, and whether a search-page - question needs all four, is the largest open question -2. **Query expansion**, its own call plus a 5x retrieval fan-out -3. **Retrieval**, which [spec 009](../009-collection-routing/spec.md) addresses and - which is no longer the obvious first target +1. **The answer model's time to first token**, 6.1s against a retrieved context and + the largest block left. Nothing in these specs addresses it; a smaller or faster + model, or a shorter context, are the obvious handles +2. **Preprocessing**, now 2.6s in two rounds. Whether a search-page question needs + all four calls at all is still open -- the rounds only removed the waiting +3. **Query expansion and retrieval**, 2.3s together, after + [spec 009](../009-collection-routing/spec.md) narrowed the collections Stating a budget the code cannot meet would bake it into a contract another repo builds against. This is what we are doing instead. diff --git a/specs/010-search-page-answers/tasks.md b/specs/010-search-page-answers/tasks.md index 7926bd6b..9f4462a3 100644 --- a/specs/010-search-page-answers/tasks.md +++ b/specs/010-search-page-answers/tasks.md @@ -52,7 +52,8 @@ state. ## Phase 5: Latency (does NOT gate the handover) -- [ ] T019 Measure first-token and completion separately across the tracked questions; publish the distribution, not one question. Baseline for one question, 2026-09-17: first ANSWER token at 36.1s, not the 3.0s a naive stream-the-first-token measurement reports +- [x] T019 Measure first-token and completion separately across the tracked questions; publish the distribution, not one question. Measured 2026-09-18, two runs each: first token p50 9.6s / p90 12.2s (n=26), completion p50 10.4s / p90 18.1s (n=30). The earlier "36.1s to first token" came from one question and does not reproduce (PR #238) +- [x] T019a Run preprocessing in two rounds instead of four sequential calls in src/agent/profiles/react_to_me.py; the base class already overlapped, and this override discarded it (PR #238) - [ ] T020 Reduce query expansion from 5 variants, measuring recall with bin/retrieval_baseline — its own call plus a 5x retrieval fan-out - [ ] T020b Establish whether the four preprocessing calls must be sequential, and whether a search-page question needs all of them. They cost ~16s before retrieval starts and produce 36 tokens between them — the largest block in front of the first answer token - [ ] T021 Land spec 009 collection routing and re-measure diff --git a/src/agent/profiles/react_to_me.py b/src/agent/profiles/react_to_me.py index e9037c56..39574afa 100644 --- a/src/agent/profiles/react_to_me.py +++ b/src/agent/profiles/react_to_me.py @@ -1,3 +1,4 @@ +import asyncio import logging from typing import Any, cast @@ -120,21 +121,32 @@ def _register_userguide_rag( async def preprocess( self, state: ReactToMeState, config: RunnableConfig ) -> ReactToMeState: - rephrased_input: str = await self.rephrase_chain.ainvoke( - { - "user_input": state["user_input"], - "chat_history": state.get("chat_history", []), - }, - config, - ) - safety_check: SafetyCheck = await self.safety_checker.ainvoke( - {"rephrased_input": rephrased_input}, config - ) - detected_language: str = await self.language_detector.ainvoke( - {"user_input": state["user_input"]}, config + # Two rounds, not four. This override used to run all four calls back to + # back, discarding the overlap the base class documents. Only the + # dependencies force an order: language detection reads the raw + # `user_input` and so needs nothing from the rephraser, while safety and + # intent both read `rephrased_input` and so must follow it -- but not + # each other. Both always run regardless of the safety verdict, here and + # before, so overlapping them changes no behaviour. + rephrased_input: str + detected_language: str + rephrased_input, detected_language = await asyncio.gather( + self.rephrase_chain.ainvoke( + { + "user_input": state["user_input"], + "chat_history": state.get("chat_history", []), + }, + config, + ), + self.language_detector.ainvoke({"user_input": state["user_input"]}, config), ) - intent: QueryIntent = await self.intent_classifier.ainvoke( - {"rephrased_input": rephrased_input}, config + safety_check: SafetyCheck + intent: QueryIntent + safety_check, intent = await asyncio.gather( + self.safety_checker.ainvoke({"rephrased_input": rephrased_input}, config), + self.intent_classifier.ainvoke( + {"rephrased_input": rephrased_input}, config + ), ) active_sources = resolve_active_sources(intent.source, self._available_sources) if intent.source not in self._available_sources: diff --git a/tests/agent/test_preprocess_concurrency.py b/tests/agent/test_preprocess_concurrency.py index 671f7770..704f96b8 100644 --- a/tests/agent/test_preprocess_concurrency.py +++ b/tests/agent/test_preprocess_concurrency.py @@ -9,13 +9,17 @@ import asyncio import time -from typing import Any +from typing import TYPE_CHECKING, Any +import pytest from langchain_core.runnables import RunnableConfig, RunnableLambda from agent.profiles.base import BaseGraphBuilder, BaseState from agent.tasks.safety_checker import SafetyCheck +if TYPE_CHECKING: + from agent.profiles.react_to_me import ReactToMeGraphBuilder + DELAY = 0.2 @@ -85,3 +89,129 @@ def test_rephrase_still_precedes_the_safety_check() -> None: assert ( spans["rephrase"][1] <= spans["safety"][0] ), "the safety check started before the rephrase finished" + + +# --- the profile that is actually served ------------------------------------- +# +# Everything above pins BaseGraphBuilder. ReactToMeGraphBuilder overrides +# `preprocess` outright, and its override ran all four calls back to back -- so +# the profile behind both the chat UI and the answer endpoint discarded the +# overlap these tests exist to protect, and no test noticed. These pin the +# override on its own terms. + + +def _react_builder(log: list[tuple[str, float, float]]) -> "ReactToMeGraphBuilder": + from agent.profiles.react_to_me import ReactToMeGraphBuilder + from agent.tasks.intent_classifier import QueryIntent + + builder = ReactToMeGraphBuilder.__new__(ReactToMeGraphBuilder) + builder.rephrase_chain = _slow("rephrased", log, "rephrase") + builder.safety_checker = _slow( + SafetyCheck(safety="true", reason_unsafe=""), log, "safety" + ) + builder.language_detector = _slow("en", log, "language") + builder.intent_classifier = _slow(QueryIntent(source="reactome"), log, "intent") + builder._available_sources = frozenset({"reactome"}) + return builder + + +def _spans(log: list[tuple[str, float, float]]) -> dict[str, tuple[float, float]]: + return {name: (start, end) for name, start, end in log} + + +def _overlap(a: tuple[float, float], b: tuple[float, float]) -> float: + return min(a[1], b[1]) - max(a[0], b[0]) + + +def test_react_to_me_runs_preprocessing_in_two_rounds() -> None: + """Four calls, two rounds: (rephrase | language) then (safety | intent). + + Language detection reads the raw user input, so it need not wait for the + rephraser; safety and intent both read the rephrased text, so they must + follow it but not each other. + """ + from agent.profiles.react_to_me import ReactToMeState + + log: list[tuple[str, float, float]] = [] + state = ReactToMeState(user_input="what is TP53?", active_sources=[]) + + asyncio.run(_react_builder(log).preprocess(state, RunnableConfig())) + + spans = _spans(log) + assert set(spans) == {"rephrase", "safety", "language", "intent"} + + assert ( + _overlap(spans["rephrase"], spans["language"]) > DELAY / 2 + ), "language detection is waiting for the rephraser it does not depend on" + assert ( + _overlap(spans["safety"], spans["intent"]) > DELAY / 2 + ), "safety and intent are running one after the other again" + + +def test_react_to_me_keeps_the_ordering_the_dependencies_require() -> None: + """Overlap must not be bought by running something before its input exists.""" + from agent.profiles.react_to_me import ReactToMeState + + log: list[tuple[str, float, float]] = [] + asyncio.run( + _react_builder(log).preprocess( + ReactToMeState(user_input="what is TP53?", active_sources=[]), + RunnableConfig(), + ) + ) + + spans = _spans(log) + for dependent in ("safety", "intent"): + assert ( + spans["rephrase"][1] <= spans[dependent][0] + ), f"{dependent} started before the rephrased text it reads existed" + + +def _failing(message: str) -> RunnableLambda: + async def run(_: Any) -> Any: + raise RuntimeError(message) + + return RunnableLambda(run) + + +def test_a_failed_rephrase_still_surfaces_as_an_error() -> None: + """`gather` changes how a failure travels, so pin that it still travels. + + Sequentially, a rephrase failure short-circuited: nothing after it ran. Under + `gather` the sibling call is already in flight and keeps going, and only the + first exception propagates. What must not change is that preprocess still + raises rather than returning a half-built state -- the endpoint turns an + exception into `state: failed`, and a silently empty `rephrased_input` would + instead retrieve against nothing and answer from it. + """ + from agent.profiles.react_to_me import ReactToMeState + + log: list[tuple[str, float, float]] = [] + builder = _react_builder(log) + builder.rephrase_chain = _failing("rephrase upstream is down") + + with pytest.raises(RuntimeError, match="rephrase upstream is down"): + asyncio.run( + builder.preprocess( + ReactToMeState(user_input="what is TP53?", active_sources=[]), + RunnableConfig(), + ) + ) + + +def test_a_failed_intent_classification_still_surfaces_as_an_error() -> None: + """The second round has the same property, and it is the round that pairs + two calls neither of which the other needs.""" + from agent.profiles.react_to_me import ReactToMeState + + log: list[tuple[str, float, float]] = [] + builder = _react_builder(log) + builder.intent_classifier = _failing("intent classifier is down") + + with pytest.raises(RuntimeError, match="intent classifier is down"): + asyncio.run( + builder.preprocess( + ReactToMeState(user_input="what is TP53?", active_sources=[]), + RunnableConfig(), + ) + )