原创作者: bestxiaok   阅读:5890次   评论:5条   更新时间:2011-05-26    

总是感觉自己的elipse启动比别人的慢,开始以为是装的插件太多(pydev,GAE,scala……)或者是导入的项目有点大。后来把-Xloggc:gc.log这个配置加上去看看启动的日志,吓了一跳,一次启动做了9次fullgc。和jboss服务器一样,肯定可以优化一下配置来更少的full gc来节约启动时间。

   第一次优化:把-Xms(初始化堆大小) -Xmx(JVM最大堆大小)设置为一样大小512m,避免GC后JVM重新分配内存。但是重启eclipse的时候full gc的次数并没有减少,而且启动的时候GC全部变成了full gc,日志如下:

3.308: [Full GC 3.308: [Tenured: 0K->19530K(262144K), 0.1515426 secs] 172215K->19530K(498112K), [Perm : 16383K->16383K(16384K)], 0.1516281 secs] [Times: user=0.14 sys=0.00, real=0.15 secs] 

8.472: [Full GC 8.472: [Tenured: 19530K->34170K(262144K), 0.2060534 secs] 145021K->34170K(498112K), [Perm : 20479K->20479K(20480K)], 0.2061412 secs] [Times: user=0.19 sys=0.00, real=0.21 secs] 

9.027: [Full GC 9.027: [Tenured: 34170K->35855K(262144K), 0.1790415 secs] 54259K->35855K(498112K), [Perm : 24575K->24575K(24576K)], 0.1791281 secs] [Times: user=0.19 sys=0.00, real=0.18 secs] 

10.004: [Full GC 10.004: [Tenured: 35855K->44735K(262144K), 0.2850547 secs] 81210K->44735K(498112K), [Perm : 28671K->28646K(28672K)], 0.2851505 secs] [Times: user=0.28 sys=0.00, real=0.28 secs] 

10.725: [Full GC 10.725: [Tenured: 44735K->49542K(262144K), 0.2657311 secs] 71680K->49542K(498112K), [Perm : 32759K->32759K(32768K)], 0.2658216 secs] [Times: user=0.25 sys=0.00, real=0.27 secs] 

12.057: [Full GC 12.057: [Tenured: 49542K->64706K(262144K), 0.3637080 secs] 179985K->64706K(498112K), [Perm : 36863K->36863K(36864K)], 0.3637938 secs] [Times: user=0.37 sys=0.00, real=0.36 secs] 

12.788: [Full GC 12.788: [Tenured: 64706K->65640K(262144K), 0.3229940 secs] 87100K->65640K(498112K), [Perm : 40959K->40959K(40960K)], 0.3230836 secs] [Times: user=0.31 sys=0.00, real=0.32 secs] 

13.652: [Full GC 13.652: [Tenured: 65640K->70639K(262144K), 0.4553435 secs] 116918K->70639K(498112K), [Perm : 45055K->44963K(45056K)], 0.4554289 secs] [Times: user=0.45 sys=0.00, real=0.46 secs] 

14.679: [Full GC 14.679: [Tenured: 70639K->72308K(262144K), 0.4009647 secs] 122313K->72308K(498112K), [Perm : 49151K->49151K(49152K)], 0.4010552 secs] [Times: user=0.38 sys=0.00, real=0.40 secs] 

    从日志中分析可以看出:触发full gc的罪魁祸首是Perm,这个没有设置,所以继续优化!

    第二次优化:-XX:PermSize=64m  -XX:MaxPermSize=64m,把持久化的初始化大小和最大大小设置为一样。Full gc消失了,来了24次minor gc。

0.689: [GC 0.689: [DefNew: 32256K->2724K(36288K), 0.0108873 secs] 32256K->2724K(520256K), 0.0109685 secs] [Times: user=0.02 sys=0.00, real=0.01 secs] 

1.020: [GC 1.020: [DefNew: 34980K->3090K(36288K), 0.0159294 secs] 34980K->5812K(520256K), 0.0159941 secs] [Times: user=0.02 sys=0.00, real=0.02 secs] 

1.451: [GC 1.451: [DefNew: 35346K->2612K(36288K), 0.0131000 secs] 38068K->8344K(520256K), 0.0131866 secs] [Times: user=0.01 sys=0.00, real=0.01 secs] 

2.670: [GC 2.674: [DefNew: 34868K->4032K(36288K), 0.0338445 secs] 40600K->14881K(520256K), 0.0357554 secs] [Times: user=0.03 sys=0.02, real=0.04 secs] 

3.537: [GC 3.537: [DefNew: 36280K->4032K(36288K), 0.0297593 secs] 47129K->19882K(520256K), 0.0298390 secs] [Times: user=0.03 sys=0.00, real=0.03 secs] 

