码迷，mamicode.com
首页 > 其他好文 > 详细

jvm的GC日志分析 [转]

时间：2017-04-04 19:15:57      阅读：323      评论：0      收藏：0      [点我收藏+]

标签：port   inline   最大   tag   百分比   变化   默认值   ucid   pos   

 

jvm的GC日志分析

标签： jvm内存javagc
2015-06-22 16:37 1566人阅读 评论(1) 收藏 举报
技术分享 分类：

JVM的GC日志的主要参数包括如下几个：

-XX:+PrintGC 输出GC日志

-XX:+PrintGCDetails 输出GC的详细日志

-XX:+PrintGCTimeStamps 输出GC的时间戳（以基准时间的形式）

-XX:+PrintGCDateStamps 输出GC的时间戳（以日期的形式，如 2013-05-04T21:53:59.234+0800）

-XX:+PrintHeapAtGC 在进行GC的前后打印出堆的信息

-XX:+PrintGCApplicationStoppedTime // 输出GC造成应用暂停的时间

-Xloggc:../logs/gc.log 日志文件的输出路径


常用JVM参数
分析gc日志后，经常需要调整jvm内存相关参数，常用参数如下
-Xms：初始堆大小，默认为物理内存的1/64(<1GB)；默认(MinHeapFreeRatio参数可以调整)空余堆内存小于40%时，JVM就会增大堆直到-Xmx的最大限制
-Xmx：最大堆大小，默认(MaxHeapFreeRatio参数可以调整)空余堆内存大于70%时，JVM会减少堆直到 -Xms的最小限制
-Xmn：新生代的内存空间大小，注意：此处的大小是（eden+ 2 survivor space)。与jmap -heap中显示的New gen是不同的。整个堆大小=新生代大小 + 老生代大小 + 永久代大小。 
在保证堆大小不变的情况下，增大新生代后,将会减小老生代大小。此值对系统性能影响较大,Sun官方推荐配置为整个堆的3/8。
-XX:SurvivorRatio：新生代中Eden区域与Survivor区域的容量比值，默认值为8。两个Survivor区与一个Eden区的比值为2:8,一个Survivor区占整个年轻代的1/10。
-Xss：每个线程的堆栈大小。JDK5.0以后每个线程堆栈大小为1M,以前每个线程堆栈大小为256K。应根据应用的线程所需内存大小进行适当调整。在相同物理内存下,减小这个值能生成更多的线程。但是操作系统对一个进程内的线程数还是有限制的，不能无限生成，经验值在3000~5000左右。一般小的应用， 如果栈不是很深， 应该是128k够用的，大的应用建议使用256k。这个选项对性能影响比较大，需要严格的测试。和threadstacksize选项解释很类似,官方文档似乎没有解释,在论坛中有这样一句话:"-Xss is translated in a VM flag named ThreadStackSize”一般设置这个值就可以了。
-XX:PermSize：设置永久代(perm gen)初始值。默认值为物理内存的1/64。
-XX:MaxPermSize：设置持久代最大值。物理内存的1/4。


在我做了如下的设置

[java] view plain copy
 print?
  1. -XX:+PrintGCDetails -Xloggc:../logs/gc.log -XX:+PrintGCTimeStamps  

以后打印出来的日志为：

[java] view plain copy
 print?
  1. 0.756: [Full GC (System) 0.756: [CMS: 0K->1696K(204800K), 0.0347096 secs] 11488K->1696K(252608K), [CMS Perm : 10328K->10320K(131072K)], 0.0347949 secs] [Times: user=0.06 sys=0.00, real=0.05 secs]  
  2. 1.728: [GC 1.728: [ParNew: 38272K->2323K(47808K), 0.0092276 secs] 39968K->4019K(252608K), 0.0093169 secs] [Times: user=0.01 sys=0.00, real=0.00 secs]  
  3. 2.642: [GC 2.643: [ParNew: 40595K->3685K(47808K), 0.0075343 secs] 42291K->5381K(252608K), 0.0075972 secs] [Times: user=0.03 sys=0.00, real=0.02 secs]  
  4. 4.349: [GC 4.349: [ParNew: 41957K->5024K(47808K), 0.0106558 secs] 43653K->6720K(252608K), 0.0107390 secs] [Times: user=0.03 sys=0.00, real=0.02 secs]  
  5. 5.617: [GC 5.617: [ParNew: 43296K->7006K(47808K), 0.0136826 secs] 44992K->8702K(252608K), 0.0137904 secs] [Times: user=0.03 sys=0.00, real=0.02 secs]  
  6. 7.429: [GC 7.429: [ParNew: 45278K->6723K(47808K), 0.0251993 secs] 46974K->10551K(252608K), 0.0252421 secs]  

