上一篇：28-1《基准设计：同机串行、口径先行》｜ 下一篇：28-3《复现核心三表：冷启动 / decode / KV 恢复》
真机实测通过：本文实验已在 RK3588 板端实测完成（2026-09；方法学与原始记录见仓库 docs 与《实验脚本》目录）
一句话导读：推理引擎分析工具：读引擎自己的仪表盘——上手 serve 日志分段、加载计时与长上下文拆解三件测量工具，讲怎么把墙钟拆成 prefill 与 decode，落到一次 2243-token prefill 的 GEMM、Attention 与四类算子占比。
关键词：手搓推理引擎、大模型推理、日志时间戳、prefill、decode、性能拆解、RK3588
口径立住后，得先学会读引擎自己的仪表盘。这篇上手三件测量工具：serve 日志里的[PREFILL-TIMING]/[PREFILL-KERNELS]分段、[M-T] model load took加载计时、以及"跑一次长上下文，把 prefill 与 decode 从墙钟里拆开"的完整方法。板端实测一条 2243-token 的 prefill：总 75.5s，其中 GEMM 占 57.9%、Attention 占 39.0%，再细到 QKV/O/GATEUP/DOWN 四类算子。
1. 知识点：性能问题的"三层归因"
用户感知的只有墙钟（从发出请求到收到回答）。性能调优第一课：把墙钟拆成可归因的段。推理请求的墙钟天然分两段：
- prefill（预填充）：处理全部 prompt token，产出首个 token。特征是大矩阵乘（一次算完 N 个 token 的注意力）。指标：TTFT（首 token 时间）、prefill tok/s。
- decode（逐词生成）：每步只喂 1 个 token，逐 token 出结果。特征是访存密集（KV 全扫 + 小矩阵）。指标：TPOT（每 token 时间）。
Kestrel 的 serve 日志把 prefill 再拆一层（vllm_safetensors.c 11078–11089）：
[PREFILL-TIMING] n=2243 total=75460.4ms | GEMM=43703.0ms(57.9%) ATTN=29456.8ms(39.0%) OTHER=2300.5ms( 3.0%) [PREFILL-KERNELS] QKV=7935.8ms(18.2%) O=4623.9ms(10.6%) GATEUP=20033.6ms(45.8%) DOWN=11109.8ms(25.4%)归因逻辑：total 里 GEMM/ATTN/OTHER 谁占比大 → 看 [PREFILL-KERNELS] 再拆 GEMM（QKV 投影 / O 投影 / GATEUP 上投影 / DOWN 下投影）——每一行都是一次"成本被谁吃掉"的审计。
2. 对应代码：日志从哪来
/* vllm_safetensors.c 11078–11089（prefill 计时输出） */t_gemm=t_qkv+t_o+t_gu+t_down;/* 四类 GEMM 求和 */doublet_total=t_gemm+t_attn+t_other;if(t_total>0.0){fprintf(stderr,"[PREFILL-TIMING] n=%d total=%.1fms | GEMM=%.1fms(%4.1f%%) ""ATTN=%.1fms(%4.1f%%) OTHER=%.1fms(%4.1f%%)\n",...);四类 GEMM 分别由内部计时器累加（QKV = 输入投影，O = 输出投影，GATEUP = MoE/FFN 门控+上投影，DOWN = 下投影）。加载计时是另一行[M-T] model load took … ms（vqf mmap 路径，Day 28-3 冷启动要读它）。命令行侧还有两个配套：--perf-partA只跑单用户 TTFT/TPOT 子集、--bench-users控制并发（本机口径以单用户为准，见 28-1）。
3. 改动后果：一次 2243-token prefill 的真实拆解
实测口径：RK3588 / aarch64 / 2026-09-07。serve +
/v1/chat/completions（prompt 为约 3300 字中文 → 引擎实际 2243 tokens，max_tokens=32）。注意：本会话为引擎默认配置，未开启基准报告中的"优化档全开"（sparse-attn k=32 + spec-k4 等）——报告 2K 档 prefill 45s @2049 tokens，本次默认档 75.5s @2243 tokens，速度差异正是配置差异，不是引擎版本差异（28-1 的教训在复现时立刻应验）。
# serve 日志（节选） [M-T] model load took 341 ms (startup time) [PREFILL] 512/2243 tokens done ... [PREFILL] 2243/2243 tokens done [PREFILL-TIMING] n=2243 total=75460.4ms | GEMM=43703.0ms(57.9%) ATTN=29456.8ms(39.0%) OTHER=2300.5ms( 3.0%) [PREFILL-KERNELS] QKV=7935.8ms(18.2%) O=4623.9ms(10.6%) GATEUP=20033.6ms(45.8%) DOWN=11109.8ms(25.4%) # 客户端墙钟 [long] wall=89.9s finish=stop # prefill 75.5s + decode(含调度/首token) ≈ 14.4s读数：① prefill 29.7 tok/s（2243/75.46s，默认档）；② GEMM 占 57.9% 为主成本，其中GATEUP 20.0s（占 GEMM 的 45.8%）是最大单项——2B 模型的 FFN 上投影宽度（6144）决定它吃走大头；③ ATTN 39.0%（无 sparse 时全量注意力，2.2K 上下文的平方成本）；④ OTHER 仅 3%（norm/采样/调度等杂项）。如果要做优化：先打 GATEUP（NEON/多线程 GEMM）与 ATTN（上 sparse），而不是盲猜。推演改动后果：若有人把OTHER误报进 GEMM 或把某类算子计时器漏加，[PREFILL-TIMING] 的百分比会悄悄失真——这也是为什么日志格式先t_gemm = t_qkv + t_o + t_gu + t_down显式求和，四个计时器缺一个百分比总和就不等于 100%。
4. 学员调试任务
- A 档（板端动手）：
- 复刻本篇：serve + 长 prompt（或用
--perf-partA跑单用户档），收集[PREFILL-TIMING]与[PREFILL-KERNELS]两行，验证 GEMM% + ATTN% + OTHER% ≈ 100%； - 改变上下文长度重跑（1K vs 4K），观察 ATTN 占比如何随长度上升（全量注意力 O(n²) 的直接证据）；
- 读
--perf-partA分支（main.c 3039 附近）说明它输出哪些指标。
- 复刻本篇：serve + 长 prompt（或用
- B 档（纯读源码）：读
vllm_safetensors.c11078–11089 与相关计时器累加点，回答：① QKV/O/GATEUP/DOWN 四类分别对应 Transformer 的哪些计算？② 为什么 decode 阶段不打印[PREFILL-TIMING]？（提示：逐 token 计时器另有归属，prefill 是批量一次性）③ 若要在 2243-token 档把 prefill 从 75s 压到 40s，按占比顺序你会先优化哪个算子？依据是什么？
预期输出：一次长上下文 prefill 的 TIMING/KERNELS 日志 + 你画的"墙钟 → prefill/decode → GEMM/ATTN → QKV/O/GATEUP/DOWN"归因树。
收尾
- 本篇源码点名：vllm_safetensors.c（PREFILL-TIMING 11078–11089）、main.c（–perf-partA 1596/3039、–bench-users 4833）
- 开源仓库：Kestrel-LLM (Gitee)（AGPL-3.0-or-later 或商业许可，二选一）
- 下篇预告：工具会读了，去复现报告的三张核心表。28-3 按报告口径跑：冷启动、长上下文拆解、前缀/KV 恢复——并如实记录哪些复现成功、哪些与报告有出入（配置口径差异），把"复现"变成方法论的一部分。
