eclipse设置打印GC

最新推荐文章于 2022-11-16 10:38:55 发布

小白的学习笔记

最新推荐文章于 2022-11-16 10:38:55 发布

阅读量4.2k

点赞数

分类专栏： Java/虚拟机

Java/虚拟机专栏收录该内容

14 篇文章 0 订阅

订阅专栏

首先建立评估体系，将workspace里所有的项目close掉，关闭eclipse。优化的用例就是启动eclipse，open一个项目，eclipse会自动build这个项目，保证没有感觉到明显的卡，也就是没有full GC。

开始：

eclipse.ini里加入打印gc情况的参数：

-XX:+PrintGCTimeStamps 
-XX:+PrintGCDetails 
-verbose:gc 
-Xloggc:gc.log

这样eclipse在运行过程中会记录gc日志，显示详细的gc情况，并打印在gc.log中，通过分析这个日志寻找eclipse的性能瓶颈和优化方式。
我最初的参数只是在原版基础上调了堆大小

-Xms512m 
-Xmx512m

将堆初始化和最大值设为一样，消除堆大小根据当前堆使用情况而变化带来的影响。
启动eclipse，发现gc.log里打出了很多full gc的日志

4.226: [Full GC 4.226: [Tenured: 18470K->19304K(30544K), 0.1159544 secs] 25154K->19304K(44368K), [Perm : 24574K->24554K(24576K)], 0.1160431 secs] [Times: user=0.13 sys=0.00, real=0.13 secs]

在启动的6秒多时间里共出现了8次full gc，所以启动慢，觉得启动时候挺卡的。从日志里可以看出来 FullGC主要是在回收tenured区和Perm区，其中Perm一直都是快满的状态，Perm : 24574K->24554K(24576K)，Perm大小在不断调整，所以需要固定Perm区的大小，保证够用，eclipse.ini里加入

-XX:PermSize=64m 
-XX:MaxPermSize=64m

再启动：发现没有full gc了只有数量比较多的minor gc，挑启动开始到启动完成的第一条和最后一条日志