我们取倒数第二条记录分析一下各个字段都代表了什么含义

[java] view plain copy
 print?
  1. 5.617（时间戳）: [GC（Young GC） 5.617（时间戳）: [ParNew（GC的区域）: 43296K（垃圾回收前的大小）->7006K（垃圾回收以后的大小）(47808K)（该区域总大小）, 0.0136826 secs（回收时间）] 44992K（堆区垃圾回收前的大小）->8702K（堆区垃圾回收后的大小）(252608K)（堆区总大小）, 0.0137904 secs（回收时间）] [Times: user=0.03（GC用户耗时） sys=0.00（GC系统耗时）, real=0.02 secs（GC实际耗时）]  

我们再对数据做一个简单的分析

从最后一条GC记录中我们可以看到 Young GC回收了 45278-6723=38555K的内存

Heap区通过这次回收总共减少了 46974-10551=36423K的内存。

38555-36423=2132K说明通过该次Young GC有2132K的内存被移动到了Old Gen，

 

我们来验证一下

在最后一次Young GC的回收以前 Old Gen的大小为8702-7006=1696

回收以后Old Gen的内存使用为10551-6723=3828

Old Gen在该次Young GC以后内存增加了3828-1696=2132K 与预计的相符

[java] view plain copy
 print?
  1. 4.231: [GC 4.231: [DefNew: 4928K->512K(4928K), 0.0044047 secs] 6835K->3468K(15872K), 0.0045291 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]  
  2. 4.445: [Full GC (System) 4.445: [Tenured: 2956K->3043K(10944K), 0.1869806 secs] 4034K->3043K(15872K), [Perm : 3400K->3400K(12288K)], 0.1870847 secs] [Times: user=0.05 sys=0.00, real=0.19 secs]  

最前面的数字 4.231 和 4.445 代表虚拟机启动以来的秒数。

