查看gc日志

Java GC日志查看，GC日志时间分析

2019-03-09 17:00:49 博大的Java世界 阅读数 1218更多

分类专栏： jvm

版权声明：本文为博主原创文章，遵循CC 4.0 BY-SA版权协议，转载请附上原文出处链接和本声明。

本文链接：https://blog.csdn.net/xiaocai9999/article/details/88368395

Java中的GC有哪几种类型？


参数
描述

UseSerialGC
虚拟机运行在Client模式的默认值，打开此开关参数后，

使用Serial+Serial Old收集器组合进行垃圾收集。

UseParNewGC
打开此开关参数后，使用ParNew+Serial Old收集器组合进行垃圾收集。

UseConcMarkSweepGC
打开此开关参数后，使用ParNew+CMS+Serial Old收集器组合进行垃圾收集。Serial Old作为CMS收集器出现Concurrent Mode Failure的备用垃圾收集器。

UseParallelGC
虚拟机运行在Server模式的默认值，打开此开关参数后，使用Parallel Scavenge+Serial Old收集器组合进行垃圾收集。

UseParallelOldGC
打开此开关参数后，使用Parallel Scavenge+Parallel Old收集器组合进行垃圾收集。

在Java程序启动完成后，通过jps观察进程来查询到当前运行的java进程，使用

jinfo –flag UseSerialGC 进程

的方式可以定位其使用的gc策略，因为这些参数都是boolean型的常量，如果使用该种gc策略会出现＋号，否则－号。

使用-XX:+上述GC策略可以开启对应的GC策略。

GC日志查看

可以通过在java命令种加入参数来指定对应的gc类型，打印gc日志信息并输出至文件等策略。

GC的日志是以替换的方式(>)写入的，而不是追加(>>)，如果下次写入到同一个文件中的话，以前的GC内容会被清空。

对应的参数列表

-XX:+PrintGC 输出GC日志
-XX:+PrintGCDetails 输出GC的详细日志
-XX:+PrintGCTimeStamps 输出GC的时间戳（以基准时间的形式）
-XX:+PrintGCDateStamps 输出GC的时间戳（以日期的形式，如 2013-05-04T21:53:59.234+0800）
-XX:+PrintHeapAtGC 在进行GC的前后打印出堆的信息
-Xloggc:../logs/gc.log 日志文件的输出路径

例如:eclipse.ini中配置下面代码启动后会在同一目录下生成gc.log


1

2

3
-Xloggc:gc.log

-XX:+PrintGCTimeStamps

-XX:+PrintGCDetails

这里使用如下的参数来进行日志的打印：

-XX:+PrintGCDateStamps -XX:+PrintGCDetails -Xloggc:./gclogs

对于新生代回收的一行日志，其基本内容如下：

2014-07-18T16:02:17.606+0800: 611.633: [GC 611.633: [DefNew: 843458K->2K(948864K), 0.0059180 secs] 2186589K->1343132K(3057292K), 0.0059490 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]

其含义大概如下：

2014-07-18T16:02:17.606+0800（当前时间戳）: 611.633（时间戳）: [GC（表示Young GC） 611.633: [DefNew（单线程Serial年轻代GC）: 843458K（年轻代垃圾回收前的大小）->2K（年轻代回收后的大小）(948864K（年轻代总大小）), 0.0059180 secs（本次回收的时间）] 2186589K（整个堆回收前的大小）->1343132K（整个堆回收后的大小）(3057292K（堆总大小）), 0.0059490 secs（回收时间）] [Times: user=0.00（用户耗时） sys=0.00（系统耗时）, real=0.00 secs（实际耗时）]

老年代回收的日志如下：

2014-07-18T16:19:16.794+0800: 1630.821: [GC 1630.821: [DefNew: 1005567K->111679K(1005568K), 0.9152360 secs]1631.736: [Tenured:
2573912K->1340650K(2574068K), 1.8511050 secs] 3122548K->1340650K(3579636K), [Perm : 17882K->17882K(21248K)], 2.7854350 secs] [Times: user=2.57 sys=0.22, real=2.79 secs]

gc日志中的最后貌似是系统运行完成前的快照：

Heap
 def new generation   total 1005568K, used 111158K [0x00000006fae00000, 0x000000073f110000, 0x0000000750350000)
  eden space 893888K,  12% used [0x00000006fae00000, 0x0000000701710e90, 0x00000007316f0000)
  from space 111680K,   3% used [0x0000000738400000, 0x000000073877c9b0, 0x000000073f110000)
  to   space 111680K,   0% used [0x00000007316f0000, 0x00000007316f0000, 0x0000000738400000)
 tenured generation   total 2234420K, used 1347671K [0x0000000750350000, 0x00000007d895d000, 0x00000007fae00000)
   the space 2234420K,  60% used [0x0000000750350000, 0x00000007a2765cb8, 0x00000007a2765e00, 0x00000007d895d000)
 compacting perm gen  total 21248K, used 17994K [0x00000007fae00000, 0x00000007fc2c0000, 0x0000000800000000)
   the space 21248K,  84% used [0x00000007fae00000, 0x00000007fbf92a50, 0x00000007fbf92c00, 0x00000007fc2c0000)
