性能问答>到达 Safepoint 时间长达 96 秒>
6回复
2年前

到达 Safepoint 时间长达 96 秒



虚拟机日志
CleanShot 20200319 at 15.56.592x.png

sync = spin + block + 其他

不知道“其他”是哪些因素导致的呢?

已经开启:

-XX:+SafepointTimeout -XX:SafepointTimeoutDelay=2000

但是没有打印出相关信息。

JVM 类型:

Java HotSpot(TM) 64-Bit Server VM (25.121-b13) for linux-amd64 JRE (1.8.0_121-b13)

虚拟机参数:

-Xms5529m -Xmx5529m -XX:MaxDirectMemorySize=2663m -XX:+PrintGCApplicationStoppedTime -XX:+PrintGCApplicationConcurrentTime -XX:+PrintGCDetails -XX:+PrintGCDateStamps -XX:+PrintGCTimeStamps -XX:+PrintPromotionFailure -XX:+PrintGCCause -XX:+PrintSafepointStatistics -XX:PrintSafepointStatisticsCount=1 -XX:+SafepointTimeout -XX:SafepointTimeoutDelay=2000
3932 阅读
请先登录,再评论

可以看看那会的IO吗

2年前
回复 江户川:

1.先判断这个高cpu的线程是不是业务线程,如果是的话,很简单,看下代码逻辑就知道了。
2.如果不是,类似VMThread,这个就要再仔细分析下了。因为能让它工作的情况有很多种。
2.1都知道的是gc,所以可以优先排查下gc是否正常(回收的比例),如果不正常是不是有内存泄露;如果还是正常的,继续往下排查。
2.2vmThread其实就是一直处理VMOP(虚拟机操作这样的事件,由一个队列维护,这样的事件可能是gc、threaddump、jit优化等很多,可以网上搜索一下)。这里VMOP因为是要读取线程状态、或者内存堆对象情况,就会要所有所有线程进入安全点,然后暂停(STW),再做VMOP的操作,比如threadDump,最后再释放/清除(具体的过程,可以网上再看看,会更仔细些)。

上面2.2这里会出现除gc外导致的应用暂停。比如:进入safePoint比较慢 和 vmop操作执行本身耗时比较严重。

这两个点,可以自行百度下。我遇到过的一种是vmop本身比较慢的情况。

java启动命令增加参数:
打印SafePoint信息,显示程序停止时间
-XX:+PrintApplicationStoppedTime(程序暂停了多少时间) -XX:+PrintGCApplicationConcurrentTime(两次连续暂停的时间间隔)

打印引起SafePoint的操作、线程运行情况等
-XX:+PrintSafepointStatistics -XX:PrintSafepointStatisticsCount=1

PrintApplicationStoppedTime >>> 输出安全点日志耗时情况(应用线程停止时间、停止线程花费时间)>> 两者差就是引起safepoint的vmoption对应的消耗时间
Total time for which application threads were stopped: 0.0572646 seconds, Stopping threads took: 0.0000088 seconds

PrintSafepointStatistics >>> 会输出vmop的操作以及响应的耗时 >>> 其输出的日志在控制台不在业务日志和gc日志中

vmop [threads: total initially_running wait_to_block] [time: spin block sync cleanup vmop] page_trap_count
18521.041: FindDeadlocks [ 1594 0 0 ] [ 0 0 0 3 0 ] 0
vmop [threads: total initially_running wait_to_block] [time: spin block sync cleanup vmop] page_trap_count
18521.045: FindDeadlocks [ 1594 0 0 ] [ 0 0 0 3 0 ] 0
--
vmop [threads: total initially_running wait_to_block] [time: spin block sync cleanup vmop] page_trap_count
18521.332: ThreadDump [ 1594 0 0 ] [ 0 0 0 3 3339 ] 0
--
vmop [threads: total initially_running wait_to_block] [time: spin block sync cleanup vmop] page_trap_count
18524.691: RevokeBias [ 1594 0 0 ] [ 0 0 0 3 0 ] 0
vmop [threads: total initially_running wait_to_block] [time: spin block sync cleanup vmop] page_trap_count
18524.697: RevokeBias [ 1594 0 0 ] [ 0 0 0 3 0 ] 0
--

发现 ThreadDump vm自身耗时 3339 ,这个时间可以跟PrintApplicationStoppedTime输出的日志(在gc日志文件中)对应上(上面的日志,是我找的两个例子拼凑的,差对不上)

不断地dump肯定不是人为处理,推断是系统对外的jmx接口被调用导致,不断地触发,排查java启动命令是包含agent(prometheus)的,去除掉后,问题不再出现。

更合理的方式是:
endpoints.dump.enabled=false (springboot项目)

它对应的代码是:
@ConfigurationProperties(prefix = "endpoints.dump")
public class DumpEndpoint extends AbstractEndpoint<List<ThreadInfo>> {

/**
 * Create a new {@link DumpEndpoint} instance.
 */
public DumpEndpoint() {
	super("dump");
}

@Override
public List<ThreadInfo> invoke() {
	return Arrays.asList(ManagementFactory.getThreadMXBean().dumpAllThreads(true, true));
}

}

处理后,暂没有threadDump的情况发生。

10月前回复
回复 江户川:

因为进入安全点的触发动作就只有一个线程(VMThread)会执行,所以也只会有一个核占用比较高也正常,这个持续过程如果能抓到,并通过perf跟踪下那会的情况就好了,sys高肯定有有问题的,这个已经和你写得java代码没有关系了

2年前回复
回复 你假笨:

笨神你好,后来又出现了很多这样的情况,IO 看起来是正常的,但是 CPU 的某个核的 sys 达到 100%,这个程序的 JVM 是在 yarn 的 container 中运行的。cpu 某个核 sys 过高会是 Java 程序本身的原因吗?应该怎么排查呢

2年前回复

期待大佬解读

2年前

补充一下使用的GC算法:-XX:+UseParallelGC

2年前