Lesson 4: Performance

Latency breakdown

"The system is slow" is not actionable. Break the request into phases and measure each.

@dataclass
class LatencyBreakdown:
    total_ms: int
    query_rewrite_ms: int
    embedding_ms: int
    retrieval_ms: int
    rerank_ms: int
    generation_ms: int
    time_to_first_token_ms: int
    own_overhead_ms: int          # total minus the measured phases

That last field is the one that finds surprises. If the phases sum to 1,800 milliseconds and the total is 2,600, then 800 milliseconds is being spent in your own code, and that is usually where the cheapest win is: a synchronous call blocking the loop, JSON serialisation of something large, or a database query nobody counted.

@asynccontextmanager
async def phase(name: str, breakdown: dict[str, int]):
    started = time.monotonic()
    try:
        yield
    finally:
        breakdown[name] = _ms(started)

async def answer(query: str) -> Answer:
    timings: dict[str, int] = {}
    overall = time.monotonic()

    async with phase("embedding", timings):
        vector = await embedder.embed_query(query)
    async with phase("retrieval", timings):
        chunks = await retriever.search(vector, top_k=50)
    async with phase("rerank", timings):
        top = await reranker.rank(query, chunks)
    async with phase("generation", timings):
        completion = await provider.generate(build_messages(query, top))

    timings["total"] = _ms(overall)
    timings["own_overhead"] = timings["total"] - sum(
        v for k, v in timings.items() if k != "total"
    )
    logger.info("request_latency", extra=timings)
    return build_answer(completion, top)

Measure before optimising. Generation usually dominates, and teams routinely spend a week optimising retrieval that accounts for eight percent of the total.

[IMAGE PROMPT M11-5
Purpose: Show a latency breakdown as a waterfall so learners can see which phase dominates and where unaccounted overhead appears.
Visual type: Horizontal waterfall chart with an overhead segment.
Prompt: A clean educational waterfall chart with a horizontal time axis labelled "milliseconds" running from 0 to 2600. Stacked horizontally left to right are labelled segments of proportional width: "query rewrite 180", "embedding 90", "retrieval 140", "rerank 220", "generation 1170", and a final differently hatched segment labelled "unaccounted overhead 800". Beneath the generation segment, a smaller inner marker at its left edge is labelled "first token at 340ms into generation". A bracket above the whole chart is labelled "total 2600ms". A callout beside the overhead segment reads "phases summed to 1800, total was 2600, look here first". A second callout beside the generation segment reads "usually dominates, optimise this or reduce output".
Required elements: Proportionally sized labelled segments in order, a visually distinct overhead segment, a first-token marker inside generation, a total bracket, two callouts.
Style: Clean educational illustration, professional, uncluttered, high contrast, flat vector, hatching to distinguish the overhead segment.
Layout: Single horizontal stacked bar across the frame, axis beneath, callouts above and below.
Text labels: "milliseconds", "query rewrite 180", "embedding 90", "retrieval 140", "rerank 220", "generation 1170", "unaccounted overhead 800", "first token at 340ms into generation", "total 2600ms", "phases summed to 1800, total was 2600, look here first", "usually dominates, optimise this or reduce output".
Aspect ratio: 16:9
Accessibility: Label every segment with its name and value in text, and distinguish overhead by hatching plus label rather than colour.
Avoid: Vendor logos, decorative elements, tiny text, watermarks.
Alt text: Latency waterfall showing query rewrite, embedding, retrieval, rerank, and generation phases summing to 1800 milliseconds against a 2600 millisecond total, leaving 800 milliseconds of unaccounted overhead.
END IMAGE PROMPT]

Percentiles over averages

An average hides the experience of the users having a bad time.

Consider 100 requests: 95 take 500 milliseconds and 5 take 20 seconds. The average is 1.5 seconds, which sounds acceptable and describes nobody. Five percent of users waited twenty seconds.

def percentiles(values: list[float]) -> dict[str, float]:
    ordered = sorted(values)
    def at(p: float) -> float:
        return ordered[min(int(len(ordered) * p), len(ordered) - 1)]
    return {"p50": at(0.50), "p90": at(0.90), "p95": at(0.95), "p99": at(0.99),
            "max": ordered[-1], "mean": sum(ordered) / len(ordered)}

Which percentile to watch. p50 is the typical experience. p95 is the number to set targets on, since it covers almost everyone without being dominated by rare outliers. p99 matters at scale, because one percent of a million requests is ten thousand bad experiences. The maximum tells you the worst case, which is usually a timeout and worth confirming is bounded.

Percentiles do not average. The p95 of two services is not the p95 of the combination, and averaging p95 across time buckets is arithmetically meaningless. Compute percentiles from raw values over the window you care about.

Streaming needs two. Module 8 established time to first token and total duration as separate metrics with separate causes, so track percentiles for both.

