上一篇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] n2243 total75460.4ms | GEMM43703.0ms(57.9%) ATTN29456.8ms(39.0%) OTHER2300.5ms( 3.0%) [PREFILL-KERNELS] QKV7935.8ms(18.2%) O4623.9ms(10.6%) GATEUP20033.6ms(45.8%) DOWN11109.8ms(25.4%)归因逻辑total 里 GEMM/ATTN/OTHER 谁占比大 → 看 [PREFILL-KERNELS] 再拆 GEMMQKV 投影 / O 投影 / GATEUP 上投影 / DOWN 下投影——每一行都是一次成本被谁吃掉的审计。2. 对应代码日志从哪来/* vllm_safetensors.c 11078–11089prefill 计时输出 */t_gemmt_qkvt_ot_gut_down;/* 四类 GEMM 求和 */doublet_totalt_gemmt_attnt_other;if(t_total0.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 … msvqf mmap 路径Day 28-3 冷启动要读它。命令行侧还有两个配套--perf-partA只跑单用户 TTFT/TPOT 子集、--bench-users控制并发本机口径以单用户为准见 28-1。3. 改动后果一次 2243-token prefill 的真实拆解实测口径RK3588 / aarch64 / 2026-09-07。serve /v1/chat/completionsprompt 为约 3300 字中文 → 引擎实际 2243 tokensmax_tokens32。注意本会话为引擎默认配置未开启基准报告中的优化档全开sparse-attn k32 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] n2243 total75460.4ms | GEMM43703.0ms(57.9%) ATTN29456.8ms(39.0%) OTHER2300.5ms( 3.0%) [PREFILL-KERNELS] QKV7935.8ms(18.2%) O4623.9ms(10.6%) GATEUP20033.6ms(45.8%) DOWN11109.8ms(25.4%) # 客户端墙钟 [long] wall89.9s finishstop # prefill 75.5s decode(含调度/首token) ≈ 14.4s读数① prefill 29.7 tok/s2243/75.46s默认档② GEMM 占 57.9% 为主成本其中GATEUP 20.0s占 GEMM 的 45.8%是最大单项——2B 模型的 FFN 上投影宽度6144决定它吃走大头③ ATTN 39.0%无 sparse 时全量注意力2.2K 上下文的平方成本④ OTHER 仅 3%norm/采样/调度等杂项。如果要做优化先打 GATEUPNEON/多线程 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 附近说明它输出哪些指标。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.cPREFILL-TIMING 11078–11089、main.c–perf-partA 1596/3039、–bench-users 4833开源仓库Kestrel-LLM (Gitee)AGPL-3.0-or-later 或商业许可二选一下篇预告工具会读了去复现报告的三张核心表。28-3 按报告口径跑冷启动、长上下文拆解、前缀/KV 恢复——并如实记录哪些复现成功、哪些与报告有出入配置口径差异把复现变成方法论的一部分。