[GC 和 [Full GC 是垃圾回收的停顿类型，而不是区分是新生代还是年老代，如果有 Full 说明发生了Stop-The-World 。如果是调用 System.gc() 触发的，那么将显示的是 [Full GC (System) 。

接下来的 [DefNew, [Tenured, [Perm 表示 GC 发生的区域，区域的名称与使用的 GC 收集器相关。
Serial 收集器中新生代名为 “Default New Generation”，显示的名字为 “[DefNew”。对于ParNew收集器，显示的是 “[ParNew”，表示 “Parallel New Generation”。 对于 Parallel Scavenge 收集器，新生代名为 “PSYoungGen”。年老代和永久代也相同，名称都由收集器决定。

方括号内部显示的 “4928K->512K(4928K)” 表示 “GC 前该区域已使用容量 -> GC 后该区域已使用容量 (该区域内存总容量) ”。

再往后的 “0.0044047 secs” 表示该区域GC所用时间，单位是秒。

再往后的 “6835K->3468K(15872K)” 表示 “GC 前Java堆已使用容量 -> GC后Java堆已使用容量 （Java堆总容量）”。

再往后的 “0.0045291 secs” 是Java堆GC所用的总时间。

最后的 “[Times: user=0.00 sys=0.00, real=0.00 secs]” 分别代表 用户态消耗的CPU时间、内核态消耗的CPU时间 和 操作从开始到结束所经过的墙钟时间。墙钟时间包括各种非运算的等待耗时，如IO等待、线程阻塞。CPU时间不包括等待时间，当系统有多核时，多线程操作会叠加这些CPU时间，所以user或sys时间会超过real时间。

堆的分代

技术分享

  • young区域就是新生代，存放新创建对象；
  • tenured是年老代，存放在新生代经历多次垃圾回收后仍存活的对象；
  • perm是永生代，存放类定义信息、元数据等信息。

当GC发生在新生代时，称为Minor GC，次收集；当GC发生在年老代时，称为Major GC，主收集。 一般的，Minor GC的发生频率要比Major GC高很多。

重新设置GC日志的输出

[java] view plain copy
 print?
  1. -XX:+PrintGCDetails  
  2. -XX:+PrintHeapAtGC  
  3. -XX:+PrintGCDateStamps  
  4. -XX:+PrintTenuringDistribution  
  5. -verbose:gc  
  6. -Xloggc:gc.log  

后可以看到进行GC前后的堆内存信息 

[java] view plain copy
 print?
  1. {Heap before GC invocations=1 (full 0):  
  2.  PSYoungGen      total 152896K, used 131072K [0x00000000f5560000, 0x0000000100000000, 0x0000000100000000)  
  3.   eden space 131072K, 100% used [0x00000000f5560000,0x00000000fd560000,0x00000000fd560000)  
  4.   from space 21824K, 0% used [0x00000000feab0000,0x00000000feab0000,0x0000000100000000)  
  5.   to   space 21824K, 0% used [0x00000000fd560000,0x00000000fd560000,0x00000000feab0000)  
  6.  PSOldGen        total 349568K, used 0K [0x00000000e0000000, 0x00000000f5560000, 0x00000000f5560000)  
  7.   object space 349568K, 0% used [0x00000000e0000000,0x00000000e0000000,0x00000000f5560000)  
  8.  PSPermGen       total 26432K, used 26393K [0x00000000d0000000, 0x00000000d19d0000, 0x00000000e0000000)  
  9.   object space 26432K, 99% used [0x00000000d0000000,0x00000000d19c64a0,0x00000000d19d0000)  
  10. 2013-05-05T23:16:10.480+0800: 5.228: [GC  
  11. Desired survivor size 22347776 bytes, new threshold 7 (max 15)  
  12.  [PSYoungGen: 131072K->8319K(152896K)] 131072K->8319K(502464K), 0.0176346 secs] [Times: user=0.03 sys=0.00, real=0.02 secs]   
  13. Heap after GC invocations=1 (full 0):  
  14.  PSYoungGen      total 152896K, used 8319K [0x00000000f5560000, 0x0000000100000000, 0x0000000100000000)  
  15.   eden space 131072K, 0% used [0x00000000f5560000,0x00000000f5560000,0x00000000fd560000)  
  16.   from space 21824K, 38% used [0x00000000fd560000,0x00000000fdd7ff78,0x00000000feab0000)  
  17.   to   space 21824K, 0% used [0x00000000feab0000,0x00000000feab0000,0x0000000100000000)  
  18.  PSOldGen        total 349568K, used 0K [0x00000000e0000000, 0x00000000f5560000, 0x00000000f5560000)  
  19.   object space 349568K, 0% used [0x00000000e0000000,0x00000000e0000000,0x00000000f5560000)  
  20.  PSPermGen       total 26432K, used 26393K [0x00000000d0000000, 0x00000000d19d0000, 0x00000000e0000000)  
  21.   object space 26432K, 99% used [0x00000000d0000000,0x00000000d19c64a0,0x00000000d19d0000)  
  22. }  

[java] view plain copy
 print?
  1. [0x00000000f5560000,0x00000000f5560000,0x00000000fd560000)  

这种形式的日志有两种意义： 
当这种日志出现在generation的详细信息里的时候，三个数字在HotSpot里分别称为low_boundary、high、high_boundary。 
low_boundary: reserved space的最低地址边界；通常也跟“low”相等，这是commited space的最低地址边界 
high: commited space的最高地址边界 
high_boundary: reserved space的最高地址边界。 

[low_boundary, high_boundary)范围内的就是reserved space，这个space的大小就是max capacity。 
[low, high)范围内的就是commited space，而这个space的大小就是current capacity（当前容量），简称capacity。 
capacity有可能在一对最小值和最大值之间浮动。最大值就是上面说的max capacity。 


Gc日志分析工具

(1)GCHisto
http://java.net/projects/gchisto
直接点击gchisto.jar就可以运行，点add载入gc.log
统计了总共gc次数，youngGC次数，FullGC次数，次数的百分比，GC消耗的时间，百分比，平均消耗时间，消耗时间最小最大值等

(2)GCLogViewer
http://code.google.com/p/gclogviewer/
点击run.bat运行
整个过程gc情况的趋势图，还显示了gc类型，吞吐量，平均gc频率，内存变化趋势等
Tools里还能比较不同gc日志


参考文章：

http://swcdxd.iteye.com/blog/1859858

http://qa.blog.163.com/blog/static/19014700220128199421589/

http://coderbee.net/index.php/jvm/20131216/646





jvm的GC日志分析 [转]

标签：port   inline   最大   tag   百分比   变化   默认值   ucid   pos   

原文地址：http://www.cnblogs.com/duenboa/p/6665550.html
踩
(0)
赞
(0)
   
举报
评论 一句话评论（0）
登录后才能评论！
分享档案
更多>
2021年07月29日 (22)
2021年07月28日 (40)
2021年07月27日 (32)
2021年07月26日 (79)
2021年07月23日 (29)
2021年07月22日 (30)
2021年07月21日 (42)
2021年07月20日 (16)
2021年07月19日 (90)
2021年07月16日 (35)
周排行
mamicode.com排行更多图片
更多
友情链接
兰亭集智   国之画   百度统计   站长统计   阿里云   chrome插件   新版天听网
关于我们 - 联系我们 - 留言反馈
© 2014 mamicode.com 版权所有  联系我们:gaon5@hotmail.com
迷上了代码！