[IMAGE PROMPT M11-6
Purpose: Show why an average misrepresents user experience and what each percentile describes.
Visual type: Distribution histogram with marked statistics.
Prompt: A clean educational histogram with a horizontal axis labelled "request duration" and a vertical axis labelled "number of requests". The distribution is strongly right skewed: a tall cluster of bars near the left around a low duration, a long thin tail extending far to the right. Four vertical marker lines are drawn with labels above them: "p50" positioned within the tall cluster, "mean" positioned to the right of p50 in the sparse region between the cluster and the tail, "p95" positioned in the early tail, and "p99" positioned far into the tail. A callout pointing at the mean line reads "describes almost no actual request". A callout pointing at the p95 line reads "the number to set targets on". A shaded region covering the tail is labelled "5% of users, the ones who complain".
Required elements: A right-skewed histogram, four labelled vertical markers at correct relative positions with the mean falling between p50 and p95, two callouts, a labelled tail region.
Style: Clean educational illustration, professional, uncluttered, high contrast, flat vector, simple bar histogram.
Layout: Histogram filling the frame, markers vertical with labels above, callouts to the right.
Text labels: "request duration", "number of requests", "p50", "mean", "p95", "p99", "describes almost no actual request", "the number to set targets on", "5% of users, the ones who complain".
Aspect ratio: 16:9
Accessibility: Label every marker in text and describe the tail region in words rather than relying on shading alone.
Avoid: Specific millisecond values, vendor logos, decorative elements, tiny text, watermarks.
Alt text: Right-skewed histogram of request durations with p50 inside the main cluster, the mean pulled to the right of it, and p95 and p99 in the long tail, showing that the mean describes almost no real request.
END IMAGE PROMPT]

Caching

Module 7 covered Redis mechanics and Module 10 covered provider-side prompt caching. This is application-level caching of results.

Exact match keys on the input verbatim. Safe, and it hits only on identical repeats.

Normalized key canonicalises before hashing, so trivial differences hit the same entry.

def normalized_key(query: str, *, feature: str, model: str, prompt_version: str) -> str:
    """Normalise trivial variation, and include everything that changes the answer."""
    canonical = " ".join(query.lower().strip().split())
    digest = hashlib.sha256(canonical.encode()).hexdigest()[:32]
    return f"answer:{feature}:{model}:{prompt_version}:{digest}"

Everything affecting the output belongs in the key. The model, the prompt version, and the retrieval index version all change the answer, and omitting any of them means serving an answer produced by a configuration you no longer run. This is the same mistake as omitting the embedding model from a cache key in Module 9, and it has the same symptom: results that look plausible and are wrong.

Semantic caching matches on embedding similarity rather than exact text, so "how hot for focaccia" hits an entry stored for "what temperature to bake focaccia".

The hit rate is far higher and the failure mode is serving a wrong answer. Two questions can be similar above any threshold you pick and have different answers, and "bake at 220C" against "bake at 180C" is exactly the near-miss Module 9 warned about.

If you use it: set the threshold high, exclude anything where a wrong answer is costly, log every semantic hit with both questions so you can audit them, and measure the false hit rate before trusting it. Treat it as an optimisation requiring evidence rather than a default.

Cache invalidation and correctness risk

Module 7 gave the ordering rule: write first, then invalidate, because invalidating first leaves a window where a reader repopulates with the old value.

Three additional risks specific to this system.

Configuration drift. Any change to the prompt, model, or index makes cached answers stale in a way no TTL detects, which the versioned key above prevents.

Permission changes. A cached answer built from documents a user could see remains cached after their access is revoked. Never cache across permission boundaries without the permission scope in the key.

Corpus updates. A document retracted or corrected should invalidate answers derived from it, which requires knowing which cached answers cited which chunks. Storing the citation identifiers alongside the cache entry makes that possible.

What should never be cached, extending Module 7's list: anything permission-dependent without the scope in the key, anything where staleness has real consequences, and any answer whose sources have been retracted.

Profiling

Measurement finds the phase. Profiling finds the line.

cProfile for a deterministic run of CPU-bound code.

uv run python -m cProfile -o profile.out -m recipe_extractor.batch
uv run python -c "import pstats; pstats.Stats('profile.out').sort_stats('cumulative').print_stats(25)"

Sort by cumulative time to find which call tree dominates, and by total time to find the individual function burning it.

py-spy samples a running process without modifying or restarting it, which makes it the right tool for something slow in production.

uv run py-spy top --pid 12345
uv run py-spy dump --pid 12345          # what every thread is doing right now

The dump command is the one to remember: for a process that appears stuck, it shows exactly where each thread is, and in async code it frequently reveals the blocking call from Module 8 that is stalling the loop.

tracemalloc for memory.

