feat(analyzer): surface TTFT/TPOT as features and CDF figures

The gateway records three epoch-ms stamps per request (admitted, forwarded to
backend, backend first token). They reached *-raw.jsonl but stopped there:
features.csv had only total latency, and none of the figures covered
time-to-first-token.

Derive ttft_ms, ttft_e2e_ms and tpot_ms in one helper shared by the streaming
path (preparation.py) and the in-memory path (features.py) so the two cannot
drift, and add figures 14 (TTFT, backend vs end-to-end) and 15 (TPOT). The two
TTFT series are plotted together because their offset is the gateway admission
delay, which is then readable straight off the chart.

Rows missing a backend stamp and single-token responses are recorded as 0 and
filtered at plot time; left in, they would stack at the origin and pull every
percentile down. Figure 15 is a single panel: TPOT is near-deterministic
(p50 21.9, p90 23.0), so a p90 zoom renders a flat line and a vertical edge.

Verified by recomputing ttft_ms straight from the original SLS rows for all
2190 requests of a sample: 0 mismatches.

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

README.md

@@ -10,7 +10,7 @@
 - `trace_analyzer` 不再直接处理 provider-native 原始日志。
 - `details/` 只放画图所需数据。
 - `figures/` 只放最终图片。
-- 当前主分析入口只维护 13 张图，对应的数据也只保留为这 13 张图服务的最小集合。
+- 当前主分析入口只维护 15 张图，对应的数据也只保留为这 15 张图服务的最小集合。
 
 朴素 wall-clock 时间字段如 `time` 按 `UTC+8` 解释。
 
@@ -113,6 +113,7 @@ outputs/
 
 - `request_metrics.csv`
   请求级主表。用于：
+  - TTFT / TPOT
   - input/output length
   - session turns / turn 维度请求长度
   - trigger role 占比
@@ -131,7 +132,7 @@ outputs/
 - `progress.json`
   大 trace 运行时的进度与资源占用信息。
 
-### `figures/` 当前只保留的 13 张图
+### `figures/` 当前只保留的 15 张图
 
 `figures/` 是展示层，只放图片和轻量说明文件。
 
@@ -148,6 +149,8 @@ outputs/
 11. `11_alive_kvcache_blocks_timeline.png`
 12. `12_bucket_kvcache_reuse_ratio.png`
 13. `13_session_cross_bucket_kvcache_miss.png`
+14. `14_ttft_cdf.png`
+15. `15_tpot_cdf.png`
 
 另外还有：
 

trace_analyzer/cli.py

@@ -423,7 +423,7 @@ def main(argv=None):
                 progress,
                 4,
                 total_steps,
-                "figures: 13 approved request/session/tool/kvcache plots",
+                "figures: 15 approved request/session/tool/latency/kvcache plots",
             )
             figure_result = render_figures(
                 analysis_dir=output_dir,

trace_analyzer/features.py

@@ -1,7 +1,7 @@
 from collections import Counter
 from dataclasses import asdict
 
-from .helpers import percentile, safe_div
+from .helpers import latency_breakdown, percentile, safe_div
 from .models import TraceFeatures
 
 LONG_CONTEXT_THRESHOLD = 32000
@@ -75,6 +75,7 @@ def compute_features(records):
             high_cache=1 if cache_hit_ratio >= HIGH_CACHE_THRESHOLD else 0,
             tool_burst_alert=1 if (max(bursts) if bursts else 0) >= TOOL_BURST_THRESHOLD else 0,
             tool_loop_alert=1 if tool_to_tool_count >= TOOL_LOOP_THRESHOLD else 0,
+            **latency_breakdown(record.meta, output_tokens),
         )
         feature.pattern_labels = base_pattern_labels(feature)
         features.append(feature)

trace_analyzer/figures.py

@@ -44,6 +44,8 @@ FIGURE_STEMS = [
     "11_alive_kvcache_blocks_timeline",
     "12_bucket_kvcache_reuse_ratio",
     "13_session_cross_bucket_kvcache_miss",
+    "14_ttft_cdf",
+    "15_tpot_cdf",
 ]
 
 
@@ -112,6 +114,9 @@ def _load_request_metrics(path: Path) -> list[dict]:
                     "output_tokens": safe_int(row.get("output_tokens")),
                     "request_ready_time_ms": safe_int(row.get("request_ready_time_ms")),
                     "request_end_time_ms": safe_int(row.get("request_end_time_ms")),
+                    "ttft_ms": safe_int(row.get("ttft_ms")),
+                    "ttft_e2e_ms": safe_int(row.get("ttft_e2e_ms")),
+                    "tpot_ms": safe_float(row.get("tpot_ms")),
                     "input_length_bucket": row.get("input_length_bucket", ""),
                     "theoretical_prompt_unit_length": safe_int(row.get("theoretical_prompt_unit_length")),
                     "theoretical_prefix_hit_blocks": safe_int(row.get("theoretical_prefix_hit_blocks")),
@@ -623,6 +628,42 @@ def _plot_session_cross_bucket_miss(fig_dir: Path, rows: list[dict]) -> None:
     _save(fig, fig_dir, "13_session_cross_bucket_kvcache_miss")
 
 
