url/colibri
1
0
Fork 0
Code Issues Pull Requests Actions Packages Projects Releases Wiki Activity

Profiling page: per-turn phase timings, live in the web dashboard

Browse Source 
The engine already tracks where each turn's wall time goes (expert-disk
service, I/O wait, expert matmul, attention, lm_head) — it just only spoke
at exit or under PROF=1. Stream it instead:

- glm.c: mux serve emits a per-turn "PROF" protocol line next to TIERS/HITS
  (window deltas per request, same convention as the STAT hit%); the phase
  window base is now always captured (a few loads per request).
- openai_server.py: parses PROF into a 120-turn rolling window and serves it
  at /profile (read-only, same trust level as /health).
- web: new Profiling tab — stat tiles (tok/s, wall, tokens/forward, disk
  service), wall-time composition bars for the last turn and the window,
  per-turn throughput and stacked phase columns with hover readouts, and a
  table of recent turns. Disk service is shown apart from the stack: it
  overlaps with compute, so only the I/O wait the compute thread felt counts
  inside wall time. Phase colours are a CVD-validated set with gaps + legend
  + table so identity never rides on colour alone.

Co-Authored-By: Claude Fable 5 <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_01WhTmF8yvEBgSkUKSVfZF7P
This commit is contained in:
Claude
2026-07-14 23:48:54 +00:00
committed by Nicholas Beerbower
parent 63a6824881
commit 6afffbcbf2
10 changed files with 321 additions and 8 deletions
Download Patch File Download Diff File Expand all files Collapse all files
c/glm.c
+13 -2
View File
@@ -4874,7 +4874,8 @@ typedef struct {
float temp, top_p;
double started;
uint64_t hits0, miss0;
ProfBase pb; /* PROF=1: window start (same convention as hits0) */
ProfBase pb; /* phase-time window start (same convention as hits0):
feeds the PROF protocol line and the PROF=1 report */
} ServeReq;
static void mux_data(Tok *T, unsigned long long id, int token){
@@ -4891,6 +4892,16 @@ static void mux_done(Model *m, ServeCtx *sc, ServeReq *r){
tiers_emit(m);
emap_emit(m);
hits_emit(m);
/* PROF: per-turn phase timings for the dashboard profiling page —
* "PROF <wall_s> <prompt> <completion> <edisk> <ewait> <emm> <attn> <head> <n_fw>".
* With KV_SLOTS>1 concurrent slots share the batched forwards, so the shares
* describe the whole engine over the window, not the single request (same
* convention as the STAT hit% below). */
printf("PROF %.3f %d %d %.3f %.3f %.3f %.3f %.3f %llu\n",dt,
r->prompt_tokens,r->emitted,
m->t_edisk-r->pb.edisk,m->t_ewait-r->pb.ewait,m->t_emm-r->pb.emm,
m->t_attn-r->pb.attn,m->t_head-r->pb.head,
(unsigned long long)(m->n_fw-r->pb.n_fw));
printf("DONE %llu STAT %d %.2f %.1f %.2f %d %d\n",r->id,r->emitted,
r->emitted/dt,(dh+dm)>0?100.0*dh/(dh+dm):0.0,rss_gb(),
r->prompt_tokens,r->length_limited);
@@ -4961,7 +4972,7 @@ static int mux_submit(Model *m, Tok *T, ServeCtx *ctx, ServeReq *req, int nctx,
ServeReq *r=&req[sub.slot]; memset(r,0,sizeof(*r));
r->id=sub.id; r->maximum=sub.max_tokens; r->temp=sub.temperature; r->top_p=sub.top_p;
r->prompt_tokens=nt; r->started=now_s(); r->hits0=m->hits; r->miss0=m->miss;
if(g_prof) prof_base(m,&r->pb);
prof_base(m,&r->pb); /* a few loads: cheap enough to always track */
int room=maxctx-sc->len-1; if(r->maximum>room){r->maximum=room; r->length_limited=1;}
g_temp=r->temp; g_nuc=r->top_p;
int next=pick_tok(logit,m->c.vocab,-1); free(logit);
c/openai_server.py
+23
View File
@@ -27,6 +27,7 @@ HERE = Path(__file__).resolve().parent
END = b"\x01\x01END\x01\x01\n"
READY = b"\x01\x01READY\x01\x01\n"
MAX_BODY = 4 << 20
PROFILE_TURNS = 120 # rolling window of per-turn PROF snapshots kept for /profile
DEFAULT_CORS_ORIGINS = (
"http://127.0.0.1:8000",
"http://localhost:8000",
@@ -473,6 +474,8 @@ class Engine:
self.emap = None
self.hits = None
self.hits_seq = 0 # latest "TIERS" snapshot from the engine
self.profile = collections.deque(maxlen=PROFILE_TURNS) # per-turn phase timings
self.profile_seq = 0
read_engine_turn(self.process.stdout, READY, lambda _: None)
self.dispatcher = threading.Thread(target=self._dispatch_stdout,
name="colibri-stdout", daemon=True)
@@ -550,6 +553,20 @@ class Engine:
elif kind == "HITS" and len(fields) == 4:
self.hits = fields[3]
self.hits_seq += 1
elif kind == "PROF" and len(fields) >= 10:
# per-turn phase timings: where the engine spent this turn's wall time
self.profile.append({
"wall_s": float(fields[1]),
"prompt_tokens": int(fields[2]),
"completion_tokens": int(fields[3]),
"expert_disk_s": float(fields[4]),
"expert_wait_s": float(fields[5]),
"expert_matmul_s": float(fields[6]),
"attention_s": float(fields[7]),
"lm_head_s": float(fields[8]),
"forwards": int(fields[9]),
})
self.profile_seq += 1
elif kind == "TIERS" and len(fields) >= 6:
self.tiers = {"vram": int(fields[1]), "ram": int(fields[2]),
"disk": int(fields[3]), "vram_gb": float(fields[4]),
@@ -782,6 +799,12 @@ class APIHandler(BaseHTTPRequestHandler):
payload["seq"] = eng.hits_seq
self.send_json(200, payload, request_id)
return
if path == "/profile":
eng = self.server.engine
payload = {"seq": getattr(eng, "profile_seq", 0) if eng else 0,
"turns": list(getattr(eng, "profile", ()) or ()) if eng else []}
self.send_json(200, payload, request_id)
return
if self.serve_static(path):
return
self.require_auth()
c/tests/test_openai_server.py
+33
View File
@@ -380,6 +380,25 @@ class DispatcherTest(unittest.TestCase):
engine.close()
self.assertEqual(chunks, ["é"])
def test_records_profile_snapshots_from_prof_lines(self):
def respond(process, frame):
request_id = frame.split()[1]
process.stdout.feed(b"DATA " + request_id + b" 2\nok\n")
process.stdout.feed(b"PROF 2.500 7 12 0.400 0.100 0.900 0.600 0.200 15\n")
process.stdout.feed(b"DONE " + request_id + b" STAT 12 4.8 0 1.0 7 0\n")
process = FakeProcess(respond)
with patch("openai_server.subprocess.Popen", return_value=process):
engine = Engine("glm", "model")
engine.generate("hello", 16, 0.7, 0.9, lambda _: None)
engine.close()
self.assertEqual(engine.profile_seq, 1)
self.assertEqual(list(engine.profile), [{
"wall_s": 2.5, "prompt_tokens": 7, "completion_tokens": 12,
"expert_disk_s": 0.4, "expert_wait_s": 0.1, "expert_matmul_s": 0.9,
"attention_s": 0.6, "lm_head_s": 0.2, "forwards": 15,
}])
def test_cancels_generation_after_consumer_disconnects(self):
request_id = None
@@ -443,6 +462,20 @@ class HTTPTest(unittest.TestCase):
self.assertIn("queued", scheduler)
self.assertEqual(health["kv_slots"], 2)
def test_profile_reports_recent_turns_without_auth(self):
with urlopen(self.base + "/profile", timeout=2) as response:
self.assertEqual(json.load(response), {"seq": 0, "turns": []})
turn = {"wall_s": 2.5, "prompt_tokens": 7, "completion_tokens": 12,
"expert_disk_s": 0.4, "expert_wait_s": 0.1, "expert_matmul_s": 0.9,
"attention_s": 0.6, "lm_head_s": 0.2, "forwards": 15}
self.engine.profile = [turn]
self.engine.profile_seq = 1
try:
with urlopen(self.base + "/profile", timeout=2) as response:
self.assertEqual(json.load(response), {"seq": 1, "turns": [turn]})
finally:
del self.engine.profile, self.engine.profile_seq
def test_browser_preflight(self):
request = Request(self.base + "/v1/chat/completions", method="OPTIONS", headers={
"Origin": "http://localhost:5173",