feat(trace): add -vvv binary trace events + live dashboard

Adds a low-overhead binary trace pipeline for inspecting per-request
lifecycle latency end-to-end (issue -> worker_received -> conn_acquired
-> write -> headers -> 1st chunk -> final chunk -> main_received ->
complete), plus per-process asyncio event-loop lag sampling.

- New `inference_endpoint.utils.trace` lock-free SPSC emitter (~90 ns
  per event), FIFO transport with O_NONBLOCK writes and 1 MiB kernel
  pipe buffer, per-process `emit_loop_lag` async task drives flush at
  0.3 s cadence — sole flush driver, no locks needed.
- New `scripts/trace_dashboard.py` rich.Live TUI reading the FIFO and
  the loadgen `final_snapshot.json` written by the metrics aggregator.
  Renders REQUEST LIFECYCLE / LOADGEN vs TRACE / EVENT LOOP LAG with
  one-row-per-metric layout (skips rows with no data on either side).
- Worker + main-process emit sites for the 9-stage lifecycle.
- 40 unit tests for the dashboard's count, fold, drop, loop-lag,
  loadgen comparison, and row-skip behavior.

Disabled by default; enabled with `-vvv` on `inference-endpoint`.

Co-Authored-By: Claude Opus 4.7 (1M context) <noreply@anthropic.com>

Author: viraatc

AGENTS.md

@@ -93,6 +93,24 @@ For streaming workloads, also watch **SSE-pkts/s** — a small stream interval (
 
 ---
 
+## Diagnosing client overhead with `-vvv` trace
+
+`Stall%` (above) tells you _that_ the client is the bottleneck; the `-vvv` trace dashboard tells you _where_. Add `-vvv` to any `benchmark` command to spawn a live dashboard that breaks each request into per-stage timings and samples per-worker event-loop lag:
+
+```bash
+inference-endpoint benchmark offline --endpoints URL --model NAME --dataset PATH -vvv
+```
+
+The dashboard renders to the terminal; the run's own stdout/stderr are redirected to `/tmp/endpoints_trace_<pid>/logs.txt` for the duration. Reading the panels:
+
+- **REQUEST LIFECYCLE** — each row is a stage's share of end-to-end (`%E2E`), with a `client work / server work / backpressure` verdict and a stacked timeline below it. A high `issue -> conn acquired` share is client-side IPC/back-pressure; high `payload written -> headers/response` is server-bound (not your client). This is the per-stage view behind a high `Stall%`.
+- **EVENT LOOP LAG** — per-worker loop drift. A worker with p99 above a few ms is loop-saturated (GIL / GC / a blocking syscall) even if its CPU% looks modest — the canonical "add workers won't help, the loop is stalled" signal.
+- **LOADGEN** — drop-immune issued/completed counts + rates and e2e/ttft/tpot latencies, sourced from the metrics aggregator.
+
+The trace channel is intentionally lossy: at high QPS the FIFO can't carry every frame, so the producer adaptively samples and the LIFECYCLE row counts (`N`) are a representative subset, not the totals. Use the lifecycle panel for the _distribution_ of where time goes; use the LOADGEN totals (and the sweep's `Recv Rate`) for exact throughput. Overhead of `-vvv` itself is negligible against a real endpoint and a few percent only at the CPU-bound roofline (local `MaxThroughputServer`).
+
+---
+
 ## IPC Transport Buffer Sizes
 
 The ZMQ transport uses a pre-allocated receive buffer (`bytearray`) for zero-copy message deserialization. If a serialized message exceeds this buffer, the worker crashes with:

docs/CLIENT_PERFORMANCE_TUNING.md

