Skip to content

Make the low-latency timeout trap self-attributing in the log - #704

Open
KeitaW wants to merge 1 commit into
deepseek-ai:mainfrom
KeitaW:pr/self-attributing-timeout-trap
Open

Make the low-latency timeout trap self-attributing in the log#704
KeitaW wants to merge 1 commit into
deepseek-ai:mainfrom
KeitaW:pr/self-attributing-timeout-trap

Conversation

@KeitaW

@KeitaW KeitaW commented Jul 27, 2026

Copy link
Copy Markdown

Problem

CUDA 719 (CUDA_ERROR_LAUNCH_FAILED) is sticky: once raised on a context, every later launch on that context reports the same code. The three low-latency timeout sites in csrc/kernels/legacy/internode_ll.cu call trap() when mask_buffer_ptr == nullptr — that trap() is the origin of the 719 — but they print no line number and no reason, so the failure is attributed to whichever library happens to make the next launch-API call.

On a 32-rank EP32 cell the same-second 719 split 25 / 7 between DeepGEMM's runtime_utils.hpp:143 and this file's own launch site. Both are victims; neither is the cause. Recovering the real origin took a separate CUDA_LAUNCH_BLOCKING=1 run — the log alone could not have told anyone.

The fatal branch is not hypothetical. On a vLLM build that does not pass enable_shrink when constructing the low-latency Buffer, buffer.py:42 defaults it to False, so deep_ep.cpp:386 never allocates the mask buffer and mask_buffer_ptr is nullptr — every one of these three sites then traps rather than masks. That is the configuration this was measured on. Current vLLM main does wire it up (all2all.py:282-284 reads parallel_config.enable_fault_tolerance into enable_shrink at all2all.py:326), so on main the branch is reachable whenever fault tolerance is left off, which is the default. Either way the trap is live and says nothing about where it came from.

Change

Diagnostics only — no behaviour change. Each of the three sites (barrier, dispatch-receive, combine-receive) additionally prints:

  • the resolved source line via __LINE__
  • waited vs limit cycles
  • the mask_buffer pointer value
  • an explicit FATAL-WILL-TRAP(origin of CUDA 719) vs masked-survivable marker, selected on the same condition that decides whether trap() fires

The if (mask_buffer_ptr == nullptr) trap(); lines themselves are untouched.

The existing Warning: DeepEP timeout for ... prefix is preserved verbatim so downstream log scanners keep matching. A silently blinded scanner would turn a real timeout into a false PASS, so that property is verified rather than assumed (below).

Verification

  • nvcc -arch=sm_90, real H100. The vararg lists type-check on the device path, below-threshold iterations print nothing, and trap() still yields exactly 719 when armed — fatal semantics unchanged.
  • Log-scanner regression. Replayed the real device-printf bytes against a scanning regex: 7/7 patched lines match, 3/3 pre-patch lines match, no regressions.
  • Reachability. Confirmed against the extracted build under test that mask_buffer_ptr and enable_shrink are both reachable, i.e. the patched branch is not dead code behind a hardcoded-false flag.

Why legacy/ and not the new backend

csrc/kernels/legacy/ is currently the only DeepEP path vLLM builds against: all2all.py:241,317 construct deep_ep.Buffer (deep_ep/buffers/legacy.py), and ElasticBuffer is never referenced. So this patch targets the path in production use today; it is not an argument against the direction of travel.

To be clear about what this does not claim: the newer trees reach trap() too, via deep_ep/include/deep_ep/common/comm.cuh:46ptx.cuh:21-23, so this is not a problem that only exists in legacy/. The newer path is in better shape for it, though — comm::timeout_while (comm.cuh:30-49) already waits ~1 s before trapping so other threads can flush, and its timeout printfs already carry rank/thread/status detail (e.g. dispatch.cuh:140, comm.cuh:122). What legacy/ is missing is exactly that: the source line and the reason, which is what this patch adds.

