• jvm的GC日志分析 [转]

     

    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时间。

    堆的分代

    JVM-heap-generations

    • 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
  • 相关阅读:
    Spring 集成Quartz
    windows跟linux文件共享
    5.5.3使用terminfo功能标志
    5.4.1 termios结构，关闭回显功能，一键入字符fgetc立刻返回，不用按下回车键
    5.2与终端进行对话
    5.1对终端进行读写
    4.8资源和限制
    4.7日志
    大小端问题
    QWebView下载文件，QUrl中解析文件名
  • 原文地址：https://www.cnblogs.com/duenboa/p/6665550.html
Copyright © 2020-2023  润新知