代码优化实战：P99 从 1280ms 降到 180ms，前两周我全优化错了地方

先说个让我想骂人的事：我优化错地方了整整两周

2023 年 9 月，我接手一个订单聚合接口。Prometheus 上 P99 是 1280ms，高峰期 CPU 常年 78%，Young GC 一小时 40 多次，Full GC 两三次，单次 Full GC 停 400ms 左右——这个数其实已经很致命了，但当时我注意力全在接口本身耗时上，觉得是某个函数太慢。

翻代码第一眼，看到一段 RSA 验签逻辑，单次调用 40ms。我当时心想这不就是元凶吗。然后花了两周，把 RSA 换成 ECDSA、加本地 Caffeine 缓存（maximumSize 10000，expireAfterWrite 10 分钟）、又把 Base64 编解码从 Apache Commons 换成 JDK 自带。单次验签从 40ms 压到 11ms，降幅 72%。上线之后，P99 从 1280ms 变成 1240ms。

是的，只降了 3%。

后来用 async-profiler 抓了一份 60 秒的 CPU 火焰图：

./profiler.sh -d 60 -e cpu -f /tmp/flame.html 12345

火焰图打开那一瞬间我就沉默了。占 CPU 最多的是 java.lang.String.format，31.2%。顺着调用栈往上翻，是 log.debug()，在一个 for 循环里逐条打印商品 SKU 信息。这个接口平均一次请求处理 340 个 SKU，每个 SKU 打 3 行 debug 日志，线上 QPS 1200 左右。算一下：1200 × 340 × 3 ≈ 每秒 122 万次调用。Logger 内部确实做了 level 判断，但 debug 日志的字符串拼接是在进入 log 之前就完成的，String.format 那 0.3ms 乘以 122 万次——这才是真正吃掉 CPU 的东西。而那个 RSA 验签，整个服务每秒只调用 3 次。

这就是我要说的核心：性能优化排优先级，看的是「调用次数 × 单次耗时」这个乘积，不是只看单次耗时。把一个每秒跑 122 万次的东西省下 0.1ms，收益是把一个每秒跑 3 次的东西省下 30ms 的 13 倍还多。这个道理听着简单，但我见过太多人（包括我自己）第一眼就奔着那个看起来最慢的函数去。

采样是有偏差的，别把火焰图当真相

再说个反面的：profiler 也会骗人，我自己就被骗过一次。

async-profiler 默认采样间隔是 10ms，而且它对 itimer 和 perf_events 两个后端的处理不一样。一个只跑了 3ms 的函数，大概率一次都采不到——不是它不重要，是它没被采样窗口捕捉到。反过来，一个跑了 8ms 的函数，如果运气好被采中，在火焰图上看起来就特别扎眼。

我后来养成了用三种方式交叉验证的习惯。

第一种，async-profiler 的 wall-clock 模式，不是默认的 CPU 模式：

./profiler.sh -d 60 -e wall -t -f /tmp/wall.html 12345

CPU 模式只能看到正在跑的函数，wall 模式能看到在等锁、等 IO 的线程。我有个服务 CPU 只有 30%，接口却慢得离谱，就是靠 wall 模式发现有个 ReentrantLock 在排队，平均每个请求等 180ms，换成 StampedLock 的乐观读之后 P99 直接掉了 60%。

第二种，JFR，JDK 自带，开销比大多数人想的小得多：

java -XX:StartFlightRecording=duration=120s,filename=rec.jfr,settings=profile -jar app.jar

JFR 的好处是它能同时给你 GC、内存分配、锁竞争、文件 IO 的数据，不用自己猜。我一般重点看三个事件：jdk.ObjectAllocationSample 找谁在疯狂分配对象，jdk.JavaMonitorEnter 找锁竞争，jdk.ExecutionSample 找 CPU 热点。顺便说一句，settings=profile 的开销大概在 1% 到 2%，生产环境可以放心开，比很多人想象的轻。

第三种最简单，也最容易被忽略：直接数。在关键路径上加计数器，用 LongAdder 而不是 AtomicLong——高并发下 AtomicLong 的 CAS 自旋能把你 CPU 吃掉一大块，LongAdder 通过分段累加把这个问题绕过去了。我最初那个日志问题的复现，就是靠 LongAdder 在线上数出来的每秒 122 万次。

三种方式对不上的时候，通常意味着采样窗口太短，或者 JIT 已经把代码优化得面目全非了。

微基准测试里的数字，有一半是假的

说到 JIT，就必须说 JMH。很多人优化前会写个 benchmark，量出一个数，然后照着这个数去优化。但大多数 JMH 基准测出来的根本不是真实性能，原因有三个。

第一个是死代码消除。你写个循环去测某个方法耗时，如果这个方法的结果没被用到，JIT 会把整个循环删掉。跑出来 0.001ms/op，看着很惊艳，其实 C2 编译器觉得你这段代码毫无意义。

第二个是逃逸分析。方法里 new 出来的对象如果没跑出作用域，JIT 直接在栈上分配，甚至把对象拆成标量。你测出来的「对象创建开销」可能压根不存在。我见过一个团队花一周去优化一个 DTO 的字段访问，上线发现毫无变化，因为那个 DTO 早被标量替换掉了。

