[BugFix] capture mixed trace after prefill admission

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）**
 >

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
+   wait for stable Decode activity, submit one native `input_ids` based
-   inject one native `input_ids` based `128K -> 1` request without benchmark
+   `128K -> 1` request, and start `/start_profile` only after the first 8K
-   client startup delay. The 32-step range therefore spans both sides of the
+   chunk enters Prefill. This image blocks other API requests while
-   injection.
+   `/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

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 prefill_before=0
-  local profile_request_pid=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}"
+  prefill_before="$(server_long_prefill_count)"
-  wait "${profile_request_pid}"
+  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}"
 }