Skip to content

Commit 0b1d56e

Browse files
justinchubyCopilot
andcommitted
docs: add profiling-onnx-models skill
Add ONNX model profiling skill covering ORT session profiling, JSON result analysis, bottleneck identification, attention kernel hierarchy, common CUDA performance issues with Gemma4 H200 data, and GenAI pipeline throughput measurement. Co-authored-by: Copilot <223556219+Copilot@users.noreply.github.com> Signed-off-by: Justin Chu <justinchu@microsoft.com>
1 parent 0d8a635 commit 0b1d56e

1 file changed

Lines changed: 297 additions & 0 deletions

File tree

  • .agents/skills/profiling-onnx-models
Lines changed: 297 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,297 @@
1+
---
2+
name: profiling-onnx-models
3+
description: >
4+
Use this skill when profiling ONNX model performance on CUDA with
5+
OnnxRuntime. Covers ORT session profiling, reading JSON results,
6+
identifying compute and memory bottlenecks, debugging memcpy nodes,
7+
and measuring GenAI pipeline throughput (tok/s, TTFT).
8+
---
9+
10+
# Skill: Profiling ONNX Models on CUDA
11+
12+
## When to use
13+
14+
Use this skill when:
15+
- Measuring ONNX model latency on GPU
16+
- Identifying compute vs memory bottlenecks
17+
- Debugging why inference is slower than expected
18+
- Investigating memcpy nodes (CPU↔GPU transfers)
19+
- Measuring GenAI pipeline throughput (tokens/second, TTFT)
20+
- Comparing fused vs unfused attention kernels
21+
22+
## ORT session profiling
23+
24+
### Enable profiling
25+
26+
```python
27+
import onnxruntime as ort
28+
import json
29+
30+
opts = ort.SessionOptions()
31+
opts.enable_profiling = True
32+
33+
sess = ort.InferenceSession(
34+
"model.onnx",
35+
opts,
36+
providers=["CUDAExecutionProvider"],
37+
)
38+
39+
# Run inference (warmup + measured runs)
40+
for _ in range(3): # warmup
41+
sess.run(None, inputs)
42+
43+
for _ in range(10): # measured
44+
sess.run(None, inputs)
45+
46+
# End profiling and get output file
47+
prof_file = sess.end_profiling()
48+
print(f"Profile saved to: {prof_file}")
49+
```
50+
51+
### Profile output format
52+
53+
The profile is a JSON file with an array of trace events:
54+
55+
```json
56+
[
57+
{
58+
"cat": "Node",
59+
"name": "MatMul_42",
60+
"dur": 156,
61+
"args": {
62+
"op_name": "MatMul",
63+
"provider": "CUDAExecutionProvider",
64+
"input_type_shape": [{"float": [1, 128, 4096]}],
65+
"output_type_shape": [{"float": [1, 128, 14336]}]
66+
}
67+
}
68+
]
69+
```
70+
71+
Key fields:
72+
73+
| Field | Description |
74+
|-------|-------------|
75+
| `name` | Node name in the ONNX graph |
76+
| `dur` | Duration in microseconds |
77+
| `cat` | Category — `"Node"` for ops, `"Kernel"` for CUDA kernels |
78+
| `args.op_name` | ONNX op type (MatMul, Attention, etc.) |
79+
| `args.provider` | Execution provider (CUDA vs CPU) |
80+
81+
## Reading profile results
82+
83+
### Parse and analyze by op type
84+
85+
```python
86+
import json
87+
from collections import defaultdict
88+
89+
with open(prof_file) as f:
90+
events = json.load(f)
91+
92+
# Filter to node events only
93+
nodes = [e for e in events if e.get("cat") == "Node"]
94+
95+
# Group by op type
96+
op_times = defaultdict(list)
97+
for n in nodes:
98+
op = n["args"].get("op_name", n["name"])
99+
op_times[op].append(n["dur"])
100+
101+
# Summary: total time per op type, sorted
102+
print(f"{'Op Type':<30} {'Count':>6} {'Total (ms)':>12} {'Avg (µs)':>10}")
103+
print("-" * 62)
104+
for op, times in sorted(op_times.items(), key=lambda x: -sum(x[1])):
105+
total_ms = sum(times) / 1000
106+
avg_us = sum(times) / len(times)
107+
print(f"{op:<30} {len(times):>6} {total_ms:>12.2f} {avg_us:>10.1f}")
108+
```
109+
110+
### Check node placement (CPU vs CUDA)
111+
112+
```python
113+
cpu_nodes = [n for n in nodes
114+
if n["args"].get("provider") == "CPUExecutionProvider"]
115+
cuda_nodes = [n for n in nodes
116+
if n["args"].get("provider") == "CUDAExecutionProvider"]
117+
118+
print(f"CUDA nodes: {len(cuda_nodes)}")
119+
print(f"CPU nodes: {len(cpu_nodes)}")
120+
121+
if cpu_nodes:
122+
print("\nCPU-placed ops (may cause memcpy):")
123+
for n in cpu_nodes:
124+
print(f" {n['args'].get('op_name', '?')}: {n['name']}")
125+
```
126+
127+
### Identify memcpy overhead
128+
129+
```python
130+
memcpy_events = [n for n in nodes
131+
if "Memcpy" in n.get("name", "")]
132+
total_memcpy_us = sum(n["dur"] for n in memcpy_events)
133+
total_compute_us = sum(n["dur"] for n in nodes)
134+
135+
print(f"Memcpy: {total_memcpy_us/1000:.2f} ms "
136+
f"({100*total_memcpy_us/total_compute_us:.1f}% of total)")
137+
```
138+
139+
## Identifying bottlenecks
140+
141+
### Compute-bound ops
142+
143+
| Op | Typical role | What to check |
144+
|----|-------------|---------------|
145+
| `MatMul` / `Gemm` | QKV projections, FFN up/down/gate | Should dominate profile for large models. Verify cuBLAS is used. |
146+
| `Attention` | Self-attention | Check which kernel: Flash, GQA, MEA, or unfused. Fused is 3-7x faster. |
147+
| `com.microsoft.GroupQueryAttention` | Fused GQA | Best for GQA models. Check `head_dim` ≤ 256 for Flash path. |
148+
| `Conv` | Vision encoder, conv layers | Should be on CUDA. CPU fallback is very slow. |
149+
150+
### Memory-bound ops
151+
152+
| Op | Typical role | What to check |
153+
|----|-------------|---------------|
154+
| `MemcpyFromHost` / `MemcpyToHost` | CPU↔GPU transfer | Each one is a sync point. 280+ means serious issue. |
155+
| `Transpose` | Layout conversion | Should be fused into adjacent ops where possible. |
156+
| `Reshape` / `Squeeze` / `Unsqueeze` | Shape manipulation | Zero-copy on CUDA (metadata only). Non-zero time = problem. |
157+
158+
### Attention kernel hierarchy
159+
160+
From fastest to slowest for GQA models:
161+
162+
1. **Flash Attention** (via GQA op) — requires `head_dim` ≤ 256
163+
2. **Memory-Efficient Attention (MEA)** — fallback when Flash unavailable
164+
3. **Unfused Attention** — standard `Attention` op decomposed to MatMul + Softmax + MatMul
165+
166+
**Real example (Gemma4, head_dim=256):**
167+
- GQA with Flash: ~66 µs per decode step
168+
- Unfused attention: ~450 µs (6.8x slower)
169+
170+
## Common CUDA performance issues
171+
172+
### 1. Excessive memcpy nodes (280+)
173+
174+
**Symptom:** Hundreds of `MemcpyFromHost`/`MemcpyToHost` nodes in the
175+
profile, each adding latency and forcing GPU sync.
176+
177+
**Cause:** Ops that don't have a CUDA kernel fall to CPU, requiring
178+
data transfer. Common culprits:
179+
- Opset version mismatch (e.g. opset 24 ops not yet in ORT CUDA EP)
180+
- Dynamic `Shape` + `Gather` patterns
181+
- `ConstantOfShape` with unusual dtypes
182+
183+
**Fix:** See the `debugging-memcpy` skill for root-cause analysis and
184+
fix patterns. The most impactful fix is usually lowering opset version
185+
or replacing unsupported ops with CUDA-friendly alternatives.
186+
187+
### 2. cuBLAS warmup spike
188+
189+
**Symptom:** First decode step is 40-100ms, subsequent steps are
190+
~66 µs.
191+
192+
**Cause:** cuBLAS initializes and JIT-compiles kernels on first use.
193+
This is a one-time cost per session.
194+
195+
**Fix:** Not a bug — this is expected CUDA behavior. Exclude the
196+
first inference call from benchmarks. For latency-sensitive
197+
applications, run a warmup inference before serving.
198+
199+
### 3. head_dim > 256 breaks Flash Attention
200+
201+
**Symptom:** Attention is 3-7x slower than expected. Profile shows
202+
unfused attention ops instead of `GroupQueryAttention` with Flash.
203+
204+
**Cause:** Flash Attention v2 requires `head_dim` ≤ 256. Models with
205+
larger head dimensions (e.g. Gemma4 global attention with
206+
`head_dim=512`) fall back to unfused or MEA attention.
207+
208+
**Fix:** This is a hardware/library limitation. Options:
209+
- Use the `--ep default` (CPU) build which doesn't need Flash
210+
- Wait for Flash Attention v3 / updated ORT with larger head_dim support
211+
- For Gemma4 specifically, the GQA bypass was removed so models use
212+
standard attention ops with runtime kernel selection
213+
214+
### 4. Batch size=1 on large GPUs
215+
216+
**Symptom:** GPU utilization is low (10-30%). Throughput doesn't
217+
improve with larger GPU.
218+
219+
**Cause:** Single-token decode with batch=1 is memory-bandwidth bound,
220+
not compute bound. Large GPUs (H100, H200) have excess compute for
221+
small batch sizes.
222+
223+
**Fix:** Increase batch size if possible, or use continuous batching
224+
(vLLM-style). For single-user latency, smaller GPUs may be more
225+
cost-effective.
226+
227+
## Profiling GenAI pipeline
228+
229+
### Measure tokens per second
230+
231+
```python
232+
import time
233+
import onnxruntime_genai as og
234+
235+
model = og.Model("model_dir/")
236+
tokenizer = og.Tokenizer(model)
237+
238+
prompt = "Explain quantum computing in simple terms."
239+
input_ids = tokenizer.encode(prompt)
240+
241+
params = og.GeneratorParams(model)
242+
params.set_search_options(max_length=200, do_sample=False)
243+
244+
gen = og.Generator(model, params)
245+
gen.append_tokens(input_ids)
246+
247+
# Measure TTFT (time to first token)
248+
t0 = time.perf_counter()
249+
gen.generate_next_token()
250+
ttft = time.perf_counter() - t0
251+
252+
# Measure decode throughput
253+
t1 = time.perf_counter()
254+
num_tokens = 0
255+
while not gen.is_done():
256+
gen.generate_next_token()
257+
num_tokens += 1
258+
decode_time = time.perf_counter() - t1
259+
260+
print(f"TTFT: {ttft*1000:.1f} ms")
261+
print(f"Decode: {num_tokens} tokens in {decode_time:.2f}s")
262+
print(f"Throughput: {num_tokens/decode_time:.1f} tok/s")
263+
```
264+
265+
### Key metrics
266+
267+
| Metric | Description | Typical values |
268+
|--------|-------------|----------------|
269+
| **TTFT** | Time to first token (prefill) | 50-500 ms (depends on prompt length) |
270+
| **Decode tok/s** | Tokens per second during generation | 10-100+ tok/s (depends on model size, GPU) |
271+
| **Prefill tok/s** | Prompt processing throughput | 500-5000 tok/s |
272+
273+
### Real example: Gemma4 on H200
274+
275+
| Metric | Value |
276+
|--------|-------|
277+
| TTFT (short prompt) | ~85 ms |
278+
| Decode throughput | ~12-15 tok/s (CPU), ~60+ tok/s (CUDA) |
279+
| cuBLAS warmup | ~40 ms (first step only) |
280+
| Steady-state decode | ~66 µs per MatMul |
281+
282+
## Debugging workflow
283+
284+
1. **Profile the model** with ORT session profiling
285+
2. **Check memcpy count** — if >10, investigate CPU-placed ops
286+
3. **Check attention kernel** — verify GQA/Flash is being used
287+
4. **Group by op type** — find the top time consumers
288+
5. **Compare prefill vs decode** — decode should be much faster
289+
6. **Measure GenAI throughput** — tok/s is the user-facing metric
290+
7. **Check GPU utilization**`nvidia-smi` during inference
291+
292+
## Cross-references
293+
294+
- **Debugging memcpy:** `.agents/skills/debugging-memcpy/SKILL.md`
295+
- **Building ORT with CUDA:** `.agents/skills/building-ort-genai/SKILL.md`
296+
- **ONNX export:** `.agents/skills/onnx-export-quantization/SKILL.md`
297+
- **Reusable components:** `.agents/skills/reusable-components/SKILL.md`

0 commit comments

Comments
 (0)