JVM 日志读取与解析

JVM 随着 Oracle 的快速发布策略，会经常发生变化。所以在一些版本行之有效的参数，可能在另一些新的版本里并不起作用。可以通过这个命令查看当前 JVM 默认的参数配置

java -XX:+PrintFlagsFinal

但是 JVM 的参数配置项很多，长长的列表上，很多配置项不需要我们修改。所以可以过滤并只关注我们需要的参数。

还有一个命令可用

java -XX:+PrintCommandLineFlags -version

gaopengdeMacBook-Pro-2:script gaopeng$ java -XX:+PrintCommandLineFlags -version
-XX:InitialHeapSize=134217728 -XX:MaxHeapSize=2147483648 -XX:+PrintCommandLineFlags -XX:+UseCompressedClassPointers -XX:+UseCompressedOops -XX:+UseParallelGC 
java version "1.8.0_221"
Java(TM) SE Runtime Environment (build 1.8.0_221-b11)
Java HotSpot(TM) 64-Bit Server VM (build 25.221-b11, mixed mode)

可以看到 JVM 采用了并行收集器，堆内存的初始化/最大值配置等。

一 gc 日志

线上机器的 GC 日志，需要在运行时加入相关的 JVM 参数，然后得到一个时间周期内的 GC 日志。GC 日志直接的可读性相对较低，需要了解日志各项内容的含义。

在本地测试的时候，我用了如下的 demo 代码：

public class PrintGCDetailsDemo {

    public static void main(String[] args) {
        int _1m = 1024*1024;
        byte[] data = new byte[_1m];

        data = null;

        System.gc();
    }
}

运行这段代码之前，在对应的 JVM 启动参数上添加变更：

-XX:+PrintGCDetails
-XX:+PrintGCTimeStamps
-XX:+PrintGCDateStamps
-XX:+PrintHeapAtGC
-Xloggc:/Users/gaopeng/gc.log

打印出详细的 GC 日志，并输出为文件。

要查看 GC 日志的详细内容。

Java HotSpot(TM) 64-Bit Server VM (25.221-b11) for bsd-amd64 JRE (1.8.0_221-b11), built on Jul  4 2019 04:36:22 by "java_re" with gcc 4.2.1 (Based on Apple Inc. build 5658) (LLVM build 2336.11.00)
Memory: 4k page, physical 8388608k(224720k free)

/proc/meminfo:

