一次高IO下的GC分析之旅

起因：收到GC STW报警

【监控系统】Total time for which application threads were stopped: 67.7651070 seconds, Stopping threads took: 0.0000240 seconds

快速分析原因

此处不分析具体GC日志，主要分析方法:

• 从线上拷贝日志到本地
• 打包成gc.zip格式
• 上传到gceasy.io

找到原因

找到是因为缺IO或内存资源导致高IO，并不是GC本身过程耗时太多(上一步GC的报告中获得)：

通过监控系统，找到当时机器IO飙升(公司内部监控机器的平台，zabbix实时收集机器的一些状态)：

深层次原因

整个应用程序的停顿主要由两部分组成：由于JVM GC行为造成的停顿(T1->T2)，以及为了记录JVM GC日志(T3->T4)，系统调用write()被OS阻塞的时间。下面这张图展示了二者之间的关系。

解决方案

首先，JVM实现完全可以解决掉这个问题。显然，如果将写GC日志的操作与可能会导致STW停顿的JVM GC处理过程分开，这个问题自然就不存在了。例如，JVM可以将记录GC日志的功能放到另一个线程中，独立来处理日志文件的写入，这样就不会增加STW停顿的时间了。但是，这种采用其他线程来处理的方式，可能会导致在JVM崩溃时丢失最后的GC日志信息。最好的方式，可能是提供一个JVM选项，让用户来选择适合的方式,但这个方法基本没办法我们自己来处理。 由于后台IO造成的STW停顿时间，与IO的繁重程度有关，所以我们可以采用多种方式来降低后台IO的压力。例如，不要在同一节点上安装其他IO密集型的应用程序，减少其他类型的日志行为，提高日志回滚频率等等。

我们最后的解决办法是将GC日志文件放到其他低IO磁盘上，把gc日志放到图中的/data2,很明显从iostat来看它的磁盘IO压力很小。