3.595: [GC 3.595: [DefNew: 36223K->74K(36288K), 0.0121076 secs] 52074K->19924K(520256K), 0.0122015 secs] [Times: user=0.00 sys=0.00, real=0.01 secs] 

4.108: [GC 4.108: [DefNew: 32330K->1755K(36288K), 0.0071144 secs] 52180K->21605K(520256K), 0.0071898 secs] [Times: user=0.02 sys=0.00, real=0.01 secs] 

7.550: [GC 7.550: [DefNew: 34011K->4032K(36288K), 0.0460676 secs] 53861K->35250K(520256K), 0.0461438 secs] [Times: user=0.05 sys=0.00, real=0.05 secs] 

8.818: [GC 8.818: [DefNew: 36288K->4032K(36288K), 0.0352634 secs] 67506K->38332K(520256K), 0.0353470 secs] [Times: user=0.05 sys=0.00, real=0.04 secs] 

9.926: [GC 9.926: [DefNew: 36288K->4032K(36288K), 0.0410570 secs] 70588K->45524K(520256K), 0.0411413 secs] [Times: user=0.03 sys=0.02, real=0.04 secs] 

10.332: [GC 10.332: [DefNew: 36288K->4031K(36288K), 0.0325734 secs] 77780K->52292K(520256K), 0.0326496 secs] [Times: user=0.05 sys=0.00, real=0.03 secs] 

10.583: [GC 10.583: [DefNew: 36287K->4031K(36288K), 0.0250005 secs] 84548K->57151K(520256K), 0.0250791 secs] [Times: user=0.03 sys=0.00, real=0.02 secs] 

10.765: [GC 10.765: [DefNew: 36213K->4032K(36288K), 0.0691980 secs] 89333K->72388K(520256K), 0.0692885 secs] [Times: user=0.08 sys=0.00, real=0.07 secs] 

10.977: [GC 10.977: [DefNew: 36288K->4031K(36288K), 0.0426303 secs] 104644K->81872K(520256K), 0.0427115 secs] [Times: user=0.05 sys=0.00, real=0.04 secs] 

11.211: [GC 11.211: [DefNew: 36287K->4032K(36288K), 0.0550659 secs] 114128K->91896K(520256K), 0.0551464 secs] [Times: user=0.03 sys=0.02, real=0.06 secs] 

11.641: [GC 11.641: [DefNew: 36288K->3147K(36288K), 0.0295076 secs] 124152K->93474K(520256K), 0.0296096 secs] [Times: user=0.03 sys=0.00, real=0.03 secs] 

12.591: [GC 12.591: [DefNew: 35403K->2274K(36288K), 0.0241671 secs] 125730K->95722K(520256K), 0.0242549 secs] [Times: user=0.02 sys=0.02, real=0.02 secs] 

12.896: [GC 12.896: [DefNew: 34530K->3023K(36288K), 0.0193394 secs] 127978K->98567K(520256K), 0.0194275 secs] [Times: user=0.02 sys=0.00, real=0.02 secs] 

13.249: [GC 13.249: [DefNew: 35280K->939K(36288K), 0.0161462 secs] 130824K->99419K(520256K), 0.0162313 secs] [Times: user=0.01 sys=0.00, real=0.02 secs] 

13.919: [GC 13.919: [DefNew: 33195K->2070K(36288K), 0.0124033 secs] 131675K->100550K(520256K), 0.0125083 secs] [Times: user=0.02 sys=0.00, real=0.01 secs] 

14.396: [GC 14.396: [DefNew: 34326K->4032K(36288K), 0.0204527 secs] 132806K->104239K(520256K), 0.0205335 secs] [Times: user=0.02 sys=0.00, real=0.02 secs] 

14.554: [GC 14.554: [DefNew: 36288K->4031K(36288K), 0.0554755 secs] 136495K->114252K(520256K), 0.0555567 secs] [Times: user=0.06 sys=0.00, real=0.06 secs] 

14.735: [GC 14.735: [DefNew: 36287K->4031K(36288K), 0.0728643 secs] 146508K->129069K(520256K), 0.0729860 secs] [Times: user=0.06 sys=0.00, real=0.07 secs] 

14.954: [GC 14.954: [DefNew: 36287K->4032K(36288K), 0.0529429 secs] 161325K->137308K(520256K), 0.0530283 secs] [Times: user=0.05 sys=0.00, real=0.05 secs] 

15.308: [GC 15.308: [DefNew: 36288K->1126K(36288K), 0.0192389 secs] 169564K->138221K(520256K), 0.0193313 secs]

   从日志中分析可以看出:频繁的minor gc是由新生代没有设置自动分配造成的。

    第三次优化:-Xmn256m 设置新生代大小为256M。好了,就4次minor gc。完成任务。日志如下:

