查看gc日志
Java GC日志查看,GC日志时间分析
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 |
|
这里使用如下的参数来进行日志的打印:
-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配置,提升机器总的计算能力。