第三个是内联。JVM 热点方法内联阈值默认是 -XX:MaxInlineSize=35 字节码（不热的方法），热点方法走 -XX:FreqInlineSize=325。超过这个大小的热点方法不会被内联，方法调用的开销就会暴露出来。所以你把一个 400 字节码的方法拆成两个 200 字节的，有可能反而让它被内联，性能还变好了。这个反直觉的事我踩过一次，当时把一个校验方法按职责拆开后，TP99 反而降了 15ms。

写 JMH 有几个参数我基本固定用：

@BenchmarkMode(Mode.AverageTime)
@OutputTimeUnit(TimeUnit.NANOSECONDS)
@Warmup(iterations = 5, time = 2)
@Measurement(iterations = 10, time = 3)
@Fork(3)
@State(Scope.Thread)

@Fork(3) 是为了让每轮测量跑在不同 JVM 进程里，避免前一轮的 JIT 状态污染后面的结果。很多人不加 Fork，跑出来的数字前后能差 30%。Warmup 至少 5 轮，因为 C1 到 C2 的编译是要时间的，一般 1 万次调用触发 C1 编译，10 万次左右触发 C2。还有，JMH 里一定要用 Blackhole.consume() 把结果吃掉，不然还是会被死代码消除。

删代码，往往比写更快的代码收益大

那轮优化做完我回头统计：总共改了 11 个文件，删掉大约 800 行代码，新增的只有 200 行左右。

具体删了什么？第一，把线上 log.debug 全部用 if (log.isDebugEnabled()) 包起来，或者更干脆——直接删。业务日志真不需要每条都打，我后来只保留错误日志和关键节点 info，日志量从 47GB/天降到 6GB/天，磁盘 IO 和采集 agent 的 CPU 一起降。第二，干掉一层几乎没意义的 DTO 转换。原来流程是 Entity → DO → DTO → VO 四层，每层都是 getter/setter 拷贝。用 JFR 看分配热点，jdk.ObjectAllocationSample 显示这四层转换占了年轻代 40% 的分配量。后来直接砍成 Entity → VO 两层，用 MapStruct 编译期生成映射代码代替运行期反射，Young GC 从每小时 40 多次降到 8 次，单次停顿从 25ms 降到 6ms。第三，String.split() 在循环里用——这玩意儿内部走正则，每次调用都要查 Pattern 缓存，缓存满了还会重新编译。换成 indexOf + substring，改动不到 20 行。

还有个更隐蔽的：ArrayList 没指定初始容量。一次请求要塞 340 个元素，默认容量 10，扩容路径是 10 → 15 → 22 → 33 ……每次扩容都要 Arrays.copyOf。340 个元素大概扩容 8 次，每次拷全量数据。指定 new ArrayList<>(512) 之后这个开销就没了。说实话单看这一项省不了多少，可能就几毫秒，但在高 QPS 下分配的对象少了，GC 压力小了，收益会自己滚起来。

我现在的排查顺序，可以直接抄

1. 先看监控大盘，把时间窗口对齐。别看平均延迟，看 P99 和 P999。平均值会把所有问题摊平，一个每秒卡 1 秒的坏请求，混在 100 万个正常请求里，平均值上根本看不出来。

2. 打开 JFR 或 async-profiler 的 wall 模式，抓 60 秒全局视图。先看线程都在干什么，别急着看 CPU。很多瓶颈根本不在 CPU 上，而在等锁、等连接池、等下游 RPC。

3. 再跑一次 CPU 模式采样，对着火焰图从下往上找。注意看每个栈帧的百分比，超过 5% 的才值得点进去。别一开始就钻进最底层那个窄条，那可能是采样噪声。

4. 对排在前面的热点函数，先去数它真实调用次数。这一步最容易跳过，但恰恰最关键。

5. 算总账：调用次数 × 单次耗时。按乘积排序，从大到小改。

6. 改完只动一个变量，再重新采样。别一次改五个地方，不然你不知道是哪个起了作用，回滚的时候也不知道该回滚哪个。

7. 上线盯 24 小时。有些问题只在流量峰值暴露，比如缓存穿透、连接池打满。我见过一个改动白天好好的，凌晨批处理任务一跑直接把数据库连接池打爆了。

最终那个接口 P99 从 1280ms 降到了 180ms。但说实话，真正起作用的只有三处：删日志、砍 DTO 层、List 预分配。其余那些看起来很厉害的算法优化，加起来贡献不到 5%。

最后说点反常识的

现在回头看那两周不算白花，至少让我明白一件事：代码优化里最贵的成本不是 CPU 时间，是你的注意力。

「不要过早优化」这句话本身没错，但它经常被人拿来当挡箭牌，好像优化就等于瞎折腾。真正的问题不是要不要优化，而是你有没有办法证明自己优化对了地方。没有数据支撑的优化就是撞大运，改十次可能对一次，剩下九次都在给后面的维护挖坑。

还有个更实在的建议：先看看你的可观测性够不够。你要是连接口 P99 都拿不到，日志里只有平均值，那别谈优化了，先去把监控补齐。我见过太多团队监控只有「接口平均响应时间」这一条曲线，然后一群人围着这条曲线猜哪里慢。

补监控这件事，比读十篇性能优化文章有用。