深入理解JVM - 解读GC日志

简介: ​ 这里给堆分配了20M的内存空间,新生代分配10M,同时打印GC信息,新生代的分配比例为8:1:1,最后使用serrial收集器。注意是serrial收集器。

前言


这次的文章会根据实战来介绍如何看JVM的日志,看JVM日志说难也难,说容易也容易,更多的是需要时间去不断的尝试进行总结。


另外,因为代码的实际运行效果在不同的机器是不一样的!这篇文章使用的是jdk1.8.0_221 的版本,具体的系统配置查看:


image.png


概述:


主要内容还是以讲解如何阅读日志,同时不同的机器运行的结果不同,文章更多的是介绍如何解读参数:


参数配置案例


image.png


配置介绍:


  1. 新生代5M
  2. 最大新生代内存5M
  3. 初始化堆内存大小10M
  4. 最大堆内存大小10M
  5. 新生代eden区域大小,或者说survior配比:8 代表 8:1:1
  6. 使用ParNew+CMS收集器


实际操作:


不执行任何代码测试:


参数配置:


image.png


-verbose:gc -Xms20M -Xmx20M -Xmn10M -XX:+PrintGCDetails -XX:SurvivorRatio=8 -XX:+UseSerialGC


参数的含义:


这里给堆分配了20M的内存空间,新生代分配10M,同时打印GC信息,新生代的分配比例为8:1:1,最后使用serrial收集器。注意是serrial收集器。


代码配置


先从最简单的方法开始,我们运行一个没有任何代码的Main方法


public class MinorGcTest {
    public static void main(String[] args) {
    }
}

注意下面的内容是运行一个空Main方法的日志内容。


Heap
 def new generation   total 9216K, used 3977K [0x00000000fec00000, 0x00000000ff600000, 0x00000000ff600000)
  eden space 8192K,  48% used [0x00000000fec00000, 0x00000000fefe27f0, 0x00000000ff400000)
  from space 1024K,   0% used [0x00000000ff400000, 0x00000000ff400000, 0x00000000ff500000)
  to   space 1024K,   0% used [0x00000000ff500000, 0x00000000ff500000, 0x00000000ff600000)
 tenured generation   total 10240K, used 0K [0x00000000ff600000, 0x0000000100000000, 0x0000000100000000)
   the space 10240K,   0% used [0x00000000ff600000, 0x00000000ff600000, 0x00000000ff600200, 0x0000000100000000)
 Metaspace       used 3241K, capacity 4496K, committed 4864K, reserved 1056768K
  class space    used 349K, capacity 388K, committed 512K, reserved 1048576K

解释:


首先看下第二行:def new generation total 9216K, used 3977K,很明显,说明新生代总大小为9216K也就是9M的空间大小,为什么是9M呢,因为这里计算的是8M的eden区域+1M的survior from区域,剩下一个survior to的区域加起来一共10M,而可用空间根据复制算法只有9M也是正确的。


然后看下:eden space 8192K,  48% used,可以看到即使不运行任何的代码我们也使用了4M左右的空间,那么这4M的空间是什么东西呢,这部分对象其实是JVM自身运行产生的一些对象,这里也会放到后面的文章进行解读。


Metaspace代表着元空间,由于JDK8没有了永久代,所以JDK8之前的JVM看到的内容在这里是不一样的。


堆溢出测试:


下面来看下堆溢出的情况下GC的日志打印了哪些内容,JAVA异常的信息忽略了,因为影响我们看日志:


参数配置:


-verbose:gc -Xms20M -Xmx20M -Xmn10M -XX:+PrintGCDetails -XX:SurvivorRatio=8 -XX:+UseSerialGC


代码配置:


byte[] allocation1, allocation2, allocation3, allocation4, allocation5;
allocation1 = new byte[_1MB * 2];
allocation1 = new byte[_1MB * 2];
allocation1 = new byte[_1MB * 1];
allocation3 = new byte[20*_1MB * 2];

下面是日志的结果:


