ascend-timeline

name	ascend-timeline
description	Pull and analyze inference timelines on Ascend with lmdeploy+dlinfer. Covers profiling script templates, delay selection, raw timeline handling, fixed-real-batch decode/KV-context audit, and analysis reporting.

Ascend Timeline: Pulling and Analysis

---

Analysis Goals

Key questions to answer from a timeline:

• Device bubbles: idle gaps between kernels on the NPU, caused by slow CPU kernel dispatch or CPU-device synchronization. On Ascend, the sync inside update_step_context is unavoidable and is the primary suspect.
• High-cost device operators and communication: find the most expensive device-side events by duration, covering both compute kernels and communication. Typical names include GroupedMatmul (MoE), MatMulV2 / aclnnMatmul (attention/projection), FusedInferAttentionScore, model-specific custom kernels, and communication/wait events such as HcclAllReduce, EVENT_WAIT, and MEM_WAIT_VALUE.
• Prefill vs decode: prefill runs in eager mode (compute-intensive, no bubbles); decode uses graph mode (focus on graph replay cycle).
• update_step_context ratio: if this function's CPU time exceeds 5% of the device graph execution time, it needs attention. Under MTP each head has its own graph, making this ratio more sensitive.

---

Required Deliverables

Every run should produce:

1. The original timeline JSON files generated by lmdeploy profiling, without deleting or rewriting them.
2. The stdout/stderr log used to choose the profiling window and diagnose runtime issues.
3. A concise analysis report covering:
   • profiling window and scenario parameters
   • which raw timeline file(s) were analyzed
   • device bubbles and likely causes
   • update_step_context / NOTIFY_WAIT overhead
   • top compute kernels by device time
   • compute-stream kernel composition and percentages, excluding wait/sync and CPU/dequeue/enqueue events
   • top communication/wait events by device time
   • communication kernel / communication-wait percentages, including explicit HCCL kernels and stream waits around communication
   • for a requested fixed-batch decode trace: qualified replay count, observed real batch size, and KV-context min/max/mean range
   • caveats, missing data, or rank/file anomalies

Do not include hard-coded model benchmark numbers in this skill. If performance numbers are needed, derive them from the current run and report them as run-specific results.

---

Environment Variables

export LMDEPLOY_PROFILE_CPU=1          # enable CPU profiling
export LMDEPLOY_PROFILE_CUDA=1         # enable NPU profiling (routes to torch_npu.profiler on Ascend)
export LMDEPLOY_PROFILE_DELAY=<secs>   # wait N seconds from first request before starting profiling
export LMDEPLOY_PROFILE_DURATION=1     # profiling duration (1s is sufficient for analysis)
export LMDEPLOY_PROFILE_OUT_PREFIX=<path_prefix>  # output filename prefix; rank appended automatically
export LMDEPLOY_AUDIT_DECODE_BATCH_SIZE=1  # emit real scheduler batch marker in each qualified replay
export LMDEPLOY_AUDIT_KV_CONTEXT=1         # emit KV-context min/max/mean marker in the same replay
# Optional fail-fast contract for every graph replay reached by the run:
export LMDEPLOY_ASSERT_DECODE_BATCH_SIZE=<target_bs>

Choosing LMDEPLOY_PROFILE_DELAY

Do not hard-code delay seconds in the skill or scripts without a local test.