import tracemalloc

tracemalloc.start()
snapshot_before = tracemalloc.take_snapshot()
await process_batch(documents)
snapshot_after = tracemalloc.take_snapshot()

for stat in snapshot_after.compare_to(snapshot_before, "lineno")[:10]:
    logger.info("memory_growth", extra={"stat": str(stat)})

Comparing snapshots around an operation attributes growth to a line, which is how you find the accumulation that turns a constant-memory pipeline into one that dies at record 1.4 million.

Cheap wins

Before optimising anything clever, check these.

Connection pooling. Module 7 covered it, and reusing HTTP and database connections is the most common large win. Creating an AsyncClient per request is a real and frequent mistake.

Concurrency where work is independent. Module 8's fan-out: three sequential 200 millisecond calls become one 200 millisecond phase.

Prompt caching. Module 10's cache-aware layout reduces latency as well as cost, since a cached prefix is not reprocessed.

Smaller output. Output tokens are generated serially, so halving the response roughly halves generation time.

Fewer retrieved chunks. Fewer input tokens shortens prefill, which is exactly what time to first token measures.

A smaller model where quality permits. Module 10's routing improves latency and cost together.

OpenTelemetry and LLM tracing

Structured logs answer "what happened". Traces answer "where did the time go across a distributed system", and they are the same data with parent and child relationships.

OpenTelemetry is the vendor-neutral standard for emitting traces, metrics, and logs. Its value is that instrumenting once lets you change backend without re-instrumenting, which matters given how much the observability tooling market has consolidated recently.

from opentelemetry import trace

tracer = trace.get_tracer(__name__)


async def answer(query: str) -> Answer:
    with tracer.start_as_current_span("answer_query") as span:
        span.set_attribute("gen_ai.operation.name", "chat")
        span.set_attribute("gen_ai.request.model", MODEL)

        with tracer.start_as_current_span("retrieval") as retrieval_span:
            chunks = await retriever.search(await embed(query), top_k=50)
            retrieval_span.set_attribute("retrieval.chunk_count", len(chunks))

        completion = await provider.generate(build_messages(query, chunks))
        span.set_attribute("gen_ai.usage.input_tokens", completion.usage.input_tokens)
        span.set_attribute("gen_ai.usage.output_tokens", completion.usage.output_tokens)
        span.set_attribute("gen_ai.response.finish_reasons", [completion.finish_reason])
        return build_answer(completion, chunks)

[VOLATILE: the OpenTelemetry GenAI semantic conventions define the gen_ai.* attribute vocabulary and were still in development status as of late 2026, having been moved into a separate repository to version independently. Attribute names may change. Verify against the current specification, and consider the stability opt-in mechanism for dual emission during transitions.]

One convention worth following even if you use nothing else. Do not put prompt or completion text in span attributes. Attributes are indexed, have size limits, and expose content to your observability backend. The GenAI conventions put content in span events instead, which can be filtered or dropped at the collector without changing application code. This is the same rule as the logging lesson, enforced at a different layer.

Auto-instrumentation packages exist for the major providers and frameworks and will create spans without changes to your business logic, which is the fastest way to start. Add custom spans for the stages they do not know about, such as your retrieval and reranking phases.

Why generic APM is not enough for this system. Traditional monitoring assumes the same input produces the same output, that cost correlates with request count, and that a 200 response means success. None of those hold here: output varies, cost tracks tokens, and Module 6 established that a 200 with malformed content is a failure your HTTP layer cannot see.

Alerting

Alert on symptoms users feel, not on every anomaly.

ALERTS = [
    Alert("error_rate", condition="rate(errors) > 0.02 for 5m", severity="page"),
    Alert("p95_latency", condition="p95(duration_ms) > 5000 for 10m", severity="page"),
    Alert("spend_rate", condition="hourly_cost > 2 * baseline", severity="page"),
    Alert("degradation", condition="rate(fallback_used) > 0.10 for 10m", severity="notify"),
    Alert("cache_hit_rate", condition="cache_hit_rate < 0.30 for 30m", severity="notify"),
    Alert("abstention_rate", condition="rate(abstained) > 2 * baseline for 30m", severity="notify"),
]

Four categories worth covering. Error rate for outright failures. Latency at p95 for the experience. Spend rate for the runaway cost Module 10 guarded against, alerting on rate rather than total so you find out in an hour rather than at month end. And degradation, meaning Module 5's fallback ladder being used more than usual, which is the alert that tells you something is wrong while users are still being served.

The last two in the list are the quiet ones. A cache hit rate collapsing means something invalidated your prefix, and a rising abstention rate means retrieval or the corpus has degraded. Neither shows up as an error.

Every alert needs a defined response. An alert nobody acts on trains people to ignore alerts, and severity should distinguish "wake someone" from "look at this tomorrow".