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(), + ) + )