From cf75cd6a0637d8edd1e00e261f205c8c0d738043 Mon Sep 17 00:00:00 2001 From: Anton Alexander Date: Wed, 29 Jul 2026 22:48:07 +0000 Subject: [PATCH 1/3] Make the host-side dispatch timeout self-attributing The two host-side CPU-wait timeouts in csrc/legacy/buffer.hpp report the symptom but not its origin. On a stall the only signal is a count of -1, which says nothing about which counter never became ready, how long the wait actually was, or where in the file the throw came from. buffer.hpp:596 (intranode dispatch) is the worse of the two: it throws "DeepEP error: CPU recv timeout" with no diagnostics at all -- no rank, no counters, no elapsed time. buffer.hpp:1105 (internode dispatch) prints the total and per-expert counters, but the exception text itself carries nothing, so once the printf output is separated from the exception (a common case with multi-rank log interleaving, or when only the Python traceback is captured) the attribution is lost. Diagnostics only -- no behaviour change. Both sites now include, in the exception text: - the resolved source location via __FILE__ and __LINE__ - waited vs limit seconds - rank and num_local_experts - an explicit list of exactly which counters were still negative (total / rdma / each per-expert index), or a note that all counters were ready at throw time, which would indicate a race rather than a stalled transport The existing printf lines at the internode site are preserved verbatim, and both error strings keep their original prefixes ("DeepEP error: CPU recv timeout" and "DeepEP error: timeout (dispatch CPU)"), with the new detail appended after. Downstream log scanners that match on those prefixes keep matching; a silently blinded scanner would turn a real timeout into a false pass, so that property was verified rather than assumed. Verification: - The inserted logic was extracted verbatim and compiled standalone with g++ -std=c++17 -Wall -Wextra: clean, no warnings. - Ran it with a representative stall state (total=-1, rdma=-1, experts {-1, 0, -1, 5}) and confirmed the message names experts 0 and 2 as stalled while omitting the two that were ready. - Log-scanner regression: the legacy "Global rank: ..." line, all four per-expert lines, and the error-string prefix all still match their original patterns; pre-patch logs from an existing failure also still match the same scanner. - Brace and paren balance re-checked across the file (197/197, 1378/1378). - Added #include , which was not previously included directly, rather than relying on a transitive include for std::string and std::to_string. Motivation: on AWS EFA we hit this exact timeout across a batch of 384-expert runs. The failure turned out to be a build-configuration regression in our own image, but the log could not have told us that -- recovering the cause needed source archaeology and a bisect against a known-good image. With this patch the exception alone distinguishes "no counter ever arrived" from "some experts arrived and others did not", which separates a dead transport from a partial-routing problem. Signed-off-by: Anton Alexander --- csrc/legacy/buffer.hpp | 53 +++++++++++++++++++++++++++++++++++++----- 1 file changed, 47 insertions(+), 6 deletions(-) diff --git a/csrc/legacy/buffer.hpp b/csrc/legacy/buffer.hpp index 39ddcee3f..3f12b1443 100644 --- a/csrc/legacy/buffer.hpp +++ b/csrc/legacy/buffer.hpp @@ -7,6 +7,7 @@ #include #include +#include #include #include @@ -591,9 +592,28 @@ struct Buffer { break; // Timeout check - if (std::chrono::duration_cast(std::chrono::high_resolution_clock::now() - start_time).count() > - LEGACY_NUM_CPU_TIMEOUT_SECS) - throw std::runtime_error("DeepEP error: CPU recv timeout"); + auto waited_secs = + std::chrono::duration_cast(std::chrono::high_resolution_clock::now() - start_time).count(); + if (waited_secs > LEGACY_NUM_CPU_TIMEOUT_SECS) { + // Attribute the stall: report which counter never became ready, so the + // failure is not silently attributed to whatever runs next. + std::string stalled; + if (num_recv_tokens < 0) + stalled += "moe_recv_counter(total)=" + std::to_string(num_recv_tokens) + " "; + for (int i = 0; i < num_local_experts; ++i) + if (moe_recv_expert_counter[i] < 0) + stalled += "moe_recv_expert_counter[" + std::to_string(i) + "]=" + + std::to_string(moe_recv_expert_counter[i]) + " "; + if (stalled.empty()) + stalled = "(none: all counters ready at throw time -- suspect a race) "; + throw std::runtime_error( + std::string("DeepEP error: CPU recv timeout") + " at " + __FILE__ + ":" + + std::to_string(__LINE__) + " [intranode dispatch] rank=" + std::to_string(rank) + + " waited=" + std::to_string(waited_secs) + "s limit=" + + std::to_string(LEGACY_NUM_CPU_TIMEOUT_SECS) + "s num_local_experts=" + + std::to_string(num_local_experts) + " stalled: " + stalled + + "-- the GPU never published these counts; the dispatch kernel or its transport did not complete"); + } } num_recv_tokens_per_expert_list = std::vector(moe_recv_expert_counter, moe_recv_expert_counter + num_local_experts); } @@ -1097,12 +1117,33 @@ struct Buffer { break; // Timeout check - if (std::chrono::duration_cast(std::chrono::high_resolution_clock::now() - start_time).count() > - LEGACY_NUM_CPU_TIMEOUT_SECS) { + auto waited_secs = + std::chrono::duration_cast(std::chrono::high_resolution_clock::now() - start_time).count(); + if (waited_secs > LEGACY_NUM_CPU_TIMEOUT_SECS) { + // Preserve the existing printf lines verbatim so downstream log scanners keep matching. printf("Global rank: %d, num_recv_tokens: %d, num_rdma_recv_tokens: %d\n", rank, num_recv_tokens, num_rdma_recv_tokens); for (int i = 0; i < num_local_experts; ++i) printf("moe_recv_expert_counter[%d]: %d\n", i, moe_recv_expert_counter[i]); - throw std::runtime_error("DeepEP error: timeout (dispatch CPU)"); + // Attribute the stall in the exception itself: which counter never became ready. + // Without this the only signal is "-1", which says nothing about where it came from. + std::string stalled; + if (num_recv_tokens < 0) + stalled += "moe_recv_counter(total)=" + std::to_string(num_recv_tokens) + " "; + if (num_rdma_recv_tokens < 0) + stalled += "moe_recv_rdma_counter=" + std::to_string(num_rdma_recv_tokens) + " "; + for (int i = 0; i < num_local_experts; ++i) + if (moe_recv_expert_counter[i] < 0) + stalled += "moe_recv_expert_counter[" + std::to_string(i) + "]=" + + std::to_string(moe_recv_expert_counter[i]) + " "; + if (stalled.empty()) + stalled = "(none: all counters ready at throw time -- suspect a race) "; + throw std::runtime_error( + std::string("DeepEP error: timeout (dispatch CPU)") + " at " + __FILE__ + ":" + + std::to_string(__LINE__) + " [internode dispatch] rank=" + std::to_string(rank) + + " waited=" + std::to_string(waited_secs) + "s limit=" + + std::to_string(LEGACY_NUM_CPU_TIMEOUT_SECS) + "s num_local_experts=" + + std::to_string(num_local_experts) + " stalled: " + stalled + + "-- the GPU never published these counts; the dispatch kernel or its transport (proxy/GIN/NVSHMEM) did not complete"); } } num_recv_tokens_per_expert_list = std::vector(moe_recv_expert_counter, moe_recv_expert_counter + num_local_experts); From 8b06138ed31f1e9873fdc05e120722e78fc61e97 Mon Sep 17 00:00:00 2001 From: Anton Alexander Date: Wed, 29 Jul 2026 23:29:41 +0000 Subject: [PATCH 2/3] Snapshot the counters once before formatting the timeout message Review found a real defect in the first revision: the stall-attribution string re-read the counters while building the message. They are volatile int* and the GPU can publish a value between the timeout check and the format, so the message could contradict the printf lines emitted immediately above it, or list an already-ready counter as stalled. Both sites now take a single snapshot -- total, rdma (internode only), and a std::vector of the per-expert counters -- and format exclusively from that snapshot. The printf lines and the timeout predicate are untouched. Also from review: - The all-ready branch previously read "all counters ready at throw time -- suspect a race", which was self-contradictory in a message whose purpose is to name what stalled. With a real snapshot the case has a precise meaning, so it now says the GPU published between the timeout check and the format. - Split the two trailing explanation strings so no added line exceeds ColumnLimit=140; the format gate was the realistic CI failure. - Added for the snapshot. Note on the earlier commit message: it framed the include as necessary. It is hygiene only -- exception.cuh already includes transitively. Recording that rather than leaving the overstatement. Re-verified: the inserted logic was extracted verbatim with volatile sources and compiled standalone under g++ -std=c++17 -Wall -Wextra, clean; with the stall state {total=-1, rdma=-1, experts={-1,0,-1,5}} the message names experts 0 and 2 and omits the two that were ready; no added line exceeds 140 columns; brace/paren balance 197/197, 1382/1382. Signed-off-by: Anton Alexander --- csrc/legacy/buffer.hpp | 46 +++++++++++++++++++++++++++++------------- 1 file changed, 32 insertions(+), 14 deletions(-) diff --git a/csrc/legacy/buffer.hpp b/csrc/legacy/buffer.hpp index 3f12b1443..9ee1d3410 100644 --- a/csrc/legacy/buffer.hpp +++ b/csrc/legacy/buffer.hpp @@ -8,6 +8,7 @@ #include #include #include +#include #include #include @@ -597,22 +598,29 @@ struct Buffer { if (waited_secs > LEGACY_NUM_CPU_TIMEOUT_SECS) { // Attribute the stall: report which counter never became ready, so the // failure is not silently attributed to whatever runs next. + // Snapshot once before formatting: volatile counters can change mid-format. + const int total_snap = num_recv_tokens; + std::vector expert_snap(num_local_experts); + for (int i = 0; i < num_local_experts; ++i) + expert_snap[i] = moe_recv_expert_counter[i]; std::string stalled; - if (num_recv_tokens < 0) - stalled += "moe_recv_counter(total)=" + std::to_string(num_recv_tokens) + " "; + if (total_snap < 0) + stalled += "moe_recv_counter(total)=" + std::to_string(total_snap) + " "; for (int i = 0; i < num_local_experts; ++i) - if (moe_recv_expert_counter[i] < 0) + if (expert_snap[i] < 0) stalled += "moe_recv_expert_counter[" + std::to_string(i) + "]=" + - std::to_string(moe_recv_expert_counter[i]) + " "; + std::to_string(expert_snap[i]) + " "; if (stalled.empty()) - stalled = "(none: all counters ready at throw time -- suspect a race) "; + stalled = "(none: every counter read as ready in this snapshot, so the GPU " + "published between the timeout check and here) "; throw std::runtime_error( std::string("DeepEP error: CPU recv timeout") + " at " + __FILE__ + ":" + std::to_string(__LINE__) + " [intranode dispatch] rank=" + std::to_string(rank) + " waited=" + std::to_string(waited_secs) + "s limit=" + std::to_string(LEGACY_NUM_CPU_TIMEOUT_SECS) + "s num_local_experts=" + std::to_string(num_local_experts) + " stalled: " + stalled + - "-- the GPU never published these counts; the dispatch kernel or its transport did not complete"); + "-- the GPU never published these counts; the dispatch kernel or " + "its transport did not complete"); } } num_recv_tokens_per_expert_list = std::vector(moe_recv_expert_counter, moe_recv_expert_counter + num_local_experts); @@ -1126,24 +1134,34 @@ struct Buffer { printf("moe_recv_expert_counter[%d]: %d\n", i, moe_recv_expert_counter[i]); // Attribute the stall in the exception itself: which counter never became ready. // Without this the only signal is "-1", which says nothing about where it came from. + // Snapshot every counter ONCE before formatting: these are volatile and the GPU may + // publish a value mid-format, which would otherwise let the message contradict the + // printf above it, or list an already-ready counter as stalled. + const int total_snap = num_recv_tokens; + const int rdma_snap = num_rdma_recv_tokens; + std::vector expert_snap(num_local_experts); + for (int i = 0; i < num_local_experts; ++i) + expert_snap[i] = moe_recv_expert_counter[i]; std::string stalled; - if (num_recv_tokens < 0) - stalled += "moe_recv_counter(total)=" + std::to_string(num_recv_tokens) + " "; - if (num_rdma_recv_tokens < 0) - stalled += "moe_recv_rdma_counter=" + std::to_string(num_rdma_recv_tokens) + " "; + if (total_snap < 0) + stalled += "moe_recv_counter(total)=" + std::to_string(total_snap) + " "; + if (rdma_snap < 0) + stalled += "moe_recv_rdma_counter=" + std::to_string(rdma_snap) + " "; for (int i = 0; i < num_local_experts; ++i) - if (moe_recv_expert_counter[i] < 0) + if (expert_snap[i] < 0) stalled += "moe_recv_expert_counter[" + std::to_string(i) + "]=" + - std::to_string(moe_recv_expert_counter[i]) + " "; + std::to_string(expert_snap[i]) + " "; if (stalled.empty()) - stalled = "(none: all counters ready at throw time -- suspect a race) "; + stalled = "(none: every counter read as ready in this snapshot, so the GPU " + "published between the timeout check and here) "; throw std::runtime_error( std::string("DeepEP error: timeout (dispatch CPU)") + " at " + __FILE__ + ":" + std::to_string(__LINE__) + " [internode dispatch] rank=" + std::to_string(rank) + " waited=" + std::to_string(waited_secs) + "s limit=" + std::to_string(LEGACY_NUM_CPU_TIMEOUT_SECS) + "s num_local_experts=" + std::to_string(num_local_experts) + " stalled: " + stalled + - "-- the GPU never published these counts; the dispatch kernel or its transport (proxy/GIN/NVSHMEM) did not complete"); + "-- the GPU never published these counts; the dispatch kernel or its " + "transport (proxy/GIN/NVSHMEM) did not complete"); } } num_recv_tokens_per_expert_list = std::vector(moe_recv_expert_counter, moe_recv_expert_counter + num_local_experts); From 8574ff9092e765823cde68cab0d5b3bacb1b561e Mon Sep 17 00:00:00 2001 From: Anton Alexander Date: Wed, 12 Aug 2026 15:00:38 +0000 Subject: [PATCH 3/3] Deduplicate the timeout report and capture the throw line exactly Review follow-ups on the remaining four threads: - The ~15 lines of stall-string construction duplicated at both throw sites are extracted into build_cpu_timeout_detail(), shared by the intranode and internode paths. This follows the precedent the review pointed at: the elastic path already centralizes its diagnostics in a get_buffer_info lambda (csrc/elastic/buffer.hpp:1045) and passes it to the throw. The intranode path passes rdma_snap=nullptr since it has no RDMA counter. - Both throws now use the repo's EPExceptionWithLineInfo, so __FILE__/__LINE__ are captured on the throw line itself. Previously __LINE__ expanded two lines below the actual throw (611 vs 609 intranode, 1142 vs 1140 internode). The exception type changes from std::runtime_error to EPException; both derive from std::exception and the elastic path already throws EPException through the same binding layer. The original prefixes are preserved verbatim as the exception name, so the message now reads e.g. "DeepEP error: CPU recv timeout exception (csrc/legacy/buffer.hpp:NNN): [intranode dispatch] rank=..." and scanners matching the old prefixes keep matching. - The all-counters-ready branch no longer contradicts itself. The trailing attribution is conditional: when the snapshot shows every counter ready the message says the timeout raced with a completion that landed just after the check, and the "GPU never published" claim is emitted only when something actually reads negative. Format gate (ColumnLimit thread): every added line is stable under the repo's clang-format 15.0.7 + .clang-format (running the format.sh clang-format step changes none of the added lines; the longest added line is 138 columns). Note the file as a whole does not round-trip clang-format cleanly even on upstream main (130+ reformat lines pre-existing), so this commit deliberately avoids introducing that whole-file churn. Verification: - g++ -std=c++17 -fsyntax-only over the full header with torch 2.10, CUDA, and NCCL-device include paths: clean. - clang-format 15.0.7 round-trip: zero changes within the added regions. - Behaviour unchanged: printf lines, timeout predicate, and snapshot semantics are exactly as in the previous commit; only the formatting of the exception text and its construction site moved. Signed-off-by: Anton Alexander --- csrc/legacy/buffer.hpp | 88 ++++++++++++++++++++++++------------------ 1 file changed, 50 insertions(+), 38 deletions(-) diff --git a/csrc/legacy/buffer.hpp b/csrc/legacy/buffer.hpp index 9ee1d3410..15de2616f 100644 --- a/csrc/legacy/buffer.hpp +++ b/csrc/legacy/buffer.hpp @@ -21,6 +21,38 @@ namespace deep_ep::legacy { +// Shared by the two CPU-timeout throw sites below (intranode + internode dispatch): format the +// "which counter never became ready" attribution from a coherent snapshot taken by the caller. +// Pass rdma_snap = nullptr on paths without an RDMA counter. When every snapshot value reads +// ready, the timeout raced with a completion that landed just after the check -- say that, +// instead of claiming the GPU never published. +static inline std::string build_cpu_timeout_detail(const std::string& site, + const int rank, + const long long waited_secs, + const long long limit_secs, + const int total_snap, + const int* rdma_snap, + const std::vector& expert_snap, + const std::string& transport_hint) { + std::string stalled; + if (total_snap < 0) + stalled += "moe_recv_counter(total)=" + std::to_string(total_snap) + " "; + if (rdma_snap != nullptr and *rdma_snap < 0) + stalled += "moe_recv_rdma_counter=" + std::to_string(*rdma_snap) + " "; + for (size_t i = 0; i < expert_snap.size(); ++i) + if (expert_snap[i] < 0) + stalled += "moe_recv_expert_counter[" + std::to_string(i) + "]=" + std::to_string(expert_snap[i]) + " "; + std::string detail = site + " rank=" + std::to_string(rank) + " waited=" + std::to_string(waited_secs) + + "s limit=" + std::to_string(limit_secs) + "s num_local_experts=" + std::to_string(expert_snap.size()) + " stalled: "; + if (stalled.empty()) + detail += + "(none) -- every counter read as ready in this snapshot: the timeout raced with a " + "completion that landed just after the check"; + else + detail += stalled + "-- the GPU never published these counts; the dispatch kernel or its " + transport_hint + " did not complete"; + return detail; +} + struct Buffer { EP_STATIC_ASSERT(LEGACY_NUM_MAX_NVL_PEERS == 8, "The number of maximum NVLink peers must be 8"); @@ -603,24 +635,15 @@ struct Buffer { std::vector expert_snap(num_local_experts); for (int i = 0; i < num_local_experts; ++i) expert_snap[i] = moe_recv_expert_counter[i]; - std::string stalled; - if (total_snap < 0) - stalled += "moe_recv_counter(total)=" + std::to_string(total_snap) + " "; - for (int i = 0; i < num_local_experts; ++i) - if (expert_snap[i] < 0) - stalled += "moe_recv_expert_counter[" + std::to_string(i) + "]=" + - std::to_string(expert_snap[i]) + " "; - if (stalled.empty()) - stalled = "(none: every counter read as ready in this snapshot, so the GPU " - "published between the timeout check and here) "; - throw std::runtime_error( - std::string("DeepEP error: CPU recv timeout") + " at " + __FILE__ + ":" + - std::to_string(__LINE__) + " [intranode dispatch] rank=" + std::to_string(rank) + - " waited=" + std::to_string(waited_secs) + "s limit=" + - std::to_string(LEGACY_NUM_CPU_TIMEOUT_SECS) + "s num_local_experts=" + - std::to_string(num_local_experts) + " stalled: " + stalled + - "-- the GPU never published these counts; the dispatch kernel or " - "its transport did not complete"); + throw EPExceptionWithLineInfo("DeepEP error: CPU recv timeout", + build_cpu_timeout_detail("[intranode dispatch]", + rank, + waited_secs, + LEGACY_NUM_CPU_TIMEOUT_SECS, + total_snap, + nullptr, + expert_snap, + "transport")); } } num_recv_tokens_per_expert_list = std::vector(moe_recv_expert_counter, moe_recv_expert_counter + num_local_experts); @@ -1142,26 +1165,15 @@ struct Buffer { std::vector expert_snap(num_local_experts); for (int i = 0; i < num_local_experts; ++i) expert_snap[i] = moe_recv_expert_counter[i]; - std::string stalled; - if (total_snap < 0) - stalled += "moe_recv_counter(total)=" + std::to_string(total_snap) + " "; - if (rdma_snap < 0) - stalled += "moe_recv_rdma_counter=" + std::to_string(rdma_snap) + " "; - for (int i = 0; i < num_local_experts; ++i) - if (expert_snap[i] < 0) - stalled += "moe_recv_expert_counter[" + std::to_string(i) + "]=" + - std::to_string(expert_snap[i]) + " "; - if (stalled.empty()) - stalled = "(none: every counter read as ready in this snapshot, so the GPU " - "published between the timeout check and here) "; - throw std::runtime_error( - std::string("DeepEP error: timeout (dispatch CPU)") + " at " + __FILE__ + ":" + - std::to_string(__LINE__) + " [internode dispatch] rank=" + std::to_string(rank) + - " waited=" + std::to_string(waited_secs) + "s limit=" + - std::to_string(LEGACY_NUM_CPU_TIMEOUT_SECS) + "s num_local_experts=" + - std::to_string(num_local_experts) + " stalled: " + stalled + - "-- the GPU never published these counts; the dispatch kernel or its " - "transport (proxy/GIN/NVSHMEM) did not complete"); + throw EPExceptionWithLineInfo("DeepEP error: timeout (dispatch CPU)", + build_cpu_timeout_detail("[internode dispatch]", + rank, + waited_secs, + LEGACY_NUM_CPU_TIMEOUT_SECS, + total_snap, + &rdma_snap, + expert_snap, + "transport (proxy/GIN/NVSHMEM)")); } } num_recv_tokens_per_expert_list = std::vector(moe_recv_expert_counter, moe_recv_expert_counter + num_local_experts);