unsloth/studio/backend/tests/test_llama_stats.py
Daniel Han 9a966adf51
Studio: trim serving-log noise and surface llama-server engine stats (#6377)
* Studio: trim serving-log noise and surface llama-server engine stats

Studio prints one structured line per HTTP request, so the SPA's polling and
per-invalidation fan-out bury the lines that matter.

- Dedup identical successful GETs within a short window (default 300ms,
  UNSLOTH_STUDIO_ACCESS_LOG_DEDUP_MS) so a burst logs once. The dedup key
  includes the query string, so distinct query-driven GETs are not collapsed.
  Runs after the response is sent, so it adds no request latency; mutations,
  non-2xx, and loading polls are untouched.
- Collapse pure-liveness polls (/api/health, /api/auth/status,
  /api/inference/status, /api/inference/monitor) to a longer heartbeat
  (default 10s, UNSLOTH_STUDIO_ACCESS_LOG_POLL_DEDUP_MS). The API monitor
  console polls /monitor every 1.5s while open.
- Translate llama-server's Prometheus /metrics into a periodic vLLM-style
  engine_stats line (generation/prompt throughput and requests in flight) from
  a daemon poller, gated on UNSLOTH_STUDIO_ENGINE_STATS. Throughput uses
  llama-server's predicted_tokens_seconds / prompt_tokens_seconds gauges, with
  a tokens_predicted_total / prompt_tokens_total counter-delta fallback; it does
  not use n_decode_total (which counts llama_decode() calls, not tokens). No KV
  field is emitted, since llama.cpp does not expose kv_cache_usage_ratio.
  --metrics is added only when probe_server_capabilities reports the binary
  supports it, so older/custom binaries still load. The poller keeps retrying
  through transient scrape failures (stop() drives shutdown) and a malformed
  sample cannot crash its thread.
- api_monitor.append_reply: once the preview cap is reached, skip the per-chunk
  re-concat (avoids O(n^2) on long generations) while still recording the "..."
  truncation marker for a reply that lands exactly on the cap.
- unsloth studio --verbose and unsloth studio run --verbose both restore every
  per-request log; --verbose before a subcommand is rejected with guidance
  (matching --secure / --parallel). run --verbose still forwards --log-verbose
  to llama-server, preserving the pre-existing pass-through verbosity.

* [pre-commit.ci] auto fixes from pre-commit.com hooks

for more information, see https://pre-commit.ci

---------

Co-authored-by: pre-commit-ci[bot] <66853113+pre-commit-ci[bot]@users.noreply.github.com>
2026-06-17 05:37:57 -07:00

128 lines
4.1 KiB
Python

# SPDX-License-Identifier: AGPL-3.0-only
# Copyright 2026-present the Unsloth AI Inc. team. All rights reserved. See /studio/LICENSE.AGPL-3.0
"""Tests for the llama-server /metrics -> engine_stats translator: generation
throughput comes from generated-token metrics (not llama_decode() calls), and
the unexposed kv_cache_usage_ratio is never fabricated into the log line."""
from core.inference.llama_stats import LlamaServerStatsLogger
class _Capture:
def __init__(self):
self.events = []
def info(self, event, **kw):
self.events.append((event, dict(kw)))
def debug(self, *a, **k):
pass
def _drive(snaps):
"""Run _run() synchronously over `snaps`, then stop deterministically."""
cap = _Capture()
lg = LlamaServerStatsLogger("http://127.0.0.1:0", cap)
lg._interval = 0.001 # bypass the 1s floor for a fast, synchronous run
state = {"i": 0}
def fake_scrape():
i = state["i"]
state["i"] += 1
if i >= len(snaps):
lg.stop()
return None
return snaps[i]
lg._scrape = fake_scrape
lg._run()
return [kw for ev, kw in cap.events if ev == "engine_stats"]
def test_gen_tok_s_uses_token_metrics_not_decode_calls():
# tokens_predicted_total jumps 95 while n_decode_total only moves 9; the
# gauge reports 95 tok/s. Decode-call rate (9) must not be reported.
snaps = [
{
"tokens_predicted_total": 0.0,
"prompt_tokens_total": 0.0,
"n_decode_total": 0.0,
"predicted_tokens_seconds": 95.0,
"prompt_tokens_seconds": 30.0,
"requests_processing": 1.0,
},
{
"tokens_predicted_total": 95.0,
"prompt_tokens_total": 30.0,
"n_decode_total": 9.0,
"predicted_tokens_seconds": 95.0,
"prompt_tokens_seconds": 30.0,
"requests_processing": 1.0,
},
]
stats = _drive(snaps)
assert stats, "expected engine_stats while a request is processing"
assert all(s["gen_tok_s"] == 95.0 for s in stats)
assert all(s["prompt_tok_s"] == 30.0 for s in stats)
def test_kv_cache_pct_not_emitted_when_metric_absent():
# llama.cpp does not expose kv_cache_usage_ratio, so it must not appear.
snaps = [
{
"tokens_predicted_total": 0.0,
"prompt_tokens_total": 0.0,
"predicted_tokens_seconds": 10.0,
"requests_processing": 1.0,
},
{
"tokens_predicted_total": 10.0,
"prompt_tokens_total": 5.0,
"predicted_tokens_seconds": 10.0,
"requests_processing": 1.0,
},
]
stats = _drive(snaps)
assert stats
assert all("kv_cache_pct" not in s for s in stats)
def test_scrape_parses_labelled_and_bare_metrics(monkeypatch):
# Prometheus samples may carry labels; both labelled and bare lines parse.
import core.inference.llama_stats as ls
body = (
'llamacpp:tokens_predicted_total{model="m"} 20\n'
'llamacpp:prompt_tokens_total{model="m"} 5\n'
"llamacpp:requests_processing 1\n"
"# HELP llamacpp:ignored ignored\n"
)
class _Resp:
status = 200
def read(self):
return body.encode()
def __enter__(self):
return self
def __exit__(self, *a):
return False
monkeypatch.setattr(ls.urllib.request, "urlopen", lambda *a, **k: _Resp())
m = ls.LlamaServerStatsLogger("http://127.0.0.1:0", _Capture())._scrape()
assert m["tokens_predicted_total"] == 20.0
assert m["prompt_tokens_total"] == 5.0
assert m["requests_processing"] == 1.0
def test_counter_delta_fallback_without_gauges():
# Older binaries expose only the counters; throughput falls back to deltas.
snaps = [
{"tokens_predicted_total": 100.0, "prompt_tokens_total": 0.0, "requests_processing": 1.0},
{"tokens_predicted_total": 100.0, "prompt_tokens_total": 0.0, "requests_processing": 1.0},
]
stats = _drive(snaps)
# running=1 keeps it emitting; gen_tok_s falls back to the (here zero) delta.
assert stats and all(s["gen_tok_s"] >= 0.0 for s in stats)