性能文章>FGC实战:如何用Idea揪出开源组件调用System.gc导致频繁FGC>

FGC实战:如何用Idea揪出开源组件调用System.gc导致频繁FGC原创

2年前
7732010

某天上午收到最近发布的一个服务频繁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 < 10; i++) {
            excelGen();
        }
    }

    private static void excelGen() throws Exception {
        WritableWorkbook book = null;
        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。之所以这么做,是为了笔者接下来介绍的方法能更精确的定位问题所在:

<!-- https://mvnrepository.com/artifact/net.sourceforge.jexcelapi/jxl -->
<dependency>
    <groupId>net.sourceforge.jexcelapi</groupId>
    <artifactId>jxl</artifactId>
    <version>2.6.12</version>
</dependency>

接下来就是笔者介绍的方法:如何通过牛逼的IDEA找出是哪里调用了System.gc()。在搜索触发FGC的元凶之前,需要先下载jxl的源码–这段重现问题源码唯一的Maven依赖。这个下载必不可少,否则IDEA是无法搜到的:

image.png

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():

image.png

如果jxl源码下载后,Find in Path中选择范围Project and Libraries后搜索System.gc()的结果应该如下所示,红色框中就是依赖的开源组件jxl调用System.gc的地方:

image.png

现在范围就很小很小了,经过代码排查,我们很快就发现是在调用WritableWorkbook的close()方法时调用了System.gc(),从而触发了FGC。

image.png

很多同学可能会想到通过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异常,或者有堆外内存泄漏的情况(堆外内存只升不降)。幸运的是,没有任何问题。开心!

分类:标签:
请先登录,感受更多精彩内容
快去登录吧,你将获得
  • 浏览更多精彩评论
  • 和开发者讨论交流,共同进步

为你推荐

不起眼,但是足以让你有收获的JVM内存分析案例
分析 这个问题说白了,就是说有些int[]对象不知道是哪里来的,于是我拿他的例子跑了跑,好像还真有这么回事。点该 dump 文件详情,查看相关的 int[] 数组,点该对象的“被引用对象”,发现所
从一起GC血案谈到反射原理
前言 首先回答一下提问者的问题。这主要是由于存在大量反射而产生的临时类加载器和 ASM 临时生成的类,这些类会被保留在 Metaspace,一旦 Metaspace 即将满的时候,就会触发 Fu
关于内存溢出,咱再聊点有意思的?
概述 上篇文章讲了JVM在GC上的一个设计缺陷,揪出一个导致GC慢慢变长的JVM设计缺陷,可能有不少人还是没怎么看明白的,今天准备讲的大家应该都很容易看明白 本文其实很犹豫写不写,因为感觉没有
协助美团kafka团队定位到的一个JVM Crash问题
概述 有挺长一段时间没写技术文章了,正好这两天美团kafka团队有位小伙伴加了我微信,然后咨询了一个JVM crash的问题,大家对crash的问题都比较无奈,因为没有现场,信息量不多,碰到这类问题我
又发现一个导致JVM物理内存消耗大的Bug(已提交Patch)
概述 最近我们公司在帮一个客户查一个JVM的问题(JDK1.8.0_191-b12),发现一个系统老是被OS Kill掉,是内存泄露导致的。在查的过程中,阴差阳错地发现了JVM另外的一个Bug。这个B
JVM实战:优化我的IDEA GC
IDEA是个好东西,可以说是地球上最好的Java开发工具,但是偶尔也会卡顿,仔细想想IDEA也是Java开发的,会不会和GC有关,于是就有了接下来对IDEA的GC进行调优 IDEA默认JVM参数: -
不起眼,但是足以让你收获的JVM内存案例
今天的这个案例我觉得应该会让你涨姿势吧,不管你对JVM有多熟悉,看到这篇文章,应该还是会有点小惊讶的,不过我觉得这个案例我分享出来,是想表达不管多么奇怪的现象请一定要追究下去,会让你慢慢变得强大起来,
如何通过反射获得方法的真实参数名(以及扩展研究)
前段时间,在做一个小的工程时,遇到了需要通过反射获得方法真实参数名的场景,在这里我遇到了一些小小的问题,后来在部门老大的指导下,我解决了这个问题。通过解决这个问题,附带着我了解到了很多新的知识,我觉得