From ../lmdeploy/lmdeploy/pytorch/engine/model_agent/profiler.py, AgentProfiler.profile_task() waits LMDEPLOY_PROFILE_DELAY seconds with asyncio.sleep(self.delay), then starts the PyTorch profiler, then waits LMDEPLOY_PROFILE_DURATION seconds before dumping. ../lmdeploy/docs/*/advance/pytorch_profiling.md documents the same behavior with an example delay, not a scenario-specific rule.

Practical method:

1. Run the scenario once without profiling, or with a short harmless profiling window, and keep the script's timestamps:
   • warmup done time
   • per-round start/end time
   • total completion time
2. Pick LMDEPLOY_PROFILE_DELAY so [delay, delay + duration] lands inside the phase you want:
   • prefill: after warmup/graph compilation effects, inside repeated short prefill test rounds
   • decode: after warmup prefill and graph capture, inside a stable decode round
   • MTP: inside a stable decode round after all MTP graph captures are complete
3. Verify the generated trace contains the expected phase. If the trace starts too early or misses active decode, adjust delay and rerun.

Phase validation is mandatory:

• A prefill timeline must contain at least one complete CPU-side forward_eager event. It may also contain decode/graph events; that does not invalidate it as long as the complete prefill event is present.
• A decode timeline must contain at least one complete CPU-side forward_cudagraph event. It may also contain prefill/eager events; that does not invalidate it as long as the complete decode graph event is present.
• A timeline whose target marker is missing is invalid for that target phase:
  • prefill requested but no forward_eager → rerun with a corrected LMDEPLOY_PROFILE_DELAY
  • decode requested but no forward_cudagraph → rerun with a corrected LMDEPLOY_PROFILE_DELAY
• Mixed windows are acceptable for phase validation, but when reporting target-phase percentages, either explicitly slice to the target phase or state that the full-window percentages include mixed-phase work.
• Do not infer decode only from batch_size > 1, output length, or device kernels. Use the CPU phase markers above to validate the captured window.
• forward_cudagraph proves graph-phase activity only. It does not prove the scheduler supplied the requested real batch, because graph replay/capture can be padded or can be warmup work. Use the fixed-batch audit below when that distinction matters.

Historical values from one machine should not be copied into new runs. Model, batch size, graph capture time, Ray startup, CANN parsing, and local patches can all change the correct value.

---

Profiling Script Template

Must use lmdeploy.pipeline API. Using Engine + threaded stream_infer directly causes hangs due to END_SESSION / ADD_SESSION race conditions in the session management layer.

# profile_bench.py
import argparse, time, lmdeploy
from lmdeploy import PytorchEngineConfig, GenerationConfig


def make_prompt(input_len):
    base = "Tell me a very long and detailed story about artificial intelligence. " * 40
    return base[:input_len * 4]  # rough: 1 token ≈ 4 chars


def main():
    parser = argparse.ArgumentParser()
    parser.add_argument('--batch_size', type=int, default=1)
    parser.add_argument('--input_len', type=int, default=1024)
    parser.add_argument('--output_len', type=int, default=1)
    parser.add_argument('--total_rounds', type=int, default=100)
    parser.add_argument('--max_batch_size', type=int, default=None)
    parser.add_argument('--speculative_method', type=str, default=None)
    parser.add_argument('--num_speculative_tokens', type=int, default=0)
    parser.add_argument('--model_path', type=str, default='/path/to/model')
    args = parser.parse_args()

    max_bs = args.max_batch_size or args.batch_size
    spec = None
    if args.speculative_method and args.num_speculative_tokens > 0:
        from lmdeploy.messages import SpeculativeConfig
        spec = SpeculativeConfig(
            method=args.speculative_method,
            num_speculative_tokens=args.num_speculative_tokens)

    pipe = lmdeploy.pipeline(
        args.model_path,
        backend_config=PytorchEngineConfig(
            tp=2, block_size=128, device_type="ascend",
            max_batch_size=max_bs, eager_mode=False,
        ),
        speculative_config=spec,
        trust_remote_code=True,
    )

    gen_cfg = GenerationConfig(max_new_tokens=args.output_len, ignore_eos=True)
    prompts = [make_prompt(args.input_len)] * args.batch_size

    # 1 warmup round (triggers graph compilation)
    t0 = time.perf_counter()
    pipe(prompts, gen_config=gen_cfg)
    print(f"[t={time.perf_counter()-t0:.1f}s] Warmup done", flush=True)

    # test rounds
    for r in range(args.total_rounds):
        t1 = time.perf_counter()
        pipe(prompts, gen_config=gen_cfg)
        t2 = time.perf_counter()
        print(
            f"[t={t1-t0:.1f}-{t2-t0:.1f}s] "
            f"round {r+1}/{args.total_rounds}: {t2-t1:.3f}s",
            flush=True)

    print(f"[t={time.perf_counter()-t0:.1f}s] All done", flush=True)


if __name__ == '__main__':
    main()

---

Scenario Parameters

Choose scenario parameters from the user's requested workload. The skill should not prescribe benchmark cases as fixed performance references.

Record these fields in the run log and final analysis:

Field	Meaning
scenario name	user-defined case name, such as prefill, decode, MTP, or another workload
batch_size	request batch size
input_len	approximate prompt length used for the run
output_len	max generated tokens
total_rounds	number of measured rounds after warmup
max_batch_size	backend max batch size
target_decode_batch_size	requested real scheduler batch for the selected replay window; distinct from max_batch_size
delay	measured LMDEPLOY_PROFILE_DELAY
duration	LMDEPLOY_PROFILE_DURATION

Design rationale:

• output_len=500 gives a long enough decode round that the measured profiling window [delay, delay+duration] can land inside active decode. Recompute this for the local model and batch size from the dry-run timings.
• For short prefill-style runs, use enough total_rounds to provide repeated target-phase work after warmup. Confirm the chosen window is inside those test rounds from stdout timestamps.
• If changing duration, revalidate both the output size expectation and whether the full window remains inside the target phase.

Shell Script Template

#!/bin/bash
export PYTHONPATH=/path/to/lmdeploy:/path/to/dlinfer:$PYTHONPATH
export HCCL_OP_EXPANSION_MODE="AI_CPU"
export CPLUS_INCLUDE_PATH=/usr/local/python3.11.14/include/python3.11:$CPLUS_INCLUDE_PATH

export LMDEPLOY_PROFILE_CPU=1
export LMDEPLOY_PROFILE_CUDA=1
export LMDEPLOY_PROFILE_DELAY=<measured_secs>
export LMDEPLOY_PROFILE_DURATION=1
export LMDEPLOY_PROFILE_OUT_PREFIX=/path/to/timeline/<case>_
export LMDEPLOY_AUDIT_DECODE_BATCH_SIZE=1
export LMDEPLOY_AUDIT_KV_CONTEXT=1
# Export LMDEPLOY_ASSERT_DECODE_BATCH_SIZE=<BS> only when every reached replay
# must fail fast if it is not exactly <BS>.

mkdir -p /path/to/timeline

python3 profile_bench.py \
    --batch_size <BS> \
    --input_len 128 \
    --output_len 500 \
    --total_rounds 1 \
    --max_batch_size <MAX_BS> \
    [--speculative_method <METHOD> --num_speculative_tokens <N>] \
    2>&1 | tee /path/to/timeline/<case>.log

echo "=== Done ==="

---

Fixed Real-Batch Decode and KV-Context Audit

Use this procedure whenever the conclusion is “the captured decode replay ran at batch size B”. Here real batch means the number of scheduler-valid sequences entering the replay before graph padding. max_batch_size, captured graph size, submitted request count, and forward_cudagraph count are not proof of that value.

Required Temporary Source Patch (Do Not Commit)

This audit requires a local source patch; setting the three audit environment variables alone does not create the CPU markers. Apply the exact patches below immediately before a fixed-B run, and reverse the same patches immediately after the raw trace and log have been retained. They are diagnostic instrumentation, not product changes, and must not be committed or included in unrelated changes.

Before applying, every target path must be clean. This prevents the final reverse patch from discarding another local change:

DLINFER_DIR=/path/to/dlinfer
LMDEPLOY_DIR=/path/to/lmdeploy

git -C "$DLINFER_DIR" diff --exit-code -- \
    dlinfer/framework/lmdeploy_ext/cudagraph/ascend_cudagraph.py
git -C "$LMDEPLOY_DIR" diff --exit-code -- \
    lmdeploy/pytorch/engine/inputs_maker.py \
    lmdeploy/pytorch/model_inputs.py \
    lmdeploy/pytorch/strategies/ar/model_inputs.py \
    lmdeploy/pytorch/strategies/ar_spec/step_inputs.py

Apply the zero-context unified diffs below from their indicated repository root. First check them with git apply --unidiff-zero --check, then apply the same content with git apply --unidiff-zero (or make the identical change with apply_patch). Zero-context application is intentional: it keeps the patch embedded in this Markdown free of whitespace-only diff lines. The clean preflight above is mandatory before this less-forgiving patch form is used.

If a location no longer matches, do not force or fuzz-apply it: inspect the current clean revision, regenerate the intended minimal patch, and update this skill before profiling.

Patch A — run from the dlinfer repository root:

diff --git a/dlinfer/framework/lmdeploy_ext/cudagraph/ascend_cudagraph.py b/dlinfer/framework/lmdeploy_ext/cudagraph/ascend_cudagraph.py
index a16d2a50..90841015 100644
--- a/dlinfer/framework/lmdeploy_ext/cudagraph/ascend_cudagraph.py
+++ b/dlinfer/framework/lmdeploy_ext/cudagraph/ascend_cudagraph.py
@@ -3,0 +4,2 @@ import functools
+from contextlib import ExitStack, nullcontext
+from os import getenv
@@ -6 +7,0 @@ from dataclasses import dataclass
-from contextlib import ExitStack
@@ -399,7 +400,21 @@ class AscendSingleGraphRunner:
-        self.model.update_context_cudagraph(self.meta, context)
-        if aclgraph_use_torch_npu_update():
-            self._graph.replay()
-            self._graph.update(
-                cpu_update_input=[
-                    {"actual_seq_lengths_kv": self.meta.input_buffers["kv_seqlens"]}
-                ]
+        actual_batch_size = len(context.q_seqlens)
+        expected_batch_size = getenv("LMDEPLOY_ASSERT_DECODE_BATCH_SIZE")
+        if expected_batch_size is not None and actual_batch_size != int(expected_batch_size):
+            raise RuntimeError(
+                "Decode batch-size audit failed in Ascend graph replay: "
+                f"expected {expected_batch_size}, got {actual_batch_size}"
+            )
+        audit_scope = nullcontext()
+        if (getenv("LMDEPLOY_AUDIT_DECODE_BATCH_SIZE") is not None
+                and context.min_kv_seqlen is not None):
+            # This scope is inside the rank worker and nested in the matching
+            # forward_cudagraph event. q_seqlens exists before graph padding.
+            audit_scope = record_function(f"decode_actual_batch_size={actual_batch_size}")
+        kv_audit_scope = nullcontext()
+        if (getenv("LMDEPLOY_AUDIT_KV_CONTEXT") is not None
+                and context.min_kv_seqlen is not None):
+            kv_audit_scope = record_function(
+                "decode_kv_context_"
+                f"min={context.min_kv_seqlen},"
+                f"max={context.max_kv_seqlen},"
+                f"mean={context.sum_kv_seqlen / actual_batch_size:g}"
@@ -407,6 +422,15 @@ class AscendSingleGraphRunner:
-        else:
-            update_attn_params(self.update_stream, self.meta, self.max_batches)
-            self._graph.replay()
-        output_buffers = self.meta.output_buffers
-        output = self.model.get_outputs_cudagraph(output_buffers, **kwargs)
-        return output
+        with audit_scope, kv_audit_scope:
+            self.model.update_context_cudagraph(self.meta, context)
+            if aclgraph_use_torch_npu_update():
+                self._graph.replay()
+                self._graph.update(
+                    cpu_update_input=[
+                        {"actual_seq_lengths_kv": self.meta.input_buffers["kv_seqlens"]}
+                    ]
+                )
+            else:
+                update_attn_params(self.update_stream, self.meta, self.max_batches)
+                self._graph.replay()
+            output_buffers = self.meta.output_buffers
+            output = self.model.get_outputs_cudagraph(output_buffers, **kwargs)
+            return output

Patch B — run from the lmdeploy repository root:

diff --git a/lmdeploy/pytorch/engine/inputs_maker.py b/lmdeploy/pytorch/engine/inputs_maker.py
index 76a75ae0..da60b279 100644
--- a/lmdeploy/pytorch/engine/inputs_maker.py
+++ b/lmdeploy/pytorch/engine/inputs_maker.py
@@ -702,0 +703 @@ class InputsMakerAsync:
+        min_kv_seqlen = min(kv_seqlens)
@@ -712,0 +714 @@ class InputsMakerAsync:
+            min_kv_seqlen=min_kv_seqlen,
diff --git a/lmdeploy/pytorch/model_inputs.py b/lmdeploy/pytorch/model_inputs.py
index 760e84be..0f0dd047 100644
--- a/lmdeploy/pytorch/model_inputs.py
+++ b/lmdeploy/pytorch/model_inputs.py
@@ -141,0 +142 @@ class ModelInputsDelta:
+    min_kv_seqlen: int | None = None
@@ -218,0 +220,3 @@ class ModelInputs:
+    # CPU scalar retained for timeline auditing; None for inputs that do not
+    # originate from a scheduler decode delta.
+    min_kv_seqlen: int | None = None
@@ -238,0 +243 @@ class ModelInputs:
+            min_kv_seqlen=(None if self.min_kv_seqlen is None else self.min_kv_seqlen + self.max_q_seqlen),
@@ -302,0 +308 @@ class StepContext:
+    min_kv_seqlen: int | None = None
@@ -382,0 +389 @@ class StepContext:
+            min_kv_seqlen=inputs.min_kv_seqlen,
diff --git a/lmdeploy/pytorch/strategies/ar/model_inputs.py b/lmdeploy/pytorch/strategies/ar/model_inputs.py
index bc475453..b449f9d6 100644
--- a/lmdeploy/pytorch/strategies/ar/model_inputs.py
+++ b/lmdeploy/pytorch/strategies/ar/model_inputs.py
@@ -36,0 +37 @@ def get_model_inputs_next_decoding(inputs: ModelInputs, input_ids: torch.Tensor,
+        min_kv_seqlen=(None if inputs.min_kv_seqlen is None else inputs.min_kv_seqlen + max_q_seqlen),
@@ -100,0 +102,2 @@ def merge_model_inputs(inputs: ModelInputs, other: ModelInputs) -> ModelInputs:
+        min_kv_seqlen=(None if inputs.min_kv_seqlen is None or other.min_kv_seqlen is None
+                        else min(inputs.min_kv_seqlen, other.min_kv_seqlen)),
@@ -133,0 +137 @@ def index_select_model_inputs(inputs: ModelInputs,
+                              min_kv_seqlen: int | None = None,
@@ -155,0 +160 @@ def index_select_model_inputs(inputs: ModelInputs,
+    min_kv_seqlen = min_kv_seqlen or inputs.min_kv_seqlen
@@ -195,0 +201 @@ def index_select_model_inputs(inputs: ModelInputs,
+        min_kv_seqlen=min_kv_seqlen,
diff --git a/lmdeploy/pytorch/strategies/ar_spec/step_inputs.py b/lmdeploy/pytorch/strategies/ar_spec/step_inputs.py
index 5a6a2ca8..2fc74baa 100644
--- a/lmdeploy/pytorch/strategies/ar_spec/step_inputs.py
+++ b/lmdeploy/pytorch/strategies/ar_spec/step_inputs.py
@@ -42,0 +43 @@ def _reindex_model_inputs_arspec(
+    min_kv_seqlen = delta.min_kv_seqlen
@@ -58,0 +60 @@ def _reindex_model_inputs_arspec(
+    min_kv_seqlen = min_kv_seqlen or inputs.min_kv_seqlen
@@ -90,0 +93 @@ def _reindex_model_inputs_arspec(
+        min_kv_seqlen=min_kv_seqlen,

The lmdeploy portion preserves min_kv_seqlen as a CPU scalar from scheduler input creation, through ModelInputs and StepContext, including the AR and AR-spec transform paths. This is deliberately not replaced by .item() on an NPU tensor during replay.

For restoration, use these same exact Patch A and Patch B contents with git apply --unidiff-zero -R --check followed by git apply --unidiff-zero -R, from their respective repository roots. Do not use git restore, git checkout --, or a broad reverse of the current working tree. After the reverse patches, rerun the two clean checks above; only the preserved timeline/log artifacts and the skill itself should remain changed.

1. With the temporary patch active, instrument the actual Ascend replay path, dlinfer/framework/lmdeploy_ext/cudagraph/ascend_cudagraph.py:AscendSingleGraphRunner.forward, rather than a CUDA-only runner. The record_function scopes are inside the enclosing forward_cudagraph scope and cover context update/replay.
2. Emit these CPU markers only for scheduler-derived decode contexts (not graph-capture warmup):
   • decode_actual_batch_size=<B>, where B = len(context.q_seqlens) before padding.
   • decode_kv_context_min=<N>,max=<N>,mean=<N>, using scalar statistics from the scheduler's valid sequences.
3. Carry min_kv_seqlen, max_kv_seqlen, and sum_kv_seqlen from scheduler input construction through ModelInputs / StepContext. Do not calculate them by calling .item() on an NPU KV-length tensor in the replay path; that adds a synchronization and changes the timeline being measured.
4. Enable both audit environment variables above, then preserve the untouched rank JSON files and the run log. Use LMDEPLOY_ASSERT_DECODE_BATCH_SIZE=<B> only for a fail-fast whole-run contract; it intentionally fails once the scheduler later reaches a non-B replay.

Qualify a replay only when all of the following are true in the same rank trace:

• the decode_actual_batch_size=<B> and decode_kv_context_* intervals are both nested in one complete forward_cudagraph interval (same process/thread and timestamp containment);
• every selected batch marker equals the requested B; and
• the marker pair is one-to-one with the selected replay intervals.

Treat a bare forward_cudagraph, or a replay with only one audit marker, as graph warmup/unqualified work and exclude it from the fixed-B summary. Scan every qualified marker, not a single screenshot. Report the qualified replay count, exact B, each marker's KV min/max/mean or their observed ranges, rank agreement, and the selected trace interval. State explicitly that this proves the qualified captured window, not the entire request lifetime, unless the fail-fast assertion covered the complete run. The first qualified marker need not be the first decode token if profiling began later.

---

Running Multiple Scenarios (HCCL Port Conflict)

After each scenario, Ray workers hold HCCL ports for ~45 seconds. Running the next scenario too soon gives:

Communication_Error_Bind_IP_Port(EJ0003): Failed to bind the IP port.
The IP address and port have been bound already.

Solution: wrap each scenario with explicit Ray process cleanup:

# run_scenario.sh
#!/bin/bash
SCRIPT=$1
LOG=$2

# Kill leftover Ray/HCCL processes
kill -9 $(ps aux | grep -E "profile_bench|ray::|RayWorker|gcs_server|raylet" 2>/dev/null \
    | grep -v grep | grep -v defunct | awk '{print $2}') 2>/dev/null
sleep 45  # wait for port release

bash "$SCRIPT" >> "$LOG" 2>&1

Run scenarios serially when collecting multiple timelines:

bash run_scenario.sh run_profile_<case1>.sh timeline/<case1>_stdout.log
bash run_scenario.sh run_profile_<case2>.sh timeline/<case2>_stdout.log
bash run_scenario.sh run_profile_<case3>.sh timeline/<case3>_stdout.log

---

Timeline File Handling

Naming

<PREFIX><rank>.json, rank=0 is NPU 0, rank=1 is NPU 1.

Preserve Raw Files

Keep every raw timeline file produced by the profiler. Do not delete rank files as part of the skill workflow; the user needs the original timeline files.

When a rank file is incomplete or anomalous, record that in the analysis report and choose the most complete file for analysis. Prefer files that contain both CPU and device-side kernel events over files that contain only CPU metadata.

Common anomaly patterns:

• very small file: often CPU metadata only, no useful device-side kernel data
• unexpectedly huge file: profiler may have continued capturing after the requested duration
• missing rank: worker exited before dump or failed during profiler stop/export

File size is only a sanity check. Always inspect whether the trace contains the expected time window and device streams before deciding which file to analyze.

Apply the phase validation rules above to every rank. If the marker check fails, keep the raw file but exclude it from the target scenario's analysis and pull a replacement timeline.

Viewers

Chrome Trace JSON format.

• Perfetto UI — handles files >300MB, recommended
• chrome://tracing — works for files <200MB

---

Key Event Types

Event	Layer	Meaning
MatMul*	device	standard matmul (attention QK/AV)
GroupedMatmul*	device	MoE expert matmul
FusedInferAttentionScore	device	fused attention
MoeInitRouting*	device	MoE routing (gate + topk)
AddRmsNorm	device	fused Add+RMSNorm
Concat*	device	device concat / layout assembly kernel; if it dominates compute streams, report it explicitly
model-specific custom kernels	device	custom attention, convolution, routing, or fused model kernels
Hccl*	device	TP AllReduce
allreduceAicpuKernel, broadcastAicpuKernel	device/AI CPU	communication helper kernels; include in communication analysis
forward_eager	CPU	eager forward path, normally prefill
forward_cudagraph	CPU	graph replay forward path, required marker for decode timelines
decode_actual_batch_size=<B>	CPU audit	scheduler-derived, pre-padding real decode batch; use only when nested in forward_cudagraph
decode_kv_context_min=<N>,max=<N>,mean=<N>	CPU audit	KV context statistics for the same qualified replay
aten::*, cpu_op	CPU	PyTorch CPU-side ops
Dequeue@aclnn*	CPU+device	CANN op dequeue (visible in eager prefill)

---

Analysis Methods

1. Identifying Device Bubbles

Look for blank stretches in the NPU stream timeline rows.

Diagnosing source:

• Long NOTIFY_WAIT before a gap → update_step_context sync (CPU reading kv_seqlens etc.)
• EVENT_WAIT inside a gap → waiting for AllReduce to complete
• Scattered gaps inside graph replay → CPU kernel dispatch can't keep up

Prefill (eager mode) should have no bubbles.

2. Measuring update_step_context Overhead

One decode step:

[CAPTURE_RECORD burst: graph replay kernels]
         ↓
[NOTIFY_WAIT: CPU waits for NPU (= update_step_context sync cost)]
         ↓
[CPU computes next-step params (kv_seqlens, block_offsets...)]
         ↓
[next CAPTURE_RECORD burst]

Measure NOTIFY_WAIT duration vs CAPTURE_RECORD burst duration:

Ratio	Assessment
< 5%	excellent — high device utilization
5%–25%	acceptable
> 25%	needs attention — consider reducing sync points

Report the measured values from the current timeline only. Do not carry over historical ratios or timing tables from other models or machines.

3. MTP Analysis

Under MTP, each step contains multiple graph replay bursts:

[main model graph replay]
[mtp_head_0 graph replay]
[mtp_head_1 graph replay]
[verification sync]

Key metrics:

• MEM_WAIT_VALUE frequency and duration (MTP state sync between heads)
• NOTIFY_WAIT / graph duration ratio per head (more sensitive than main model)
• aclnnMatmul duration (draft model attention)

Report only the MTP timing and synchronization behavior visible in the current timeline. Do not include generic throughput-gain tables in this skill.

4. Finding Expensive Device Operators and Communication

Sort device-side events by total duration in Perfetto. Do this for both compute kernels and communication/wait events; a communication bottleneck can appear either as an explicit HCCL op or as stream wait time around it.

Report at least:

1. Top device events by sum(duration), grouped by name
2. Top device events by max(duration), to catch rare long stalls
3. Communication/wait subset: Hccl*, EVENT_WAIT, MEM_WAIT_VALUE, NOTIFY_WAIT, DMA/SDMA rows
4. Compute subset: matmul/attention/MoE/normalization/linear-attention kernels
5. Per-stream compute kernel composition: for the busiest compute streams, list top kernels by sum duration and percent of that stream's compute time
6. Communication kernel percentage: explicit communication kernels and helper kernels as a percent of device compute time, and communication waits as a percent of all device-side duration

Common expensive compute kernels:

• GroupedMatmul: MoE compute, scales with active tokens and expert routing
• MatMulV2 / aclnnMatmul: attention and projection matmuls; under MTP, watch draft-head proportion
• FusedInferAttentionScore: fused attention, grows with KV cache length
• ConcatD: device concat / layout assembly. If it appears near the top, report its stream-level percentage; it can dominate actual compute even when matmul kernels are small.
• model-specific custom kernels: custom attention, convolution, routing, or fused model kernels when they enter the top-duration list
• MoeInitRoutingV3, AddRmsNorm, and other fused elementwise kernels when they enter the top-duration list

Common communication/wait events:

• HcclAllreduce / HcclAllReduce: TP communication; check whether it overlaps with compute or serializes the step
• allreduceAicpuKernel / broadcastAicpuKernel: communication helper kernels. Count these in explicit communication kernel time, not generic model compute.
• EVENT_WAIT: stream waits, often around communication completion
• MEM_WAIT_VALUE: MTP/head synchronization or device-side state waits
• NOTIFY_WAIT: CPU-device synchronization, especially update_step_context
• SDMA_SQE: DMA transfers such as HostToDevice metadata movement

When summarizing, separate "top compute" and "top communication/wait" even if one category has lower absolute time. The goal is to avoid missing communication overhead hidden below dominant matmuls.

5. Compute Stream Kernel Composition

When the user asks what is really running on device compute streams, do not answer only with total device events or wait events. Produce a compute-only view:

1. Exclude CPU-side events: cpu_op, aten::*, Dequeue@*, and Enqueue@*.
2. Exclude wait/sync/data-movement events from the compute-only denominator: *_WAIT, NOTIFY_*, EVENT_*, CAPTURE_*, SDMA_*, and WRITE_VALUE_*.
3. Keep device kernel/task rows such as KERNEL_AICORE, KERNEL_AIVEC, KERNEL_MIX_AIC, KERNEL_MIX_AIV, AI_CORE, AI_CPU, and named kernels including ConcatD, GroupedMatmul, MatMulV2, FusedInferAttentionScore, MoeInitRoutingV3, RmsNorm, AddRmsNorm, convolution, softmax, routing, and model-specific custom kernels.
4. Group by physical stream id (args["Physic Stream Id"] when available; otherwise tid) and report:
   • total compute time per stream and percent of total compute time
   • top kernels on each busiest stream by sum(duration), max(duration), and count
   • kernel-family totals and percentages, e.g. ConcatD, GroupedMatmul, MatMul, Attention, RmsNorm, Convolution, MoeInitRouting, and model-specific kernels

This view is different from bubble analysis. A model can be dominated by waits overall but still have a clear compute-stream bottleneck such as ConcatD; report both facts separately.

6. Communication Kernel Percentage

Communication analysis should include two denominators because explicit communication kernels and stream waits answer different questions:

1. Explicit communication kernel percentage over compute/device-kernel time:
   • Include Hccl*, allreduceAicpuKernel, broadcastAicpuKernel, and other collective helper kernels.
   • Report sum(duration), max(duration), count, and percent of compute-only device time.
2. Communication/wait pressure over all device-side duration:
   • Include EVENT_WAIT, MEM_WAIT_VALUE, and communication-adjacent stream waits.
   • Keep NOTIFY_WAIT separate when it is an update_step_context sync rather than collective communication.
   • Include SDMA_SQE / DMA rows separately from collectives.
   • Report these waits as percent of all device-side duration, not as compute kernels.

Always label which denominator is used. Do not mix Dequeue@Hccl* CPU/dequeue time into device communication kernel time unless the user explicitly asks for enqueue/dequeue overhead.

---

Known Issues

Rank File Anomalies

Symptoms: a rank file may be unexpectedly large, unexpectedly small, or missing device events.
Cause: npu_profile may fail to stop correctly at duration boundary — either continues capturing after stop() is called (async stop + background parsing), or records almost nothing.
Fix: preserve every raw file, record the anomaly in the analysis report, and analyze the rank file that contains the most complete CPU and device event data.

Profiling Stop Can Stall an Active Round

Symptom: the round active when profiling stops can be much slower than nearby rounds.
Cause: dump() calls npu_profile.stop() which can block the async event loop while CANN parses profiling data. Any request round in flight at that moment is frozen until parsing completes.
Workaround: do not treat the profiler-stop-affected round as workload performance. Use the timeline events and unaffected round logs for analysis.

HCCL port conflict between scenarios

Symptom: second scenario fails with hcclCommInitRootInfoConfig error code 7: Failed to bind the IP port.
Cause: Ray workers hold HCCL ports for ~45 seconds after scenario exit.
Fix: use run_scenario.sh wrapper (kills all Ray processes + sleeps 45s before each run).

---

Checklist

□ Set HCCL_OP_EXPANSION_MODE="AI_CPU"
□ Verify pipeline works without profiling (5 rounds, stable timing)
□ Dry-run the scenario and choose LMDEPLOY_PROFILE_DELAY from measured timestamps
□ Set LMDEPLOY_PROFILE_* env vars (measured DELAY; DURATION=1 unless a longer local window is needed)
□ Use run_scenario.sh wrapper (kills Ray processes, 45s wait between scenarios)
□ output_len long enough that profiling window falls inside test round
□ After run: preserve all raw timeline JSON files and stdout/stderr logs
□ Check each rank file for CPU events, device streams, expected time window, and anomalies
□ Before a fixed-B audit: verify the five target paths are clean, then check and apply Patch A and Patch B
□ For a fixed-B decode claim: enable both audit markers and verify their nesting in the same `forward_cudagraph`
□ Exclude bare/warmup graph events; scan every qualified marker and require every observed real batch to equal the target
□ Report qualified replay count plus KV-context min/max/mean values or ranges, separately for each rank
□ State whether the result covers only the captured qualified window or the full run (fail-fast assertion)
□ After retaining the trace/log: reverse the exact two patches and rerun the clean checks; do not use broad Git restore commands
□ Open in Perfetto UI (>200MB) or chrome://tracing
□ Focus on: NOTIFY_WAIT ratio, device idle gaps, top compute kernels, top communication/wait events
□ For compute questions: exclude wait/sync and CPU/dequeue/enqueue rows; report compute-stream kernel families and percentages
□ For communication questions: report explicit communication kernel percentage and communication/wait pressure with clearly labeled denominators
□ Return the raw timeline file paths plus the analysis report