3.592: [GC 3.592: [DefNew: 209792K->19904K(235968K), 0.0765218 secs] 209792K->19904K(498112K), 0.0766072 secs] [Times: user=0.06 sys=0.02, real=0.08 secs] 

10.457: [GC 10.457: [DefNew: 229696K->26176K(235968K), 0.1996293 secs] 229696K->58203K(498112K), 0.1997121 secs] [Times: user=0.17 sys=0.03, real=0.20 secs] 

12.862: [GC 12.862: [DefNew: 235968K->17131K(235968K), 0.1315169 secs] 267995K->74647K(498112K), 0.1315965 secs] [Times: user=0.14 sys=0.00, real=0.13 secs] 

14.465: [GC 14.465: [DefNew: 226923K->26176K(235968K), 0.1363962 secs] 284439K->101396K(498112K), 0.1364835 secs]

最后的配置如下:

-Xmn128m

-Xms512m

-Xmx512m

-XX:PermSize=64m  

-XX:MaxPermSize=64m

-verbose:gc

-XX:+PrintGCTimeStamps

-XX:+PrintGCDetails 

-Xloggc:gc.log

评论 共 5 条 请登录后发表评论
5 楼 KarlChan 2016-07-16 15:23
第二次是因为permanent设置太小。
第三次因为JVM分配的最大young generation heap太小了。而且
4 楼 beneo 2011-08-12 18:04
-Xms128m
-Xmx512m
-XX:PermSize=128m
-XX:MaxPermSize=196m
-XX:ReservedCodeCacheSize=64m
-XX:+TieredCompilation
-Xss128k
-XX:ParallelGCThreads=4
-XX:+UseParNewGC
-XX:SurvivorRatio=8
-XX:TargetSurvivorRatio=90
-XX:MaxTenuringThreshold=31
-XX:MaxGCPauseMillis=10
-XX:MaxHeapFreeRatio=70
-XX:+UseConcMarkSweepGC
-XX:+CMSIncrementalMode
-XX:+CMSIncrementalPacing
-XX:+UnlockExperimentalVMOptions
-XX:+UseFastAccessorMethods
-XX:+AggressiveOpts
-Dcom.sun.management.jmxremote
-ea
3 楼 beneo 2011-08-12 18:01
-Xms128m
-Xmx512m
-XX:MaxPermSize=250m
-XX:ReservedCodeCacheSize=64m
-XX:+TieredCompilation
-Xss4m
-XX:PermSize=128m
-XX:CompileThreshold=5
-XX:MaxGCPauseMillis=10
-XX:MaxHeapFreeRatio=70
-XX:+UseConcMarkSweepGC 
-XX:+CMSIncrementalMode
-XX:+CMSIncrementalPacing
-XX:+UnlockExperimentalVMOptions
-XX:+UseFastAccessorMethods
-Dcom.sun.management.jmxremote
-ea
2 楼 tom&jerry 2011-06-17 10:36
-verbose:gc

-XX:+PrintGCTimeStamps

-XX:+PrintGCDetails

-Xloggc:gc.log
1 楼 xgj1988 2011-04-27 15:36
为什么我在eclipse.ini里面配置了 -Xloggc:d:\gc.log 的信息和你的不同

感觉我的信息好少,而且我也加了-verbose:gc
我的配置如下:
-showsplash
com.genuitec.myeclipse.product
--launcher.XXMaxPermSize
-vmargs
-Xms512m
-Xmx512m
-Duser.language=en
-XX:PermSize=64M
-XX:MaxPermSize=64M
-verbose:gc
-Xloggc:d:\eclipseSetup.log


输入出的内容是:

0.000: [GC 32256K->8553K(520256K), 0.0512999 secs]
1.422: [GC 40809K->17014K(520256K), 0.0653821 secs]
2.818: [GC 49270K->20493K(520256K), 0.0385799 secs]
4.124: [GC 52749K->23110K(520256K), 0.0347348 secs]
5.405: [GC 55366K->25459K(520256K), 0.0312760 secs]
7.144: [GC 57715K->29170K(520256K), 0.0319969 secs]
8.417: [GC 61426K->31353K(520256K), 0.0300393 secs]
9.880: [GC 63609K->36043K(520256K), 0.0470010 secs]
10.370: [GC 68285K->37646K(520256K), 0.0254765 secs]
11.312: [GC 69902K->52962K(520256K), 0.0735824 secs]
11.716: [GC 85218K->56060K(520256K), 0.0343752 secs]


这样我根本不知道当前的GC是执行的哪个,比如你的有GC 信息里面有个 DefNew,还知道是新生代 GC 造成的,但是我的怎么没这个信息呢?

发表评论

您还没有登录,请您登录后再发表评论

文章信息

Global site tag (gtag.js) - Google Analytics