如何剖析Java阻塞代码:测量含等待时长的实际执行时间而非CPU时间
问题本质
Java Flight Recorder(JFR)默认的性能剖析配置仅采集CPU运行态的线程栈样本,当线程处于WAITING/TIMED_WAITING/BLOCKED状态时——包括你代码里的Thread.sleep、等待数据库/REST接口响应的Socket阻塞、锁等待等场景——都不会被计入CPU耗时统计,因此你在默认的CPU热点视图里完全看不到这类非CPU密集型方法的耗时,和你需要统计的「包含阻塞等待的真实执行时间(墙钟时间/Wall Clock Time)」逻辑完全不符。
可落地的配置调整步骤
- 开启JFR墙钟采样模式
在IntelliJ的JFR运行配置中,不要使用默认的Performance分析模板,手动编辑录制参数:- 进入方法采样(Method Sampling)配置项,将采样模式从默认的
CPU Load切换为Wall Clock,也可以同时保留两种采样方便对比 - 将墙钟采样间隔设置为10ms即可(间隔过小会增加额外性能开销,测试环境可按需调低到1ms),该模式下无论线程是在执行CPU计算还是阻塞等待,都会按固定间隔抓取线程栈,最终统计的方法耗时就是从方法进入到退出的真实墙钟时间,对你给出的示例代码来说,统计结果会和你预期的一致:
fast总耗时占比约10%,slow总耗时占比约90%。
- 进入方法采样(Method Sampling)配置项,将采样模式从默认的
- 开启细分阻塞事件采集
如果需要进一步定位阻塞的具体原因(是数据库IO慢?锁竞争?还是主动sleep?),需要在JFR录制配置中打开对应事件的采集开关,并根据场景调低事件采集的默认阈值(默认通常仅记录超过10ms的事件):- 打开
Thread Sleep事件,采集所有Thread.sleep调用的栈和耗时 - 打开
Socket Read/Socket Write事件,采集网络IO阻塞的耗时(数据库调用、REST调用的底层都是Socket读写) - 打开
Java Monitor Wait/Java Monitor Blocked事件,采集锁等待、锁阻塞的耗时
- 打开
- 切换到正确的分析视图
不要看JFR报告默认的「CPU热点方法」视图,这个视图仅统计CPU执行时间:- IntelliJ内置的JFR查看器中,找到方法剖析分类下的
Wall Clock视图查看即可 - 如果内置视图功能不全,可以导出录制的jfr文件,用JDK Mission Control打开,在
Method Profiling分类下选择墙钟时间维度统计,也可以直接查看IO、锁等待分类下的事件,直接定位慢调用的具体位置和耗时。
- IntelliJ内置的JFR查看器中,找到方法剖析分类下的
注意:墙钟采样的性能开销略高于纯CPU采样,生产环境使用时不建议把采样间隔设到5ms以下,测试/压测环境下10ms间隔的开销几乎可以忽略,不会影响性能测试结果的准确性。
内容的提问来源于stack exchange,提问作者bollin
相关产品推荐
相关产品推荐