Relationship to #480 and #539

#480 reports that critical timeout logs go missing. #539 adds a delay before trap() so other warps can flush their printf buffers.

This change is complementary and non-overlapping: #539 keeps messages from being lost; this one makes the message that does survive say where it came from and why it is fatal. Different files (utils.cuh/configs.cuh vs internode_ll.cu), and #539 changes trap()'s behaviour while this is diagnostics-only. Both are needed — with #539 alone a flushed message still carries no line number, and with this alone the message can still be lost before it reaches the host.

… log

CUDA 719 (CUDA_ERROR_LAUNCH_FAILED) is sticky: once raised on a context, every
later launch on that context reports the same code. The three low-latency
timeout sites here call trap() when mask_buffer_ptr == nullptr, which is the
ORIGIN of the 719 -- but they left no line number behind, so the error got
attributed to whichever library happened to make the next launch-API call.

On a 32-rank EP32 cell the same-second 719 split 25/7 between DeepGEMM's
runtime_utils.hpp:143 and this file's own launch site. Both are victims;
neither is the cause. (Line numbers quoted from the build under test; the
sites in this file are the barrier, dispatch-receive and combine-receive
timeout branches.)

This commit changes diagnostics only, not behaviour. Each of the three sites
(barrier / dispatch-receive / combine-receive) now also prints:
  - the resolved source line via __LINE__
  - waited vs limit cycles
  - the mask_buffer pointer value
  - an explicit "FATAL-WILL-TRAP(origin of CUDA 719)" vs "masked-survivable"
    marker, selected on the same condition that decides whether trap() fires

The existing "Warning: DeepEP timeout for ..." prefix is preserved verbatim so
downstream log scanners keep matching; a silently blinded scanner would turn a
real timeout into a false PASS, so that property is verified explicitly rather
than assumed.

Verified:
  - nvcc -arch=sm_90 on a real H100: the vararg lists type-check on the device
    path, below-threshold prints nothing, and trap still yields exactly 719
    when armed, so fatal semantics are unchanged.
  - Replayed the real device-printf bytes against a log-scanning regex read
    live out of the harness: 7/7 patched lines match, 3/3 pre-patch lines
    match, no regex regressions.
  - Confirmed against the extracted pinned tree that mask_buffer_ptr and
    enable_shrink are both reachable, i.e. not hardcoded-falsy.

Reachability of the fatal branch is not hypothetical: vLLM builds the
low-latency Buffer without enable_shrink (all2all.py:296-305), buffer.py:42
defaults it to False, so deep_ep.cpp:386 never allocates and mask_buffer_ptr
is nullptr on the path actually run.

Related: deepseek-ai#480 reports that critical timeout logs go missing, and deepseek-ai#539 adds a
delay before trap() so other warps can flush their printf buffers. This change
is complementary and does not overlap: deepseek-ai#539 keeps messages from being lost,
while this one makes the message that does survive identify where it came from
and why it is fatal.

Signed-off-by: Keita Watanabe <keitaw09@gmail.com>
@ds-review-bot

Copy link
Copy Markdown
Collaborator

🤖 ds-review-bot Code Review

v6

The changes only expand existing CUDA timeout diagnostics; control flow and timeout behavior remain unchanged. The added device-printf formats match their argument types.

v4

⚠️ 未完成评审(no_result_file:模型未产出结果文件)

v3

Diagnostics-only change to csrc/kernels/legacy/internode_ll.cu that makes the three low-latency DeepEP timeout sites (barrier, dispatch-receive, combine-receive) self-attributing. Each printf now additionally emits the resolved source line via LINE (as 'internode_ll.cu:%d'), waited vs limit cycles, the mask_buffer pointer value, and an explicit 'FATAL-WILL-TRAP(origin of CUDA 719)' vs 'masked-survivable' marker selected on the same 'mask_buffer_ptr == nullptr' condition that decides whether trap() fires.

