记一次Java服务频繁Full GC的排查过程

现象

从监控来看,堆内存是够用的,但是频繁触发Full GC,每秒钟三次,每次耗时三四秒。

image.png

结合Young GC的信息和堆内存的使用情况,可以发现新生代的内存够用,老生代的内存不够用,频繁Full GC,老生代的内存使用率依旧达到了98%。

2018-11-20T15:02:46.002+0800: 2779214.232: [GC2018-11-20T15:02:46.002+0800: 2779214.232: [ParNew: 1643604K->4513K(1843200K), 0.0129920 secs] 4994360K->3355569K(5257216K), 0.0131040 secs] [Times: user=0.05 sys=0.00, real=0.01 secs]
$ sudo jmap -heap 11927
Attaching to process ID 11927, please wait...
Debugger attached successfully.
Server compiler detected.
JVM version is 24.65-b04-internal

using parallel threads in the new generation.
using thread-local object allocation.
Concurrent Mark-Sweep GC

Heap Configuration:
   MinHeapFreeRatio = 40
   MaxHeapFreeRatio = 70
   MaxHeapSize      = 5593104384 (5334.0MB)
   NewSize          = 2097152000 (2000.0MB)
   MaxNewSize       = 2097152000 (2000.0MB)
   OldSize          = 5439488 (5.1875MB)
   NewRatio         = 2
   SurvivorRatio    = 8
   PermSize         = 536870912 (512.0MB)
   MaxPermSize      = 536870912 (512.0MB)
   G1HeapRegionSize = 0 (0.0MB)

Heap Usage:
New Generation (Eden + 1 Survivor Space):
   capacity = 1887436800 (1800.0MB)
   used     = 899619040 (857.9435729980469MB)
   free     = 987817760 (942.0564270019531MB)
   47.66353183322482% used
Eden Space:
   capacity = 1677721600 (1600.0MB)
   used     = 895864384 (854.3628540039062MB)
   free     = 781857216 (745.6371459960938MB)
   53.39767837524414% used
From Space:
   capacity = 209715200 (200.0MB)
   used     = 3754656 (3.580718994140625MB)
   free     = 205960544 (196.41928100585938MB)
   1.7903594970703125% used
To Space:
   capacity = 209715200 (200.0MB)
   used     = 0 (0.0MB)
   free     = 209715200 (200.0MB)
   0.0% used
concurrent mark-sweep generation:
   capacity = 3495952384 (3334.0MB)
   used     = 3432530640 (3273.516311645508MB)
   free     = 63421744 (60.48368835449219MB)
   98.18585217892945% used
Perm Generation:
   capacity = 536870912 (512.0MB)
   used     = 52807616 (50.36126708984375MB)
   free     = 484063296 (461.63873291015625MB)
   9.836184978485107% used

28784 interned Strings occupying 3175392 bytes.

排查过程

这种现象表明,服务存在内存泄露,所以需要分析堆的使用。使用gcore产生core文件,这比直接使用jmap dump快得多,可以避免对线上服务造成影响。core文件的大小跟进程使用的堆大小一样大。

$ sudo gcore 11927
[Thread debugging using libthread_db enabled]
[New Thread 0x487ac940 (LWP 1653)]
[New Thread 0x486ab940 (LWP 1652)]
[New Thread 0x485aa940 (LWP 1651)]
0x00000030f0e07ba5 in pthread_join () from /lib64/libpthread.so.0

Saved corefile core.11927

使用jmap将core文件转换成bin文件。hprof文件跟进程实际使用的堆内存一样大。

$sudo jmap -dump:format=b,file=heap.hprof.bin /opt/taobao/java/bin/java core.11927
Attaching to core core.11927 from executable /opt/taobao/java/bin/java, please wait...
Debugger attached successfully.
Server compiler detected.
JVM version is 24.65-b04-internal
Dumping heap to heap.hprof.bin ...

这个转换过程非常慢。将5.3GB的core转换成4GB的hprof文件,花了将近半个小时。通过top来看,这个dump是单线程做的,一直跑满了一个核。

