feat(telemetry): add prefill-phase attribution (#175)

Split the prompt phase into the same wall-additive terms decode already reports:
prefill_cpu_s / prefill_read_mib / prefill_io_s / prefill_stall_s / prefill_mgmt_s,
as session-level deltas of the streamer's cumulative counters across the prefill
chunks. Session layer only; the streamer is untouched. The keys ride both
BMOE_DONE and the CSV `# summary` trailer, appended so existing readers ignore them.

Closes #173.

CHANGELOG.md

@@ -4,6 +4,19 @@ All notable changes to this project are documented here. The format follows
 [Keep a Changelog](https://keepachangelog.com/), and the project aims to follow
 Semantic Versioning.
 
+## [0.23.0] - 2026-08-28
+
+### Added
+- **Prefill-phase attribution in `BMOE_DONE` and the CSV `# summary`.** `prefill_cpu_s` /
+  `prefill_read_mib` / `prefill_io_s` / `prefill_stall_s` / `prefill_mgmt_s`: the prompt phase's
+  own split of the same cumulative counters the decode fields come from, as session-level deltas
+  across the prefill chunks — the streamer is untouched. On a >RAM model the prompt is what the
+  user actually waits for before the first token, and until now the phase carried a single bare
+  wall number (`prefill_s`) with no compute/flash split; these keys are what settles which of
+  the two binds at a given prompt length (#173). The CSV `# summary` trailer carries the same
+  five raw fields under the same names and units — appended keys, so existing readers ignore
+  them. Host measurements in the PR.
+
 ## [0.22.0] - 2026-08-28
 
 ### Added

cli/main.cpp

@@ -330,6 +330,8 @@ static int run_session_loop(const RunConfig & cfg,
                     "\"prefill_tps\":%.2f,\"load_s\":%.3f,\"cache_hit_pct\":%.1f,\"n_prompt\":%d,\"n_past\":%d,"
                     "\"compute_s_tok\":%.4f,\"io_s_tok\":%.4f,\"cache_resident_mib\":%.0f,\"cache_budget_mib\":%.0f,"
                     "\"read_mib\":%.1f,\"stall_s_tok\":%.4f,\"mgmt_s_tok\":%.4f,\"majflt_tok\":%.2f,\"cpu_s_tok\":%.4f,"
+                    "\"prefill_cpu_s\":%.3f,\"prefill_read_mib\":%.1f,\"prefill_io_s\":%.3f,"
+                    "\"prefill_stall_s\":%.3f,\"prefill_mgmt_s\":%.3f,"
                     "\"token_demand_mib\":%.1f,\"mtp_drafted\":%lld,\"mtp_accepted\":%lld,\"mtp_decodes\":%lld,"
                     "\"mtp_draft_s_tok\":%.4f,\"drafted_steps\":%lld,\"loop_overhead_s_tok\":%.4f,"
                     "\"reasoning\":\"%s\",\"text\":\"%s\"}\n",
@@ -337,9 +339,11 @@ static int run_session_loop(const RunConfig & cfg,
                     (s.prefill_seconds > 0 ? s.n_prompt / s.prefill_seconds : 0.0), s.load_seconds, s.cache_hit_pct,
                     s.n_prompt, s.n_past, s.moe_compute_s_per_token, s.moe_io_s_per_token, s.cache_resident_mib,
                     s.cache_budget_mib, s.moe_read_mib, s.moe_stall_s_per_token, s.moe_mgmt_s_per_token,
-                    s.majflt_per_token, s.cpu_s_per_token, s.token_demand_mib, s.mtp_drafted, s.mtp_accepted,
-                    s.mtp_decodes, s.mtp_draft_s_per_token, s.drafted_steps, s.loop_overhead_s_per_token,
-                    json_escape(r.reasoning_text).c_str(), json_escape(r.generated_text).c_str());
+                    s.majflt_per_token, s.cpu_s_per_token, s.prefill_cpu_seconds, s.prefill_read_mib,
+                    s.prefill_io_seconds, s.prefill_stall_seconds, s.prefill_mgmt_seconds, s.token_demand_mib,
+                    s.mtp_drafted, s.mtp_accepted, s.mtp_decodes, s.mtp_draft_s_per_token, s.drafted_steps,
+                    s.loop_overhead_s_per_token, json_escape(r.reasoning_text).c_str(),
+                    json_escape(r.generated_text).c_str());
         std::fflush(stdout);
     }
 

core/include/bmoe/metrics.h

@@ -113,6 +113,20 @@ struct RunSummary {
     double load_seconds = 0.0;
     double prefill_seconds = 0.0;
 
+    // Prefill-phase attribution (#173): the same wall-additive quantities the decode phase
+    // reports, as deltas of the streamer's cumulative counters across THIS turn's prefill
+    // chunks (plus process CPU). Before #169-style attribution existed prefill was a single
+    // bare wall number, so the phase a >RAM prompt actually waits on had no compute/flash
+    // split at all. Zero when streaming is off (prefill_cpu_seconds still reported: CPU is
+    // measured regardless). Same reading rules as the decode fields: io is the summed lane
+    // busy time under overlap, stall is the union of stalled intervals, and cpu covers the
+    // whole process — an upper bound on compute-thread CPU-equivalent time.
+    double prefill_cpu_seconds = 0.0;
+    double prefill_read_mib = 0.0;
+    double prefill_io_seconds = 0.0;
+    double prefill_stall_seconds = 0.0;
+    double prefill_mgmt_seconds = 0.0;
+
     // MoE streaming totals (zero when streaming is off)
     double moe_read_mib = 0.0;
     double moe_io_seconds = 0.0;

core/src/engine/session.cpp

@@ -191,6 +191,40 @@ struct GenTally {
     }
 };
 
+// The prompt phase's measurement, the prefill counterpart of GenTally above: the source's
+// counters are cumulative across a warm session, so begin() pins them (with the process CPU
+// clock) just above the prompt chunk loop and end() closes the deltas just after it — the same
+// wall-additive terms the decode fields report, read with the same rules. end()'s sample is the
+// phase boundary itself: the decode baseline below seeds its cursors from it, so prefill's end
+// and decode's start are one reading of the counters, not two that could drift apart.
+struct PrefillTally {
+    IExpertSource::Stats pre;
+    double cpu0 = 0.0;
+
+    // Deltas across this turn's prefill chunks — valid after end().
+    double cpu_seconds = 0.0;
+    double read_mib = 0.0;
+    double io_seconds = 0.0;
+    double stall_seconds = 0.0;
+    double mgmt_seconds = 0.0;
+
+    // The stats sample end() closed on, for the decode baseline to start from.
+    IExpertSource::Stats post;
+
+    void begin(bool moe_on, const IExpertSource & src) {
+        pre = moe_on ? src.stats() : IExpertSource::Stats{};
+        cpu0 = pio::process_cpu_seconds();
+    }
+    void end(bool moe_on, const IExpertSource & src) {
+        post = moe_on ? src.stats() : IExpertSource::Stats{};
+        cpu_seconds = pio::process_cpu_seconds() - cpu0;
+        read_mib = (double) ((long long) post.read_bytes - (long long) pre.read_bytes) / (1024.0 * 1024.0);
+        io_seconds = post.read_seconds - pre.read_seconds;
+        stall_seconds = post.stall_seconds - pre.stall_seconds;
+        mgmt_seconds = post.mgmt_seconds - pre.mgmt_seconds;
+    }
+};
+
 // The names of the expert weight tensors the streamer rebinds. "Dense" is defined by subtraction —
 // everything the model has that is NOT one of these — so both consumers below start by asking this
 // same question, and used to answer it with their own copy of the same triple loop.
@@ -1089,6 +1123,11 @@ RunResult Session::generate(const GenerateRequest & req,
     };
 
     // ── prefill (chunked by n_batch; positions auto-continue from the reused prefix) ──
+    // Prefill attribution (#173): the cumulative counters are pinned before the prompt chunks so
+    // their deltas across prefill carry the same wall-additive terms the decode phase reports.
+    // The session layer already holds everything needed; the streamer is untouched.
+    PrefillTally prefill_tally;
+    prefill_tally.begin(moe.enabled, im.source);
     const auto t_prefill0 = clock_t_::now();
     // Two predicates, deliberately distinct. spec_on is "the verify loop runs" — a wide batch, an
     // accept pass, a rollback — and both sources need all of it. mtp_on is "the draft comes from the
@@ -1133,6 +1172,11 @@ RunResult Session::generate(const GenerateRequest & req,
     // has actually got, so calling it before prefill would warn about a gap that is about to close.
     if (mtp_on) common_speculative_begin(im.mtp.get(), /*seq_id*/ 0, tokens);
     const double prefill_seconds = secs(t_prefill0, clock_t_::now());
+    // Prefill attribution, closed here (the begin() snapshot sits above the chunk loop): deltas
+    // of the cumulative counters across the prompt, the quantities the decode phase reports per
+    // token. Read with the same rules: io is summed lane busy time under overlap, stall is the
+    // union of stalled intervals, cpu is whole-process (upper bound on compute-thread time).
+    prefill_tally.end(moe.enabled, im.source);
     const float * logits = llama_get_logits_ith(ctx, -1);
 
     // ── greedy generation ──
@@ -1141,14 +1185,16 @@ RunResult Session::generate(const GenerateRequest & req,
     int n_gen = 0;
     double gen_seconds = 0.0;
 
-    // Baseline snapshot taken AFTER prefill: the summary reports the generation phase only,
-    // from real per-token deltas (prefill routes near the whole bank, so folding it into a
-    // per-token average would badly inflate the flash-I/O figure). In a warm session these
-    // counters carry the prior prompts' totals; the deltas make each prompt self-relative.
+    // Baseline seeded from prefill's closing sample: the summary reports the generation phase
+    // only, from real per-token deltas (prefill routes near the whole bank, so folding it into a
+    // per-token average would badly inflate the flash-I/O figure). Nothing runs between the two
+    // phases, so end()'s snapshot IS the decode baseline — one reading of the counters at the
+    // boundary instead of two that could drift apart. In a warm session these counters carry the
+    // prior prompts' totals; the deltas make each prompt self-relative.
     GenTally tally;
     tally.overlap = moe.overlap;
     if (moe.enabled) {
-        const IExpertSource::Stats st0 = im.source.stats();
+        const IExpertSource::Stats & st0 = prefill_tally.post;
         tally.prev_bytes = (long long) st0.read_bytes;
         tally.prev_io_s = st0.read_seconds;
         tally.prev_mgmt_s = st0.mgmt_seconds;
@@ -1456,6 +1502,11 @@ RunResult Session::generate(const GenerateRequest & req,
     s.n_past = chat_on ? (int) im.kv_tokens.size() : n_prompt + n_gen; // total context length now
     s.load_seconds = im.load_seconds;
     s.prefill_seconds = prefill_seconds;
+    s.prefill_cpu_seconds = prefill_tally.cpu_seconds;
+    s.prefill_read_mib = prefill_tally.read_mib;
+    s.prefill_io_seconds = prefill_tally.io_seconds;
+    s.prefill_stall_seconds = prefill_tally.stall_seconds;
+    s.prefill_mgmt_seconds = prefill_tally.mgmt_seconds;
     s.majflt_per_token = n_gen ? (double) tally.majflt / n_gen : 0.0;
     s.cpu_s_per_token = n_gen ? tally.cpu_seconds / n_gen : 0.0;
     if (moe.enabled) {

core/src/metrics/csv_metrics_sink.cpp

@@ -80,7 +80,9 @@ public:
                      "drafted_steps=%lld "
                      "ra_committed=%lld ra_passthrough=%lld ra_agree_pct=%.1f ra_gemv_ms/tok=%.2f "
                      "ra_issue_ms/tok=%.2f ra_wd_ms/tok=%.2f drain_s/tok=%.3f adopt_s/tok=%.3f "
-                     "evictions=%lld rereads=%lld\n",
+                     "evictions=%lld rereads=%lld "
+                     "prefill_cpu_s=%.3f prefill_read_mib=%.1f prefill_io_s=%.3f "
+                     "prefill_stall_s=%.3f prefill_mgmt_s=%.3f\n",
                      s.n_generated, s.s_per_token, s.tokens_per_second, s.moe_read_mib, s.moe_io_seconds,
                      s.moe_compute_s_per_token, s.moe_io_s_per_token, s.cache_hit_pct, s.n_prompt, s.load_seconds,
                      s.prefill_seconds, s.prefill_seconds > 0 ? s.n_prompt / s.prefill_seconds : 0.0,
@@ -93,7 +95,8 @@ public:
                      s.n_generated ? s.route_ahead_gemv_ns / 1e6 / s.n_generated : 0.0,
                      s.n_generated ? s.route_ahead_issue_ns / 1e6 / s.n_generated : 0.0,
                      s.n_generated ? s.route_ahead_wd_ns / 1e6 / s.n_generated : 0.0, s.moe_drain_s_per_token,
-                     s.moe_adopt_s_per_token, s.cache_evictions, s.cache_rereads);
+                     s.moe_adopt_s_per_token, s.cache_evictions, s.cache_rereads, s.prefill_cpu_seconds,
+                     s.prefill_read_mib, s.prefill_io_seconds, s.prefill_stall_seconds, s.prefill_mgmt_seconds);
         std::fflush(f_);
     }
 

docs/telemetry.md

@@ -320,6 +320,12 @@ average the two wait columns below, and `evictions` / `rereads` are the cache-ch
 the `moe-cache:` line — a read of an entry the cache had already held once is the only way a
 prefetch whose reads are all "useful" can still raise the byte count.
 
+The prefill phase's own split rides the trailer too: `prefill_cpu_s=<s>`, `prefill_read_mib=<f>`,
+`prefill_io_s=<s>`, `prefill_stall_s=<s>`, `prefill_mgmt_s=<s>` — the same raw values, names and
+units as the `BMOE_DONE` keys of those names (see the protocol notes above), appended keys so
+existing readers ignore them. A recorded run can now answer "what did the prompt cost, and in
+what" without the protocol line.
+
 The trailing block is the memory picture, added so a run can be diagnosed from its own file:
 
 | column | meaning |
@@ -474,6 +480,8 @@ BMOE_DONE  {"id":<int>,"cancelled":<bool>,"tokens":<int>,"tok_s":<float>,
             "n_prompt":<int>,"n_past":<int>,"compute_s_tok":<float>,"io_s_tok":<float>,
             "cache_resident_mib":<float>,"cache_budget_mib":<float>,"read_mib":<float>,
             "stall_s_tok":<float>,"mgmt_s_tok":<float>,"majflt_tok":<float>,"cpu_s_tok":<float>,
+            "prefill_cpu_s":<float>,"prefill_read_mib":<float>,"prefill_io_s":<float>,
+            "prefill_stall_s":<float>,"prefill_mgmt_s":<float>,
             "token_demand_mib":<float>,"mtp_drafted":<int>,"mtp_accepted":<int>,"mtp_decodes":<int>,
             "mtp_draft_s_tok":<float>,"drafted_steps":<int>,"loop_overhead_s_tok":<float>,
             "reasoning":"<string>","text":"<string>"}
@@ -489,6 +497,16 @@ excludes both, so `1 / (1/tok_s + loop_overhead_s_tok)` is the rate a user actua
 for `--ngram`, which decodes plainly when it has no match. See [mtp.md](mtp.md) and
 [ngram.md](ngram.md).
 
+The `prefill_*` keys are the prompt phase's own attribution (#173): `prefill_read_mib` / `_io_s` /
+`_stall_s` / `_mgmt_s` are deltas of the same cumulative streamer counters the decode fields come
+from, taken across this turn's prefill chunks, and `prefill_cpu_s` is process CPU over the same
+window (an upper bound on compute-thread CPU-equivalent time, as everywhere). Read them with the
+same per-phase rules: `prefill_io_s` is summed lane busy time under overlap and can exceed the
+wall; `prefill_stall_s` is the union of stalled intervals. On a >RAM model the prompt is what the
+user actually waits for before the first token, and until these keys it had exactly one number
+(`prefill_s`) with no compute/flash split at all — the phase the decode-oriented counters could
+not see. They are `0` with streaming off (`prefill_cpu_s` still reported).
+
 `BMOE_READY`'s `n_expert_used` is the **effective** routing width, after any `--n-expert-used`
 override (`0` on a non-MoE model). A UI needs it to say anything sensible about
 [`--drop-cold-experts`](expert-dropping.md), whose threshold is a fraction of `1/top-k`: the same

tests/CMakeLists.txt

@@ -49,6 +49,13 @@ target_link_libraries(bmoe_stall_union_test PRIVATE bmoe_core)
 target_include_directories(bmoe_stall_union_test PRIVATE ${CMAKE_SOURCE_DIR}/core/src/moe)
 add_test(NAME stall_union COMMAND bmoe_stall_union_test)
 
+# The CSV `# summary` trailer serialization. Drives the sink directly with a filled RunSummary —
+# no model, no llama.cpp — so the emitted key names and units are pinned by a test rather than by
+# whatever script last read them. The prefill keys must match BMOE_DONE's, token for token.
+add_executable(bmoe_csv_summary_test csv_summary_test.cpp)
+target_link_libraries(bmoe_csv_summary_test PRIVATE bmoe_core)
+add_test(NAME csv_summary COMMAND bmoe_csv_summary_test)
+
 find_program(PYTHON3 NAMES python3 python)
 
 if(PYTHON3)

tests/csv_summary_test.cpp

@@ -0,0 +1,70 @@
+// Serialization regression for the CSV `# summary` trailer (core/src/metrics/csv_metrics_sink.cpp).
+//
+// The trailer is what scripts/bench-report.sh and the phone app read back, and its prefill keys
+// must carry the same raw values BMOE_DONE prints — same names, same units, no normalization.
+// This drives the sink directly with a filled RunSummary and asserts the emitted tokens, so a
+// renamed key, a dropped field or a unit change fails here instead of in someone's analysis
+// script.
+//
+// Checks are explicit (not <cassert>): the Release build defines NDEBUG, which compiles assert out.
+
+#include "bmoe/metrics.h"
+
+#include <cstdio>
+#include <fstream>
+#include <string>
+
+using namespace bmoe;
+
+static int failures = 0;
+
+// The trailer is whitespace-separated key=value tokens; asserting the exact token also pins the
+// printf precision, which is part of the contract (values must round the way BMOE_DONE rounds).
+static void expect_key(const std::string & line, const char * key, const char * wanted) {
+    const std::string pat = std::string(key) + "=" + wanted;
+    if (line.find(pat) != std::string::npos) {
+        std::printf("[PASS] summary %s\n", key);
+    } else {
+        std::printf("[FAIL] summary %s\n  wanted token '%s' in:\n  %s\n", key, pat.c_str(), line.c_str());
+        ++failures;
+    }
+}
+
+int main(int argc, char ** argv) {
+    // Next to the test binary's invocation, in the test working directory: parallel ctest runs
+    // each get their own file and nothing is left behind.
+    const std::string out = argc > 1 ? argv[1] : "csv-summary-test.csv";
+    IMetricsSink * sink = make_csv_metrics_sink(out);
+    if (!sink) {
+        std::printf("[FAIL] could not open %s for writing\n", out.c_str());
+        return 1;
+    }
+    RunInfo r; // defaults: the preamble is not what this test is about
+    sink->on_run_info(r);
+
+    RunSummary s;                     // value-init: every other field zero, only the five under test are set
+    s.prefill_cpu_seconds = 12.3456;  // %.3f -> 12.346
+    s.prefill_read_mib = 4096.5;      // %.1f -> 4096.5
+    s.prefill_io_seconds = 3.4567;    // %.3f -> 3.457
+    s.prefill_stall_seconds = 2.7182; // %.3f -> 2.718
+    s.prefill_mgmt_seconds = 1.4142;  // %.3f -> 1.414
+    sink->on_summary(s);
+    delete sink; // the destructor closes and flushes the file
+
+    std::ifstream in(out);
+    std::string line, summary;
+    while (std::getline(in, line))
+        if (line.rfind("# summary", 0) == 0) summary = line;
+    if (summary.empty()) {
+        std::printf("[FAIL] no '# summary' line in %s\n", out.c_str());
+        ++failures;
+    } else {
+        expect_key(summary, "prefill_cpu_s", "12.346");
+        expect_key(summary, "prefill_read_mib", "4096.5");
+        expect_key(summary, "prefill_io_s", "3.457");
+        expect_key(summary, "prefill_stall_s", "2.718");
+        expect_key(summary, "prefill_mgmt_s", "1.414");
+    }
+    std::remove(out.c_str());
+    return failures ? 1 : 0;
+}