如何打印GC日志排查問題

在工作當(dāng)中，有時(shí)候我們會(huì)需要打印GC的相關(guān)信息來定位問題。該如何做呢？

先來看個(gè)示例

public static void main(String[] args) {
        List<Integer> list0 = new ArrayList<>();
        long start0 = System.currentTimeMillis();
        for (int i = 0; i < 1000000; i++) {
            list0.add(i);
        }
        System.out.println("cost: " + (System.currentTimeMillis() - start0));

        List<Integer> list1 = new ArrayList<>();
        long start1 = System.currentTimeMillis();
        for (int i = 0; i < 1000000; i++) {
            list1.add(i);
        }
        System.out.println("cost: " + (System.currentTimeMillis() - start1));
    }

直接運(yùn)行，結(jié)果如下

cost: 135

cost: 85

你應(yīng)該覺得奇怪，同樣的往一個(gè)list插入100萬條數(shù)據(jù)，為啥第一個(gè)耗時(shí)比較久？

這種時(shí)候，有經(jīng)驗(yàn)的工程師應(yīng)該能馬上懷疑是GC的問題，我們可以通過在運(yùn)行時(shí)添加JVM參數(shù)來打印程序運(yùn)行時(shí)的GC情況。

-XX:+PrintGCDetails

如果是使用IDEA來運(yùn)行，可以在 run configurations 的 VM options添加上面的參數(shù)即可。

再次運(yùn)行，輸出如下

[GC (Allocation Failure) [PSYoungGen: 1536K->512K(1536K)] 1884K->1234K(262144K), 0.0009030 secs] [Times: user=0.01 sys=0.00, real=0.00 secs]
[GC (Allocation Failure) [PSYoungGen: 1302K->1017K(2560K)] 2025K->1948K(263168K), 0.0012290 secs] [Times: user=0.01 sys=0.01, real=0.01 secs]
[GC (Allocation Failure) [PSYoungGen: 2553K->1504K(3072K)] 3484K->3051K(263680K), 0.0017210 secs] [Times: user=0.02 sys=0.00, real=0.00 secs]
[GC (Allocation Failure) [PSYoungGen: 3040K->2033K(4608K)] 4587K->4228K(265216K), 0.0023170 secs] [Times: user=0.02 sys=0.00, real=0.00 secs]
[GC (Allocation Failure) [PSYoungGen: 4593K->2560K(5120K)] 8195K->6681K(265728K), 0.0249700 secs] [Times: user=0.31 sys=0.00, real=0.03 secs]
[GC (Allocation Failure) [PSYoungGen: 5120K->3584K(6656K)] 11352K->11408K(267264K), 0.0241680 secs] [Times: user=0.30 sys=0.01, real=0.03 secs]
[GC (Allocation Failure) [PSYoungGen: 6656K->3296K(7680K)] 17645K->17909K(268288K), 0.0349010 secs] [Times: user=0.45 sys=0.00, real=0.03 secs]
[GC (Allocation Failure) [PSYoungGen: 6368K->3328K(10240K)] 25729K->25825K(270848K), 0.0314260 secs] [Times: user=0.40 sys=0.00, real=0.03 secs]
cost: 137
[GC (Allocation Failure) [PSYoungGen: 8166K->4469K(10240K)] 30663K->30103K(270848K), 0.0285370 secs] [Times: user=0.36 sys=0.01, real=0.03 secs]
[GC (Allocation Failure) [PSYoungGen: 9166K->3785K(13312K)] 34800K->33427K(273920K), 0.0226780 secs] [Times: user=0.28 sys=0.01, real=0.02 secs]
[GC (Allocation Failure) [PSYoungGen: 11465K->6142K(13824K)] 41107K->38511K(274432K), 0.0065540 secs] [Times: user=0.08 sys=0.00, real=0.00 secs]
[GC (Allocation Failure) [PSYoungGen: 13822K->7837K(19456K)] 46191K->44246K(280064K), 0.0099720 secs] [Times: user=0.11 sys=0.01, real=0.01 secs]
cost: 79

所以你大概明白了，第一次minor gc的次數(shù)比第二次多，所以運(yùn)行時(shí)間比較長。

那么上面打印出來的日志，具體是什么意思呢？

已經(jīng)有人畫出了很詳細(xì)的圖，我借來用下

如果想了解 GC 的更多的內(nèi)容，可以看看 oracle 官方對于 HosSpotJVM GC的詳細(xì)介紹

小結(jié)一下

了解GC日志的打印方法，并且能看懂GC日志，對于查找定位問題非常有幫助的。

我自己就遇到過生產(chǎn)上一個(gè)CPU飆到好幾百的情況，打印GC日志發(fā)現(xiàn) JVM 一直在 fullGC，而且每次GC之后內(nèi)存基本沒有變化，從而定位到應(yīng)用程序可能存在內(nèi)存泄漏的問題。

gc日志打印時(shí)間戳

今天發(fā)現(xiàn)在jvm參數(shù)中，用-XX:+PrintGCDateStamps 替換 -XX:PrintGCTimeStamps，就可以打印真實(shí)的gc時(shí)間信息，而不像現(xiàn)在相對啟動(dòng)時(shí)間的秒數(shù)。

有了真實(shí)時(shí)間戳，可以方便與應(yīng)用的log做對比，便于分析排查問題。

線下實(shí)驗(yàn)過，真實(shí)有效gc日志打印時(shí)間戳

以上為個(gè)人經(jīng)驗(yàn)，希望能給大家一個(gè)參考，也希望大家多多支持腳本之家。

最新評論