如何减少线程到达安全点 - 同步状态所花费的时间

问题描述

关于问题:
在 VM 中的大量 IO 期间,由于停止线程需要更多时间,我们面临 JVM 暂停/缓慢。查看安全点日志时,它显示同步状态花费的时间最多。

Safepoint log reference

我们还尝试在超时延迟 (-XX:+SafepointTimeout -XX:SafepointTimeoutDelay=200) 上打印 Safepoint 跟踪,以了解导致此问题的线程,但似乎没有任何可疑之处。同样,在为安全点设置超时时,当花费的时间处于“同步”状态时,我们不会检测到超时打印。

关于安全点追踪的问题:

  1. 安全点超时如何工作?
  2. 在记录线程详细信息后,安全点是否存在并且所有线程都恢复了?
  3. 是否会执行该 VM 操作。如果 vmop 是 GC 会发生什么。

使用异步分析器:
尝试使用 async-profiler 进行安全点时间分析,并注意到 VM 线程在 SafepointSynchronize::begin() 方法上花费的时间更多,而 C2 编译器线程花费的时间几乎与 VM 线程相同。

Flame Graph

我们怀疑 C2 编译器可能需要时间才能达到安全点。有人可以帮助我们解决这个问题并解释这个到达安全点的时间火焰图。提前致谢。

解决方法

SafepointTimeout 选项只影响日志记录,即线程不会被中断,VM 操作会正常运行等。

SafepointTimeout 并不总是打印超时线程:在打印发生时线程可能已经到达安全点。此外,如果整个进程已被操作系统冻结,SafepointTimeout 甚至可能不会检测到超时。

例如,这样的“冻结”很多发生

  • 当进程在 cgroup(容器)中用尽其 cpu 配额时;
  • 当系统物理内存不足,并且发生 direct reclaim 时;
  • 由于另一个进程的活动(例如,当 atop 实用程序检查系统时,我观察到 JVM 长时间暂停)。

async-profiler 确实有一个安全点时间分析选项 (--ttsp),但正确使用它似乎很棘手。它在具有 wall 输出的 jfr 分析模式下效果最佳。在此配置中,async-profiler 将在安全点同步期间对所有线程(包括运行和阻塞)进行采样,并使用时间戳记录每个单独的事件。

然后可以使用 JDK Mission Control 分析此类配置文件:选择长暂停前后的时间间隔,并查看该间隔内 java 线程的堆栈跟踪。

请注意,如果 JVM 进程被“冻结”,async-profiler 线程也不会工作,即在此期间您将看不到收集的样本。通常,在挂钟分析模式下,所有线程都被均匀采样。但是,如果您看到“间隔”(在某个时间间隔内错过了事件),则显然意味着 JVM 进程尚未收到 CPU 时间。在这种情况下,JVM 暂停的原因不在 Java 应用程序中,而是在操作系统/环境中。