CommandLine flags: -XX:InitialHeapSize=134217728 -XX:MaxHeapSize=2147483648 -XX:+PrintGC -XX:+PrintGCDateStamps -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:+PrintHeapAtGC -XX:+UseCompressedClassPointers -XX:+UseCompressedOops -XX:+UseParallelGC 
{Heap before GC invocations=1 (full 0):
 PSYoungGen      total 38400K, used 3022K [0x0000000795580000, 0x0000000798000000, 0x00000007c0000000)
  eden space 33280K, 9% used [0x0000000795580000,0x0000000795873838,0x0000000797600000)
  from space 5120K, 0% used [0x0000000797b00000,0x0000000797b00000,0x0000000798000000)
  to   space 5120K, 0% used [0x0000000797600000,0x0000000797600000,0x0000000797b00000)
 ParOldGen       total 87552K, used 0K [0x0000000740000000, 0x0000000745580000, 0x0000000795580000)
  object space 87552K, 0% used [0x0000000740000000,0x0000000740000000,0x0000000745580000)
 Metaspace       used 2937K, capacity 4496K, committed 4864K, reserved 1056768K
  class space    used 320K, capacity 388K, committed 512K, reserved 1048576K
2020-10-21T16:40:16.802-0800: 0.107: [GC (System.gc()) [PSYoungGen: 3022K->544K(38400K)] 3022K->552K(125952K), 0.0012104 secs] [Times: user=0.01 sys=0.00, real=0.00 secs] 
Heap after GC invocations=1 (full 0):
 PSYoungGen      total 38400K, used 544K [0x0000000795580000, 0x0000000798000000, 0x00000007c0000000)
  eden space 33280K, 0% used [0x0000000795580000,0x0000000795580000,0x0000000797600000)
  from space 5120K, 10% used [0x0000000797600000,0x0000000797688000,0x0000000797b00000)
  to   space 5120K, 0% used [0x0000000797b00000,0x0000000797b00000,0x0000000798000000)
 ParOldGen       total 87552K, used 8K [0x0000000740000000, 0x0000000745580000, 0x0000000795580000)
  object space 87552K, 0% used [0x0000000740000000,0x0000000740002000,0x0000000745580000)
 Metaspace       used 2937K, capacity 4496K, committed 4864K, reserved 1056768K
  class space    used 320K, capacity 388K, committed 512K, reserved 1048576K
}
{Heap before GC invocations=2 (full 1):
 PSYoungGen      total 38400K, used 544K [0x0000000795580000, 0x0000000798000000, 0x00000007c0000000)
  eden space 33280K, 0% used [0x0000000795580000,0x0000000795580000,0x0000000797600000)
  from space 5120K, 10% used [0x0000000797600000,0x0000000797688000,0x0000000797b00000)
  to   space 5120K, 0% used [0x0000000797b00000,0x0000000797b00000,0x0000000798000000)
 ParOldGen       total 87552K, used 8K [0x0000000740000000, 0x0000000745580000, 0x0000000795580000)
  object space 87552K, 0% used [0x0000000740000000,0x0000000740002000,0x0000000745580000)
 Metaspace       used 2937K, capacity 4496K, committed 4864K, reserved 1056768K
  class space    used 320K, capacity 388K, committed 512K, reserved 1048576K
2020-10-21T16:40:16.803-0800: 0.108: [Full GC (System.gc()) [PSYoungGen: 544K->0K(38400K)] [ParOldGen: 8K->396K(87552K)] 552K->396K(125952K), [Metaspace: 2937K->2937K(1056768K)], 0.0036883 secs] [Times: user=0.01 sys=0.00, real=0.00 secs] 
Heap after GC invocations=2 (full 1):
 PSYoungGen      total 38400K, used 0K [0x0000000795580000, 0x0000000798000000, 0x00000007c0000000)
  eden space 33280K, 0% used [0x0000000795580000,0x0000000795580000,0x0000000797600000)
  from space 5120K, 0% used [0x0000000797600000,0x0000000797600000,0x0000000797b00000)
  to   space 5120K, 0% used [0x0000000797b00000,0x0000000797b00000,0x0000000798000000)
 ParOldGen       total 87552K, used 396K [0x0000000740000000, 0x0000000745580000, 0x0000000795580000)
  object space 87552K, 0% used [0x0000000740000000,0x0000000740063038,0x0000000745580000)
 Metaspace       used 2937K, capacity 4496K, committed 4864K, reserved 1056768K
  class space    used 320K, capacity 388K, committed 512K, reserved 1048576K
}
Heap
 PSYoungGen      total 38400K, used 998K [0x0000000795580000, 0x0000000798000000, 0x00000007c0000000)
  eden space 33280K, 3% used [0x0000000795580000,0x0000000795679b20,0x0000000797600000)
  from space 5120K, 0% used [0x0000000797600000,0x0000000797600000,0x0000000797b00000)
  to   space 5120K, 0% used [0x0000000797b00000,0x0000000797b00000,0x0000000798000000)
 ParOldGen       total 87552K, used 396K [0x0000000740000000, 0x0000000745580000, 0x0000000795580000)
  object space 87552K, 0% used [0x0000000740000000,0x0000000740063038,0x0000000745580000)
 Metaspace       used 2949K, capacity 4496K, committed 4864K, reserved 1056768K
  class space    used 322K, capacity 388K, committed 512K, reserved 1048576K

关于如何查看 gc 日志，就不在这里展开，有单独的篇章。youngGC 次数频繁，对系统的影响一般不会很大。需要注意的是 fullGC。

二 dump 内存快照

除了 gc 日志，还有一类文件是需要我们注意的。

.hprof

