From c4e6c7695847815e8362061c512d294aba73ea16 Mon Sep 17 00:00:00 2001 From: bong-water-water-bong Date: Wed, 11 Nov 2026 03:12:19 -0400 Subject: [PATCH] tools: npu_serve_smoke prints the box's load, and names a busy box when only the timing failed (Refs #2106) The gate's rate was read three ways on #2106 in one night: 93-94 tok/s, 50 tok/s, and "a function of answer length". It is none of the last two. On the shipped binary the median is 85.7-88.7 tok/s at 16, 32, 96 and 128 answer tokens on a quiet box; the 50 was a loaded box (the route keeps about 1.5 CPU cores of host work per token, and npu-hold serialises the device, not the CPU; I measured 51-89 beside a 10-job build of my own). So the tool now prints one `load` line: the 1-minute load average as the run found it. When the route and the content pass and only the timing fails, the line says a busy box is the likely cause and to re-run on a quiet one. It never changes the result. The load is saved in load.json so --judge reports the run's box, not today's. Self-test: 7 new checks (a pass blames nothing; the busy-box row is named; first token alone counts; the slow route and empty content are never excused; no load average, no line; the result stays FAIL). Co-Authored-By: Claude Fable 5.2 --- docs/hw-gate.md | 9 +++++ tools/npu_serve_smoke.py | 72 ++++++++++++++++++++++++++++++++++++++-- 2 files changed, 78 insertions(+), 3 deletions(-) diff --git a/docs/hw-gate.md b/docs/hw-gate.md index e9b70eb52..ed0dedb4a 100644 --- a/docs/hw-gate.md +++ b/docs/hw-gate.md @@ -275,6 +275,15 @@ tools/npu_serve_smoke.py --self-test # the judging on the shape of each f tools/npu_serve_smoke.py --judge # judge a finished run's serve.log and reply_*.json again ``` +It also prints one `load` line: the box's 1-minute load average as the run found it (kept in `load.json`, so +`--judge` reports the run's load and not today's). The fast route keeps about 1.5 CPU cores of host work per token and +`npu-hold` serialises the device, not the CPU. Measured on the shipped binary (#2106): 86-94 tok/s at 16, 32, 96 and +128 answer tokens on a quiet box, and 51-89 tok/s while a 10-job build ran beside it, on the same route with the same +answers. So the floor is not a function of answer length, and when the route and the content pass and only the timing +fails, the line says a busy box is the likely cause and to re-run on a quiet one. It never turns a FAIL into a PASS: +a starved box is something the release run should notice. + + The two route texts are what the serve prints today (`on the private route dx`, `per-op forward`); `--fast-route` and `--slow-route` change them when the serve's wording does, and a log that names neither is a failure, not a pass. It prints one line per assertion and `RESULT: PASS` or `RESULT: FAIL` (exit 0 or 1). It takes no device diff --git a/tools/npu_serve_smoke.py b/tools/npu_serve_smoke.py index cd142527c..4665b4d1a 100755 --- a/tools/npu_serve_smoke.py +++ b/tools/npu_serve_smoke.py @@ -119,10 +119,41 @@ def judge(log_text, replies, floor=60.0, first_token_ms=600.0, fast_route=FAST_R return out -def report(verdicts): +def load_note(verdicts, load1, ncpu): + """One line about the box, or None. Pure: verdicts and two numbers in, text out. + + The fast route keeps about 1.5 CPU cores of host work per token, and npu-hold serialises the device, not the CPU. + Measured on the shipped binary (engine#2106): 86-94 tok/s on a quiet box at every answer length, 51-89 while a + 10-job build ran beside it, on the same route with the same answers. So a run where the route and the content + pass and ONLY the timing fails is, more often than a regression, a busy box. This says so; it never changes the + result -- a starved box is something the release run should notice, not excuse. + """ + if load1 is None: + return None + got = {v[0]: v[1] for v in verdicts} + timing_only = got.get("route") and got.get("content") and not (got.get("rate") and got.get("first-token")) + line = "1-minute load average %.1f on %d CPUs" % (load1, ncpu) + if timing_only: + line += ("; the route and the content passed and only the timing failed -- a busy box is the likely cause" + " (the route needs about 1.5 cores per token). Re-run on a quiet box before reading this as a regression") + return line + + +def box_load(): + """(1-minute load average, CPU count), or (None, 0) where the platform has no load average.""" + try: + return os.getloadavg()[0], os.cpu_count() or 1 + except (OSError, AttributeError): + return None, 0 + + +def report(verdicts, load1=None, ncpu=0): ok = all(v[1] for v in verdicts) for name, good, detail in verdicts: print("%-12s %s %s" % (name, "ok " if good else "FAIL", detail)) + note = load_note(verdicts, load1, ncpu) + if note: + print("%-12s %s %s" % ("load", "info", note)) print("RESULT: %s" % ("PASS" if ok else "FAIL")) return 0 if ok else 1 @@ -151,6 +182,10 @@ def stop(signum, _frame): os.makedirs(out, exist_ok=True) log_path = os.path.join(out, "serve.log") cmd = [args.bin, "serve", "-m", args.model, "--device", "npu", "--host", "127.0.0.1", "-p", str(args.port)] + load1, ncpu = box_load() # before the serve starts: the box as the run found it, not the run's own load + if load1 is not None: + with open(os.path.join(out, "load.json"), "w") as f: + json.dump({"load1": load1, "ncpu": ncpu}, f) replies = [] with open(log_path, "wb") as log: serve = subprocess.Popen(cmd, stdout=log, stderr=subprocess.STDOUT, preexec_fn=die_with_parent) @@ -194,7 +229,7 @@ def stop(signum, _frame): log_text = f.read() if not replies: print("serve FAIL it never became ready within %d s (exit %s); see %s" % (args.ready_seconds, serve.returncode, log_path)) - return report(judge(log_text, replies, args.floor, args.first_token_ms, args.fast_route, args.slow_route)) + return report(judge(log_text, replies, args.floor, args.first_token_ms, args.fast_route, args.slow_route), load1, ncpu) def rejudge(args): @@ -207,7 +242,14 @@ def rejudge(args): with open(os.path.join(d, "reply_%d.json" % i)) as f: replies.append(json.load(f)) i += 1 - return report(judge(log_text, replies, args.floor, args.first_token_ms, args.fast_route, args.slow_route)) + load1, ncpu = None, 0 # the load the RUN recorded, if it did: judging again later must not read today's box + try: + with open(os.path.join(d, "load.json")) as f: + rec = json.load(f) + load1, ncpu = float(rec["load1"]), int(rec["ncpu"]) + except (OSError, ValueError, KeyError, TypeError): + pass + return report(judge(log_text, replies, args.floor, args.first_token_ms, args.fast_route, args.slow_route), load1, ncpu) FAKE_SERVE = r'''#!/usr/bin/env python3 @@ -334,6 +376,30 @@ def expect(name, verdicts, want): # the measured demo row passes expect("the measured fast-route row", judge(fast_log, good), all_ok) + # the load line: always states the box, and names a busy box only when the timing ALONE failed + def note_is(name, verdicts, load1, want_hint, want_none=False): + n = load_note(verdicts, load1, 32) + if want_none: + if n is not None: + fails.append("%s: expected no load line, got %r" % (name, n)) + elif n is None or ("busy box" in n) != want_hint or ("%.1f" % load1) not in n: + fails.append("%s: load line %r (hint wanted: %s)" % (name, n, want_hint)) + busy = [reply("The capital of France is Paris.", 53.3, 433), reply("def fib(n): ...", 46.4, 446), reply("391", 50.0, 433)] + note_is("a pass states the load and blames nothing", judge(fast_log, good), 4.6, False) + note_is("the busy-box row (fast route, right answers, 50 tok/s)", judge(fast_log, busy), 21.0, True) + late = [reply("The capital of France is Paris.", 90.0, 900), reply("def fib(n): ...", 88.0, 950), reply("391", 91.0, 910)] + note_is("first token alone over the limit is a timing-only failure too", judge(fast_log, late), 18.0, True) + note_is("the slow route is never excused by load", judge(slow_log, busy), 21.0, False) + note_is("empty content is never excused by load", + judge(fast_log, [reply("", 50.0, 433, reasoning="Okay ...") for _ in range(3)]), 21.0, False) + note_is("no load average on the platform: no line", judge(fast_log, busy), None, False, want_none=True) + import contextlib + import io + printed = io.StringIO() + with contextlib.redirect_stdout(printed): + rc = report(judge(fast_log, busy), 21.0, 32) + if rc != 1 or "RESULT: FAIL" not in printed.getvalue() or "load info" not in printed.getvalue(): + fails.append("a busy-box failure must still FAIL and print its load line: the note never changes the result") # engine#2102 as it was seen: the slow route answers correctly, at 1.9 tok/s. Three of four assertions catch it. slow = [reply("The capital of France is Paris.", 1.9, 4100), reply("def fib(n): ...", 1.87, 4200), reply("391", 1.9, 4000)] expect("the silent fallback", judge(slow_log, slow), {"route": False, "rate": False, "first-token": False, "content": True})