diff --git a/app/forward_serve.cpp b/app/forward_serve.cpp index 2a616c1e4..eeaba5ccb 100644 --- a/app/forward_serve.cpp +++ b/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 wlogits; + std::vector 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(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()); diff --git a/npu/forward/src/q4nx_forward.cpp b/npu/forward/src/q4nx_forward.cpp index cef1a007b..e60a4a95d 100644 --- a/npu/forward/src/q4nx_forward.cpp +++ b/npu/forward/src/q4nx_forward.cpp @@ -3569,6 +3569,24 @@ bool Q4nxNpuForward::step_batch(const std::vector& tokens, int start_pos, } } deepstack_add(l); + // NPU_INFER_DUMP_DIR= writes this layer's residual stream (M x H floats, row-major) as layer_.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(); } diff --git a/npu/target/xdna/xdna_target.cpp b/npu/target/xdna/xdna_target.cpp index 9e2e5a1f3..26b7d0e88 100644 --- a/npu/target/xdna/xdna_target.cpp +++ b/npu/target/xdna/xdna_target.cpp @@ -1072,7 +1072,12 @@ void XdnaTarget::npu_gemm_rows(const GemvArgs& ar, std::vector& 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& 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 } } diff --git a/tests/serve_port.sh b/tests/serve_port.sh index b9144ee06..93cabf825 100755 --- a/tests/serve_port.sh +++ b/tests/serve_port.sh @@ -38,8 +38,12 @@ serve_port_from_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() { # [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() { # [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