| 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:
- The original timeline JSON files generated by lmdeploy profiling, without deleting or rewriting them.
- The stdout/stderr log used to choose the profiling window and diagnose runtime issues.
- 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
export LMDEPLOY_PROFILE_CUDA=1
export LMDEPLOY_PROFILE_DELAY=<secs>
export LMDEPLOY_PROFILE_DURATION=1
export LMDEPLOY_PROFILE_OUT_PREFIX=<path_prefix>
export LMDEPLOY_AUDIT_DECODE_BATCH_SIZE=1
export LMDEPLOY_AUDIT_KV_CONTEXT=1
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:
- 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
- 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
- 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.
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]
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
t0 = time.perf_counter()
pipe(prompts, gen_config=gen_cfg)
print(f"[t={time.perf_counter()-t0:.1f}s] Warmup done", flush=True)
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
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:
@@ -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:
@@ -702,0 +703 @@ class InputsMakerAsync:
+ min_kv_seqlen = min(kv_seqlens)
@@ -712,0 +714 @@ class InputsMakerAsync:
+ min_kv_seqlen=min_kv_seqlen,
@@ -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,
@@ -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,
@@ -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.
- 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.
- 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.
- 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.
- 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:
SCRIPT=$1
LOG=$2
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
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:
- Top device events by sum(duration), grouped by name
- Top device events by max(duration), to catch rare long stalls
- Communication/wait subset:
Hccl*, EVENT_WAIT, MEM_WAIT_VALUE, NOTIFY_WAIT, DMA/SDMA rows
- Compute subset: matmul/attention/MoE/normalization/linear-attention kernels
- Per-stream compute kernel composition: for the busiest compute streams, list top kernels by sum duration and percent of that stream's compute time
- 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 routingMatMulV2 / aclnnMatmul: attention and projection matmuls; under MTP, watch draft-head proportionFusedInferAttentionScore: fused attention, grows with KV cache lengthConcatD: 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 stepallreduceAicpuKernel / broadcastAicpuKernel: communication helper kernels. Count these in explicit communication kernel time, not generic model compute.EVENT_WAIT: stream waits, often around communication completionMEM_WAIT_VALUE: MTP/head synchronization or device-side state waitsNOTIFY_WAIT: CPU-device synchronization, especially update_step_contextSDMA_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:
- Exclude CPU-side events:
cpu_op, aten::*, Dequeue@*, and Enqueue@*.
- Exclude wait/sync/data-movement events from the compute-only denominator:
*_WAIT, NOTIFY_*, EVENT_*, CAPTURE_*, SDMA_*, and WRITE_VALUE_*.
- 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.
- 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:
- 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.
- 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
