关闭

快速解读GC日志

标签: jvm解读分析GC日志
27077人阅读 评论(0) 收藏 举报
分类:

本文是 Plumbr 发行的 Java垃圾收集指南 的部分内容。文中将介绍GC日志的输出格式, 以及如何解读GC日志, 从中提取有用的信息。我们通过 -XX:+UseSerialGC 选项,指定JVM使用串行垃圾收集器, 并使用下面的启动参数让 JVM 打印出详细的GC日志:

-XX:+PrintGCDetails
-XX:+PrintGCDateStamps
-XX:+PrintGCTimeStamps

这样配置以后,发生GC时输出的日志就类似于下面这种格式(为了显示方便,已手工折行):

2015-05-26T14:45:37.987-0200: 151.126: 
  [GC (Allocation Failure) 151.126:
    [DefNew: 629119K->69888K(629120K), 0.0584157 secs]
    1619346K->1273247K(2027264K), 0.0585007 secs] 
  [Times: user=0.06 sys=0.00, real=0.06 secs]

2015-05-26T14:45:59.690-0200: 172.829: 
  [GC (Allocation Failure) 172.829: 
    [DefNew: 629120K->629120K(629120K), 0.0000372 secs]
    172.829: [Tenured: 1203359K->755802K(1398144K), 0.1855567 secs]
    1832479K->755802K(2027264K),
    [Metaspace: 6741K->6741K(1056768K)], 0.1856954 secs]
  [Times: user=0.18 sys=0.00, real=0.18 secs]

上面的GC日志暴露了JVM中的一些信息。事实上,这个日志片段中发生了 2 次垃圾回收事件(Garbage Collection events)。其中一次清理的是年轻代(Young generation), 而第二次处理的是整个堆内存。下面我们来看,如何解读第一次GC事件,发生在年轻代中的小型GC(Minor GC):

2015-05-26T14:45:37.987-02001:151.1262:[GC3(Allocation Failure4)
151.126: [DefNew5:629119K->69888K6(629120K)7
, 0.0584157 secs]1619346K->1273247K8(2027264K)9,0.0585007 secs10]
[Times: user=0.06 sys=0.00, real=0.06 secs]
11

  1. 2015-05-26T14:45:37.987-0200 – GC事件(GC event)开始的时间点.
  2. 151.126 – GC时间的开始时间,相对于JVM的启动时间,单位是秒(Measured in seconds).
  3. GC – 用来区分(distinguish)是 Minor GC 还是 Full GC 的标志(Flag). 这里的 GC 表明本次发生的是 Minor GC.
  4. Allocation Failure – 引起垃圾回收的原因. 本次GC是因为年轻代中没有任何合适的区域能够存放需要分配的数据结构而触发的.
  5. DefNew – 使用的垃圾收集器的名字. DefNew 这个名字代表的是: 单线程(single-threaded), 采用标记复制(mark-copy)算法的, 使整个JVM暂停运行(stop-the-world)的年轻代(Young generation) 垃圾收集器(garbage collector).
  6. 629119K->69888K – 在本次垃圾收集之前和之后的年轻代内存使用情况(Usage).
  7. (629120K) – 年轻代的总的大小(Total size).
  8. 1619346K->1273247K – 在本次垃圾收集之前和之后整个堆内存的使用情况(Total used heap).
  9. (2027264K) – 总的可用的堆内存(Total available heap).
  10. 0.0585007 secs – GC事件的持续时间(Duration),单位是秒.
  11. [Times: user=0.06 sys=0.00, real=0.06 secs] – GC事件的持续时间,通过多种分类来进行衡量:
    • user – 此次垃圾回收, 垃圾收集线程消耗的所有CPU时间(Total CPU time).
    • sys – 操作系统调用(OS call) 以及等待系统事件的时间(waiting for system event)
    • real – 应用程序暂停的时间(Clock time). 由于串行垃圾收集器(Serial Garbage Collector)只会使用单个线程, 所以 real time 等于 user 以及 system time 的总和.

通过上面的分析, 我们可以计算出在垃圾收集期间, JVM 中的内存使用情况。在垃圾收集之前, 堆内存总的使用了 1.54G (1,619,346K)。其中, 年轻代使用了 614M(629,119k)。可以算出老年代使用的内存为: 967M(990,227K)。

下一组数据( -> 右边)中蕴含了更重要的结论, 年轻代的内存使用在垃圾回收后下降了 546M(559,231k), 但总的堆内存使用(total heap usage)只减少了 337M(346,099k). 通过这一点,我们可以计算出, 有 208M(213,132K) 的年轻代对象被提升到老年代(Old)中。

这个GC事件可以用下面的示意图来表示, 上方表示GC之前的内存使用情况, 下方表示结束后的内存使用情况:

这里写图片描述

