FGC实战：如何用Idea揪出开源元件呼叫System.gc导致频繁FGC
某天上午收到最近释出的一个服务频繁FGC的告警，这个服务只是给公司内部相关人员使用的，并非给互联网使用者提供服务的系统。而且功能也比较简单，就是检视一些统计资讯、报表资料、资料汇出Excel等，访问量非常低。
另外，由于这个服务并不是OLTP，所以就是简单的使用预设的ParallGC垃圾回收器，JVM引数也只是做了简单的配置：
-Xmx512m -Xms512m -Xmn256m XX:+PrintGCDetails -XX:+PrintGCDateStamps -Xloggc:/log/gc/gc.log -XX:+HeapDumpOnOutOfMemoryError -XX:HeapDumpPath=/log/dump
关键线索
废话不多说，既然有FGC，那就首先检视GC日志。毕竟FGC的原因还是比较多的，GC日志也是最直观的展示FGC原因的证据之一。这里要补充一句，我们在排查问题时，切记不要靠自己的主观意识猜测，而应该做到每一步的推断都有理有据，这样才能越来越接近真相，找出真正的凶手。
GC日志中寻找FGC的命令以及结果如下所示（只贴出部分）：
afeideMacBook-Pro:jvm afei$ grep "full gc" -i gc.log
2019-06-15T09:35:04.168-0800: [Full GC (System.gc()) [PSYoungGen: 6963K->0K(229376K)] [ParOldGen: 8K->6793K(262144K)] 6971K->6793K(491520K), [Metaspace: 5160K->5160K(1056768K)], 0.0085889 secs] [Times: user=0.03 sys=0.01, real=0.01 secs]
2019-06-15T09:40:08.520-0800: [Full GC (System.gc()) [PSYoungGen: 5184K->0K(229376K)] [ParOldGen: 6793K->6090K(262144K)] 11977K->6090K(491520K), [Metaspace: 5168K->5168K(1056768K)], 0.0085573 secs] [Times: user=0.01 sys=0.00, real=0.00 secs]
... ...
根据这段GC日志就能非常肯定：是因为某些地方呼叫System.gc触发的FGC。
因为这个服务访问亮比较小，并发量并不高。所以，笔者想看看触发FGC的时候，服务被呼叫了什么界面（如果是并发很高的OLTP，这种方法可能就不是很适用，毕竟每秒TPS成百上千，甚至更大，根本无法确定是哪个界面引起的）。
以上面这段FGC日志，根据其触发的时间点，然后去系统业务日志中查询。很顺利我们就找到了这个时候是呼叫了一个汇出报表资料到Excel并下载的界面。一开始我还有点怀疑会不会是汇出资料量很大引起FGC，但是后面走读业务程式码，发现汇出资料限制最大不超过1000，所以，这个猜想也就被否定了。
重现问题
既然是汇出Excel引起的，那么笔者就打算模拟这段程式码，试图以最小量的程式码看是否能重现这个问题。毕竟：范围越小，距离真相也就越近。所以，笔者根据这个界面的业务程式码，等价的写出了下面这段程式码：
public class JxlTest {
public static void main(String[] args) throws Exception {
for (int i = 0; i excelGen;
}
}
private static void excelGen throws Exception {
WritableWorkbook book = ;
WritableSheet sheet;
try {
book = Workbook.createWorkbook(new File("/Users/litian/afei.xls"));
sheet = book.createSheet("PageNo.1", 0);
Label label = new Label(0, 0, "公众号：【阿飞的部落格】");
sheet.addCell(label);
book.write;
} catch (Exception e) {
e.printStackTrace;
} finally {
book.close;
}
}
}
配套的JVM引数如下，接下来执行这段程式码即可。过程是如此顺利，10次Excel操作，10次FGC：
-XX:+PrintGCDateStamps -XX:+PrintGCDetails
-Xmx512m -Xms512m -Xmn256m
-verbose:gc
之所以用这段JVM引数，是为了希望通过-verbose:gc将GC日志直接输出到idea的控制台，而不是将GC日志输出到GC日志档案中，这样更方便定位问题。而且这段JVM引数相比生产环境的JVM引数，堆的大小和比例都是一样的，垃圾回收器也都是预设的。
既然重现问题了，那就相当于问题解决了一半。窃喜，哈哈哈～～～
另辟蹊径
事实上定位这种问题最常见的方法还是借助btrace跟踪是哪里呼叫了System.gc，毕竟，如果不能像笔者这种场景用一段很小的程式码重现问题，笔者接下来介绍的方法可行性就不是很高。但是既然重现了，那么笔者今天就介绍另外一个门槛更低的办法：借助IDEA强大的搜寻功能。毕竟定位问题不是为了炫技，只要能找出问题的办法，都是好办法。需要说明的，这段程式码笔者是在一个新建的Maven工程中执行的，这段程式码只依赖了一个jxl。之所以这么做，是为了笔者接下来介绍的方法能更精确的定位问题所在：
net.sourceforge.jexcelapi
jxl
2.6.12
接下来就是笔者介绍的方法：如何通过牛逼的IDEA找出是哪里呼叫了System.gc。在搜寻触发FGC的元凶之前，需要先下载jxl的源代码--这段重现问题源代码唯一的Maven依赖。这个下载必不可少，否则IDEA是无法搜到的：
jxl源代码下载完成后，就是开启IDEA强大的搜寻了，由于有些同学是Window，有些同学是Mac，快捷键可能不同。所以笔者不介绍开启这个搜寻功能的快捷键，而是介绍开启这个搜寻功能的路径：
# 这里是Find in Path，而不是Find
Edit->Find->Find in Path
# 范围选择
Scope->Custom->Project and Libraries
需要再次强调，一定要先通过idea下载jxl的源代码，否则Find in Path是搜不到专案依赖的jxl中的内容。如下图所示，只能搜到jdk源代码中哪些地方呼叫了System.gc：
如果jxl源代码下载后，Find in Path中选择范围Project and Libraries后搜寻System.gc的结果应该如下所示，红色框中就是依赖的开源元件jxl呼叫System.gc的地方：
现在范围就很小很小了，经过程式码排查，我们很快就发现是在呼叫WritableWorkbook的close方法时呼叫了System.gc，从而触发了FGC。
很多同学可能会想到通过JVM引数-XX:+DisableExplicitGC来遮蔽掉System.gc的呼叫，这不是解决问题，而是掩盖问题。而且事实上，这里还有更好的办法，请继续往下看。
解决方案
我们排查jxl中所有呼叫System.gc的地方，发现都是下面这种姿势。Bingo，那么我们只需要将workbookSettings中gcDisabled这个字段的值设定为true就不会呼叫System.gc了：if (!workbookSettings.getGCDisabled)
{
System.gc;
}
gcDisabled设定为true非常简单，只需要稍微改造一下Workbook.createWorkbook即可：
WorkbookSettings settings = new WorkbookSettings;
settings.setGCDisabled(true);
book = Workbook.createWorkbook(new File("/Users/litian/afei.xls"), settings);
程式码改造后再次执行，再也不会有呼叫System.gc触发FGC了。美滋滋呀～～
需要说明的是，最后还需要对这段程式码进行压测，不断循环呼叫，看看是否GC异常，或者有堆外内存泄漏的情况（堆外内存只升不降）。幸运的是，没有任何问题。开心！
【阿飞的部落格】公众号二维码
↓↓↓↓