top - 15:43:38 up 214 days,  1:02,  2 users,  load average: 1.69, 1.83, 1.56
Tasks: 142 total,   1 running, 141 sleeping,   0 stopped,   0 zombie
Cpu(s): 51.5%us,  0.8%sy,  0.0%ni, 47.7%id,  0.0%wa,  0.0%hi,  0.0%si,  0.0%st
Mem:   8194164k total,  8135628k used,    58536k free,    75324k buffers
Swap:        0k total,        0k used,        0k free,   797688k cached

  PID USER      PR  NI  VIRT  RES  SHR S %CPU %MEM    TIME+  COMMAND
11927 www       20   0 6513m 5.3g  82m S 105.5 67.4  10760:36 java
 3764 root      20   0 2458m 791m  12m S 100.5  9.9  18:53.36 jmap
16376 root      20   0  411m 360m 1468 S  0.0  4.5  19:52.15 syslog-ng
11190 agent     20   0  540m 143m 5832 S  0.0  1.8  65:14.77 java

接着就是如何分析这个hprof文件的问题。目前主流的分析工具,有MAT和jhat,下面分别使用二者分析一下。

jhat

jhat看起来比较简单,从分析结果里面可以看出用户自定义类中,SlsRecordWriter类的对象比较多,再做进一步的分析就不知如何下手了。

image.png
image.png

MAT

MAT体验比较好,直接分析出持有内存最大的类,然后从dominator_tree里面可以看到具体的应用情况,可以发现SlsRecordWriter对象很多。需要注意的是,使用MAT分析大的dump文件很吃内存,所以需要调大堆内存。Mac上Eclipse的配置文件路径是/Applications/Eclipse.app/Contents/Eclipse/eclipse.ini

image.png
image.png

结论

构造一个demo验证一下。下面这个例子,运行一段时间便会触发Young GC(IDEA VM options设置上"-verbose:gc -XX:+PrintGCDetails"),但是从来不会调用Foo的finalize方法,只有停止运行的时候,才会进入hook执行,接着释放对象。如果注释掉addShutdownHook这段代码,就符合期望了。所以addShutdownHook会导致Runtime持有对象,需要注意使用场景。

class Foo {

    private String bar = new String("fdsaflkjdsalfjldsajflsajfoiwefnaslfjlaskejfowieajfalfjelajfieslkjflksdajlf");

    private int num = 0;

    public Foo() {
    }

    public Foo(int num) {

        System.out.println(String.format("Foo initialize: %d", num));

        this.num = num;

        Runtime.getRuntime().addShutdownHook(new Thread(new Runnable() {
            public void run() {
                clean();
            }
        }));
    }

    void clean() {

        System.out.println(String.format("Foo clean: %d", num));
    }

    @Override
    protected void finalize() throws Throwable {
        super.finalize();

        System.out.println(String.format("foo finalize: %d", this.num));
    }
}

public class Demo {

    public static void main(String[] args) {

        int num = 0;

        while (true) {
            try {
                Foo foo = new Foo(num);
                num += 1;
                Thread.sleep(100);
            }catch (Exception e) {

            }
        }
    }
}

参考资料

  1. 阿里巴巴JDK故障排查指南
