1. 程式人生 > >eclipse設定列印GC

eclipse設定列印GC

首先建立評估體系,將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] 46992
K->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