一、一个让我困惑的 618ms
今天排查一个分页查询性能问题,接口返回明明只有 10 条数据,SQL 执行也就 600 多毫秒,可 IDEA 自带的 Profiler 却给出了一组整齐划一的数字:
CollectionUtils.isEmpty— 618 msBeanCopyUtil.map— 618 mscollect(Collectors.toList())— 618 msobjectMapper.writeValueAsString— 还是 618 ms
起初我以为类型转换和 JSON 序列化真的这么慢,下意识地就开始查反射、查 Jackson 配置。根据我的排查我逐渐开始换衣IDEA 的Profiler的运行结果,直到我换成 Arthas,用trace命令一看,所有这些Profiler认为慢的步骤加起来不到 2 毫秒。这才意识到,IDEA Profiler 的 618ms 不过是一串“幽灵耗时”,完全把我带偏了方向。
为什么同样的程序,两个工具给出的结果差出两个数量级?后来我梳理清楚了背后的技术原理,根源在于采样型 Profiler 与插桩型 Profiler 在 JVM 运行时面前的表现完全不同。下面把整个推导过程记录下来,并留出实际运行结果。
二、两大阵营:采样器 vs 插桩器
在 JVM 生态中,性能分析工具主要分为两个流派:
| 流派 | 代表工具 | 核心原理 |
|---|---|---|
| 采样型(Sampling) | async-profiler, IDEA Profiler, JProfiler(采样模式) | 定期收集线程调用栈,统计栈帧出现频率,推算方法耗时 |
| 插桩型(Instrumentation) | Arthas, BTrace, SkyWalking(增强后) | 修改目标方法字节码,在方法入口和出口插入计时器,直接记录耗时 |
IDEA 集成的 Profiler 底层正是async-profiler(或 Java Flight Recorder),属于采样型;而 Arthas 是通过 Java Agent 动态附加,利用ASM 字节码增强实现插桩。两种原理的差异,直接决定了它们在面对 JIT 编译、GC 停顿时表现出的“准度”鸿沟。
三、采样型 Profiler 的致命伤
3.1 工作原理
采样器像一位摄影师,每隔 10ms 给 JVM 拍一张“栈快照”。方法出现在栈顶的次数越多,我们就认为它的 CPU 占用越高。这种方法本质是统计学推断,而非精确测量。
3.2 内联:让方法“隐身”的魔术
JVM 在运行时会对热点代码进行即时编译(JIT),其中最重要的优化之一是方法内联(Inlining)。当BeanCopyUtil.map被频繁调用时,JIT 会直接把它的字节码嵌入到调用者convert2OrderStatisticsEntityList的编译代码中,消除方法调用开销。
一旦方法被内联,线程的调用栈中就不再出现BeanCopyUtil.map这个帧。采样器只能看到一个巨大的“编译后方法”,所有子方法耗时都被错误地归算到外层方法上,甚至完全消失。这就是为什么很多时候你会发现 IDEA Profiler 第二次录制时“监控不到方法”——它们已经被内联“吞噬”了。
3.3 GC 停顿:偷时间的隐身贼
采样器还有另一个致命问题:无法区分 CPU 执行时间和线程暂停时间。当 JVM 发生 GC 时,所有应用线程都会被暂停(Stop-The-World)。如果采样信号恰好落在 GC 停顿期间,它会把这段暂停时间错误地归算到当时正在执行的方法上。
[业务线程] ----执行业务A----|---GC停顿---|---执行业务A---- [采样信号] ↑ ↑ 正确样本 错误样本(A被记入大量耗时)这就解释了开头提到的“618ms 魔咒”——很可能是一次 Young GC 或 Full GC 恰好与采样点重合,导致多个方法都分到了相同的 618ms。而 Arthas 的插桩计时器在 GC 暂停期间根本不会走动,因为它统计的是实际执行时间或准确的墙钟时间差,不会把暂停时间混入方法耗时。
四、Arthas:用手术刀代替照相机
4.1 字节码增强原理
Arthas 通过 Java Agent 动态 attach 到目标 JVM,利用InstrumentationAPI 和 ASM 库,在你指定的方法前后直接织入计时代码。
这种方法有几个关键优势:
- 不受 JIT 内联影响:计时逻辑直接嵌在原始方法内部,即使该方法被内联到其他方法,计时器仍然跟随执行。你可以精准测量某个子方法的耗时,无需关心它是否被编译优化。
- 精确区分 GC 影响:如果测量基于
System.nanoTime(),GC 停顿期间线程暂停,计时器自然停滞,不会将 GC 时间算入业务方法。 - 可下钻到任意层次:Arthas 允许你
trace任何类的任何方法,甚至可以追踪第三方库(如ObjectMapper.writeValueAsString)的内部调用,这是采样器无法做到的(因为第三方类可能没有 debug 信息,采样器无法复原被内联的栈帧)。
4.2 Arthas 的工作流程详解
核心要点:
- Arthas 的计时发生在字节码层面,与 JIT 编译后的机器码无缝融合。
- 对于内联的方法,如果你单独 trace 它,Arthas 会直接增强那个被内联的方法体,你依然能看到它的耗时。
- 整个增