From 82b7d91ac0bdfb4c597722b050a36ad8629bba65 Mon Sep 17 00:00:00 2001 From: Zhiyi Hong <2497491955@qq.com> Date: Sun, 2 Aug 2026 00:30:46 +0800 Subject: [PATCH] [BugFix] capture mixed trace after prefill admission --- README.md | 4 +- .../README.md | 9 ++- .../run_timeline_profiling.sh | 80 +++++++++---------- 3 files changed, 46 insertions(+), 47 deletions(-) diff --git a/README.md b/README.md index 5c82256..2357c21 100644 --- a/README.md +++ b/README.md @@ -1,8 +1,8 @@ # sskj — 多平台大模型推理性能基准测试项目 -> **更新（2026-08-02 00:08:00 CST）** +> **更新（2026-08-02 00:35:00 CST）** > -> 修复 DeepSeek-V4-Pro 双机 Pro6000D SGLang Phase 3 混合 Capture 时序。首轮正式 Run 证明当前 SGLang `/start_profile` 请求会阻塞到捕获结束，旧实现因此在 Profile 完成后才发送 128K Prefill，第二份 Trace 未覆盖注入；随后混合背景触发默认 300 秒 Scheduler watchdog，第三段未执行。新实现异步触发 Profile，先捕获 2 个 Decode Step，再通过原生 `/generate` + `input_ids` 立即注入 128K 请求，避免 benchmark 客户端启动延迟；混合背景缩为单波 32 请求，Profiling 专用 watchdog 提升至 1800 秒，并让异常退出自动将 manifest 标记为 `FAILED`。 +> 修复 DeepSeek-V4-Pro 双机 Pro6000D SGLang Phase 3 混合 Capture 时序。两轮失败 Run 证明当前镜像的 `/start_profile` 会阻塞 API 事件循环：Profile 激活后发送的 128K 请求只能在捕获结束后进入 Scheduler，因此异步调用仍无法覆盖注入。最终实现先稳定 Decode 背景，再通过原生 `/generate` + `input_ids` 送入 128K 请求；确认首个 8K Chunk Prefill 已开始后才捕获 32 个 Mixed Step。Control Trace 单独提供纯 Decode 基线，Mixed Trace 捕获真实 Prefill+Decode Treatment。混合背景缩为单波 32 请求，Profiling 专用 watchdog 提升至 1800 秒，异常退出会自动将 manifest 标记为 `FAILED`。 > > **更新（2026-08-01 19:34:34 CST）** > diff --git a/experiments/pro6000/dsv4pro_pro6000d_2node_sglang_timeline_profiling/README.md b/experiments/pro6000/dsv4pro_pro6000d_2node_sglang_timeline_profiling/README.md index 1eb8036..d1be2b9 100644 --- a/experiments/pro6000/dsv4pro_pro6000d_2node_sglang_timeline_profiling/README.md +++ b/experiments/pro6000/dsv4pro_pro6000d_2node_sglang_timeline_profiling/README.md @@ -31,10 +31,11 @@ staging paths. No `source`, Conda activation, or command on Worker is required. 1. `decode_control`: `1K -> 1K`, `C=32`; trigger after Decode becomes active, skip 2 engine steps, then capture 16 steps. 2. `mixed_decode_with_128k_prefill`: active `1K -> 1K`, `C=32` decode; - start `/start_profile` asynchronously, capture 2 pure Decode steps, then - inject one native `input_ids` based `128K -> 1` request without benchmark - client startup delay. The 32-step range therefore spans both sides of the - injection. + wait for stable Decode activity, submit one native `input_ids` based + `128K -> 1` request, and start `/start_profile` only after the first 8K + chunk enters Prefill. This image blocks other API requests while + `/start_profile` is active, so Control provides the pure Decode baseline and + the 32-step mixed range captures the actual Prefill-plus-Decode treatment. 3. `long_prefill`: isolated `128K -> 1`, `C=1`. The service remains under one Nsight process for all three ranges, so it uses diff --git a/experiments/pro6000/dsv4pro_pro6000d_2node_sglang_timeline_profiling/run_timeline_profiling.sh b/experiments/pro6000/dsv4pro_pro6000d_2node_sglang_timeline_profiling/run_timeline_profiling.sh index 2bcb450..de6638a 100644 --- a/experiments/pro6000/dsv4pro_pro6000d_2node_sglang_timeline_profiling/run_timeline_profiling.sh +++ b/experiments/pro6000/dsv4pro_pro6000d_2node_sglang_timeline_profiling/run_timeline_profiling.sh @@ -365,11 +365,6 @@ profile_done_count() { | grep -c 'Profiling done' || true } -profile_started_count() { - run_on_node "${HEAD_NODE}" "docker logs '${HEAD_CONTAINER}' 2>&1" \ - | grep -c 'Profiling starts' || true -} - start_profile() { local case_id="$1" local activities_json="$2" @@ -406,23 +401,6 @@ wait_for_profile_stop() { return 1 } -wait_for_profile_start() { - local before="$1" - local profile_request_pid="$2" - local expected=$(( TP_SIZE / NNODES )) - local waited=0 - while (( waited < PROFILE_STOP_WAIT_S )); do - if (( $(profile_started_count) >= before + expected )); then - return 0 - fi - kill -0 "${profile_request_pid}" 2>/dev/null || return 1 - sleep 1 - ((waited+=1)) - done - log "ERROR: profiler did not start within ${PROFILE_STOP_WAIT_S}s" - return 1 -} - server_decode_count() { run_on_node "${HEAD_NODE}" "docker logs '${HEAD_CONTAINER}' 2>&1" \ | grep -c 'Decode batch' || true @@ -450,6 +428,26 @@ wait_for_decode_steps() { return 1 } +server_long_prefill_count() { + run_on_node "${HEAD_NODE}" "docker logs '${HEAD_CONTAINER}' 2>&1" \ + | grep -c 'Prefill batch, #new-seq: 1, #new-token: 8192' || true +} + +wait_for_long_prefill_activity() { + local before="$1" + local injection_pid="$2" + local waited=0 + while (( waited < 180 )); do + if (( $(server_long_prefill_count) > before )); then + return 0 + fi + kill -0 "${injection_pid}" 2>/dev/null || return 1 + sleep 1 + ((waited+=1)) + done + return 1 +} + prepare_bench_command() { local output_file="$1" local isl="$2" @@ -636,8 +634,8 @@ run_mixed_profile() { local before=0 local decode_before=0 local mixed_baseline_before=0 - local profile_started_before=0 - local profile_request_pid=0 + local prefill_before=0 + local injection_pid=0 flush_cache mkdir -p "${background_path}" prepare_bench_command "${background_path}/bench.jsonl" \ @@ -645,11 +643,11 @@ run_mixed_profile() { print_command timeout --signal=TERM --kill-after=30s \ "${PROFILE_TIMEOUT_S}s" "${BENCH_CMD[@]}" > "${background_path}/bench_cmd.txt" if [[ "${DRY_RUN}" == "1" ]]; then - log "[DRY] start decode background, wait for Decode batch, start profile asynchronously, inject native 128K prefill" + log "[DRY] start decode background and wait for stable Decode activity" + log "[DRY] inject native 128K prefill, wait for its first 8K chunk, then start mixed profile" + run_native_injection "${injection_id}" start_profile "${case_id}" '["CUDA_PROFILER"]' \ "${NSYS_MIXED_START_STEP}" "${NSYS_MIXED_STEPS}" - log "[DRY] wait ${MIXED_PRE_INJECTION_DECODE_STEPS} Decode steps before injection" - run_native_injection "${injection_id}" return 0 fi decode_before="$(server_decode_count)" @@ -663,28 +661,28 @@ run_mixed_profile() { log "ERROR: mixed decode background did not enter main benchmark" return 1 } - before="$(profile_done_count)" - profile_started_before="$(profile_started_count)" - start_profile "${case_id}" '["CUDA_PROFILER"]' \ - "${NSYS_MIXED_START_STEP}" "${NSYS_MIXED_STEPS}" & - profile_request_pid=$! - wait_for_profile_start "${profile_started_before}" "${profile_request_pid}" || { - kill "${profile_request_pid}" "${background_pid}" 2>/dev/null || true - wait "${profile_request_pid}" "${background_pid}" 2>/dev/null || true - log "ERROR: mixed profile request did not become active" - return 1 - } mixed_baseline_before="$(server_decode_count)" wait_for_decode_steps "${mixed_baseline_before}" \ "${MIXED_PRE_INJECTION_DECODE_STEPS}" "${background_pid}" || { kill "${background_pid}" 2>/dev/null || true wait "${background_pid}" 2>/dev/null || true - log "ERROR: mixed profile did not capture the pre-injection Decode baseline" + log "ERROR: mixed decode background did not remain stable before injection" return 1 } - run_native_injection "${injection_id}" - wait "${profile_request_pid}" + prefill_before="$(server_long_prefill_count)" + run_native_injection "${injection_id}" & + injection_pid=$! + wait_for_long_prefill_activity "${prefill_before}" "${injection_pid}" || { + kill "${injection_pid}" "${background_pid}" 2>/dev/null || true + wait "${injection_pid}" "${background_pid}" 2>/dev/null || true + log "ERROR: native 128K injection did not enter chunked Prefill" + return 1 + } + before="$(profile_done_count)" + start_profile "${case_id}" '["CUDA_PROFILER"]' \ + "${NSYS_MIXED_START_STEP}" "${NSYS_MIXED_STEPS}" wait_for_profile_stop "${before}" + wait "${injection_pid}" wait "${background_pid}" }