From 825062f554f53ccf3ba65a2558ffe08d1dd8e1b7 Mon Sep 17 00:00:00 2001 From: Gahow Wang Date: Fri, 11 Sep 2026 06:31:48 +0000 Subject: [PATCH] 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) --- README.md | 7 +++-- trace_analyzer/cli.py | 2 +- trace_analyzer/features.py | 3 +- trace_analyzer/figures.py | 49 +++++++++++++++++++++++++++++++ trace_analyzer/helpers.py | 32 ++++++++++++++++++++ trace_analyzer/models.py | 3 ++ trace_analyzer/preparation.py | 3 +- trace_analyzer/resume_advanced.py | 2 +- 8 files changed, 95 insertions(+), 6 deletions(-) diff --git a/README.md b/README.md index 5abb853..cd74f80 100644 --- a/README.md +++ b/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` 另外还有： diff --git a/trace_analyzer/cli.py b/trace_analyzer/cli.py index e389c45..aaad2b5 100644 --- a/trace_analyzer/cli.py +++ b/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, diff --git a/trace_analyzer/features.py b/trace_analyzer/features.py index d86d2a2..b8eac5d 100644 --- a/trace_analyzer/features.py +++ b/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) diff --git a/trace_analyzer/figures.py b/trace_analyzer/figures.py index 83e6760..af4e995 100644 --- a/trace_analyzer/figures.py +++ b/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: diff --git a/trace_analyzer/helpers.py b/trace_analyzer/helpers.py index 9aaf75b..f16ed9d 100644 --- a/trace_analyzer/helpers.py +++ b/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 diff --git a/trace_analyzer/models.py b/trace_analyzer/models.py index 79ea289..c318fcc 100644 --- a/trace_analyzer/models.py +++ b/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) diff --git a/trace_analyzer/preparation.py b/trace_analyzer/preparation.py index 0ce01ec..bc74654 100644 --- a/trace_analyzer/preparation.py +++ b/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, diff --git a/trace_analyzer/resume_advanced.py b/trace_analyzer/resume_advanced.py index 1a29736..6f7ef4d 100644 --- a/trace_analyzer/resume_advanced.py +++ b/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)},