0.209: [GC 0.209: [DefNew: 4416K->511K(4928K), 0.0034707 secs] 4416K->614K(15872K), 0.0035239 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
…. 
6.383: [GC 6.383: [DefNew: 18880K->1985K(21184K), 0.0055311 secs] 46992K->30098K(68040K), 0.0055694 secs]

这6秒中GC日志打了69次，而内存回收率还是蛮高的 young区18880-1985=16895 jvm 46992-30098=16894 都快接近100%了，可以看出young区是由小到大在不断调整大小，所以不断GC，因此设一个初始值吧，据说设置heap的1/4比较好，那就是128M，所以eclipse.ini加入

-Xmn128m

再重启，发现GC日志就四条了，eclipse启动自然快了

1.292: [GC 1.292: [DefNew: 104960K->10984K(118016K), 0.0334165 secs] 104960K->10984K(511232K), 0.0334603 secs] [Times: user=0.03 sys=0.00, real=0.03 secs] 
2.182: [GC 2.182: [DefNew: 115944K->1852K(118016K), 0.0221714 secs] 115944K->11466K(511232K), 0.0222142 secs] [Times: user=0.00 sys=0.02, real=0.02 secs] 
3.987: [GC 3.987: [DefNew: 106779K->12531K(118016K), 0.0378228 secs] 116393K->22145K(511232K), 0.0378692 secs] [Times: user=0.03 sys=0.00, real=0.03 secs] 
5.377: [GC 5.377: [DefNew: 117491K->9403K(118016K), 0.0513728 secs] 127105K->31364K(511232K), 0.0514133 secs]

但是，启动后open我的多个项目，这些项目互相依赖，eclipse自动build，感觉有点小卡，发现日志里多了4次full GC，所以就卡了…

67.320: [Full GC (System) 67.320: [Tenured: 88847K->68809K(393216K), 0.2121213 secs] 117385K->68809K(511232K), [Perm : 41915K->41915K(65536K)], 0.2121747 secs] [Times: user=0.20 sys=0.00, real=0.20 secs] 
103.759: [Full GC (System) 103.759: [Tenured: 81882K->66784K(393216K), 0.3287387 secs] 185350K->66784K(511232K), [Perm : 53464K->53414K(65536K)], 0.3287897 secs] [Times: user=0.33 sys=0.00, real=0.33 secs]

这个时候Tenured区和Perm都还没到很接近最大值，但是为什么还有full GC呢，开始以为是JVM悲观认为Tenured区剩余空间不足以应对下一次minor GC 所以进行了full GC调整Tenured空间，索性直接增加了堆最大值到-Xmx728m（工作电脑的内存是3.5G），但重启后full gc还是有4次，而且有几次minor GC用的时间超过了0.1秒，这是因为增加了堆大小，导致GC用时也增加了，不能接受。所以还是改回-Xmx512m。
再仔细观察日志，发现Full GC (System) 字样，这个意思是eclipse里调用了System.gc()手动触发了系统GC，好吧，哥已经给你分配足够空间了，你就省省吧，在eclipse.ini里加入：

-XX:+DisableExplicitGC

这样就差不多了，整个过程没有出现full gc，再编码2个小时，中间只出现了一次full gc，在open build某50W行+的代码的时候，eclipse还是卡了…
最后又稍微调了一下各代的大小，得到目前的参数：

-Xms512m 
-Xmx512m 
-XX:PermSize=96m 
-XX:MaxPermSize=96m 
-Xmn168m 
-XX:+DisableExplicitGC

另外没有去调GC策略，主要是觉得eclipse是客户端程序，默认的client单线程的GC策略应该是比较适合的，以后有时间再试试看吧。

另一篇文章：

1、在eclipse根目录下的eclipse.ini配置文件中添加以下参数：
-verbose:gc （开启打印垃圾回收日志）
-Xloggc:eclipse_gc.log （设置垃圾回收日志打印的文件，文件名称可以自定义）
-XX:+PrintGCTimeStamps （打印垃圾回收时间信息时的时间格式）
-XX:+PrintGCDetails （打印垃圾回收详情）
添加完以上参数后当启动Eclipse后就能在Eclipse根目录看到一个eclipse_gc.log的gc日志文件
2、设置eclipse初始堆、非堆内存大小以及年轻代
-Xms50m –Xmx200m -XX:PermSize=30m -XX:MaxPermSize=60m
3、添加JVM监控参数
-Djava.rmi.server.hostname=127.0.0.1 -Dcom.sun.management.jmxremote.port=6688 -Dcom.sun.management.jmxremote.ssl=false -Dcom.sun.management.jmxremote.authenticate=false

gc日志：

Java HotSpot(TM) Client VM (25.25-b02) for windows-x86 JRE (1.8.0_25-b18), built on Oct 7 2014 14:31:05 by “java_re” with MS VC++ 10.0 (VS2010)
Memory: 4k page, physical 8340720k(3545144k free), swap 8787248k(2501780k free)
CommandLine flags: -XX:InitialHeapSize=268435456 -XX:MaxHeapSize=943718400 -XX:+PrintGC -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:-UseLargePagesIndividualAllocation
4.458: [GC (Allocation Failure) 4.458: [DefNew: 69952K->8704K(78656K), 0.0681410 secs] 69952K->22643K(253440K), 0.0690407 secs] [Times: user=0.06 sys=0.02, real=0.08 secs]
5.741: [Full GC (Metadata GC Threshold) 5.741: [Tenured: 13939K->33208K(174784K), 0.1036054 secs] 48618K->33208K(253440K), [Metaspace: 11442K->11442K(12672K)], 0.1041130 secs] [Times: user=0.11 sys=0.00, real=0.11 secs]
12.427: [GC (Allocation Failure) 12.427: [DefNew: 70016K->8704K(78720K), 0.0821340 secs] 103224K->55838K(253504K), 0.0822684 secs] [Times: user=0.08 sys=0.00, real=0.09 secs]
12.787: [Full GC (Metadata GC Threshold) 12.787: [Tenured: 47134K->56307K(174784K), 0.1662610 secs] 59785K->56307K(253504K), [Metaspace: 19215K->19215K(20864K)], 0.1663899 secs] [Times: user=0.16 sys=0.00, real=0.16 secs]
17.018: [GC (Allocation Failure) 17.018: [DefNew: 70016K->8704K(78720K), 0.0475891 secs] 126323K->68567K(253504K), 0.0477196 secs] [Times: user=0.03 sys=0.02, real=0.06 secs]
21.047: [GC (Allocation Failure) 21.047: [DefNew: 78720K->8704K(78720K), 0.0752255 secs] 138583K->83739K(253504K), 0.0753766 secs] [Times: user=0.08 sys=0.00, real=0.06 secs]
21.320: [Full GC (Metadata GC Threshold) 21.320: [Tenured: 75035K->61015K(174784K), 0.2800589 secs] 87423K->61015K(253504K), [Metaspace: 31969K->31969K(34176K)], 0.2802057 secs] [Times: user=0.28 sys=0.00, real=0.29 secs]

GC日志说明：
GC打印时间: [垃圾回收类型回收时间: [收集器名称: 年轻代回收前占用大小->年轻代回收后占用大小(年轻代当前容量),
年轻代局部GC时JVM暂停处理的时间] 堆空间GC前占用的空间->堆空间GC后占用的空间(堆空间当前容量)
,GC过程中JVM暂停处理的时间]。
垃圾回收类型：分为GC和Full GC.
GC一般为堆空间某个区发生了垃圾回收，
Full GC基本都是整个堆空间及持久代发生了垃圾回收，通常优化的目标之一是尽量减少GC和Full GC的频率。
收集器名称：一般都为收集器的简称或别名，通过收集器名称基本都能判断出那个区发生了GC。
DefNew：年轻代（新生代）发生了GC （若为DefNew可知当前JVM年轻代使用的串行收集器）
ParNew：年轻代（新生代）发生了GC （若为ParNew可知当前JVM年轻代使用了并行收集器）
Tenured：老年代发生了GC
Perm：持久代发生了GC