From 723f1a1f3ed9617e41143e4068435933907d0057 Mon Sep 17 00:00:00 2001 From: rwkeyes <86691029+rwkeyes@users.noreply.github.com> Date: Sat, 14 Nov 2026 18:20:11 -0500 Subject: [PATCH] perf: the ~165 ms is the expert-slot refill - 0.319 ms per lent slot, on the TTFT path No build was needed: engine 0.1.59 already prints the prompt path under STRATA_TRACE. Per request it shows prompt start, lent N slots, read N tokens in X ms, refill, prompt done - and the refill is the answer. 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 1609 1245 ms 188.2 ms 589 0.320 - the refill runs AFTER the read and BEFORE "prompt done", so the first token waits for it: 72 ms short prompt, 188 ms at 1.6k; - 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 read itself carries 109 ms of fixed work (109 + 0.706 ms/token); - 109 + 72 + 56 of cache bookkeeping accounts for the 165 ms section 6 could not name, so nothing is unexplained at this resolution. It also reconciles section 6 with the dispatch: pinning the cache on (conv_route shadow) raises TTFT 148-234 ms but read+refill only 7-29 ms, so the cache-on cost is checkpoint work inside the prompt span, not in the read. Both measurements were right about different parts of it. The lever: the refill does not have to be synchronous. It reclaims slots the NEXT request lends again, and decode needs its own experts - moving it after the first token takes 72-188 ms off TTFT for a few lines of engine change. That is now item 1. Also records the blocked cross-weight check: the Q2_0 pack (34 GB, copied to NVMe for this) cannot start - duplicate split shard, then "native (IQ) pack needs --native", then "11158 experts neither in VRAM nor mirrored", because its 48x512 expert shape needs its own profile where the shipped one is 48x256. Three failure logs shipped as evidence. --- .../intercept/trace/conf-q2_0.json | 59 ++++ .../intercept/trace/conf-shadow.json | 63 ++++ .../intercept/trace/ladder-iq1_m.json | 276 ++++++++++++++++ .../intercept/trace/ladder-shadow.json | 294 ++++++++++++++++++ .../intercept/trace/strata-trace-split.py | 90 ++++++ .../intercept/trace/strata-trace-window.sh | 35 +++ docs/PERF-NEXT.md | 71 ++++- 7 files changed, 877 insertions(+), 11 deletions(-) create mode 100644 dirigo-results/0.2.13-port/intercept/trace/conf-q2_0.json create mode 100644 dirigo-results/0.2.13-port/intercept/trace/conf-shadow.json create mode 100644 dirigo-results/0.2.13-port/intercept/trace/ladder-iq1_m.json create mode 100644 dirigo-results/0.2.13-port/intercept/trace/ladder-shadow.json create mode 100755 dirigo-results/0.2.13-port/intercept/trace/strata-trace-split.py create mode 100755 dirigo-results/0.2.13-port/intercept/trace/strata-trace-window.sh 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