記一次Java服務頻繁Full GC的排查過程

現象

從監控來看，堆內存是夠用的，可是頻繁觸發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 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類的對象比較多，再作進一步的分析就不知如何下手了。

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) {

            }
        }
    }
}複製代碼

以爲不錯請點贊支持，歡迎留言或進個人我的羣855801563領取【架構資料專題目合集90期】、【BATJTMD大廠JAVA面試真題1000+】，本羣專用於學習交流技術、分享面試機會，拒絕廣告，我也會在羣內不按期答題、探討。