现象

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

结合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 11927Attaching to process ID 11927, please wait...Debugger attached successfully.Server compiler detected.JVM version is 24.65-b04-internalusing parallel threads in the new generation.using thread-local object allocation.Concurrent Mark-Sweep GCHeap 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% usedEden Space:   capacity = 1677721600 (1600.0MB)   used     = 895864384 (854.3628540039062MB)   free     = 781857216 (745.6371459960938MB)   53.39767837524414% usedFrom Space:   capacity = 209715200 (200.0MB)   used     = 3754656 (3.580718994140625MB)   free     = 205960544 (196.41928100585938MB)   1.7903594970703125% usedTo Space:   capacity = 209715200 (200.0MB)   used     = 0 (0.0MB)   free     = 209715200 (200.0MB)   0.0% usedconcurrent mark-sweep generation:   capacity = 3495952384 (3334.0MB)   used     = 3432530640 (3273.516311645508MB)   free     = 63421744 (60.48368835449219MB)   98.18585217892945% usedPerm Generation:   capacity = 536870912 (512.0MB)   used     = 52807616 (50.36126708984375MB)   free     = 484063296 (461.63873291015625MB)   9.836184978485107% used28784 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.0Saved corefile core.11927复制代码

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

$sudo jmap -dump:format=b,file=heap.hprof.bin /opt/taobao/java/bin/java core.11927Attaching 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-internalDumping 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.56Tasks: 142 total,   1 running, 141 sleeping,   0 stopped,   0 zombieCpu(s): 51.5%us,  0.8%sy,  0.0%ni, 47.7%id,  0.0%wa,  0.0%hi,  0.0%si,  0.0%stMem:   8194164k total,  8135628k used,    58536k free,    75324k buffersSwap:        0k total,        0k used,        0k free,   797688k cached  PID USER      PR  NI  VIRT  RES  SHR S %CPU %MEM    TIME+  COMMAND11927 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 jmap16376 root      20   0  411m 360m 1468 S  0.0  4.5  19:52.15 syslog-ng11190 agent     20   0  540m 143m 5832 S  0.0  1.8  65:14.77 java复制代码

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

jhat

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

MAT

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

结论

构造一个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) {            }        }    }}复制代码