美文网首页
JVM 日志读取与解析

JVM 日志读取与解析

作者: 柯基去哪了 | 来源:发表于2020-10-23 11:23 被阅读0次

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

相关文章

网友评论

      本文标题：JVM 日志读取与解析

      本文链接：https://www.haomeiwen.com/subject/kscvmktx.html

      延伸阅读

      深度阅读

      • 您也可以注册成为美文阅读网的作者，发表您的原创作品、分享您的心情！

      栏目导航

      热点阅读

      关于我们|服务条款|联系我们|JVM 日志读取与解析|投稿指南|网站地图|RSS订阅|排版工具|手机版

      提供经典美文摘抄,优美散文欣赏,现代诗歌精选,短篇小说,心情随笔,表白情书范文,故事会在线阅读欣赏

      Copyright © 2014-2023 Haomeiwen.com All Rights Reserved. 好美文阅读网 版权所有

      备案信息：桂公网安备 45052102000051号 · 桂ICP备13007215号-3

      本站所收录作品、热点评论等信息部分来源互联网，目的只是为了系统归纳学习和传递资讯

      所有作品版权归原创作者所有，与本站立场无关，如不慎侵犯了你的权益，请联系我们告知，我们将做删除处理！