diff --git a/dirigo-results/0.2.13-port/intercept/trace/conf-q2_0.json b/dirigo-results/0.2.13-port/intercept/trace/conf-q2_0.json new file mode 100644 index 00000000000..a702dada195 --- /dev/null +++ b/dirigo-results/0.2.13-port/intercept/trace/conf-q2_0.json @@ -0,0 +1,59 @@ +{ + "exe": "/home/bob/bin/strata-sycl-host.sh", + "args": [ + "--pack", + "/home/bob/strata-nvme/q2_0", + "--native", + "/media/bob/3d651e2c-e9a4-4758-ba77-863725fe3731/public/strata-gguf/Q2_0/Q2_0/Qwen3.8-Flash-Next-GSQ-RCO-Q2_0-00001-of-00002.gguf", + "--stream-experts", + "--expert-cache", + "12288", + "--prefill", + "auto", + "--prompt-cache", + "6", + "--prompt-cache-every", + "4096", + "--batch", + "0", + "--spec", + "6", + "--spec-min-p", + "0.5", + "--mtp", + "/home/bob/XeStrata-data/mtp/rt", + "--mtp-draft-vocab", + "/media/bob/3d651e2c-e9a4-4758-ba77-863725fe3731/strata-0.2.13/data/draft_vocab_en.bin", + "--mtp-window", + "8192", + "--max-context", + "131072", + "--kv", + "int8", + "--kv-resident", + "32768", + "--vram-reserve-mib", + "700", + "--conversation-cache-mib", + "2048" + ], + "cwd": "/media/bob/3d651e2c-e9a4-4758-ba77-863725fe3731/strata-0.2.13", + "tokenizer": "/home/bob/XeStrata-data/packs/coder-iq1_m/tokenizer", + "model_name": "qwen3.8-flash-next-coder-iq1_m", + "log": "/media/bob/3d651e2c-e9a4-4758-ba77-863725fe3731/strata-0.2.13/strata-q2_0-noprofile.log", + "port": 8095, + "backend": "sycl", + "open_browser": false, + "thinking_policy": "on", + "conv_route": "on", + "conv_route_batch_after": 4, + "short_answer": { + "spec": 0, + "max_tokens": 16 + }, + "spec_window": 0, + "spec_window_needle_min": 6000, + "code_tune": { + "mode": "off" + } +} \ No newline at end of file diff --git a/dirigo-results/0.2.13-port/intercept/trace/conf-shadow.json b/dirigo-results/0.2.13-port/intercept/trace/conf-shadow.json new file mode 100644 index 00000000000..99559601b21 --- /dev/null +++ b/dirigo-results/0.2.13-port/intercept/trace/conf-shadow.json @@ -0,0 +1,63 @@ +{ + "exe": "/home/bob/bin/strata-sycl-host.sh", + "args": [ + "--pack", + "/home/bob/XeStrata-data/packs/coder-iq1_m", + "--native", + "/home/bob/strata-models/IQ1_M/Qwen3.8-Flash-Next-GSQ-RCO-IQ1_M-00001-of-00002.gguf", + "--ple-gguf", + "/home/bob/strata-models/IQ1_M/Qwen3.8-Flash-Next-GSQ-RCO-IQ1_M-00002-of-00002.gguf", + "--expert-profile", + "/media/bob/3d651e2c-e9a4-4758-ba77-863725fe3731/strata-0.2.13/data/expert-profile-mine.bin", + "--expert-cache", + "auto", + "--stream-experts", + "--prefill", + "auto", + "--prompt-cache", + "6", + "--prompt-cache-every", + "4096", + "--batch", + "0", + "--spec", + "6", + "--spec-min-p", + "0.5", + "--mtp", + "/home/bob/XeStrata-data/mtp/rt", + "--mtp-draft-vocab", + "/media/bob/3d651e2c-e9a4-4758-ba77-863725fe3731/strata-0.2.13/data/draft_vocab_en.bin", + "--mtp-window", + "8192", + "--max-context", + "131072", + "--kv", + "int8", + "--kv-resident", + "32768", + "--vram-reserve-mib", + "700", + "--conversation-cache-mib", + "2048" + ], + "cwd": "/media/bob/3d651e2c-e9a4-4758-ba77-863725fe3731/strata-0.2.13", + "tokenizer": "/home/bob/XeStrata-data/packs/coder-iq1_m/tokenizer", + "model_name": "qwen3.8-flash-next-coder-iq1_m", + "log": "/media/bob/3d651e2c-e9a4-4758-ba77-863725fe3731/strata-0.2.13/strata-iq1_m-shadow.log", + "port": 8095, + "backend": "sycl", + "open_browser": false, + "thinking_policy": "on", + "conv_route": "shadow", + "conv_route_batch_after": 4, + "short_answer": { + "spec": 0, + "max_tokens": 16 + }, + "spec_window": 0, + "spec_window_needle_min": 6000, + "code_tune": { + "mode": "off" + } +} \ No newline at end of file diff --git a/dirigo-results/0.2.13-port/intercept/trace/ladder-iq1_m.json b/dirigo-results/0.2.13-port/intercept/trace/ladder-iq1_m.json new file mode 100644 index 00000000000..7f9cfa6579d --- /dev/null +++ b/dirigo-results/0.2.13-port/intercept/trace/ladder-iq1_m.json @@ -0,0 +1,276 @@ +[ + { + "target": 75, + "ttft_ms": 564.7, + "wall_ms": 623.6, + "prompt_tokens": 128, + "reused": 0, + "fresh": 128, + "prefill_ms": 544, + "prefill_tps": 235.5, + "decode_ms": 78, + "park_tokens": 96, + "park_ms": 103.1, + "kv_hit_pct": 91.35, + "kv_mib_from_ram": 1.6, + "server_ms": 20.7, + "label": "iq1_m" + }, + { + "target": 75, + "ttft_ms": 546.8, + "wall_ms": 616.0, + "prompt_tokens": 128, + "reused": 0, + "fresh": 128, + "prefill_ms": 526, + "prefill_tps": 243.6, + "decode_ms": 88, + "park_tokens": 135, + "park_ms": 100.6, + "server_ms": 20.8, + "label": "iq1_m" + }, + { + "target": 75, + "ttft_ms": 454.3, + "wall_ms": 556.0, + "prompt_tokens": 128, + "reused": 0, + "fresh": 128, + "prefill_ms": 433, + "prefill_tps": 295.6, + "decode_ms": 120, + "park_tokens": 135, + "park_ms": 100.4, + "kv_hit_pct": 93.12, + "kv_mib_from_ram": 1.6, + "server_ms": 21.3, + "label": "iq1_m" + }, + { + "target": 75, + "ttft_ms": 347.5, + "wall_ms": 447.9, + "prompt_tokens": 128, + "reused": 0, + "fresh": 128, + "prefill_ms": 326, + "prefill_tps": 392.5, + "decode_ms": 119, + "kv_hit_pct": 93.11, + "kv_mib_from_ram": 1.7, + "server_ms": 21.5, + "label": "iq1_m" + }, + { + "target": 75, + "ttft_ms": 347.3, + "wall_ms": 467.1, + "prompt_tokens": 128, + "reused": 0, + "fresh": 128, + "prefill_ms": 326, + "prefill_tps": 392.7, + "decode_ms": 138, + "kv_hit_pct": 93.11, + "kv_mib_from_ram": 1.7, + "server_ms": 21.3, + "label": "iq1_m" + }, + { + "target": 75, + "ttft_ms": 346.6, + "wall_ms": 414.1, + "prompt_tokens": 128, + "reused": 0, + "fresh": 128, + "prefill_ms": 325, + "prefill_tps": 393.6, + "decode_ms": 86, + "kv_hit_pct": 93.53, + "kv_mib_from_ram": 1.7, + "server_ms": 21.6, + "label": "iq1_m" + }, + { + "target": 512, + "ttft_ms": 592.6, + "wall_ms": 683.8, + "prompt_tokens": 458, + "reused": 0, + "fresh": 458, + "prefill_ms": 570, + "prefill_tps": 803.6, + "decode_ms": 111, + "kv_hit_pct": 90.74, + "kv_mib_from_ram": 1.6, + "server_ms": 22.6, + "label": "iq1_m" + }, + { + "target": 512, + "ttft_ms": 540.0, + "wall_ms": 630.9, + "prompt_tokens": 458, + "reused": 0, + "fresh": 458, + "prefill_ms": 517, + "prefill_tps": 885.3, + "decode_ms": 110, + "kv_hit_pct": 92.24, + "kv_mib_from_ram": 5.7, + "server_ms": 23.0, + "label": "iq1_m" + }, + { + "target": 512, + "ttft_ms": 539.2, + "wall_ms": 630.0, + "prompt_tokens": 458, + "reused": 0, + "fresh": 458, + "prefill_ms": 516, + "prefill_tps": 886.8, + "decode_ms": 110, + "kv_hit_pct": 92.24, + "kv_mib_from_ram": 5.7, + "server_ms": 23.2, + "label": "iq1_m" + }, + { + "target": 512, + "ttft_ms": 540.3, + "wall_ms": 631.2, + "prompt_tokens": 458, + "reused": 0, + "fresh": 458, + "prefill_ms": 518, + "prefill_tps": 884.8, + "decode_ms": 110, + "kv_hit_pct": 92.24, + "kv_mib_from_ram": 5.7, + "server_ms": 22.3, + "label": "iq1_m" + }, + { + "target": 512, + "ttft_ms": 538.6, + "wall_ms": 606.5, + "prompt_tokens": 458, + "reused": 0, + "fresh": 458, + "prefill_ms": 516, + "prefill_tps": 887.7, + "decode_ms": 87, + "kv_hit_pct": 92.24, + "kv_mib_from_ram": 5.7, + "server_ms": 22.6, + "label": "iq1_m" + }, + { + "target": 512, + "ttft_ms": 538.7, + "wall_ms": 629.5, + "prompt_tokens": 458, + "reused": 0, + "fresh": 458, + "prefill_ms": 516, + "prefill_tps": 887.9, + "decode_ms": 110, + "kv_hit_pct": 90.82, + "kv_mib_from_ram": 5.7, + "server_ms": 22.7, + "label": "iq1_m" + }, + { + "target": 2048, + "ttft_ms": 1493.7, + "wall_ms": 1562.5, + "prompt_tokens": 1610, + "reused": 0, + "fresh": 1610, + "prefill_ms": 1466, + "prefill_tps": 1098.1, + "decode_ms": 90, + "kv_hit_pct": 92.24, + "kv_mib_from_ram": 5.7, + "server_ms": 27.7, + "label": "iq1_m" + }, + { + "target": 2048, + "ttft_ms": 1460.3, + "wall_ms": 1529.0, + "prompt_tokens": 1610, + "reused": 0, + "fresh": 1610, + "prefill_ms": 1433, + "prefill_tps": 1123.5, + "decode_ms": 90, + "kv_hit_pct": 90.88, + "kv_mib_from_ram": 19.6, + "server_ms": 27.3, + "label": "iq1_m" + }, + { + "target": 2048, + "ttft_ms": 1472.7, + "wall_ms": 1541.6, + "prompt_tokens": 1610, + "reused": 0, + "fresh": 1610, + "prefill_ms": 1446, + "prefill_tps": 1113.6, + "decode_ms": 90, + "kv_hit_pct": 90.88, + "kv_mib_from_ram": 19.6, + "server_ms": 26.7, + "label": "iq1_m" + }, + { + "target": 2048, + "ttft_ms": 1454.9, + "wall_ms": 1523.8, + "prompt_tokens": 1610, + "reused": 0, + "fresh": 1610, + "prefill_ms": 1428, + "prefill_tps": 1127.8, + "decode_ms": 90, + "kv_hit_pct": 90.88, + "kv_mib_from_ram": 19.6, + "server_ms": 26.9, + "label": "iq1_m" + }, + { + "target": 2048, + "ttft_ms": 1464.9, + "wall_ms": 1533.6, + "prompt_tokens": 1610, + "reused": 0, + "fresh": 1610, + "prefill_ms": 1437, + "prefill_tps": 1120.0, + "decode_ms": 90, + "kv_hit_pct": 90.88, + "kv_mib_from_ram": 19.6, + "server_ms": 27.9, + "label": "iq1_m" + }, + { + "target": 2048, + "ttft_ms": 1461.8, + "wall_ms": 1530.6, + "prompt_tokens": 1610, + "reused": 0, + "fresh": 1610, + "prefill_ms": 1434, + "prefill_tps": 1122.4, + "decode_ms": 90, + "kv_hit_pct": 90.88, + "kv_mib_from_ram": 19.6, + "server_ms": 27.8, + "label": "iq1_m" + } +] \ No newline at end of file diff --git a/dirigo-results/0.2.13-port/intercept/trace/ladder-shadow.json b/dirigo-results/0.2.13-port/intercept/trace/ladder-shadow.json new file mode 100644 index 00000000000..a0dc62c23bd --- /dev/null +++ b/dirigo-results/0.2.13-port/intercept/trace/ladder-shadow.json @@ -0,0 +1,294 @@ +[ + { + "target": 75, + "ttft_ms": 559.8, + "wall_ms": 674.1, + "prompt_tokens": 126, + "reused": 0, + "fresh": 126, + "prefill_ms": 539, + "prefill_tps": 234.0, + "decode_ms": 133, + "park_tokens": 96, + "park_ms": 103.2, + "server_ms": 20.8, + "label": "shadow" + }, + { + "target": 75, + "ttft_ms": 546.3, + "wall_ms": 614.9, + "prompt_tokens": 126, + "reused": 0, + "fresh": 126, + "prefill_ms": 525, + "prefill_tps": 239.9, + "decode_ms": 87, + "park_tokens": 138, + "park_ms": 103.8, + "server_ms": 21.3, + "label": "shadow" + }, + { + "target": 75, + "ttft_ms": 540.8, + "wall_ms": 609.6, + "prompt_tokens": 126, + "reused": 0, + "fresh": 126, + "prefill_ms": 520, + "prefill_tps": 242.4, + "decode_ms": 87, + "park_tokens": 133, + "park_ms": 98.1, + "kv_hit_pct": 93.0, + "kv_mib_from_ram": 1.6, + "server_ms": 20.8, + "label": "shadow" + }, + { + "target": 75, + "ttft_ms": 539.5, + "wall_ms": 640.2, + "prompt_tokens": 126, + "reused": 0, + "fresh": 126, + "prefill_ms": 518, + "prefill_tps": 243.1, + "decode_ms": 119, + "park_tokens": 133, + "park_ms": 99.4, + "kv_hit_pct": 93.0, + "kv_mib_from_ram": 1.6, + "server_ms": 21.5, + "label": "shadow" + }, + { + "target": 75, + "ttft_ms": 552.1, + "wall_ms": 620.6, + "prompt_tokens": 126, + "reused": 0, + "fresh": 126, + "prefill_ms": 531, + "prefill_tps": 237.3, + "decode_ms": 87, + "park_tokens": 138, + "park_ms": 100.6, + "kv_hit_pct": 94.4, + "kv_mib_from_ram": 1.7, + "server_ms": 21.1, + "label": "shadow" + }, + { + "target": 75, + "ttft_ms": 553.1, + "wall_ms": 653.5, + "prompt_tokens": 126, + "reused": 0, + "fresh": 126, + "prefill_ms": 532, + "prefill_tps": 236.9, + "decode_ms": 119, + "park_tokens": 133, + "park_ms": 100.3, + "kv_hit_pct": 93.0, + "kv_mib_from_ram": 1.6, + "server_ms": 21.1, + "label": "shadow" + }, + { + "target": 512, + "ttft_ms": 802.9, + "wall_ms": 894.9, + "prompt_tokens": 456, + "reused": 0, + "fresh": 456, + "prefill_ms": 781, + "prefill_tps": 583.8, + "decode_ms": 110, + "park_tokens": 138, + "park_ms": 103.9, + "kv_hit_pct": 94.4, + "kv_mib_from_ram": 1.7, + "server_ms": 21.9, + "label": "shadow" + }, + { + "target": 512, + "ttft_ms": 747.1, + "wall_ms": 838.8, + "prompt_tokens": 456, + "reused": 0, + "fresh": 456, + "prefill_ms": 725, + "prefill_tps": 628.7, + "decode_ms": 110, + "park_tokens": 463, + "park_ms": 101.3, + "kv_hit_pct": 94.07, + "kv_mib_from_ram": 5.6, + "server_ms": 22.1, + "label": "shadow" + }, + { + "target": 512, + "ttft_ms": 748.4, + "wall_ms": 840.1, + "prompt_tokens": 456, + "reused": 0, + "fresh": 456, + "prefill_ms": 726, + "prefill_tps": 627.7, + "decode_ms": 110, + "park_tokens": 463, + "park_ms": 100.0, + "server_ms": 22.4, + "label": "shadow" + }, + { + "target": 512, + "ttft_ms": 746.6, + "wall_ms": 838.2, + "prompt_tokens": 456, + "reused": 0, + "fresh": 456, + "prefill_ms": 725, + "prefill_tps": 629.2, + "decode_ms": 110, + "park_tokens": 463, + "park_ms": 99.8, + "server_ms": 21.6, + "label": "shadow" + }, + { + "target": 512, + "ttft_ms": 745.1, + "wall_ms": 872.0, + "prompt_tokens": 456, + "reused": 0, + "fresh": 456, + "prefill_ms": 723, + "prefill_tps": 630.4, + "decode_ms": 146, + "park_tokens": 463, + "park_ms": 98.3, + "kv_hit_pct": 94.07, + "kv_mib_from_ram": 5.6, + "server_ms": 22.1, + "label": "shadow" + }, + { + "target": 512, + "ttft_ms": 746.4, + "wall_ms": 838.0, + "prompt_tokens": 456, + "reused": 0, + "fresh": 456, + "prefill_ms": 725, + "prefill_tps": 629.2, + "decode_ms": 110, + "park_tokens": 463, + "park_ms": 99.0, + "server_ms": 21.4, + "label": "shadow" + }, + { + "target": 2048, + "ttft_ms": 1716.0, + "wall_ms": 1808.2, + "prompt_tokens": 1608, + "reused": 0, + "fresh": 1608, + "prefill_ms": 1692, + "prefill_tps": 950.6, + "decode_ms": 111, + "park_tokens": 463, + "park_ms": 99.6, + "kv_hit_pct": 94.07, + "kv_mib_from_ram": 5.6, + "server_ms": 24.0, + "label": "shadow" + }, + { + "target": 2048, + "ttft_ms": 1683.7, + "wall_ms": 1770.0, + "prompt_tokens": 1608, + "reused": 0, + "fresh": 1608, + "prefill_ms": 1659, + "prefill_tps": 969.1, + "decode_ms": 105, + "park_tokens": 1615, + "park_ms": 103.2, + "kv_hit_pct": 93.32, + "kv_mib_from_ram": 19.5, + "server_ms": 24.7, + "label": "shadow" + }, + { + "target": 2048, + "ttft_ms": 1707.7, + "wall_ms": 1815.7, + "prompt_tokens": 1608, + "reused": 0, + "fresh": 1608, + "prefill_ms": 1683, + "prefill_tps": 955.2, + "decode_ms": 127, + "park_tokens": 1615, + "park_ms": 104.3, + "server_ms": 24.7, + "label": "shadow" + }, + { + "target": 2048, + "ttft_ms": 1695.0, + "wall_ms": 1787.2, + "prompt_tokens": 1608, + "reused": 0, + "fresh": 1608, + "prefill_ms": 1671, + "prefill_tps": 962.5, + "decode_ms": 111, + "park_tokens": 1615, + "park_ms": 106.7, + "kv_hit_pct": 95.23, + "kv_mib_from_ram": 19.5, + "server_ms": 24.0, + "label": "shadow" + }, + { + "target": 2048, + "ttft_ms": 1699.6, + "wall_ms": 1791.8, + "prompt_tokens": 1608, + "reused": 0, + "fresh": 1608, + "prefill_ms": 1675, + "prefill_tps": 960.0, + "decode_ms": 111, + "park_tokens": 1615, + "park_ms": 108.3, + "server_ms": 24.6, + "label": "shadow" + }, + { + "target": 2048, + "ttft_ms": 1694.5, + "wall_ms": 1786.8, + "prompt_tokens": 1608, + "reused": 0, + "fresh": 1608, + "prefill_ms": 1670, + "prefill_tps": 963.1, + "decode_ms": 111, + "park_tokens": 1615, + "park_ms": 102.5, + "kv_hit_pct": 94.1, + "kv_mib_from_ram": 19.5, + "server_ms": 24.5, + "label": "shadow" + } +] \ No newline at end of file diff --git a/dirigo-results/0.2.13-port/intercept/trace/strata-trace-split.py b/dirigo-results/0.2.13-port/intercept/trace/strata-trace-split.py new file mode 100755 index 00000000000..18b9b494434 --- /dev/null +++ b/dirigo-results/0.2.13-port/intercept/trace/strata-trace-split.py @@ -0,0 +1,90 @@ +#!/usr/bin/env python3 +"""Split the per-request fixed cost using the engine's own STRATA_TRACE admission line. + +The engine prints, per admitted request: + + strata trace: admission of slot 0: drain 0.0, prompt 402.1 (read 388.0, windows 11.2, 1 checkpoint(s) 2.1 = + sync 1.0 + save 0.8 + evict 0.3, rest 0.0), first window 0.0, slot copy 0.4, slot freed 0.0, checkpoint copy 0.1 + +followed by the prompt line this probe already keys on. Pairing them by order gives the phases that make up the +"fixed cost": what is spent before the prompt read (drain + slot work), what the read itself costs, and what follows. + + ~/bin/strata-trace-split.py --log [--since-bytes N] [--json out.json] + +Use --since-bytes to ignore earlier requests, or just parse the whole log and read +the tail of the table (the run's own requests are the last ones). +""" +import argparse +import json +import re +import statistics as st + +RE_TRACE = re.compile( + r"strata trace: admission of slot (\d+): drain ([\d.]+), prompt ([\d.]+) " + r"\(read ([\d.]+), windows ([\d.]+), (\d+) checkpoint\(s\) ([\d.]+) = sync ([\d.]+) \+ save ([\d.]+) \+ " + r"evict ([\d.]+), rest ([\d.]+)\), first window ([\d.]+), slot copy ([\d.]+), slot freed ([\d.]+), " + r"checkpoint copy ([\d.]+)") +RE_PROMPT = re.compile(r"strata serve: prompt (\d+) tokens = (\d+) reused \+ (\d+) read in (\d+) ms") +PHASES = ("drain", "prompt", "read", "windows", "ckpts", "sync", "save", "evict", "rest", + "first_window", "slot_copy", "slot_freed", "ckpt_copy") + + +def parse(path, since=0): + with open(path, "rb") as f: + f.seek(since) + text = f.read().decode("utf-8", "replace") + rows, pending = [], None + for line in text.splitlines(): + m = RE_TRACE.search(line) + if m: + g = m.groups() + pending = dict(slot=int(g[0]), prompt_ms=float(g[2]), read=float(g[3]), windows=float(g[4]), + ckpts=int(g[5]), ckpt_ms=float(g[6]), sync=float(g[7]), save=float(g[8]), + evict=float(g[9]), rest=float(g[10]), first_window=float(g[11]), + slot_copy=float(g[12]), slot_freed=float(g[13]), ckpt_copy=float(g[14])) + pending["drain"] = float(g[1]) + continue + p = RE_PROMPT.search(line) + if p and pending is not None: + pending.update(prompt_tokens=int(p.group(1)), reused=int(p.group(2)), read_n=int(p.group(3)), + engine_prefill_ms=float(p.group(4))) + rows.append(pending) + pending = None + return rows + + +def main(): + ap = argparse.ArgumentParser() + ap.add_argument("--log", required=True) + ap.add_argument("--since-bytes", type=int, default=0) + ap.add_argument("--json") + args = ap.parse_args() + rows = parse(args.log, args.since_bytes) + if not rows: + print("no trace admission lines paired with a prompt line - was STRATA_TRACE set for the ENGINE process?") + return + print(f"{len(rows)} request(s) traced\n") + hdr = f"{'tokens':>7} {'reused':>7} {'prefill':>8} " + " ".join(f"{p:>11}" for p in PHASES) + print(hdr) + print("-" * len(hdr)) + for r in rows: + print(f"{r['prompt_tokens']:>7} {r['reused']:>7} {r['engine_prefill_ms']:>8.0f} " + + " ".join(f"{r[p]:>11.1f}" for p in PHASES)) + # per-size medians, and the share of the fixed cost each phase owns + print("\nper-size median of the admission phases (ms), for requests that read their prompt (reused == 0):") + for size in sorted({r["prompt_tokens"] for r in rows}): + grp = [r for r in rows if r["prompt_tokens"] == size and r["reused"] == 0] + if len(grp) < 2: + continue + med = {p: st.median([r[p] for r in grp]) for p in PHASES} + med["n"] = len(grp) + print(f" {size:>6} tok (n={med['n']}): " + + " ".join(f"{p} {med[p]:.1f}" for p in ("drain", "slot_copy", "slot_freed", "read", "windows", + "ckpts", "rest", "first_window", "ckpt_copy", "prompt"))) + if args.json: + json.dump(rows, open(args.json, "w"), indent=1) + print(f"\nwrote {args.json}") + + +if __name__ == "__main__": + main() diff --git a/dirigo-results/0.2.13-port/intercept/trace/strata-trace-window.sh b/dirigo-results/0.2.13-port/intercept/trace/strata-trace-window.sh new file mode 100755 index 00000000000..2ce0b25bb0e --- /dev/null +++ b/dirigo-results/0.2.13-port/intercept/trace/strata-trace-window.sh @@ -0,0 +1,35 @@ +#!/usr/bin/env bash +# strata-trace-window.sh - run the ladder with the engine's own STRATA_TRACE and split the fixed cost. +# +# The 0.2.13 engine already prints a per-request admission trace (drain, prompt read, windows, checkpoints, first +# window, slot copy, slot freed, checkpoint copy) when STRATA_TRACE is set, so no build is needed to ask which phase +# owns the ~165 ms that section 6 of docs/PERF-NEXT.md left unnamed. +# +# Six samples per size so each size is measured in BOTH router states: with batch_after 4 the first four requests of a +# run are served cache-on, the fifth onward cache-off. +# +# usage: strata-trace-window.sh [tag] [sizes] [samples] +# UNDO: rm this file and ~/strata-trace-run +set -uo pipefail +TAG=${1:-iq1_m} +SIZES=${2:-75,512,2048} +SAMPLES=${3:-6} +CONF=${CONF:-$TREE/strata-coder-iq1_m-sycl-tuned.json} # CONF=... for a different pack/weights +S=/media/bob/3d651e2c-e9a4-4758-ba77-863725fe3731 +TREE=$S/strata-0.2.13 +OUT=$HOME/strata-trace-run +PROBE=$HOME/bin/strata-intercept-probe.py +SPLIT=$HOME/bin/strata-trace-split.py +mkdir -p "$OUT" + +echo "[$(date +%H:%M:%S)] ===== trace-$TAG sizes=$SIZES samples=$SAMPLES" +STRATA_TRACE=1 ~/bin/strata-card-window.sh "$TREE" 8097 --conf "$CONF" -- bash -c " + LOG=\$(python3 -c \"import json;print(json.load(open('$CONF'))['log'])\") + curl -s -m 5 http://127.0.0.1:\$PORT/v1/status | python3 -c 'import json,sys;d=json.load(sys.stdin);print(\" engine:\",d[\"engine\"])' + BEFORE=\$(stat -c%s \"\$LOG\") + /usr/bin/python3 $PROBE --port \$PORT --log \"\$LOG\" --out $OUT/ladder-$TAG.json --label $TAG \ + --sizes $SIZES --samples $SAMPLES + /usr/bin/python3 $SPLIT --log \"\$LOG\" --since-bytes \$BEFORE --json $OUT/trace-$TAG.json + cp \"\$LOG\" $OUT/engine-$TAG.log +" 2>&1 | grep -aE '=====|engine:|tok \(|^ +[0-9]+ +[0-9]+|request\(s\) traced|wrote|restore|no trace' +echo "[$(date +%H:%M:%S)] trace window done" diff --git a/docs/PERF-NEXT.md b/docs/PERF-NEXT.md index fef3028a35e..f1b8dddcaf1 100644 --- a/docs/PERF-NEXT.md +++ b/docs/PERF-NEXT.md @@ -51,14 +51,15 @@ fixed term. | # | idea | evidence it could pay | cost | first test | | --- | --- | --- | --- | --- | -| 1 | ~~ship `conv-route-batch-after` 1–2~~ | **closed, keep 4.** §7: 1 buys 0.52 s across the first six single-shot requests and costs **1.88 s** on the next conversation turn (`C2` 2.465 s against 0.587) — break-even at ~21 single-shots per conversation re-open | — | done; the config key that would have set it was also dead (PR #16) | -| 2 | engine-side per-request timer | §6 leaves **~165 ms** inside prefill that no configuration lever explains (PLE reads excluded, cache slots ~58 ms of it); naming it needs a phase timer in the request path | code, a day | timestamp slot setup / first-layer expert reach / KV alloc per request | -| 3 | ~~a one-shot mode that also drops the cache slots~~ | **closed, §8**: no saving over the router's cache-off path at matched sizes (+2 ms at 456 tokens, +8 ms at 1,608), and a 0-slot start severs conversation reuse for good — every turn re-prefilled | — | done | -| 4 | residency-biased router on SYCL | `route_prior.cu` is CUDA-only; here **12,288 of 24,576** experts are resident, so half of every token's experts cross PCIe. Upstream measured +15 % / +37 % on a 12 GB NVIDIA card | engine port, days | decode lanes, 5 interleaved pairs | -| 5 | prefill chunk at 4k/8k/12k with intervals | 16k/32k were tested, but 8,192 was never shown to be the knee | ~20 min | paired, three prompt sizes, per-prompt medians | -| 6 | CPU pool workers and affinity on the 7700X | 15 workers is a 16-thread default; p-core pinning was **+27 %** decode on the 13700K | 15 min | workers 8/12/15/16, `--pool-affinity` on/off | -| 7 | dispatch overhead on SYCL | the Vulkan analysis found ~88 % of per-dispatch cost is fixed; nobody has counted dispatches per token on SYCL | a day | `unitrace` kernel count per token, then fuse the five most frequent small ops | -| 8 | DFlash2 block drafter on SYCL | upstream's headline decode lever; 7 drafts per pass | weeks | only after 1–3 | +| 1 | **defer the slot refill past the first token** | §9: the refill runs between the prompt read and `prompt done` at **0.319 ms per lent slot** — 72 ms on a 127-token prompt, 188 ms on a 1.6 k one, on the TTFT path. Decode needs its own experts, not the slots being refilled | engine change, a few lines | the same ladder with the refill moved; watch for PCIe contention with decode | +| 2 | ~~ship `conv-route-batch-after` 1–2~~ | **closed, keep 4.** §7: 1 buys 0.52 s across the first six single-shot requests and costs **1.88 s** on the next conversation turn (`C2` 2.465 s against 0.587) — break-even at ~21 single-shots per conversation re-open | — | done; the config key that would have set it was also dead (PR #16) | +| 3 | ~~engine-side per-request timer~~ | **done, no build**: `STRATA_TRACE` already splits the prompt path — §9 names 109 ms of read-side fixed work, 72 ms of refill and 56 ms of bookkeeping | — | done | +| 4 | ~~a one-shot mode that also drops the cache slots~~ | **closed, §8**: no saving over the router's cache-off path at matched sizes (+2 ms at 456 tokens, +8 ms at 1,608), and a 0-slot start severs conversation reuse for good — every turn re-prefilled | — | done | +| 5 | residency-biased router on SYCL | `route_prior.cu` is CUDA-only; here **12,288 of 24,576** experts are resident, so half of every token's experts cross PCIe. Upstream measured +15 % / +37 % on a 12 GB NVIDIA card | engine port, days | decode lanes, 5 interleaved pairs | +| 6 | prefill chunk at 4k/8k/12k with intervals | 16k/32k were tested, but 8,192 was never shown to be the knee | ~20 min | paired, three prompt sizes, per-prompt medians | +| 7 | CPU pool workers and affinity on the 7700X | 15 workers is a 16-thread default; p-core pinning was **+27 %** decode on the 13700K | 15 min | workers 8/12/15/16, `--pool-affinity` on/off | +| 8 | dispatch overhead on SYCL | the Vulkan analysis found ~88 % of per-dispatch cost is fixed; nobody has counted dispatches per token on SYCL | a day | `unitrace` kernel count per token, then fuse the five most frequent small ops | +| 9 | DFlash2 block drafter on SYCL | upstream's headline decode lever; 7 drafts per pass | weeks | only after 1–3 | ## 5. The PLE sweep, run 2026-11-14 — closed @@ -110,8 +111,8 @@ on, like stock) — client TTFT from the first content delta, and the engine's o profile is equal — 456 tokens: 539.7 against 537.3; 1,608 tokens: 1,471.3 against 1,463.3. 5. **The draft layer could not be switched off to test its share**: `--spec 0` is refused on a native IQ pack, which needs `--spec T (T >= 2)`. -6. **What is left is ~165 ms** inside prefill after the cache slots' ~58 ms, unexplained by any configuration lever - tried so far (PLE row reads are excluded by §5). Naming it needs a phase timer inside the request path. +6. **The ~165 ms is now split, without a build** — the engine already prints a per-request trace under `STRATA_TRACE`: + ~109 ms of fixed work inside the prompt read, ~72 ms of expert-slot refill, ~56 ms of cache bookkeeping. See §9. Artifacts: [`0.2.13-port/intercept/`](../dirigo-results/0.2.13-port/intercept/) — both ladders, the three cause-sweep arms, `summary.json`, the probe and both drivers, and the logs with every restore line. @@ -180,7 +181,55 @@ path, which means a build. Artifacts: [`0.2.13-port/intercept/zerocache/`](../dirigo-results/0.2.13-port/intercept/zerocache/) — both ladders, the mixed shape, the configs, the driver, and the window log with every restore line. -## 9. Method rules these numbers were produced under +## 9. Where the ~165 ms goes: the expert-slot refill + +`STRATA_TRACE=1` makes engine 0.1.59 print the prompt path per request — `prompt start`, `lent N slots`, `prompt chunk`, +`read N tokens in X ms`, `refill start`, `refilled N slots in X ms`, `prompt done`. No build is needed to read it. (The +per-request *admission* trace needs `--batch`, so with `--batch 0` it stays silent; the prompt path is what matters here.) + +Ladder with the deployed router, six samples per size, medians: + +| real tokens | read | refill | lent slots | refill per slot | +| --- | --- | --- | --- | --- | +| 127 | 252 ms | **71.7 ms** | 225 | 0.319 | +| 457 | 432 ms | **82.6 ms** | 259 | 0.319 | +| 1,609 | 1,245 ms | **188.2 ms** | 589 | 0.320 | + +1. **The refill is a fixed per-request cost on the TTFT path.** It runs *after* the prompt read and *before* `prompt + done`, so the first token waits for it: 72 ms on a short prompt, 188 ms on a 1.6 k one. +2. **It is one PCIe transfer per lent expert slot at 0.319 ms/slot** — the same rate at all three sizes to within 0.3 %. + The prompt borrows expert slots while it reads; afterwards the engine refills them with the profile's hottest experts. +3. **The read itself carries 109 ms of fixed work** (`109 ms + 0.706 ms/token` over the three sizes): first-layer expert + reach and chunk setup, plus ~56 ms of cache bookkeeping. 109 + 72 + 56 ≈ the 165 ms §6 could not name, leaving + nothing unexplained at this resolution. +4. **This reconciles §6 with the dispatch.** Pinning the cache on (`conv_route: shadow`) raises TTFT by 148–234 ms but + raises `read + refill` by only 7–29 ms: the cache-on cost is checkpoint work inside the engine's prompt span, not in + the prompt read. Both measurements were right about different parts of the same 200 ms. + +**The lever this exposes:** the refill does not have to be synchronous with the answer. It reclaims slots the *next* +request will lend again, and decode for the current request needs its own experts, not those slots. Moving it after the +first token would take 72–188 ms off TTFT — the largest remaining cheap win, and it is an engine change of a few lines +rather than a research project. + +Artifacts: [`0.2.13-port/intercept/trace/`](../dirigo-results/0.2.13-port/intercept/trace/) — both ladders, the engine +logs with every trace line, the parser and the window driver. + +### Cross-weight check: blocked, three engine constraints + +The same trace was attempted on a second weight set (the Q2_0 pack, 34 GB, copied to NVMe from the cold disk for this) +and could not start: + +| attempt | engine's answer | +| --- | --- | +| Q2_0 pack + `--ple-gguf` at the shared PLE shard | `native dense: duplicate split shard number` | +| pack only, embedding from the GGUF, no `--native` | `is a native (IQ) pack: it needs --native SHARD1, --spec T (T >= 2) and --prefill CHUNK` | +| fixed `--expert-cache 12288`, no profile | `REFUSED: 11158 experts are neither in VRAM nor mirrored` | + +The shipped `expert-profile-mine.bin` is 48×256 and the Q2_0 pack declares 48×512, so the second weight set needs its +own calibration run before it can serve. Until then every number in this inventory stands on one weight set (IQ1_M), +which is stated in §10 and is the honest bound on all of it. + +## 10. Method rules these numbers were produced under - Paired or interleaved arms; median of repeats; the box's run-to-run spread stated next to the effect. - One prompt per configuration is not a measurement: every lane here has several requests, and a single-prompt