如果你想学习更多, 请查看完整的 Java垃圾收集指南, 本示例是从其中抽取的。

原文链接: Understanding Garbage Collection Logs

翻译日期: 2015年10月18日

翻译人员: 铁锚 http://blog.csdn.net/renfufei

6
0
查看评论

7. GC 调优(实战篇) - GC参考手册

JVM上运行的程序多种多样, 启动参数也有上百个, 其中有很多会影响到 GC, 所以调优GC性能的方法也有很多种。 还是那句话, 没有真正的银弹, 能满足所有的性能调优指标。 我们能做的只是介绍一些常见的/和不常见的示例, 让你在碰到类似问题时知道是怎么回事。深入理解GC的工作原理, 熟练应用各种...
  • renfufei
  • renfufei
  • 2017-03-13 19:12
  • 7021

Full GC是否真的存在

在Plumbr这和GC暂停检测打交道的这段日子里,我查阅了与这个主题相关的大量文章,书籍以及资料。在这当中,我经常会对新生代GC, 年老代GC以及Full GC的事件的使用(滥用)感到困惑。于是便有了这篇文章,希望能够清除一些困惑。 本文需要读者对JVM内建的GC相关的常用原理有一定的了解。像...
  • caomiao2006
  • caomiao2006
  • 2015-08-19 14:59
  • 674

Java -- ExecutorService线程池触发的Full GC问题排查

今天在线上Java代码里,处理了一个由ExecutorServicec线程池引发的问题,将处理过程和一些调试沉淀下来。 分布式任务处理模块中,有一个Java daemon进程,通过队列接受Java代码描述的任务(jar),产生子进程(单独的JVM)class loader,处理定义的Java代码,并...
  • GugeMichael
  • GugeMichael
  • 2014-04-02 19:55
  • 6037

在运行时开启GC日志

关于GC的一些参数 -verbose.gc开关可显示GC的操作内容。打开它,可以显示最忙和最空闲收集行为发生的时间、收集前后的内存大小、收集需要的时间等 打开-xx:+ PrintGCDetails开关,可以详细了解GC中的变化。 打开-XX: + PrintGCTimeStamps开关,可以了...
  • AlbertFly
  • AlbertFly
  • 2016-08-09 11:23
  • 623

Minor GC、Major GC和Full GC之间的区别

对Minor GC和Major GC做点笔记    新生代 GC(Minor GC):指发生在新生代的垃圾收集动作,因为 Java 对象大多都具 备朝生夕灭的特性,所以 Minor GC 非常频繁,一般回收速度也比较快。    老年代...
  • z69183787
  • z69183787
  • 2016-06-07 20:48
  • 1569

gc监控

 一、GC监控 GC简述:GC日志记录了内存使用和回收状态,出现内存故障时,可作为分析排查手段。GC用于跟踪内存中的对象,回收哪些不再被其他对象引用的对象,gc的线程低于系统应用线程,只有没有系统应用线程的时候gc才会被触发,当堆空间的不足以满足创建新对象的时候也会被触发。...
  • forest_hou
  • forest_hou
  • 2010-04-14 10:24
  • 2639

JVM调试追中参数设置

引言: JVM提供了诸多的参数配置,打印出当前JVm的各类信息,方便后续进行Java应用的排查,本文将详细介绍若干常用的JVM调试追踪参数。
  • blueheart20
  • blueheart20
  • 2016-08-02 10:57
  • 2209

JVM调优总结 + jstat 分析

jstat -gccause pid 1 每格1毫秒输出结果 jstat -gccause pid 2000 每格2秒输出结果 不断的在屏幕打印出结果   S0     S1  ...
  • xingxiupaioxue
  • xingxiupaioxue
  • 2016-10-14 17:14
  • 2023

Spark 优化

官网地址: http://spark.apache.org/docs/latest/tuning.html 1、引言 提到Spark与Hadoop的区别,基本最常说的就是Spark采用基于内存的计算方式,尽管这种方式对数据处理的效率很高,但也会往往引发各种各样的问题,Spark中常见的OOM等等...
  • ainidong2005
  • ainidong2005
  • 2016-11-13 15:45
  • 1898

java gc的log分析

最近没什么事,主要是看到程序GC较快  所以想看下程序有没有问题,网上的一篇文章 http://book.51cto.com/art/201306/399236.htm 在程序启动的时候加上  几个参数 -verbose:gc -Xloggc:d:/gc -XX:+PrintG...
  • huaye2007
  • huaye2007
  • 2014-03-17 17:32
  • 6479
    博客专栏
    个人资料
    • 访问:3975120次
    • 积分:20845
    • 等级:
    • 排名:第457名
    • 原创:103篇
    • 转载:1篇
    • 译文:175篇
    • 评论:677条
    Google搜索该博客
    有问题?加入开源技术交流群
    有需要,qq联系我