Verdict: APPROVE. The change is correct and matches the stated intent, with no issues requiring author action.

What was verified:

  • The existing 'Warning: DeepEP timeout for ...' prefix is preserved verbatim at all three sites, so downstream log scanners keep matching (no false PASS risk from a blinded scanner).
  • The 'if (mask_buffer_ptr == nullptr) trap();' lines are untouched; control flow and fatal semantics are unchanged. This is purely additive diagnostics (+34/-5 in a single file, no new includes, no signature changes).
  • The marker string ('FATAL-WILL-TRAP(origin of CUDA 719)' vs 'masked-survivable') is derived from the exact same predicate ('mask_buffer_ptr == nullptr') that guards trap() a couple of lines below at each site (barrier line 69 vs guard line 71; dispatch line 422 vs guard line 424; combine line 993 vs guard line 995). The log marker therefore can never disagree with actual runtime behaviour.
  • Format specifiers are all sound: wait_recv_cost (uint64_t) and LEGACY_NUM_TIMEOUT_CYCLES (defined as 200000000000ull in compiled.cuh:18) are both explicitly cast to unsigned long long for %llu; mask_buffer_ptr is cast to void* for %p; LINE is an int for %d. No vararg/type mismatch on the device printf path.
  • The combine-receive site passes 'responsible_expert_idx % num_local_experts' as the local_expert_idx argument, matching the pre-existing argument that was already passed there, so no regression.

This is a low-risk, self-contained improvement that materially aids post-mortem attribution of sticky CUDA 719 (CUDA_ERROR_LAUNCH_FAILED) failures. No changes requested.

Files reviewed: 1
Issues found: ❌ Review incomplete — LLM response could not be parsed
Error: [v4] no_result_file:模型未产出结果文件

@dmvevents

Copy link
Copy Markdown

Strong +1 on the framing — "both are victims; neither is the cause" matches what we hit on AWS EFA, and the sticky-719 misattribution is exactly the failure mode that cost us time.

One data point that may be useful, and a scope note: we hit a batch of timeout (dispatch CPU) failures across 384-expert (Kimi-K2 shape, hidden 7168, top-k 8) runs on 2× p5en over EFA. A word-boundary search for 719 / CUDA_ERROR_LAUNCH_FAILED / cudaErrorLaunchFailure across all 17 run logs returned zero — so those particular failures never reached the device trap() at all. They stalled earlier, in the host-side CPU busy-wait in csrc/legacy/buffer.hpp, where the only surviving signal is num_recv_tokens: -1.

So the two sites appear to be independent blind spots on the same investigation path rather than one problem:

  • csrc/kernels/legacy/internode_ll.cu — device trap() → sticky 719, misattributed to the next launch (this PR)
  • csrc/legacy/buffer.hpp:596 and :1105 — host CPU-wait throws, no source line, no elapsed-vs-limit, and no indication of which counter never became ready

:596 is the starker of the two: it throws DeepEP error: CPU recv timeout with no diagnostics whatsoever. :1105 prints counters via printf, but the exception text carries none of it, so under multi-rank log interleaving — or when only the Python traceback survives — the attribution is lost.

I've opened #708 for the host-side half, deliberately mirroring this PR's approach (diagnostics only, existing printf lines and error-string prefixes preserved verbatim so log scanners keep matching, plus an explicit log-scanner regression check). It touches different files, so there should be no conflict with this one.

For what it's worth, our own root cause turned out to be a build-configuration regression on our side, not a DeepEP defect — stock aws-ofi's forced_pcie_copy() probe requires kernel gdrdrv >= 2.5 while our nodes carry 2.4, so the GIN gate failed deterministically and the GPU never published the counts. But the log could not have told us that: recovering it needed source archaeology plus a bisect against a known-good image. Which is precisely your argument, from the other end of the same stack.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

3 participants