即内存转储快照。何时生成快照文件，需要在 JVM 中设置并重启。

-XX:+HeapDumpOnOutOfMemoryError
-XX:HeapDumpPath=/Users/gaopeng/

如上的 JVM 配置表示在系统内存溢出时保存内存快照文件到指定目录下。除了这个快照生成时机，还有两个配置项可用

HeapDumpAfterFullGC
HeapDumpBeforeFullGC

这两个配置项，是在使用

java -XX:+PrintFlagsFinal

查看系统全局配置时找到的，默认都是关闭状态。

我使用一个会导致内存溢出的 case:

public class HeapOOM {
    static class OOMObject {

    }

    public static void main(String[] args) {
        List<OOMObject> list = new ArrayList<>();

        while(true) {
            list.add(new OOMObject());
        }
    }
}

不断创建对象，并且也没有丢弃。然后设置较小的堆空间。

-verbose:gc
-Xms20M
-Xmx20M
-Xmn10M
-XX:+PrintGCDetails
-XX:+HeapDumpOnOutOfMemoryError
-XX:HeapDumpPath=/Users/gaopeng/

运行程序，很快就会报错

/Library/Java/JavaVirtualMachines/jdk1.8.0_221.jdk/Contents/Home/bin/java -verbose:gc -Xms20M -Xmx20M -Xmn10M -XX:+PrintGCDetails -XX:+HeapDumpOnOutOfMemoryError -XX:HeapDumpPath=/Users/gaopeng/ "-javaagent:/Applications/IntelliJ IDEA.app/Contents/lib/idea_rt.jar=54021:/Applications/IntelliJ IDEA.app/Contents/bin" -Dfile.encoding=UTF-8 -classpath /Library/Java/JavaVirtualMachines/jdk1.8.0_221.jdk/Contents/Home/jre/lib/charsets.jar:/Library/Java/JavaVirtualMachines/jdk1.8.0_221.jdk/Contents/Home/jre/lib/deploy.jar:/Library/Java/JavaVirtualMachines/jdk1.8.0_221.jdk/Contents/Home/jre/lib/ext/cldrdata.jar:/Library/Java/JavaVirtualMachines/jdk1.8.0_221.jdk/Contents/Home/jre/lib/ext/dnsns.jar:/Library/Java/JavaVirtualMachines/jdk1.8.0_221.jdk/Contents/Home/jre/lib/ext/jaccess.jar:/Library/Java/JavaVirtualMachines/jdk1.8.0_221.jdk/Contents/Home/jre/lib/ext/jfxrt.jar:/Library/Java/JavaVirtualMachines/jdk1.8.0_221.jdk/Contents/Home/jre/lib/ext/localedata.jar:/Library/Java/JavaVirtualMachines/jdk1.8.0_221.jdk/Contents/Home/jre/lib/ext/nashorn.jar:/Library/Java/JavaVirtualMachines/jdk1.8.0_221.jdk/Contents/Home/jre/lib/ext/sunec.jar:/Library/Java/JavaVirtualMachines/jdk1.8.0_221.jdk/Contents/Home/jre/lib/ext/sunjce_provider.jar:/Library/Java/JavaVirtualMachines/jdk1.8.0_221.jdk/Contents/Home/jre/lib/ext/sunpkcs11.jar:/Library/Java/JavaVirtualMachines/jdk1.8.0_221.jdk/Contents/Home/jre/lib/ext/zipfs.jar:/Library/Java/JavaVirtualMachines/jdk1.8.0_221.jdk/Contents/Home/jre/lib/javaws.jar:/Library/Java/JavaVirtualMachines/jdk1.8.0_221.jdk/Contents/Home/jre/lib/jce.jar:/Library/Java/JavaVirtualMachines/jdk1.8.0_221.jdk/Contents/Home/jre/lib/jfr.jar:/Library/Java/JavaVirtualMachines/jdk1.8.0_221.jdk/Contents/Home/jre/lib/jfxswt.jar:/Library/Java/JavaVirtualMachines/jdk1.8.0_221.jdk/Contents/Home/jre/lib/jsse.jar:/Library/Java/JavaVirtualMachines/jdk1.8.0_221.jdk/Contents/Home/jre/lib/management-agent.jar:/Library/Java/JavaVirtualMachines/jdk1.8.0_221.jdk/Contents/Home/jre/lib/plugin.jar:/Library/Java/JavaVirtualMachines/jdk1.8.0_221.jdk/Contents/Home/jre/lib/resources.jar:/Library/Java/JavaVirtualMachines/jdk1.8.0_221.jdk/Contents/Home/jre/lib/rt.jar:/Library/Java/JavaVirtualMachines/jdk1.8.0_221.jdk/Contents/Home/lib/ant-javafx.jar:/Library/Java/JavaVirtualMachines/jdk1.8.0_221.jdk/Contents/Home/lib/dt.jar:/Library/Java/JavaVirtualMachines/jdk1.8.0_221.jdk/Contents/Home/lib/javafx-mx.jar:/Library/Java/JavaVirtualMachines/jdk1.8.0_221.jdk/Contents/Home/lib/jconsole.jar:/Library/Java/JavaVirtualMachines/jdk1.8.0_221.jdk/Contents/Home/lib/packager.jar:/Library/Java/JavaVirtualMachines/jdk1.8.0_221.jdk/Contents/Home/lib/sa-jdi.jar:/Library/Java/JavaVirtualMachines/jdk1.8.0_221.jdk/Contents/Home/lib/tools.jar:/Users/sina/netty/target/classes:/Users/gaopeng/.m2/repository/io/netty/netty-all/4.1.51.Final/netty-all-4.1.51.Final.jar com.gaop.netty.bio.HeapOOM
[GC (Allocation Failure) [PSYoungGen: 8192K->1008K(9216K)] 8192K->5041K(19456K), 0.0073478 secs] [Times: user=0.03 sys=0.00, real=0.00 secs] 
[GC (Allocation Failure) --[PSYoungGen: 9200K->9200K(9216K)] 13233K->19432K(19456K), 0.0121535 secs] [Times: user=0.05 sys=0.00, real=0.01 secs] 
[Full GC (Ergonomics) [PSYoungGen: 9200K->0K(9216K)] [ParOldGen: 10232K->9753K(10240K)] 19432K->9753K(19456K), [Metaspace: 3091K->3091K(1056768K)], 0.1368537 secs] [Times: user=0.40 sys=0.01, real=0.14 secs] 
[Full GC (Ergonomics) [PSYoungGen: 7859K->8108K(9216K)] [ParOldGen: 9753K->7643K(10240K)] 17613K->15751K(19456K), [Metaspace: 3091K->3091K(1056768K)], 0.1691025 secs] [Times: user=0.47 sys=0.01, real=0.17 secs] 
[Full GC (Allocation Failure) [PSYoungGen: 8108K->8090K(9216K)] [ParOldGen: 7643K->7643K(10240K)] 15751K->15733K(19456K), [Metaspace: 3091K->3091K(1056768K)], 0.0967636 secs] [Times: user=0.40 sys=0.00, real=0.09 secs] 
java.lang.OutOfMemoryError: Java heap space
Dumping heap to /Users/gaopeng/java_pid6999.hprof ...
Heap dump file created [27817336 bytes in 0.098 secs]
Exception in thread "main" java.lang.OutOfMemoryError: Java heap space
    at java.util.Arrays.copyOf(Arrays.java:3210)
    at java.util.Arrays.copyOf(Arrays.java:3181)
    at java.util.ArrayList.grow(ArrayList.java:265)
    at java.util.ArrayList.ensureExplicitCapacity(ArrayList.java:239)
    at java.util.ArrayList.ensureCapacityInternal(ArrayList.java:231)
    at java.util.ArrayList.add(ArrayList.java:462)
    at com.gaop.netty.bio.HeapOOM.main(HeapOOM.java:15)
