serve: forward-serve warms the weight cache before it says ready (44.5 s it was hiding)

app/forward_serve.cpp

@@ -1045,6 +1045,38 @@ int run_forward_serve(int argc, char** argv) {
         ~Stop() { s.stop(); if (t.joinable()) t.join(); }
     } stop{srv, listener};
 
+    // Warm the weight cache before saying "ready". A first request has to touch every (layer, role) weight once, and on
+    // the non-folded int8 route that means materialising the weight matrix in float32 and packing it -- ~112
+    // projections, which on a 27B pack is tens of seconds. Left in the request, that looks like a hang: a 8-token
+    // request returning nothing in 150 s (engine #1605), and a "ready" line that is a lie about the next minute.
+    // Paid here it is startup time, which is what startup time is for. NPU_SERVE_NO_WARMUP=1 keeps the old behaviour.
+    if (!getenv("NPU_SERVE_NO_WARMUP")) {
+        // Announce the warm-up BEFORE it runs, so a caller polling for "ready" can tell "warming, give it a minute" from
+        // "hung". Measured cost is 44.5 s on a folded 27B pack, and `tests/serve_port.sh`'s helper defaults to a 30 s
+        // budget -- a caller that only knows about `ready` would time out and report "serve never reported a port",
+        // which is the misleading shape #1531/#1545 spent effort removing.
+        std::fprintf(stderr, "1bit forward-serve: warming (weight cache; first request would otherwise pay it)\n");
+        std::fflush(stderr);
+        const auto t0 = std::chrono::steady_clock::now();
+        std::vector<float> wlogits;
+        std::vector<int> wids = {131, 131, 131, 131};   // four tokens of one id: the cheapest pass that touches every weight
+        e.fwd->reset();
+        const bool ok = e.fwd->step_batch(wids, 0, wlogits);
+        e.fwd->reset();
+        const double wms = std::chrono::duration<double, std::milli>(std::chrono::steady_clock::now() - t0).count();
+        if (!ok) {
+            std::fprintf(stderr, "1bit forward-serve: warm-up pass failed (%s); serving anyway -- the first request "
+                                 "will pay it\n", e.fwd->last_error());
+        } else {
+            // The caveat is in the log line, not only the PR: the warm-up covers the TOKEN-INVARIANT weights (wkey >=
+            // 0, "packed once and reused" -- xdna_target.cpp). Routed-expert weights are wkey < 0 and are deliberately
+            // never cached ("whose weights change per token"), so on a MoE pack the warm-up is NOT the whole first-touch
+            // cost and a reader must not expect the same 44.5 s to disappear.
+            std::fprintf(stderr, "1bit forward-serve: warm-up pass %.1f ms (token-invariant weights only -- routed MoE "
+                                 "experts are never cached, so a MoE pack still pays per-expert packing; "
+                                 "NPU_SERVE_NO_WARMUP=1 to skip)\n", wms);
+        }
+    }
     ready = true;
     std::fprintf(stderr, "1bit forward-serve: %s ready on http://%s:%d (%s)", e.id.c_str(), host.c_str(), port,
                  e.fwd->backend().c_str());

npu/forward/src/q4nx_forward.cpp

@@ -3569,6 +3569,24 @@ bool Q4nxNpuForward::step_batch(const std::vector<int>& tokens, int start_pos,
             }
         }
         deepstack_add(l);
+        // NPU_INFER_DUMP_DIR=<dir> writes this layer's residual stream (M x H floats, row-major) as layer_<l>.f32, so a
+        // per-layer cosine against a reference trace is possible at all: NPU_INFER_DUMP_LAYERS only prints mean/absmax,
+        // which cannot localise a divergence to an op. TorchLens (Apache-2.0, reference side only) supplies the other
+        // half; nothing from it ships here. Off unless the variable is set, and written with plain fopen/fwrite because
+        // this runs in the forward's hot loop only when someone asked for it.
+        if (const char* dd = getenv("NPU_INFER_DUMP_DIR")) {
+            static bool told = false;
+            if (!told) {
+                told = true;
+                std::fprintf(stderr, "  [dump] residual stream per layer -> %s (M=%d H=%d)\n", dd, M, H);
+            }
+            char path[4096];
+            std::snprintf(path, sizeof path, "%s/layer_%02d.f32", dd, l);
+            if (FILE* fp = std::fopen(path, "wb")) {
+                std::fwrite(X.data(), sizeof(float), (size_t)M * (size_t)H, fp);
+                std::fclose(fp);
+            }
+        }
     }
 
     if (phb) { g_ph.layer = ph_ms(tp_lap); tp_lap = std::chrono::steady_clock::now(); }

npu/target/xdna/xdna_target.cpp

@@ -1072,7 +1072,12 @@ void XdnaTarget::npu_gemm_rows(const GemvArgs& ar, std::vector<float>& out, std:
                 prof_add(prof_pre_, di, dpk, dql, dwt, drb);
                 prof_pre_n_++;
             }
-            if (prof_dec_n_ && (prof_dec_n_ + prof_pre_n_) % 100 == 0) prof_dump();
+            // Dump on either family's count. The `prof_dec_n_ &&` guard meant a PREFILL-ONLY process never dumped at
+            // all: no decode launch had happened, so the condition was false no matter how many prefill launches ran.
+            // That is exactly the case that matters when a request stalls -- the run that never returns is a prefill,
+            // so the profiler stayed silent and "no rows" could not be read as "no launches" (engine #1605: an 8-token
+            // request on the pb16i arm returned nothing in 420 s and printed no profiler rows).
+            if ((prof_dec_n_ + prof_pre_n_) % 100 == 0) prof_dump();
         }
         return;
     }
@@ -1155,7 +1160,7 @@ void XdnaTarget::npu_gemm_rows(const GemvArgs& ar, std::vector<float>& out, std:
             prof_add(prof_pre_, di, dpk, dql, dwt, drb);
             prof_pre_n_++;
         }
-        if (prof_dec_n_ && (prof_dec_n_ + prof_pre_n_) % 100 == 0) prof_dump();
+        if ((prof_dec_n_ + prof_pre_n_) % 100 == 0) prof_dump();   // same reason as above: prefill-only runs
     }
 }
 

tests/serve_port.sh

@@ -38,8 +38,12 @@ serve_port_from_log() {  # <log> -> the port, empty while serve has not said
     awk '/^1bit serve: ready on http:\/\//{ n = split($5, a, ":"); if (a[n] ~ /^[0-9]+$/) { print a[n]; exit } }' "$1" 2>/dev/null
 }
 
-serve_port_wait() {  # <log> <pid> [tenths-of-a-second, default 300 = 30 s] -> the port, non-zero if it never came
-    local log=$1 pid=$2 tries=${3:-300} port=
+# The default budget is 90 s, not 30: `forward-serve` warms its weight cache before printing `ready on` (engine#1621),
+# measured at 44.5 s on a folded 27B pack, and pays it on exactly the configurations these tests exercise. A caller that
+# wants the old bound can still pass it, and a log now says `warming` before the wait, so a short budget fails with a
+# readable line rather than with "serve never reported a port".
+serve_port_wait() {  # <log> <pid> [tenths-of-a-second, default 900 = 90 s] -> the port, non-zero if it never came
+    local log=$1 pid=$2 tries=${3:-900} port=
     for _ in $(seq 1 "$tries"); do
         port=$(serve_port_from_log "$log")
         if [ -n "$port" ]; then printf '%s\n' "$port"; return 0; fi