+def _plot_ttft_cdf(fig_dir: Path, request_rows: list[dict]) -> None:
+    # Requests missing either backend timestamp carry 0. Plotting those would pile
+    # a spike at the origin and drag every percentile down, so drop them.
+    backend_values = [row["ttft_ms"] for row in request_rows if row["ttft_ms"] > 0]
+    e2e_values = [row["ttft_e2e_ms"] for row in request_rows if row["ttft_e2e_ms"] > 0]
+    _plot_two_series_cdf_with_zoom(
+        fig_dir,
+        stem="14_ttft_cdf",
+        title="Time To First Token CDF",
+        xlabel="Milliseconds",
+        first_label="TTFT backend",
+        first_values=backend_values,
+        first_color=PALETTE["teal"],
+        second_label="TTFT end-to-end",
+        second_values=e2e_values,
+        second_color=PALETTE["red"],
+        zoom_quantile=0.90,
+        stats_labels=("mean", "p50", "p90", "p95", "p99"),
+    )
+
+
+def _plot_tpot_cdf(fig_dir: Path, request_rows: list[dict]) -> None:
+    # A single-token response has no decode interval to average over and is
+    # reported as 0; it is not a zero-cost token.
+    values = [row["tpot_ms"] for row in request_rows if row["tpot_ms"] > 0]
+    _plot_single_cdf(
+        fig_dir,
+        stem="15_tpot_cdf",
+        title="Time Per Output Token CDF",
+        xlabel="Milliseconds per output token",
+        label="TPOT",
+        values=values,
+        color=PALETTE["green"],
+    )
+
+
 def _write_manifest(fig_dir: Path, manifest: dict) -> None:
     (fig_dir / "manifest.json").write_text(json.dumps(manifest, ensure_ascii=False, indent=2), encoding="utf-8")
 
@@ -781,6 +822,14 @@ def render_figures(
         progress.update(1)
         progress.set_postfix(current="13_session_cross_bucket_kvcache_miss")
     _plot_session_cross_bucket_miss(fig_root, session_bucket_rows)
+    if show_progress:
+        progress.update(1)
+        progress.set_postfix(current="14_ttft_cdf")
+    _plot_ttft_cdf(fig_root, request_rows)
+    if show_progress:
+        progress.update(1)
+        progress.set_postfix(current="15_tpot_cdf")
+    _plot_tpot_cdf(fig_root, request_rows)
     _plot_session_gap_cdf(fig_root, session_rows_by_id)
 
     if show_progress:

trace_analyzer/helpers.py

@@ -154,6 +154,38 @@ def series_stats(values):
     }
 
 
+def latency_breakdown(meta, output_tokens):
+    """Split one request's latency into time-to-first-token and time-per-output-token.
+
+    The gateway records three epoch-ms stamps per request: when it admitted the
+    request, when it forwarded it to the backend, and when the backend's first
+    token came back. So:
+
+      ttft_ms      backend serving time to first token (prefill + backend queue)
+      ttft_e2e_ms  the same, plus the gateway admission delay ahead of it
+      tpot_ms      decode phase averaged over the tokens after the first
+
+    Rows missing either backend stamp -- about 0.5% of a production dump -- and
+    single-token responses (no decode interval exists) yield 0. Callers must drop
+    those rather than plot them as genuine zero-latency requests.
+    """
+    first_request_ms = safe_int(getattr(meta, "backend_first_request_time_ms", 0))
+    first_response_ms = safe_int(getattr(meta, "backend_first_response_time_ms", 0))
+    ready_ms = safe_int(getattr(meta, "request_ready_time_ms", 0))
+    end_ms = safe_int(getattr(meta, "request_end_time_ms", 0))
+    output_tokens = safe_int(output_tokens)
+
+    ttft_ms = first_response_ms - first_request_ms if first_request_ms and first_response_ms else 0
+    ttft_e2e_ms = first_response_ms - ready_ms if ready_ms and first_response_ms else 0
+    decode_ms = end_ms - first_response_ms if end_ms and first_response_ms else 0
+    tpot_ms = decode_ms / (output_tokens - 1) if decode_ms > 0 and output_tokens > 1 else 0.0
+    return {
+        "ttft_ms": ttft_ms if ttft_ms > 0 else 0,
+        "ttft_e2e_ms": ttft_e2e_ms if ttft_e2e_ms > 0 else 0,
+        "tpot_ms": round(tpot_ms, 3),
+    }
+
+
 def safe_div(numerator, denominator):
     if not denominator:
         return 0.0

trace_analyzer/models.py

@@ -91,4 +91,7 @@ class TraceFeatures:
     tool_burst_alert: int
     tool_loop_alert: int
     slow_request: int = 0
+    ttft_ms: int = 0
+    ttft_e2e_ms: int = 0
+    tpot_ms: float = 0.0
     pattern_labels: list[str] = field(default_factory=list)

trace_analyzer/preparation.py

@@ -5,7 +5,7 @@ import json
 import os
 from pathlib import Path
 
-from trace_analyzer.helpers import percentile
+from trace_analyzer.helpers import latency_breakdown, percentile
 from trace_analyzer.parser import get_adapter
 from tqdm.auto import tqdm
 
@@ -98,6 +98,7 @@ def stream_prepare(input_path: str | Path, output_dir: str | Path, *, show_progr
                     "latency_ms": record.meta.total_cost_time_ms,
                     "ms_per_input_token": _safe_div(record.meta.total_cost_time_ms, record.usage.input_tokens),
                     "ms_per_output_token": _safe_div(record.meta.total_cost_time_ms, record.usage.output_tokens),
+                    **latency_breakdown(record.meta, record.usage.output_tokens),
                     "long_context": 1 if record.usage.input_tokens >= 32000 else 0,
                     "high_cache": 1 if cache_hit_ratio >= 0.8 else 0,
                     "tool_burst_alert": 1 if max_tool_burst >= 4 else 0,

trace_analyzer/resume_advanced.py

@@ -751,7 +751,7 @@ def run_advanced_from_existing(
     details_summary = {
         "schema_version": 3,
         "request_count": total_requests,
-        "figure_count": 13,
+        "figure_count": 15,
         "cache_analysis_mode": "release_hash_ids",
         "release_path": str(release_path),
         "bucket_definition": {"buckets": _bucket_definition_rows(bucket_defs)},