耗时拆分：把 3 秒拆成 30 毫秒
「接口慢」是一个没有信息量的结论。真正有用的是把一次请求拆成若干可度量的阶段，直到每一段都小于你愿意单独讨论的阈值。本章给出统一的耗时日志格式、一个 3.2 秒的真实拆解案例，以及没有 APM 时的兜底方案。
一次请求有哪些阶段
接入层 → 认证 → 参数校验 → 业务计算 → 缓存读写 → DB 查询 → 下游 RPC → 序列化 → 写回
只统计总耗时会让你在「应用慢」和「数据库慢」之间反复猜。拆到阶段之后，一次采样就能指认大头，剩下的工作只是修它。
统一耗时日志格式
格式统一比埋得全更重要。推荐一行 key=value，既能 grep 也能直接进日志系统：
[slow] trace=8f3a1c2e path=/api/order/detail uid=10231 total=3218ms
auth=3 db=1780 redis=12 rpc=940 serialize=8 calc=430 other=45
db_count=7 rpc_count=3 slowest=orderMapper.selectByUser:1740ms
| 字段 | 含义 | 为什么需要 |
|---|---|---|
trace | 链路 ID，全链路唯一 | 把应用、DB、下游的日志串成一条线 |
total | 请求总耗时 | 与入口日志的 $request_time 对照 |
db / db_count | 数据库总耗时与调用次数 | 次数多说明 N+1，单次大说明慢查询 |
redis | 缓存总耗时 | 大 key、网络往返、连接池等待 |
rpc / rpc_count | 下游调用耗时与次数 | 定位是哪一家下游拖慢 |
serialize | 序列化与反序列化 | 大对象 JSON、重复编解码 |
calc | 业务计算 | 剩余部分，占总耗时 30% 以上就值得看线程栈 |
other | 差值兜底项 | 必须有，否则对不上账时会先怀疑埋点写错 |
other 不是可选项。没有兜底项，各阶段之和小于总耗时时，你会花时间证明「埋点没漏」而不是找真正的耗时。
一个真实案例：3.2 秒怎么来的
| 阶段 | 耗时(ms) | 占比 | 调用次数 | 判读 |
|---|---|---|---|---|
| 接入层转发 | 18 | 0.6% | 1 | 正常 |
| 认证与鉴权 | 6 | 0.2% | 1 | 正常，命中本地缓存 |
| 参数校验 | 4 | 0.1% | 1 | 正常 |
| DB 查询 | 1780 | 55.6% | 7 | 大头之一：单条 1.74s，缺索引 |
| Redis 读写 | 12 | 0.4% | 4 | 正常 |
| 下游 RPC | 940 | 29.4% | 3 | 大头之二：串行调用且未设超时 |
| 序列化 | 8 | 0.2% | 1 | 正常 |
| 业务计算与其他 | 450 | 14.0% | — | 其中约 0.3s 是重复计算，可去掉 |
| 合计 | 3218 | 100% | — | — |
两个大头合计 85%，处置动作非常明确：
DB ：order_item 加复合索引 (user_id, created_at)，1.74s → 12ms
RPC：三个下游改并行调用并设 200ms 超时，0.94s → 0.31s
改完之后总耗时从 3218ms 降到约 0.8s。这就是拆阶段的价值：不拆的话，最可能的动作是「加机器」，而加机器对缺索引和串行 RPC 毫无帮助。
埋点的实现方式
不同语言落地方式不同，约束一样：埋点代码不能太贵，也不能漏掉异常路径。
| 语言/框架 | 落地方式 | 注意 |
|---|---|---|
| Java | 拦截器或 AOP 环绕通知 + 原子累加 | 跨线程（线程池、CompletableFuture）要手动传递累加器 |
| Go | context 携带耗时结构 + middleware | 用 context 传值，goroutine 结束必须回写，否则丢失 |
| Python | 中间件 + threading.local | 异步框架要用 contextvars 而不是 thread local |
统计耗时要用累加，而不是「开始时间减结束时间」这种两个时间点相减。请求会跨越线程、协程与异步回调，只有累加 DB/Redis/RPC 各自实际占用的时间，才能得到可信的阶段占比。
采样与开销控制
全量打印慢日志会自己制造故障：日志 IO 吃掉 CPU 与磁盘，还会把日志系统打爆。
| 策略 | 适用场景 | 参数建议 |
|---|---|---|
| 慢请求全采 | 定位阶段与验证修复 | 阈值 500ms，超过即打印完整阶段 |
| 固定比例采样 | 常态观测 | 1% 或千分之一 |
| 按 trace 采样 | 单请求深挖 | 指定 trace id 强制全量，其余不打印 |
| 只记指标不落盘 | 有指标系统时 | 只累加计数与直方图，不写文本日志 |
结论：常态只记指标（计数与直方图），符合阈值或采样命中时才写完整阶段日志。这样单进程每秒开销在微秒量级，可以长期开启。
没有 APM 时的兜底方案
1. 全局拦截器/中间件记录 total
2. 包装 DataSource、Redis Client、RPC Client，各自累加耗时
3. total 超过阈值时，把累加器序列化成一行 [slow] 日志
4. 日志按天切割，配脚本做统计：分布、Top 接口、Top 慢资源
grep '\[slow\]' app.log | awk -F'db=' '{print $2}' | awk '{print $1}' | sort -n | tail -20
grep '\[slow\]' app.log | grep -o 'slowest=[^ ]*' | sort | uniq -c | sort -rn | head
grep '\[slow\]' app.log | grep -o 'other=[0-9]*' | cut -d= -f2 | awk '{s+=$1} END {print s/NR}'
| 统计结果 | 判断 |
|---|---|
| 某接口长期占据慢日志 top1 | 先修它，收益最大 |
slowest 集中在同一条 SQL | 缺索引或语句设计问题 |
db_count 随请求增大而线性增长 | N+1 查询，改成批量 |
other 平均超过总耗时 10% | 有阶段没埋到，或存在未统计的等待 |
| 慢日志条数突然放大 | 可能是引流或数据分布变化，先确认现象范围 |
这套东西大约一天工作量，能替代 APM 里 80% 的定位能力。即便已经有 APM，核心链路也应该做自定义埋点：APM 告诉你哪个方法慢，自定义埋点告诉你慢在哪个资源等待上。
巡检项
other占比是否超过 10%，超过说明有阶段没覆盖。db_count、rpc_count的单请求最大值是否异常增长。- 阶段耗时之和与入口
$request_time的差值是否稳定，漂移说明埋点或链路有变化。 - 慢日志阈值与采样率是否随流量规模调整过。
小结：把请求拆成可度量的阶段并统一日志格式，用累加而不是时间点相减；3.2 秒的案例里 85% 的耗时集中在一条缺索引的 SQL 和三个串行 RPC 上，先拆阶段再优化，才能避免用扩容解决代码问题。