Per-layer timing

Once every layer records a duration, you get the one piece of information most agent codebases are missing: where the time actually goes. A request that takes 4 seconds is a mystery until the trace shows 3.8 seconds on retrieval and 180 ms everywhere else. Now you know what to fix.

layers/observability.py (finalize)
python
    def finalize(self, thread_id: str, trace: List[dict], reply: str) -> None:
        self._last_trace[thread_id] = trace
        total_ms = sum(step["duration_ms"] for step in trace)
        self._log.info(
            "agent_request_complete",
            thread_id=thread_id,
            total_ms=round(total_ms, 3),
            layers=[step["layer"] for step in trace],
            reply_chars=len(reply),
        )

finalize emits a single structlog event per request with the total latency and the ordered list of layers. One log line, fully structured, easy to aggregate into a p95 latency chart per layer.

sample trace
json
{
  "thread_id": "t1",
  "total_ms": 421.2,
  "trace": [
    { "layer": "transport",    "status": "ok",    "duration_ms": 0.4, "notes": "validated" },
    { "layer": "guardrails",   "status": "ok",    "duration_ms": 1.2, "notes": "input",  "data": { "flags": [] } },
    { "layer": "memory",       "status": "ok",    "duration_ms": 0.1, "notes": "read",   "data": { "turns": 4 } },
    { "layer": "orchestrator", "status": "ok",    "duration_ms": 0.2, "notes": "route=retrieve" },
    { "layer": "retrieval",    "status": "ok",    "duration_ms": 38.6,"notes": "hits=3" },
    { "layer": "guardrails",   "status": "ok",    "duration_ms": 0.9, "notes": "output", "data": { "flags": [] } },
    { "layer": "memory",       "status": "ok",    "duration_ms": 0.1, "notes": "write" },
    { "layer": "observability","status": "ok",    "duration_ms": 0.3, "notes": "finalized" }
  ]
}

A real trace payload. Retrieval dominates at 38.6 ms, guardrails and orchestrator are basically free, the rest is LLM call time (rolled into the reply branch). Budgets become obvious.

Ship them as metrics. A histogram per layer name gives you p50, p95, p99 latency per step, and an SLO alert fires when a specific layer regresses. That is a dramatically more useful signal than a single overall-latency chart, because the remediation is different for each layer: cache for retrieval, model choice for synthesis, tuning for memory.

Quiz: Quiz

Loading practice…