[Full GC (Ergonomics) [PSYoungGen: 8192K->0K(9216K)] [ParOldGen: 7643K->396K(10240K)] 15835K->396K(19456K), [Metaspace: 3116K->3116K(1056768K)], 0.0042065 secs] [Times: user=0.01 sys=0.00, real=0.01 secs] 
Heap
 PSYoungGen      total 9216K, used 82K [0x00000007bf600000, 0x00000007c0000000, 0x00000007c0000000)
  eden space 8192K, 1% used [0x00000007bf600000,0x00000007bf614938,0x00000007bfe00000)
  from space 1024K, 0% used [0x00000007bfe00000,0x00000007bfe00000,0x00000007bff00000)
  to   space 1024K, 0% used [0x00000007bff00000,0x00000007bff00000,0x00000007c0000000)
 ParOldGen       total 10240K, used 396K [0x00000007bec00000, 0x00000007bf600000, 0x00000007bf600000)
  object space 10240K, 3% used [0x00000007bec00000,0x00000007bec63330,0x00000007bf600000)
 Metaspace       used 3122K, capacity 4500K, committed 4864K, reserved 1056768K
  class space    used 342K, capacity 388K, committed 512K, reserved 1048576K

Process finished with exit code 1

抓住 gc 日志报错的关键词：堆内存溢出。作为对象分配的主要区域，产生堆内存溢出的问题，就需要知道在报错的时候，堆空间的使用情况：到底是什么对象的分配占用了堆空间。这个时候就可以查看 JVM 生成的 .hprof 文件，即 dump 日志。

