Files
2026-07-13 12:24:33 +08:00

327 lines
11 KiB
Python

# SPDX-License-Identifier: Apache-2.0
"""``lmcache trace replay`` — replay a trace file against a StorageManager."""
# Future
from __future__ import annotations
# Standard
from typing import TYPE_CHECKING
import argparse
import json
import os
import sys
# First Party
from lmcache.cli.commands.base import BaseCommand
from lmcache.cli.metrics import Metrics, StreamHandler, get_formatter
from lmcache.logging import init_logger
logger = init_logger(__name__)
if TYPE_CHECKING:
# First Party
from lmcache.cli.commands.trace._driver import ReplayResult
from lmcache.cli.commands.trace._stats import ReplayStatsCollector
class ReplayCommand(BaseCommand):
"""Replay a trace file against a fresh StorageManager."""
def name(self) -> str:
return "replay"
def help(self) -> str:
return "Replay a trace file against a fresh StorageManager."
def add_arguments(self, parser: argparse.ArgumentParser) -> None:
add_replay_arguments(parser)
def execute(self, args: argparse.Namespace) -> None:
run_trace_replay(args)
def add_replay_arguments(parser: argparse.ArgumentParser) -> None:
"""Add ``lmcache trace replay`` arguments to *parser*.
Args:
parser: The ``ArgumentParser`` for the replay subcommand.
"""
parser.add_argument(
"trace_path",
metavar="FILE",
help="Path to a .lct trace file.",
)
parser.add_argument(
"--verbose",
action="store_true",
default=False,
help="Print one line per replayed record.",
)
parser.add_argument(
"--jsonl-out",
default=None,
metavar="PATH",
help=(
"Write one JSON object per replayed record to PATH "
"(qualname, latency_ms, failed). Useful for post-hoc "
"analysis."
),
)
parser.add_argument(
"--output-dir",
default=".",
help=(
"Directory for aggregated CSV/JSON summary output "
"(default: current directory)."
),
)
parser.add_argument(
"--no-csv",
action="store_true",
help="Skip the aggregated CSV summary export.",
)
parser.add_argument(
"--json",
action="store_true",
help="Also export an aggregated JSON summary.",
)
try:
# First Party
from lmcache.v1.distributed.config import add_storage_manager_args
from lmcache.v1.mp_observability.config import add_observability_args
add_storage_manager_args(parser)
add_observability_args(parser)
except ImportError as e:
logger.warning("lmcache trace replay import error, error is %s", e)
def run_trace_replay(args: argparse.Namespace) -> None:
"""Construct a StorageManager from *args* and drive replay.
Produces three kinds of output:
* Per-record stream: every dispatch is logged at INFO with its
progress (``[N/total]``), qualname, and latency.
``--verbose`` additionally mirrors each record to stdout,
and ``--jsonl-out PATH`` writes one JSON object per record
to ``PATH`` for post-hoc analysis.
* Aggregated per-qualname summary: CSV (unless ``--no-csv``)
and JSON (with ``--json``) written under ``--output-dir``.
* Terminal metrics table (unless ``--quiet``) using the shared
:class:`~lmcache.cli.metrics.Metrics` renderer.
Args:
args: Parsed CLI arguments.
"""
# First Party
from lmcache.cli.commands.trace._driver import StorageReplayDriver
from lmcache.v1.distributed.config import StorageManagerConfig, parse_args_to_config
from lmcache.v1.mp_observability.config import parse_args_to_observability_config
from lmcache.v1.mp_observability.trace.reader import TraceReader
sm_config: StorageManagerConfig = parse_args_to_config(args)
# ``--trace-level`` / ``--trace-output`` belong to the recording
# surface. They are still registered on the parser so the flag set
# stays in lock-step with ``lmcache server``, but they have no
# meaning here — any value a caller passes is silently clobbered to
# ``None`` so the replay-side ``ObservabilityConfig`` never tries to
# start a recorder.
args.trace_level = None
args.trace_output = None
obs_config = parse_args_to_observability_config(args)
# Create output directories *before* replay starts. A replay
# can run for minutes; surfacing a bad ``--output-dir`` or
# unwritable ``--jsonl-out`` parent now avoids silently losing
# the summary/stream after the work has already happened.
os.makedirs(args.output_dir, exist_ok=True)
if args.jsonl_out:
jsonl_parent = os.path.dirname(os.path.abspath(args.jsonl_out))
if jsonl_parent:
os.makedirs(jsonl_parent, exist_ok=True)
# ANSI: bold + yellow for the banner text, reset at the end.
bold = "\033[1;33m"
reset = "\033[0m"
bar = "=" * 78
logger.warning(
"\n%s%s\n"
" !! REPLAY ENVIRONMENT MISMATCH MAY CAUSE RETRIEVE MISSES !!\n"
"%s%s\n"
" * Replay uses the *replay-side* StorageManager config, which\n"
" may differ from the config recorded in the trace.\n"
" * Replay runs on a host whose performance may differ from\n"
" the recording host.\n"
" * StorageManager reads/writes are async — an L2 load that\n"
" had finished at record time may not have finished yet at\n"
" replay time, so the matching retrieve can miss.\n"
"\n"
" Treat retrieve-miss counts as a signal about the replay\n"
" environment, not as a defect in the trace.\n"
"%s%s",
bold,
bar,
bar,
reset,
bar,
reset,
)
# Pre-scan to count total records so progress logs can show
# [N/total]. The reader streams frames, so counting is cheap
# relative to replay (which actually dispatches StorageManager
# calls).
with TraceReader(args.trace_path) as r:
total_records = sum(1 for _ in r.records())
logger.info(
"trace replay: file=%s records=%d",
args.trace_path,
total_records,
)
jsonl_fh = open(args.jsonl_out, "w") if args.jsonl_out else None
verbose = args.verbose
counter = {"n": 0}
def _on_record(qualname: str, latency_s: float, failed: bool) -> None:
counter["n"] += 1
status = "FAIL" if failed else "OK"
logger.info(
"[%d/%d] %s %s (%.3fms)",
counter["n"],
total_records,
status,
qualname,
latency_s * 1000.0,
)
if verbose:
print(
f" [{counter['n']}/{total_records}] "
f"{status:<4} {latency_s * 1000:8.3f}ms {qualname}"
)
if jsonl_fh is not None:
jsonl_fh.write(
json.dumps(
{
"qualname": qualname,
"latency_ms": latency_s * 1000.0,
"failed": failed,
}
)
+ "\n"
)
try:
with StorageReplayDriver(
sm_config, args.trace_path, obs_config=obs_config
) as driver:
result = driver.run(on_record=_on_record)
finally:
if jsonl_fh is not None:
jsonl_fh.close()
if not args.no_csv:
csv_path = os.path.join(args.output_dir, "trace_replay_ops.csv")
result.stats.export_csv(csv_path)
logger.info("CSV written to %s", csv_path)
if args.json:
json_path = os.path.join(args.output_dir, "trace_replay_summary.json")
result.stats.export_json(json_path)
logger.info("JSON written to %s", json_path)
if not args.quiet:
_emit_replay_metrics(result.stats, result)
if result.records_failed > 0:
sys.exit(1)
def _emit_replay_metrics(
stats: "ReplayStatsCollector",
result: "ReplayResult",
) -> None:
"""Print the replay summary using the shared :class:`Metrics` renderer.
Args:
stats: The stats collector populated during replay.
result: The full :class:`ReplayResult` — used for the
replayed/skipped/failed totals and digest comparison.
"""
metrics = Metrics(title="Trace Replay Result")
metrics.add_handler(StreamHandler(get_formatter("terminal", width=64)))
overall = metrics.add_section("overall", "Overall")
overall.add("level", "Trace level", result.header_level)
overall.add("replayed", "Records replayed", result.records_replayed)
overall.add("skipped", "Records skipped", result.records_skipped)
overall.add("failed", "Records failed", result.records_failed)
overall.add(
"duration",
"Replay duration (s)",
round(stats.total_duration_s(), 3),
)
header_digest = result.header_digest
replay_digest = result.replay_config_digest
if header_digest and replay_digest and header_digest != replay_digest:
overall.add(
"digest",
"Config digest",
f"MISMATCH (rec={header_digest[:8]}, run={replay_digest[:8]})",
)
elif header_digest:
overall.add("digest", "Config digest", f"match ({header_digest[:8]})")
summary = stats.summary()
if summary:
ops_section = metrics.add_section("ops", "Per-Op Latency (ms)")
for qn in sorted(summary):
s = summary[qn]
short = _short_op_name(qn)
ops_section.add(f"{short}_count", f"{short} count", s.count)
ops_section.add(
f"{short}_mean",
f"{short} mean",
round(s.mean_ms, 3),
)
ops_section.add(
f"{short}_p50",
f"{short} p50",
round(s.p50_ms, 3),
)
ops_section.add(
f"{short}_p99",
f"{short} p99",
round(s.p99_ms, 3),
)
metrics.emit()
def _short_op_name(qualname: str) -> str:
"""Return a compact, human-readable label for a traced qualname.
Plain methods collapse to the method name: the table has limited
column width and the fully-qualified path is verbose.
Context-manager handlers (``__enter__`` / ``__exit__``) instead
collapse to ``<owning_method>.enter`` / ``<owning_method>.exit``,
so the reader can tell *which* context manager the pair belongs
to — the bare ``__enter__`` / ``__exit__`` label is useless when
multiple context-manager-returning methods are traced.
Args:
qualname: Dotted qualname recorded by the tracer, e.g.
``lmcache.v1.distributed.storage_manager.StorageManager.read_prefetched_results.__enter__``.
Returns:
A short label suitable as a metrics row prefix.
"""
parts = qualname.split(".")
last = parts[-1]
if last in ("__enter__", "__exit__") and len(parts) >= 2:
return f"{parts[-2]}.{last.strip('_')}"
return last