Make the host-side dispatch timeout self-attributing - #708
Conversation
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 <string>, 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 <dmvevents@gmail.com>
| 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]) + " "; |
There was a problem hiding this comment.
🟡 warning: 在格式化异常前重新快照所有计数器: 当 GPU 恰好在超时判断后完成写入时，num_recv_tokens 和 num_rdma_recv_tokens 仍是循环开头读取的旧值，而专家计数器还会在判断和 to_string 时被读取两次。因此异常可能把已经就绪的总计数器报告为 -1，或把非负的专家计数器列为 stalled，且无法按预期输出 all-ready race 提示；intranode 块也有同样问题。应先重新读取所有计数器到一致的局部快照，再据此生成诊断。
🤖 v6
| " 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"); |
There was a problem hiding this comment.
🟡 warning: New line exceeds ColumnLimit=140, and CI fails on any reformat. The trailing explanation string at L1146 ("-- the GPU never published these counts; ... (proxy/GIN/NVSHMEM) did not complete");) measures 141-143 columns, over the .clang-format ColumnLimit of 140. This matters because .github/workflows/format.yml runs bash format.sh, which pip-installs clang-format==15.0.7, reformats changed C/C++ files in place, and exits 1 if anything changed. Two supporting data points: (a) grepping the whole repo for lines >140 columns that contain a string literal returns zero matches, i.e. the Google-derived BreakStringLiterals behaviour has evidently been splitting such literals everywhere else, so this line is an outlier rather than an accepted exception like the pre-existing non-string lines at L114/L143/L252/L1321; (b) the hand-wrapped +-chains in both new throws sit at ~110-120 columns, well short of 140, so clang-format is likely to repack them as well, producing further diff. I could not run clang-format in this environment, so this is inference from the config plus repo-wide evidence rather than a reproduced failure - please run bash format.sh (or clang-format 15.0.7 on the file) and commit the result before merge.
🤖 v7
There was a problem hiding this comment.
Addressed in 8574ff9: every added line is now stable under clang-format 15.0.7 with the repo .clang-format (I ran the format.sh clang-format step locally — it changes none of the added lines; longest added line is 138 columns). One honest caveat: the file as a whole does not round-trip clang-format cleanly even on upstream main (~130 reformat lines pre-existing, e.g. the include order and several 140+ col lines), so a full format.sh run still reports the pre-existing churn. I deliberately did not fold that whole-file reformat into this PR to keep the diff reviewable — happy to do it as a separate commit here or a separate PR if the maintainers prefer.
| 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) "; |
There was a problem hiding this comment.
🔵 suggestion: The all-counters-ready branch produces a self-contradictory message. When stalled ends up empty the text reads: "... stalled: (none: all counters ready at throw time -- suspect a race) -- the GPU never published these counts; the dispatch kernel or its transport did not complete". The two halves assert opposite things, and this is exactly the branch whose purpose is to steer the reader away from the transport hypothesis and toward a race. Since that branch point is the one the description names as the first thing an investigator needs, make the trailing sentence conditional (or fold it into the non-empty branch) so the race case reads unambiguously. Same at L1139/L1146 for the internode site.
🤖 v7
There was a problem hiding this comment.
Fixed in 8574ff9: the trailing attribution is now conditional. When the snapshot reads all-ready the message says "(none) -- every counter read as ready in this snapshot: the timeout raced with a completion that landed just after the check", and the "GPU never published" claim is only emitted when something actually reads negative. No more self-contradiction in exactly the branch meant to disambiguate.
| auto waited_secs = | ||
| std::chrono::duration_cast<std::chrono::seconds>(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 |
There was a problem hiding this comment.
🔵 suggestion: About 15 lines of stall-string construction are duplicated at both sites, differing only by the rdma counter line and the trailing wording. Extracting a small private helper or a local lambda would keep them from drifting apart - and the modern path already does precisely that: csrc/elastic/buffer.hpp:1045 builds a get_buffer_info lambda and passes it to the throw at L1063. Following that shape here would also make it natural to reuse std::stringstream (the exception.cuh idiom) instead of long std::string +-chains, which is what is currently pushing against the column limit in the formatting comment.
🤖 v7
There was a problem hiding this comment.
Done in 8574ff9: extracted build_cpu_timeout_detail(), shared by both throw sites (the intranode path passes rdma_snap=nullptr), following the elastic-path precedent you pointed at (the get_buffer_info lambda at csrc/elastic/buffer.hpp:1045).
| 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) + |
There was a problem hiding this comment.
🔵 suggestion: __LINE__ expands at its own token position, so the reported location is two lines below the actual throw (611 vs 609 intranode, 1142 vs 1140 internode). Harmless for navigation but slightly at odds with the stated goal of a resolved source location; moving __LINE__ onto the throw line makes it exact. Note also that the repo already provides EPExceptionWithLineInfo(name, message) (deep_ep/common/exception.cuh:25), which wraps FILE/LINE and is what csrc/elastic/buffer.hpp:1063 uses. Adopting it here would change the exception type from std::runtime_error to EPException and reshape the prefix, which conflicts with the deliberate decision to keep the legacy prefixes intact - so that part is a judgement call, not a required change.
🤖 v7
There was a problem hiding this comment.
Done in 8574ff9: switched both throws to the repo's EPExceptionWithLineInfo, so FILE/LINE are captured on the throw line itself — exact, not two lines below. The original "DeepEP error: ..." prefixes are preserved verbatim as the exception name so existing log scanners keep matching.
| // 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) |
There was a problem hiding this comment.
🔵 suggestion: The stall list re-reads volatile counters, so it can disagree with the printf lines emitted immediately above. moe_recv_expert_counter[i] is volatile int* and is read again while building the string, after the ready evaluation and after the printf loop. In a live stall the values are stable so this is almost always moot, but on a late arrival the exception can name a different set of experts than the printf output two lines earlier, and it is also the mechanism that produces the empty-stalled branch. Snapshotting the counters into locals once and using that snapshot for the printf, the ready check and the message would make all three consistent by construction.
🤖 v7
🤖 ds-review-bot Code Reviewv6新增诊断会并发读取持续由 GPU 更新的计数器，却未形成稳定快照，因此在关键的超时竞态场景下可能给出自相矛盾或错误归因的信息。 v4v7Diagnostics-only change to the two host-side CPU-wait timeouts in csrc/legacy/buffer.hpp (intranode dispatch ~L597, internode dispatch ~L1122). The intent is sound and the value is real: the intranode site previously threw a context-free string, and the internode site kept all of its context in printf output that is easily separated from the exception. What I confirmed statically: the timeout predicate is unchanged ( Two notes that need no action. First, the added What I could not re-execute: this environment restricts bash to git commands, so no compilation and no clang-format run were possible. The description's Files reviewed: 1 |
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<int> 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 <vector> for the snapshot.
Note on the earlier commit message: it framed the <string> include as
necessary. It is hygiene only -- exception.cuh already includes <string>
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 <dmvevents@gmail.com>
|
Thanks — the v6 finding is correct and I've fixed it in You're right that re-reading the counters while formatting is a real defect, and specifically in the scenario the patch exists to explain. They're Both sites now take a single snapshot — Also addressed from the inline comments:
Two I'm not changing, and why:
One correction to my own earlier commit message: it framed the Re-verified after the change: the inserted logic extracted verbatim with |
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 <dmvevents@gmail.com>
2 participants
Problem
The two host-side CPU-wait timeouts in
csrc/legacy/buffer.hppreport the symptom but not its origin.buffer.hpp:596(intranode dispatch) throwsDeepEP error: CPU recv timeoutwith 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. Once theprintfoutput is separated from the exception — multi-rank log interleaving, or only the Python traceback captured — the attribution is gone. The single surviving signal is-1, which says nothing about which counter never arrived, how long the wait actually was, or where the throw came from.Change
Diagnostics only — no behaviour change. Both sites now carry, in the exception text:
__FILE__/__LINE__rankandnum_local_expertsThe existing
printflines at the internode site are preserved verbatim, and both error strings keep their original prefixes (DeepEP error: CPU recv timeout,DeepEP error: timeout (dispatch CPU)) with new detail appended after.Verification
g++ -std=c++17 -Wall -Wextra— clean, no warnings.{-1, 0, -1, 5}); the message names experts 0 and 2 as stalled and correctly omits the two that were ready.Global rank: …line, all per-expert lines, and both error-string prefixes still match their original patterns; pre-patch logs from a real failure also still match the same scanner. A silently blinded scanner would turn a real timeout into a false pass, so this was verified rather than assumed.#include <string>, which was not previously included directly, rather than relying on a transitive include forstd::string/std::to_string.Motivation
On AWS EFA we hit this exact timeout across a batch of 384-expert runs. The cause turned out to be a build-configuration regression in our own image — but the log could not have told us that; recovering it took source archaeology plus a bisect against a known-good image. With this patch the exception alone distinguishes "no counter ever arrived" (dead transport) from "some experts arrived and others did not" (partial routing), which is the first branch point in any such investigation.
Relation to #704
Complementary, non-overlapping. #704 makes the device-side low-latency
trap()self-attributing (the origin of a sticky CUDA 719) incsrc/kernels/legacy/internode_ll.cu. This PR does the host-side twin incsrc/legacy/buffer.hpp, where the CPU busy-wait throws. Different files, different failure paths — in our own logs a word-boundary search for719/LAUNCH_FAILED/cudaErrorLaunchFailurereturns zero, so our failures are purely the host-side path this PR covers. Both are needed for the same reason: today the error signal does not identify where it came from.