查看工具是 visualVM。

image.png

汇总视图中的关注点

  1. class by number of instance 创建实例数量
  2. class by size of instance 创建实例占用空间

可以看到，在限制堆空间 20M 的范围内，测试实例 OOMObject 的创建数量为 810326，占用空间为 12965216 byte，约 12MB。占据了老年代的大部分空间，而且因为仍存在 GCRoots 的关联，无法被回收，持续不断的生成最终导致内存溢出。

因此，dump 文件，可以帮我们分析和定位问题关键点。

三 基础配置项总结

堆大小默认配置

按运行程序的类型，配置堆的大小比例，取决于实际运行机器的物理内存。

类似于 ES 这样的数据检索服务节点

  • 通常把堆的初始化大小，设置成物理内存的一半。这是因为 ES 是存储类型的服务，我们需要预留一半的内存给文件缓存

另一种线上计算型节点，比如处理请求的 web 服务

  • 通常会把堆内存设置为物理内存的 2/3，剩下的 1/3 就是给堆外内存使用的。

ps. 注：这部分只能是一个大概值，并且不同场景的适用配置也不同。

配置项

打印 gc 日志

-XX:+PrintGCDetails
-XX:+PrintGCTimeStamps
-XX:+PrintGCDateStamps
-Xloggc:/Users/gaopeng/gc.log

在不同的时机 dump 内存快照

-XX:+HeapDumpOnOutOfMemoryError
-XX:+HeapDumpAfterFullGC
-XX:+HeapDumpBeforeFullGC

打印对象年龄分布

PrintTenuringDistribution

打印这个信息是作为调整 MaxTenuringThreshold 选项的参考。调节年轻代对象晋升老年代需要经历的 GC 次数。是一个需要关注的参数信息。

打印 STW 时间

PrintGCApplicationStoppedTime

超过一定大小的对象，将直接在老年代分配