@@ -0,0 +1,302 @@
+#!/usr/bin/env python3
+# SPDX-FileCopyrightText: Copyright (c) 2026 NVIDIA CORPORATION & AFFILIATES. All rights reserved.
+# SPDX-License-Identifier: Apache-2.0
+
+"""CLI entry point for the -vvv trace dashboard.
+
+Reads fixed-size binary frames from the FIFO opened by
+:func:`inference_endpoint.utils.trace.bootstrap` and renders the
+dashboard via ``rich.Live``. Dashboard aggregation lives in
+:mod:`inference_endpoint.utils.trace_dashboard` so it can be unit
+tested without standing up a TUI.
+
+Linux only: timestamps are compared across processes and rely on
+``CLOCK_MONOTONIC`` being system-wide (per ``man 7 time``).
+"""
+
+# ruff: noqa: I001
+# The pre-commit ruff hook is pinned to v0.3.3 (see
+# .pre-commit-config.yaml's "TODO: sync rev with ruff version"), which
+# does not auto-detect `inference_endpoint` as a first-party package
+# and therefore disagrees with the project's local ruff (v0.15.8) on
+# import order in this file. File-level noqa keeps both versions quiet
+# until the rev is synced.
+from __future__ import annotations
+
+import argparse
+import fcntl
+import json
+import os
+import sys
+import threading
+import time
+
+import zmq
+from inference_endpoint.async_utils.services.metrics_aggregator.snapshot import (
+    MetricsSnapshotCodec,
+    snapshot_to_dict,
+)
+from inference_endpoint.core.record import BATCH_TOPIC, TOPIC_FRAME_SIZE
+from inference_endpoint.utils.trace import (
+    FRAME_SIZE,
+    metrics_addr_path,
+    snapshot_sidecar_path,
+)
+from inference_endpoint.utils.trace_dashboard import (
+    DASHBOARD_THEME,
+    READ_CHUNK,
+    REFRESH_HZ,
+    Dashboard,
+)
+from rich.console import Console
+from rich.live import Live
+
+
+def _try_load_snapshot(path: str) -> dict | None:
+    """Best-effort read of the loadgen snapshot sidecar. Returns None
+    if the file is missing or transiently mid-rename (atomic write may
+    briefly produce a half-rename window that json.load tolerates)."""
+    try:
+        with open(path) as f:
+            return json.load(f)
+    except (OSError, json.JSONDecodeError):
+        return None
+
+
+# End-of-run exit policy for the reader thread.
+#
+# The authoritative final snapshot (state=="complete") is written by the
+# parent's trace.teardown() *just before* it closes its FIFO write fd, and
+# every worker closes its write fd at process exit. So true FIFO EOF (all
+# writers closed) is the guaranteed signal that the complete snapshot is
+# already on disk — preferring EOF makes the FINAL panel deterministic.
+#
+# But workers can take tens of seconds to drain their ZMQ queues before
+# exiting, so we can't wait for EOF unconditionally or the dashboard hangs
+# long past the end of the run. Compromise: once lifecycle frames go quiet,
+# keep reading — letting true EOF trigger an immediate clean exit — until
+# this generous cap bounds a wedged-worker hang. After the reader exits,
+# main() polls the sidecar for the complete snapshot.
+_IDLE_EXIT_CAP_S = 30.0
+
+
+class _FrameReader(threading.Thread):
+    """Blocking read loop; ingests whole frames into the Dashboard.
+
+    Uses ``select`` with a short timeout so the thread can check for an
+    idle-exit condition — the FIFO may not reach EOF until all 24+ worker
+    processes have drained their ZMQ queues and exited, which can be tens
+    of seconds after the benchmark has finished.
+    """
+
+    def __init__(self, fd: int, dash: Dashboard) -> None:
+        super().__init__(daemon=True, name="trace-reader")
+        self._fd = fd
+        self._dash = dash
+        self._pending = bytearray()
+        self._eof = threading.Event()
+
+    @property
+    def eof(self) -> bool:
+        return self._eof.is_set()
+
+    def run(self) -> None:
+        import select
+
+        try:
+            while True:
+                ready, _, _ = select.select([self._fd], [], [], 0.5)
+                if ready:
+                    try:
+                        chunk = os.read(self._fd, READ_CHUNK)
+                    except OSError:
+                        return
+                    if not chunk:
+                        return  # true EOF — all writers closed
+                    self._pending.extend(chunk)
+                    whole = (len(self._pending) // FRAME_SIZE) * FRAME_SIZE
+                    if whole:
+                        self._dash.ingest_frames(bytes(self._pending[:whole]))
+                        del self._pending[:whole]
+                # Check lifecycle idle time regardless of whether LOOP_LAG
+                # frames are still arriving — workers emit LOOP_LAG every
+                # 0.3 s even after the run ends, so frame-arrival time is
+                # not a reliable proxy for end-of-run. We keep reading so
+                # true EOF (the parent's post-teardown fd close) wins and
+                # guarantees the complete snapshot is on disk; this cap only
+                # bounds a wedged-worker hang where EOF never arrives.
+                d = self._dash
+                if (d.is_done or d.is_tail) and d.lifecycle_idle_s >= _IDLE_EXIT_CAP_S:
+                    return
+        finally:
+            self._eof.set()
+
+
+class _MetricsSubReader(threading.Thread):
+    """Opens a SUB straight to the aggregator's metrics PUB and feeds the
+    dashboard fresh LOADGEN snapshots.
+
+    The aggregator is a separate process that publishes every tick (and the
+    terminal COMPLETE frame), so it is immune to the main benchmark loop's
+    saturation — unlike the sidecar, which is written from the main proc's
+    starved in-process subscriber. Best-effort: any failure leaves the
+    sidecar fallback in place. Sets ``delivered`` once a snapshot lands so
+    main() can stop polling the sidecar.
+    """
+
+    def __init__(self, addr_path: str, dash: Dashboard) -> None:
+        super().__init__(daemon=True, name="metrics-sub")
+        self._addr_path = addr_path
+        self._dash = dash
+        # Not ``_stop``: that shadows threading.Thread._stop and breaks join().
+        self._stopping = threading.Event()
+        self.delivered = threading.Event()
+
+    def stop(self) -> None:
+        self._stopping.set()
+
+    def _wait_for_addr(self) -> str | None:
+        # The parent writes the addr only after the aggregator PUB binds,
+        # which is well after the dashboard spawns — poll for it.
+        deadline = time.monotonic() + 30.0
+        while time.monotonic() < deadline and not self._stopping.is_set():
+            try:
+                with open(self._addr_path) as f:
+                    addr = f.read().strip()
+                if addr:
+                    return addr
+            except OSError:
+                pass  # addr file not published yet — retry until the deadline
+            time.sleep(0.2)
+        return None
+
+    def run(self) -> None:
+        addr = self._wait_for_addr()
+        if addr is None:
+            return  # never published — main() keeps polling the sidecar
+        ctx = zmq.Context.instance()
+        sock = ctx.socket(zmq.SUB)
+        sock.setsockopt(zmq.SUBSCRIBE, b"")
+        sock.setsockopt(zmq.CONFLATE, 1)  # only the freshest snapshot
+        sock.setsockopt(zmq.RCVTIMEO, 500)
+        sock.setsockopt(zmq.LINGER, 0)
+        codec = MetricsSnapshotCodec()
+        try:
+            sock.connect(addr)
+            while not self._stopping.is_set():
+                try:
+                    raw = sock.recv()
+                except zmq.Again:
+                    continue  # no snapshot within RCVTIMEO — re-check stop, retry
+                except zmq.ZMQError:
+                    return
+                if raw[:TOPIC_FRAME_SIZE] == BATCH_TOPIC:
+                    continue  # metrics snapshots are never batched
+                payload = raw[TOPIC_FRAME_SIZE:] if len(raw) > TOPIC_FRAME_SIZE else raw
+                try:
+                    snap = snapshot_to_dict(codec.decode(payload))
+                except Exception:  # noqa: BLE001 — telemetry, never crash
+                    continue
+                self._dash.attach_loadgen_snapshot(snap)
+                self.delivered.set()
+        finally:
+            sock.close(0)
+
+
+# Match the producers' write-fd request in trace.py. Capped by
+# /proc/sys/fs/pipe-max-size; request fails above that → default kept.
+_F_SETPIPE_SZ = getattr(fcntl, "F_SETPIPE_SZ", 1031)
+_KERNEL_PIPE_BUF = 64 * 1024 * 1024
+
+
+def _open_trace_input(pipe_path: str | None) -> int:
+    if pipe_path:
+        fd = os.open(pipe_path, os.O_RDONLY)
+        try:
+            fcntl.fcntl(fd, _F_SETPIPE_SZ, _KERNEL_PIPE_BUF)
+        except OSError:
+            pass  # F_SETPIPE_SZ is best-effort — keep the kernel default
+        return fd
+    return sys.stdin.fileno()
+
+
+def main() -> int:
+    parser = argparse.ArgumentParser(description=__doc__)
+    parser.add_argument(
+        "--trace-pipe",
+        help="FIFO path to read binary trace frames from (default: stdin).",
+    )
+    args = parser.parse_args()
+
+    dash = Dashboard()
+    # Dashboard renders to stderr because the parent benchmark process
+    # has redirected its own stdout/stderr to a log file (see trace.bootstrap).
+    console = Console(file=sys.stderr, force_terminal=True, theme=DASHBOARD_THEME)
+    reader = _FrameReader(_open_trace_input(args.trace_pipe), dash)
+    reader.start()
+
+    # Convention paths keyed on the parent's pid (the main proc).
+    snap_path = snapshot_sidecar_path(os.getppid())
+    # Primary LOADGEN feed: a SUB straight to the aggregator PUB (fresh).
+    # Falls back to the main-proc-written sidecar if the SUB never connects.
+    sub_reader = _MetricsSubReader(metrics_addr_path(os.getppid()), dash)
+    sub_reader.start()
+
+    # screen=True uses the alternate-screen buffer so updates redraw
+    # cleanly without scrollback noise. When Live() exits the alt
+    # screen is torn down — to keep the final frame visible we capture
+    # it BEFORE leaving the context and print it to the normal buffer
+    # afterward.
+    final_frame = None
+    with Live(
+        dash.render(),
+        console=console,
+        refresh_per_second=REFRESH_HZ,
+        screen=True,
+        transient=False,
+    ) as live:
+        while not reader.eof:
+            # SUB is the fresh primary; only fall back to the sidecar
+            # until/unless the SUB has delivered at least one snapshot.
+            if not sub_reader.delivered.is_set():
+                snap = _try_load_snapshot(snap_path)
+                if snap is not None:
+                    dash.attach_loadgen_snapshot(snap)
+            live.update(dash.render())
+            time.sleep(1.0 / REFRESH_HZ)
+        # Wait for the terminal snapshot before the closing frame. teardown()
+        # writes it to the sidecar before closing the FIFO (reliably on disk
+        # by EOF); the SUB can miss the terminal PUB frame, so poll the sidecar
+        # as the source of truth.
+        _FINAL_SNAP_WAIT_S = 20.0
+        deadline = time.monotonic() + _FINAL_SNAP_WAIT_S
+        while time.monotonic() < deadline and not dash.has_terminal_loadgen:
+            s = _try_load_snapshot(snap_path)
+            if s is not None:
+                dash.attach_loadgen_snapshot(s, force=True)
+            time.sleep(0.1)
+        # Join the SUB before the final render so no late snapshot attaches.
+        sub_reader.stop()
+        sub_reader.join(timeout=1.0)
+        # Wait elapsed with no terminal snapshot → the aggregator never
+        # finalized (crash / OOM / drain past the wait). Flag it so the
+        # closing frame says "unavailable", not a perpetual "finalizing…".
+        if not dash.has_terminal_loadgen:
+            dash.mark_final_unavailable()
+        # Bypass the per-tick fold-defer window so the final render
+        # captures COMPLETE frames that landed within the last 300 ms
+        # — otherwise they sit queued and the closing frame shows
+        # stale stage histograms / verdict.
+        dash.flush_pending_folds()
+        final_frame = dash.render()
+        live.update(final_frame)
+    # Now we're back on the normal screen — print the last snapshot
+    # so the user can see the totals + verdict after the run ends.
+    if final_frame is not None:
+        console.print(final_frame)
+        console.print("[dim]── trace finished ──[/dim]")
+    return 0
+
+
+if __name__ == "__main__":
+    sys.exit(main())