先说结论，可能有点反直觉：你花最长时间去优化的那一层，大概率不是真正的瓶颈。
这句话是我在订单详情接口上折腾了快两年才敢说的。接口 QPS 峰值 320 上下，P50 只有 76ms，但 P99 一直在 2.1s 附近晃。SRE 每个周一都来问一句「那个接口怎么样了」，我每次都说「在看了在看了」。
背景先交代清楚，不然下面全是空话。服务是 Java 写的，JDK 1.8.0_202，跑在阿里云 ecs.c6.2xlarge 上（8 vCPU / 16 GiB），单机部署 8 个实例，前面挂 SLB。数据层是 MySQL 5.7.26 单主加两个只读从库，再加一个 3 节点 Redis Cluster（社区版 4.0）。订单主表 t_order 大概 4200 万行，t_order_item 一亿两千万行。
下面按时间线讲，包括我调错的地方。
第一轮：加索引，SQL 从 780ms 掉到 38ms，P99 只动了 0.2s
慢查询日志里躺着一条 SQL，780ms 左右，基本全是全表扫描：
SELECT ... FROM t_order o
LEFT JOIN t_order_item oi ON oi.order_id = o.id
LEFT JOIN t_user u ON u.id = o.user_id
WHERE o.order_no = ? AND o.user_id = ?order_no 上没索引，这事是历史遗留，建表的时候以为查询都走主键。加上 ALTER TABLE t_order ADD INDEX idx_order_no (order_no) 之后，灰度机器上实测从 780ms 降到 38ms。我当时觉得自己救了整个项目。上线之后 P99 从 2.1s 掉到 1.9s。就这。
后来才想明白：P99 是长尾指标，你优化掉一个只占总耗时 20% 的小头，对 P99 的贡献可能连 3% 都不到。这个道理其实谁都懂，Amdahl 定律都背过，但在真实的调优现场，几乎没有人先拿起计算器做这个除法。大家都直接扑向自己最熟的那一层。
第二轮：上 Redis 缓存，P99 掉到 1.4s，但我埋了个雷
缓存这块我做得挺粗暴。key 是 order:detail:{orderNo}，value 是整个 VO 对象的 JSON，TTL 10 分钟。逻辑大概是这样：
Object cached = redis.get(key);
if (cached != null) return (OrderVO) cached;
OrderVO vo = buildVO(orderNo);
redis.setex(key, 600, JSON.toJSONString(vo));
return vo;上线之后 P99 到 1.4s，QPS 上来之后 MySQL 的 QPS 掉了一半多。看起来是个成功案例对吧。
问题是：写缓存的时候那个 JSON.toJSONString(vo) 是同步执行的，VO 大概 400KB（订单、明细、用户、优惠券、物流全塞一个对象），一次序列化 200ms 上下。我给它起了个名叫缓存税 —— 我加缓存是想省时间，结果每次 cache miss 的请求反而比不加缓存更慢。这个我没马上发现，因为 Prometheus 上只看了 P50 和 P99，而 cache miss 的比例只有 4% 左右，被平均掉了。
第三轮：Arthas 抓到真凶
真正让我找到问题的是 Arthas，版本 3.5.1。生产环境上执行：
trace com.xxx.service.impl.OrderServiceImpl getOrderDetail -n 5 --skipJDKMethod false结果大概长这样：
---[62.3% 1.31s] com.xxx.service.impl.OrderServiceImpl:buildVO()
+---[58.1% 1.22s] com.fasterxml.jackson.databind.ObjectMapper:writeValueAsString()
+---[3.1% 65ms] com.xxx.mapper.OrderMapper:selectByOrderNo()
---[21.4% 450ms] com.xxx.service.impl.OrderServiceImpl:getUserInfo()到这里我才发现，真正吃时间的是我自己写的序列化逻辑。而且不止一处，日志里还藏着一行：
log.info("order detail: " + JSON.toJSONString(order));这行的 JSON.toJSONString 在 INFO 级别没开的时候照样执行，字符串拼接不是懒加载。这个坑我看过无数次，自己也踩了。
后面改了两件事。序列化换成 protostuff，那个 400KB 的 VO 只保留前端要用的 14 个字段，序列化时间从 200ms 上下掉到 12ms 左右。日志那行改成占位符加 isInfoEnabled() 判断。
顺带说个反直觉的 GC 调参
排查停顿的时候我顺手看了 GC。jstat -gcutil <pid> 1000 下来是这样的：Young GC 每 1.2s 一次，每次 40-60ms；Mixed GC 每 8 分钟一次，停顿 780ms。JVM 参数是 -Xms8g -Xmx8g -XX:+UseG1GC -XX:MaxGCPauseMillis=200。
我第一反应是把 MaxGCPauseMillis 从 200 调到 100，停顿目标更小总该更好吧。
结果相反。Young GC 频率从 1.2s 一次变成 0.7s 一次，总停顿时间反而涨了。原因不难查：G1 为了达成更小的停顿目标，会自动压缩 Young 区大小，Eden 变小，Young GC 自然更频繁。这个行为 Oracle 的 G1 调优文档里有写，但我是先在监控上看到现象，才回去翻文档的。
后来改成 -XX:G1NewSizePercent=20 -XX:G1MaxNewSizePercent=40，Young GC 降到 2.3s 一次，Mixed GC 停顿 320ms 左右。P99 从 1.4s 到了 900ms 上下。
最后的结果，和几个我到现在也说不清的东西
最终 P99 190ms，P50 从 76ms 到 41ms，MySQL 的 CPU 从长期 70% 掉到 25%。这些数字其实没那么重要，重要的是一路下来我改掉的几个判断。
先做除法再做优化。拿 Arthas 或者 async-profiler 跑一次火焰图，把总耗时按百分比拆开，先动占比最高的那一块。这个动作花你 20 分钟，能省你几个月。我第一轮和第二轮加起来浪费了大概五个月，原因就是我没做这个除法。
P99 和平均值是两个物种。平均值修的是整体，P99 修的是长尾里的那百分之几。如果 95% 的请求 80ms、5% 的请求 2s，平均值只有 176ms，报表上看着非常健康，但 P99 已经烂透了。修平均值对 P99 基本无效，反过来也一样。
调参不等于调优。G1 那一堆参数本质上是在重新分配代价，不是消除代价。你没确认 GC 是瓶颈之前，调参数只是搬家。
有个事我到现在也没完全搞明白：为什么缓存加进去之后，cache miss 那批请求的 RT 比完全不用缓存的时候还高了一截。我猜是 Redis 连接池争抢加上序列化叠加的结果，但没做严格的对照实验，不敢下定论。有人踩过类似的坑吗。