No shared spaces configured.

GC日志的离线分析

可以使用一些离线的工具来对GC日志进行分析，比如sun的gchisto( https://java.net/projects/gchisto)，gcviewer（ https://github.com/chewiebug/GCViewer ），这些都是开源的工具，用户可以直接通过版本控制工具下载其源码，进行离线分析。

下面就已gcviewer为例，简要分析一下gc日志的离线分析，gcviewer源代码工程是maven结构的，可以直接用maven进行package，这里编译的是1.34版本，本版本的快照已经上传至附件中。

需要说明的是，gcviewer支持多种参数生成的gc日志，直接通过java –jar的方式运行，加载生成的gc日志即可：

------------------------第二种理解-----------------------

首先，给出一个日志输出的例子：

参数设置为：

-XX:+PrintGCDetails -XX:-UseAdaptiveSizePolicy -XX:SurvivorRatio=8 -XX:NewSize=10M -XX:MaxNewSize=10M

参数解释：

-XX:+PrintGCDetails 启用日志

-XX:-UseAdaptiveSizePolicy 禁用动态调整，使SurvivorRatio可以起作用

-XX:SurvivorRatio=8 设置Eden:Survivior=8

-XX:NewSize=10M -XX:MaxNewSize=10M 设置整个新生代的大小为10M

默认垃圾收集器为：Parallel Scavenge

输出结果为：

[GC [PSYoungGen: 4423K->320K(9216K)] 4423K->320K(58880K), 0.0011900 secs] [Times: user=0.01 sys=0.00, real=0.01 secs] 
[Full GC (System) [PSYoungGen: 320K->0K(9216K)] [ParOldGen: 0K->222K(49664K)] 320K->222K(58880K) [PSPermGen: 2458K->2456K(21248K)], 0.0073610 secs] [Times: user=0.01 sys=0.00, real=0.00 secs] 
Heap
 PSYoungGen      total 9216K, used 491K [0x00000000ff600000, 0x0000000100000000, 0x0000000100000000)
  eden space 8192K, 6% used [0x00000000ff600000,0x00000000ff67af50,0x00000000ffe00000)
  from space 1024K, 0% used [0x00000000ffe00000,0x00000000ffe00000,0x00000000fff00000)
  to   space 1024K, 0% used [0x00000000fff00000,0x00000000fff00000,0x0000000100000000)
 ParOldGen       total 49664K, used 222K [0x00000000c5800000, 0x00000000c8880000, 0x00000000ff600000)
  object space 49664K, 0% used [0x00000000c5800000,0x00000000c58378a0,0x00000000c8880000)
 PSPermGen       total 21248K, used 2466K [0x00000000c0600000, 0x00000000c1ac0000, 0x00000000c5800000)
  object space 21248K, 11% used [0x00000000c0600000,0x00000000c0868b48,0x00000000c1ac0000)

前半段分析：

GC （minor ）日志

Full GC 日志

后半段分析：

对照上面的图，GC日志中的PSYoungGen（PS是指Parallel Scavenge）为Eden+FromSpace，而整个YoungGeneration为Eden+FromSpace+ToSpace。

我们设置的新生代大小为10240K，这包括9216K大小的PSYoungGen和1024K大小的ToSpace。其中，PSYoungGen中的Eden:FromSpace为8:1，

这包括8192K的Eden和1024K的FromSpace。

关于老年代和永久代的输出比较简单，不再详述。

更详细描述参见官方文档：http://www.oracle.com/technetwork/java/javase/gc-tuning-6-140523.html

最后注意，如果新生代的空间不能刚好按比例划分，则可能有一定的误差。比如，将上述的参数中SurvivorRatio改为10，则输出如下：

[GC [PSYoungGen: 4439K->320K(9408K)] 4439K->320K(59072K), 0.0010120 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
[Full GC (System) [PSYoungGen: 320K->0K(9408K)] [ParOldGen: 0K->222K(49664K)] 320K->222K(59072K) [PSPermGen: 2458K->2456K(21248K)], 0.0095710 secs] [Times: user=0.02 sys=0.00, real=0.00 secs] 
Heap
 PSYoungGen      total 9408K, used 514K [0x00000000ff600000, 0x0000000100000000, 0x0000000100000000)
  eden space 8576K, 6% used [0x00000000ff600000,0x00000000ff680b78,0x00000000ffe60000)
  from space 832K, 0% used [0x00000000ffe60000,0x00000000ffe60000,0x00000000fff30000)
  to   space 832K, 0% used [0x00000000fff30000,0x00000000fff30000,0x0000000100000000)
 ParOldGen       total 49664K, used 222K [0x00000000c5800000, 0x00000000c8880000, 0x00000000ff600000)
  object space 49664K, 0% used [0x00000000c5800000,0x00000000c58378a0,0x00000000c8880000)
 PSPermGen       total 21248K, used 2466K [0x00000000c0600000, 0x00000000c1ac0000, 0x00000000c5800000)
  object space 21248K, 11% used [0x00000000c0600000,0x00000000c0868b48,0x00000000c1ac0000)

可以看到新生代的相关数值是有一定误差的

GC日志分析

　在GC日志里，一条完整的GC日志记录最后，会带有本次GC所花费的时间，如下面这一条新生代GC：

[GC [DefNew: 3298K->149K(5504K), 0.0053498 secs] 3298K->3221K(9600K), .0053750 secs] [Times: user=0.00 sys=0.00, real=0.01 secs]

　　注意到日志中时间分为了三块：user， sys，和 real，三者的区别和含义如下：

  • 　　real：指的是在此次GC事件中所花费的总时间；
  • 　　user：指的是CPU工作在用户态所花费的时间；
  • 　　sys：指的是CPU工作在内核态所花费的时间。

　　user + sys 就是CPU花费的实际时间，注意这个值统计了所有CPU上的时间，如果进程工作在多线程的环境下，这个值是会超出 real 所记录的值的，即 user + sys >= real

　　对于GC事件来说，无论是 Minor GC 还是 Full GC 的过程，都存在并发的GC算法，如新生代的ParNew，老年代的ParallelOld，GC过程中工作负载是由多个线程共同完成的，这也就意味着使用这些GC算法时，GC日志中我们应该观察到：user + sys > real。譬如说：配置了ParNew且并发数为5的GC活动（-XX:+UseParNewGC -XX:ParallelGCThreads=5）中，如果user + sys的值为 2 seconds，那么 real 的时间 就近似为 400ms(2 seconds / 5)。

场景1：

[Times: user=11.53 sys=1.38, real=1.03 secs]

　　垃圾回收过程是通过并发执行，因此 user + sys 远大于 real 。

场景2：

[Times: user=0.09 sys=0.00, real=0.09 secs]

　　因为使用了串行的垃圾回收期，所以时间应该是 user 和 real 相等。

场景3：

[Times: user=0.20 sys=0.01, real=18.45 secs]

　　这是一个异常的示例，可以看到 real 所显示的时间 远 大于 user + sys。一般来说，如果观察到GC日志里多次出现了场景3所示的日志，这表明JVM的GC 过程存在某些问题（等待计算资源），原因可能是下面这两种：

  • 　　频繁的IO操作
  • 　　缺乏CPU资源

繁忙的I/O操作

　　当程序存在繁忙的I/O操作（网络IO或磁盘IO）时，会让 real 时间大幅上升。因为在记录GC日志的时候，你的程序进行了磁盘读写，如果同一时间其他IO操作较重，则此时GC事件会延迟，进而影响了最终的 real 的值。注意，如果程序本身不存在的频繁的IO操作，同一机器上其他进程的频繁IO也会影响 real 的最终结果。Linux环境下可以使用 sar 监视机器上的I/O，eg. sar -d -p 1，如果频繁的IO操作的确存在，可以通过下面两种方式改进：

  • 　　优化程序本身的IO操作逻辑；
  • 　　消除其他进程带来的IO影响。

缺乏CPU资源

　　当程序本身是CPU密集型应用，或机器上其他进程占用了大量的CPU计算资源，则有可能会出现分配不到 CPU cycles的情况，这会让程序挂起，GC所花费的实际时间也将远大于 user + sys 的值。

　　可以使用 top 命令观察一下 进程的CPU利用率，同时辅以Profiler工具统计一段时间内进程的状态分布。如果的确是CPU资源不足，解决方法无法下面几种：

  • 　　优化程序内部的线程使用，确保无冗余的线程配置；
  • 　　增加虚拟机或容器的CPU配置，提升机器总的计算能力。

原文地址：https://www.cnblogs.com/yueluoshuxiang/p/11734313.html

时间： 2024-08-04 11:22:44

查看gc日志的相关文章

Java GC日志查看

Java GC类型 Java中的GC有哪几种类型? 参数 描述 UseSerialGC 虚拟机运行在Client模式的默认值,打开此开关参数后, 使用Serial+Serial Old收集器组合进行垃圾收集. UseParNewGC 打开此开关参数后,使用ParNew+Serial Old收集器组合进行垃圾收集. UseConcMarkSweepGC 打开此开关参数后,使用ParNew+CMS+Serial Old收集器组合进行垃圾收集.Serial Old作为CMS收集器出现Concurren

JVM优化 垃圾回收 算法 垃圾收集器 GC日志可视化查看

今日内容了解什么是垃圾回收掌握垃圾会回收的常见算法学习串行.并行.并发.G1垃圾收集器学习GC日志的可视化查看 1.什么是垃圾回收?程序的运行必然需要申请内存资源,无效的对象资源如果不及时处理就会一直占有内存 资源,最终将导致内存溢出,所以对内存资源的管理是非常重要了. 1.1.C/C++语言的垃圾回收在C/C++语言中,没有自动垃圾回收机制,是通过new关键字申请内存资源,通过delete 关键字释放内存资源.如果,程序员在某些位置没有写delete进行释放,那么申请的对象将一直占用内存资源,

快速解读GC日志(转)

本文是 Plumbr 发行的 Java垃圾收集手册 的部分内容.文中将介绍GC日志的输出格式, 以及如何解读GC日志, 从中提取有用的信息.我们通过 -XX:+UseSerialGC 选项,指定JVM使用串行垃圾收集器, 并使用下面的启动参数让 JVM 打印出详细的GC日志: -XX:+PrintGCDetails -XX:+PrintGCDateStamps -XX:+PrintGCTimeStamps 这样配置以后,发生GC时输出的日志就类似于下面这种格式(为了显示方便,已手工折行): 20

浅析JVM中的GC日志

目录 一.GC日志的格式分析 二.运行时开启GC日志 一.GC日志的格式分析 在讲述GC日志之前,我们先来运行下面这段代码 1 package com.example; 2 3 public class TestMinorGC { 4 private static final int _1MB = 1024*1024; 5 6 public static void testAllocation() { 7 byte[] allocation1, allocation2, allocation3,

JAVA 从GC日志分析堆内存 第七节

JAVA 从GC日志分析堆内存 第七节 在上一章中,我们只设置了整个堆的内存大小.但是我们知道,堆又分为了新生代,年老代.他们之间的内存怎么分配呢?新生代又分为Eden和Survivor,他们的比例大小能改变吗?其实这些都是可控的,以前没有讲到是因为就算讲了也只是讲讲而已,看不到实质性的东西.因此这章我们通过分析GC日志来一步步讲解如何细化设置堆内存. 首先我们来了解几个相关的参数: -XX:+PrintGCDetails:用于告诉虚拟机回收垃圾的时候顺便打印日志. -Xloggc:路径 :将打

GC 日志分析工具 —— GChisto

零. 简介 <Java 性能优化权威指南>介绍了一款分析 GC 日志的离线分析工具, 不过官网上没有下载的地方, 需要自己从 SVN 上拉下来编译. GChisto 以表格和图形化的方式展示 GC 次数. 持续时间等, 提高了分析 GC 日志的效率. 一. 实践 编译成功后, 直接 java -jar 运行起来, 把 GC 日志 .log 文件 add 到 GChisto, GChisto 加载日志可能运行比较久, 需要等待一会. 1. 导入成功, 切到 GC Pause Stats 选项卡,

HBase GC日志

HBase依靠ZooKeeper来感知集群成员及其存活性.如果一个服务器暂停了很长时间,它将无法给ZooKeeper quorum发送心跳信息,其它服务器会认为这台服务器已死亡.这将导致master为其启动恢复进程.当该服务器脱离停顿时,它会发现它的所有租约都已失效(hbase client端每次和regionserver交互的时候,都会在服务器端生成一个租约(Lease),租约的有效期由参数hbase.regionserver.lease.period确定),然后自杀.HBase开发团队亲切地

java虚拟机优化--gc日志

加入 wrapper.java.additional.5=-XX:+PrintGC wrapper.java.additional.6=-XX:+PrintGCDetails #wrapper.java.additional.7=-XX:+PrintGC:PrintGCTimeStamps wrapper.java.additional.7=-Xloggc:gc.log wrapper.java.additional.8=-XX:+PrintGCApplicationStoppedTime wr

浅谈 G1 GC 日志格式

在 Java9 中,G1 GC 将成为默认的垃圾收集器,G1 垃圾收集器的关键特性之一是能够在不牺牲吞吐量的同时,限制 GC 暂停时间(即可以设置所需的最大停顿时间). 由于 G1 GC 正在逐渐成为默认的垃圾收集器,它的使用与关注度也会逐渐增加.因此在调整 JVM 大小和排查问题的情况下,必须先理解 G1 GC 的日志格式,接下来将介绍如何理解 G1 GC 的日志格式.由于 G1 GC 日志中有许多与子任务相关的信息,因此为了更好地理解和利用这些信息,我推荐使用 GC 日志分析工具:http: