深入理解JVM - 解读GC日志

本文涉及的产品
日志服务 SLS,月写入数据量 50GB 1个月
简介: ​ 这里给堆分配了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日志并进行多维度分析。
相关文章
|
2月前
|
缓存 算法 Java
JVM知识体系学习六:JVM垃圾是什么、GC常用垃圾清除算法、堆内存逻辑分区、栈上分配、对象何时进入老年代、有关老年代新生代的两个问题、常见的垃圾回收器、CMS
这篇文章详细介绍了Java虚拟机(JVM)中的垃圾回收机制,包括垃圾的定义、垃圾回收算法、堆内存的逻辑分区、对象的内存分配和回收过程,以及不同垃圾回收器的工作原理和参数设置。
79 4
JVM知识体系学习六:JVM垃圾是什么、GC常用垃圾清除算法、堆内存逻辑分区、栈上分配、对象何时进入老年代、有关老年代新生代的两个问题、常见的垃圾回收器、CMS
|
1月前
|
存储 监控 Java
JVM进阶调优系列(8)如何手把手,逐行教她看懂GC日志?| IT男的专属浪漫
本文介绍了如何通过JVM参数打印GC日志,并通过示例代码展示了频繁YGC和FGC的场景。文章首先讲解了常见的GC日志参数,如`-XX:+PrintGCDetails`、`-XX:+PrintGCDateStamps`等,然后通过具体的JVM参数和代码示例,模拟了不同内存分配情况下的GC行为。最后,详细解析了GC日志的内容,帮助读者理解GC的执行过程和GC处理机制。
|
2月前
|
Arthas 监控 Java
JVM知识体系学习七:了解JVM常用命令行参数、GC日志详解、调优三大方面(JVM规划和预调优、优化JVM环境、JVM运行出现的各种问题)、Arthas
这篇文章全面介绍了JVM的命令行参数、GC日志分析以及性能调优的各个方面,包括监控工具使用和实际案例分析。
68 3
|
2月前
|
算法 Java
JVM进阶调优系列(4)年轻代和老年代采用什么GC算法回收?
本文详细介绍了JVM中的GC算法,包括年轻代的复制算法和老年代的标记-整理算法。复制算法适用于年轻代,因其高效且能避免内存碎片;标记-整理算法则用于老年代,虽然效率较低,但能有效解决内存碎片问题。文章还解释了这两种算法的具体过程及其优缺点,并简要提及了其他GC算法。
 JVM进阶调优系列(4)年轻代和老年代采用什么GC算法回收?
|
1月前
|
XML 安全 Java
【日志框架整合】Slf4j、Log4j、Log4j2、Logback配置模板
本文介绍了Java日志框架的基本概念和使用方法,重点讨论了SLF4J、Log4j、Logback和Log4j2之间的关系及其性能对比。SLF4J作为一个日志抽象层,允许开发者使用统一的日志接口,而Log4j、Logback和Log4j2则是具体的日志实现框架。Log4j2在性能上优于Logback,推荐在新项目中使用。文章还详细说明了如何在Spring Boot项目中配置Log4j2和Logback,以及如何使用Lombok简化日志记录。最后,提供了一些日志配置的最佳实践,包括滚动日志、统一日志格式和提高日志性能的方法。
282 30
【日志框架整合】Slf4j、Log4j、Log4j2、Logback配置模板
|
10天前
|
监控 安全 Apache
什么是Apache日志?为什么Apache日志分析很重要?
Apache是全球广泛使用的Web服务器软件,支持超过30%的活跃网站。它通过接收和处理HTTP请求,与后端服务器通信,返回响应并记录日志,确保网页请求的快速准确处理。Apache日志分为访问日志和错误日志,对提升用户体验、保障安全及优化性能至关重要。EventLog Analyzer等工具可有效管理和分析这些日志,增强Web服务的安全性和可靠性。
|
2月前
|
XML JSON Java
Logback 与 log4j2 性能对比:谁才是日志框架的性能王者?
【10月更文挑战第5天】在Java开发中,日志框架是不可或缺的工具,它们帮助我们记录系统运行时的信息、警告和错误,对于开发人员来说至关重要。在众多日志框架中,Logback和log4j2以其卓越的性能和丰富的功能脱颖而出,成为开发者们的首选。本文将深入探讨Logback与log4j2在性能方面的对比,通过详细的分析和实例,帮助大家理解两者之间的性能差异,以便在实际项目中做出更明智的选择。
318 3
|
20天前
|
存储 监控 安全
什么是事件日志管理系统?事件日志管理系统有哪些用处?
事件日志管理系统是IT安全的重要工具,用于集中收集、分析和解释来自组织IT基础设施各组件的事件日志,如防火墙、路由器、交换机等,帮助提升网络安全、实现主动威胁检测和促进合规性。系统支持多种日志类型,包括Windows事件日志、Syslog日志和应用程序日志,通过实时监测、告警及可视化分析,为企业提供强大的安全保障。然而,实施过程中也面临数据量大、日志管理和分析复杂等挑战。EventLog Analyzer作为一款高效工具,不仅提供实时监测与告警、可视化分析和报告功能,还支持多种合规性报告,帮助企业克服挑战,提升网络安全水平。
|
2月前
|
存储 缓存 关系型数据库
MySQL事务日志-Redo Log工作原理分析
事务的隔离性和原子性分别通过锁和事务日志实现,而持久性则依赖于事务日志中的`Redo Log`。在MySQL中,`Redo Log`确保已提交事务的数据能持久保存,即使系统崩溃也能通过重做日志恢复数据。其工作原理是记录数据在内存中的更改,待事务提交时写入磁盘。此外,`Redo Log`采用简单的物理日志格式和高效的顺序IO,确保快速提交。通过不同的落盘策略,可在性能和安全性之间做出权衡。
1698 14
|
1月前
|
存储 监控 安全
什么是日志管理,如何进行日志管理?
日志管理是对IT系统生成的日志数据进行收集、存储、分析和处理的实践,对维护系统健康、确保安全及获取运营智能至关重要。本文介绍了日志管理的基本概念、常见挑战、工具的主要功能及选择解决方案的方法,强调了定义管理目标、日志收集与分析、警报和报告、持续改进等关键步骤,以及如何应对数据量大、安全问题、警报疲劳等挑战,最终实现日志数据的有效管理和利用。
下一篇
DataWorks