PretenureSizeThreshold
©著作权归作者所有,转载或内容合作请联系作者
  • 人面猴
    序言：七十年代末，一起剥皮案震惊了整个滨河市，随后出现的几起案子，更是在滨河造成了极大的恐慌，老刑警刘岩，带你破解...
    沈念sama阅读 204,590评论 6赞 478
  • 死咒
    序言：滨河连续发生了三起死亡事件，死亡现场离奇诡异，居然都是意外死亡，警方通过查阅死者的电脑和手机，发现死者居然都...
    沈念sama阅读 86,808评论 2赞 381
  • 救了他两次的神仙让他今天三更去死
    文/潘晓璐 我一进店门，熙熙楼的掌柜王于贵愁眉苦脸地迎上来，“玉大人，你说我怎么就摊上这事。” “怎么了？”我有些...
    开封第一讲书人阅读 151,151评论 0赞 337
  • 道士缉凶录：失踪的卖姜人
    文/不坏的土叔 我叫张陵，是天一观的道长。 经常有香客问我，道长，这世上最难降的妖魔是什么？ 我笑而不...
    开封第一讲书人阅读 54,779评论 1赞 277
  • 港岛之恋（遗憾婚礼）
    正文 为了忘掉前任，我火速办了婚礼，结果婚礼上，老公的妹妹穿的比我还像新娘。我一直安慰自己，他们只是感情好，可当我...
    茶点故事阅读 63,773评论 5赞 367
  • 恶毒庶女顶嫁案：这布局不是一般人想出来的
    文/花漫 我一把揭开白布。 她就那样静静地躺着，像睡着了一般。 火红的嫁衣衬着肌肤如雪。 梳的纹丝不乱的头发上，一...
    开封第一讲书人阅读 48,656评论 1赞 281
  • 城市分裂传说
    那天，我揣着相机与录音，去河边找鬼。 笑死，一个胖子当着我的面吹牛，可吹牛的内容都是我干的。 我是一名探鬼主播，决...
    沈念sama阅读 38,022评论 3赞 398
  • 双鸳鸯连环套：你想象不到人心有多黑
    文/苍兰香墨 我猛地睁开眼，长吁一口气：“原来是场噩梦啊……” “哼！你这毒妇竟也来了？” 一声冷哼从身侧响起，我...
    开封第一讲书人阅读 36,678评论 0赞 258
  • 万荣杀人案实录
    序言：老挝万荣一对情侣失踪，失踪者是张志新（化名）和其女友刘颖，没想到半个月后，有当地人在树林里发现了一具尸体，经...
    沈念sama阅读 41,038评论 1赞 299
  • 护林员之死
    正文 独居荒郊野岭守林人离奇死亡，尸身上长有42处带血的脓包…… 初始之章·张勋 以下内容为张勋视角 年9月15日...
    茶点故事阅读 35,659评论 2赞 321
  • 白月光启示录
    正文 我和宋清朗相恋三年，在试婚纱的时候发现自己被绿了。 大学时的朋友给我发了我未婚夫和他白月光在一起吃饭的照片。...
    茶点故事阅读 37,756评论 1赞 330
  • 活死人
    序言：一个原本活蹦乱跳的男人离奇死亡，死状恐怖，灵堂内的尸体忽然破棺而出，到底是诈尸还是另有隐情，我是刑警宁泽，带...
    沈念sama阅读 33,411评论 4赞 321
  • 日本核电站爆炸内幕
    正文 年R本政府宣布，位于F岛的核电站，受9级特大地震影响，放射性物质发生泄漏。R本人自食恶果不足惜，却给世界环境...
    茶点故事阅读 39,005评论 3赞 307
  • 男人毒药：我在死后第九天来索命
    文/蒙蒙 一、第九天 我趴在偏房一处隐蔽的房顶上张望。 院中可真热闹，春花似锦、人声如沸。这庄子的主人今日做“春日...
    开封第一讲书人阅读 29,973评论 0赞 19
  • 一桩弑父案，背后竟有这般阴谋
    文/苍兰香墨 我抬头看了看天上的太阳。三九已至，却和暖如春，着一层夹袄步出监牢的瞬间，已是汗流浃背。 一阵脚步声响...
    开封第一讲书人阅读 31,203评论 1赞 260
  • 情欲美人皮
    我被黑心中介骗来泰国打工， 没想到刚下飞机就差点儿被人妖公主榨干…… 1. 我叫王不留，地道东北人。 一个月前我还...
    沈念sama阅读 45,053评论 2赞 350
  • 代替公主和亲
    正文 我出身青楼，却偏偏与公主长得像，于是被迫代替她去往敌国和亲。 传闻我的和亲对象是个残疾皇子，可洞房花烛夜当晚...
    茶点故事阅读 42,495评论 2赞 343