最后编辑于
©著作权归作者所有,转载或内容合作请联系作者
  • 序言:七十年代末,一起剥皮案震惊了整个滨河市,随后出现的几起案子,更是在滨河造成了极大的恐慌,老刑警刘岩,带你破解...
    沈念sama阅读 206,126评论 6 481
  • 序言:滨河连续发生了三起死亡事件,死亡现场离奇诡异,居然都是意外死亡,警方通过查阅死者的电脑和手机,发现死者居然都...
    沈念sama阅读 88,254评论 2 382
  • 文/潘晓璐 我一进店门,熙熙楼的掌柜王于贵愁眉苦脸地迎上来,“玉大人,你说我怎么就摊上这事。” “怎么了?”我有些...
    开封第一讲书人阅读 152,445评论 0 341
  • 文/不坏的土叔 我叫张陵,是天一观的道长。 经常有香客问我,道长,这世上最难降的妖魔是什么? 我笑而不...
    开封第一讲书人阅读 55,185评论 1 278
  • 正文 为了忘掉前任,我火速办了婚礼,结果婚礼上,老公的妹妹穿的比我还像新娘。我一直安慰自己,他们只是感情好,可当我...
    茶点故事阅读 64,178评论 5 371
  • 文/花漫 我一把揭开白布。 她就那样静静地躺着,像睡着了一般。 火红的嫁衣衬着肌肤如雪。 梳的纹丝不乱的头发上,一...
    开封第一讲书人阅读 48,970评论 1 284
  • 那天,我揣着相机与录音,去河边找鬼。 笑死,一个胖子当着我的面吹牛,可吹牛的内容都是我干的。 我是一名探鬼主播,决...
    沈念sama阅读 38,276评论 3 399
  • 文/苍兰香墨 我猛地睁开眼,长吁一口气:“原来是场噩梦啊……” “哼!你这毒妇竟也来了?” 一声冷哼从身侧响起,我...
    开封第一讲书人阅读 36,927评论 0 259
  • 序言:老挝万荣一对情侣失踪,失踪者是张志新(化名)和其女友刘颖,没想到半个月后,有当地人在树林里发现了一具尸体,经...
    沈念sama阅读 43,400评论 1 300
  • 正文 独居荒郊野岭守林人离奇死亡,尸身上长有42处带血的脓包…… 初始之章·张勋 以下内容为张勋视角 年9月15日...
    茶点故事阅读 35,883评论 2 323
  • 正文 我和宋清朗相恋三年,在试婚纱的时候发现自己被绿了。 大学时的朋友给我发了我未婚夫和他白月光在一起吃饭的照片。...
    茶点故事阅读 37,997评论 1 333
  • 序言:一个原本活蹦乱跳的男人离奇死亡,死状恐怖,灵堂内的尸体忽然破棺而出,到底是诈尸还是另有隐情,我是刑警宁泽,带...
    沈念sama阅读 33,646评论 4 322
  • 正文 年R本政府宣布,位于F岛的核电站,受9级特大地震影响,放射性物质发生泄漏。R本人自食恶果不足惜,却给世界环境...
    茶点故事阅读 39,213评论 3 307
  • 文/蒙蒙 一、第九天 我趴在偏房一处隐蔽的房顶上张望。 院中可真热闹,春花似锦、人声如沸。这庄子的主人今日做“春日...
    开封第一讲书人阅读 30,204评论 0 19
  • 文/苍兰香墨 我抬头看了看天上的太阳。三九已至,却和暖如春,着一层夹袄步出监牢的瞬间,已是汗流浃背。 一阵脚步声响...
    开封第一讲书人阅读 31,423评论 1 260
  • 我被黑心中介骗来泰国打工, 没想到刚下飞机就差点儿被人妖公主榨干…… 1. 我叫王不留,地道东北人。 一个月前我还...
    沈念sama阅读 45,423评论 2 352
  • 正文 我出身青楼,却偏偏与公主长得像,于是被迫代替她去往敌国和亲。 传闻我的和亲对象是个残疾皇子,可洞房花烛夜当晚...
    茶点故事阅读 42,722评论 2 345

推荐阅读更多精彩内容

  • 上周自己负责的一个应用出现频繁full gc的问题,不得不尝试优化一下。第一次做这种事只能先看看网上的文章,然后亲...
    Acamy丶阅读 6,744评论 0 8
  • 被文同时发布在CSDN上,欢迎查看。 APP内存的使用,是评价一款应用性能高低的一个重要指标。虽然现在智能手机的内...
    大圣代阅读 4,803评论 2 54
  • 内存管理的目的就是让我们在开发中怎么有效的避免我们的应用出现内存泄漏的问题。内存泄漏大家都不陌生了,简单粗俗的讲,...
    宇宙只有巴掌大阅读 2,360评论 0 12
  • Java 应用性能优化是一个老生常谈的话题,典型的性能问题如页面响应慢、接口超时,服务器负载高、并发数低,数据库频...
    Rick617阅读 7,320评论 1 9
  • 好喜欢这个APP啊,就像写日记一样,反正也不会有人看到。 不知道从什么时候开始不喜欢在朋友圈发东西了,很多情绪也没...
    柚子晶阅读 119评论 0 0