Run react-to-me preprocessing in two rounds, and correct the latency record

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

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.

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

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:

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