[GC (Allocation Failure) [DefNew: 7909K->1023K(9216K), 0.0025258 secs] 7909K->3242K(19456K), 0.0025739 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
[GC (Allocation Failure) [DefNew: 2131K->0K(9216K), 0.0015020 secs][Tenured: 4266K->2217K(10240K), 0.0030024 secs] 4350K->2217K(19456K), [Metaspace: 3254K->3254K(1056768K)], 0.0045414 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
[Full GC (Allocation Failure) [Tenured: 2217K->2198K(10240K), 0.0017918 secs] 2217K->2198K(19456K), [Metaspace: 3254K->3254K(1056768K)], 0.0018074 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
Heap
 def new generation   total 9216K, used 404K [0x00000000fec00000, 0x00000000ff600000, 0x00000000ff600000)
  eden space 8192K,   4% used [0x00000000fec00000, 0x00000000fec65330, 0x00000000ff400000)
  from space 1024K,   0% used [0x00000000ff400000, 0x00000000ff400000, 0x00000000ff500000)
  to   space 1024K,   0% used [0x00000000ff500000, 0x00000000ff500000, 0x00000000ff600000)
 tenured generation   total 10240K, used 2198K [0x00000000ff600000, 0x0000000100000000, 0x0000000100000000)
   the space 10240K,  21% used [0x00000000ff600000, 0x00000000ff8259d8, 0x00000000ff825a00, 0x0000000100000000)
 Metaspace       used 3360K, capacity 4496K, committed 4864K, reserved 1056768K
  class space    used 362K, capacity 388K, committed 512K, reserved 1048576K
[GC (Allocation Failure) [DefNew: 7909K->1023K(9216K), 0.0025258 secs] 7909K->3242K(19456K), 0.0025739 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 

我们先看一下第一行,这里使用的是serrial收集器,所以可以看到新生代打印7909K->1023K(9216K),表示一共可用空间9216KB,而垃圾此时占用了7909K,回收之后剩下1023K。第二部分:7909K->3242K(19456K),表示整个堆的回收情况,19456K表示整个堆的可用空间,同样从堆大小可以看到从7909K回收到剩下3242K的存活对象。最后一部分:[Times: user=0.00 sys=0.00, real=0.00 secs] 表示停顿的时间,以毫秒为单位,因为此次的垃圾回收时间太短,所以没有金酸进去,user表示用户线程停顿时间,sys表示系统回收时间,real表示实际的停顿时间。

接着看一下full gc的日志,可以看到这里直接对于新生代和老年代回收内存之后发现几乎没有空间剩余,还是放不下20M的大对象,所以直接抛出了oom。


[Full GC (Allocation Failure) [Tenured: 2217K->2198K(10240K), 0.0017918 secs] 2217K->2198K(19456K), [Metaspace: 3254K->3254K(1056768K)], 0.0018074 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
Heap

parNew+cms测试:


不执行任何测试


参数配置:


注意最后使用了parnew+cms的组合


-verbose:gc
-Xms20M
-Xmx20M
-Xmn10M
-XX:+PrintGCDetails
-XX:SurvivorRatio=8
-XX:+UseParNewGC
-XX:+UseConcMarkSweepGC

代码配置:


同样是不执行任何的代码,结果和其他的收集器类似


Heap
 par new generation   total 9216K, used 3977K [0x00000000fec00000, 0x00000000ff600000, 0x00000000ff600000)
  eden space 8192K,  48% used [0x00000000fec00000, 0x00000000fefe27f0, 0x00000000ff400000)
  from space 1024K,   0% used [0x00000000ff400000, 0x00000000ff400000, 0x00000000ff500000)
  to   space 1024K,   0% used [0x00000000ff500000, 0x00000000ff500000, 0x00000000ff600000)
 concurrent mark-sweep generation total 10240K, used 0K [0x00000000ff600000, 0x0000000100000000, 0x0000000100000000)
 Metaspace       used 3255K, capacity 4496K, committed 4864K, reserved 1056768K
  class space    used 353K, capacity 388K, committed 512K, reserved 1048576K

如果去掉cms?


如果我们把上面的参数去掉-XX:+UseConcMarkSweepGC,会出现下面的内容:


Heap
 par new generation   total 9216K, used 3977K [0x00000000fec00000, 0x00000000ff600000, 0x00000000ff600000)
  eden space 8192K,  48% used [0x00000000fec00000, 0x00000000fefe27f0, 0x00000000ff400000)
  from space 1024K,   0% used [0x00000000ff400000, 0x00000000ff400000, 0x00000000ff500000)
  to   space 1024K,   0% used [0x00000000ff500000, 0x00000000ff500000, 0x00000000ff600000)
 tenured generation   total 10240K, used 0K [0x00000000ff600000, 0x0000000100000000, 0x0000000100000000)
   the space 10240K,   0% used [0x00000000ff600000, 0x00000000ff600000, 0x00000000ff600200, 0x0000000100000000)
 Metaspace       used 3238K, capacity 4496K, committed 4864K, reserved 1056768K
  class space    used 349K, capacity 388K, committed 512K, reserved 1048576K
Java HotSpot(TM) 64-Bit Server VM warning: Using the ParNew young collector with the Serial old collector is deprecated and will likely be removed in a future release

这里注意一下最后一句:


这里说明的是不推荐使用parNew+serrial的组合,并且说明在未来的版本中会废弃这种组合,实际上在JDK9中就已经完全禁止parnew+serrial的组合了


Java HotSpot(TM) 64-Bit Server VM warning: Using the ParNew young collector with the Serial old collector is deprecated and will likely be removed in a future release

总结:


根据上面的几个测试案例可以看到,阅读GC的日志还是比较简单的,但是实际运行又会发现由于各种因素的干扰,实际运行的结果会和预期的结果不一样,这里不需要过多的担心,因为只要掌握了基础的理论,在根据实践模拟不断的熟悉会发现JVM的垃圾回收规律基本还是符合我们的理论基础介绍的。


如果对于对象分配策略的感兴趣可以阅读之前个人的文章:深入理解JVM虚拟机 - jvm的对象分配策略


写在最后


阅读日志建议更多的是实操和练习,多尝试几遍之后更能加深记忆,由于个人机器本身不跑任何代码也会产生4M的对象,所以只能简单的介绍阅读日志的方法了.....

相关实践学习
日志服务之使用Nginx模式采集日志
本文介绍如何通过日志服务控制台创建Nginx模式的Logtail配置快速采集Nginx日志并进行多维度分析。
相关文章
|
5天前
|
算法 Java
Java垃圾回收(Garbage Collection,GC)是Java虚拟机(JVM)的一种自动内存管理机制,用于在运行时自动回收不再使用的对象所占的内存空间
【6月更文挑战第18天】Java的GC自动回收内存,包括标记清除(产生碎片)、复制(效率低)、标记整理(兼顾连续性与效率)和分代收集(区分新生代和老年代,用不同算法优化)等策略。现代JVM通常采用分代收集,以平衡性能和内存利用率。
31 3
|
12天前
|
运维 Java Shell
手工触发Full GC:JVM调优实战指南
本文是关于Java应用性能调优的指南,重点介绍了如何使用`jmap`工具手动触发Full GC。Full GC是对堆内存全面清理的过程,通常在资源紧张时进行以缓解内存压力。文章详细阐述了Full GC的概念,并提供了两种使用`jmap`触发Full GC的方法:通过`-histo:live`选项获取存活对象统计信息,或使用`-dump`选项生成堆转储文件以分析内存状态。同时,文中也提醒注意手动Full GC可能带来的性能开销,建议在生产环境中谨慎操作。
|
30天前
|
存储 算法 Java
JVM(垃圾回收机制 --- GC)
JVM(垃圾回收机制 --- GC)
42 5
|
1月前
|
Java 程序员 Python
JVM的垃圾回收机制(GC机制)
Java的JVM实行自动垃圾回收机制(GC),主要针对堆中的对象。当对象无引用可达时,被视为垃圾。垃圾回收包含“找垃圾”和“回收垃圾”两步。找垃圾通过引用计数(非Java使用)和可达性分析(Java使用)来识别无用对象。可达性分析从根对象开始遍历,未被标记的对象视为垃圾。回收垃圾常用标记清除方法,但可能导致内存碎片。此过程消耗资源,且碎片化影响内存分配效率。
24 1
|
1月前
|
监控 Java Linux
JVM工作原理与实战(三十七):Shenandoah GC和ZGC
JVM作为Java程序的运行环境,其负责解释和执行字节码,管理内存,确保安全,支持多线程和提供性能监控工具,以及确保程序的跨平台运行。本文主要介绍了垃圾回收器的技术演进、Shenandoah GC、ZGC等内容。
30 0
|
1月前
|
存储 缓存 监控
JVM工作原理与实战(三十四):解决GC问题的方法
JVM作为Java程序的运行环境,其负责解释和执行字节码,管理内存,确保安全,支持多线程和提供性能监控工具,以及确保程序的跨平台运行。本文主要介绍了常见的垃圾回收(GC)模式、解决GC问题的方法(优化基础JVM参数、减少对象产生、更换垃圾回收器、优化垃圾回收器的参数)等内容。
38 0
|
1月前
|
Prometheus 监控 Cloud Native
JVM工作原理与实战(三十三):监控GC过程的工具
JVM作为Java程序的运行环境,其负责解释和执行字节码,管理内存,确保安全,支持多线程和提供性能监控工具,以及确保程序的跨平台运行。本文主要介绍了jstat工具、VisualVM插件、Prometheus + Grafana、GC日志等内容。
41 0
|
1月前
|
监控 负载均衡 算法
JVM工作原理与实战(三十二):GC调优
JVM作为Java程序的运行环境,其负责解释和执行字节码,管理内存,确保安全,支持多线程和提供性能监控工具,以及确保程序的跨平台运行。本文主要介绍了GC调优、GC调优的核心指标等内容。
25 0
|
1月前
|
运维 监控 数据可视化
九、GC收集日志
九、GC收集日志
43 4
九、GC收集日志
|
1月前
|
存储 算法 Java
精华推荐 | 【JVM深层系列】「GC底层调优专题」一文带你彻底加强夯实底层原理之GC垃圾回收技术的分析指南(GC原理透析)
精华推荐 | 【JVM深层系列】「GC底层调优专题」一文带你彻底加强夯实底层原理之GC垃圾回收技术的分析指南(GC原理透析)
67 0