我是如何讓Eclipse的啟動速度提升1.5秒的
本文是Effective Java專欄Java虛擬機器專題的第十講,如果你覺得看完之後對你有所幫助,歡迎訂閱本專欄,也歡迎您將本專欄分享給你身邊的工程師同學。
前言
在這之前,我寫過一篇文章 —— 關於Java虛擬機器效能調優的清單,文章裡我梳理了JVM調優的所需理論知識和常用工具清單,今天就讓我們使用這份清單,進行一次JVM的調優實戰!
我為什麼選擇Eclipse來調優
雖然IntelliJ IDEA的風頭似乎已經蓋過了Eclipse,但由於工作的原因,在大多數時候我還是使用Eclipse作為開發工具,我想現在使用Eclipse的程式設計師也一定很多。
那麼,正在使用或者曾經使用過Eclipse的你,有沒有想過:
- Eclipse是採用什麼垃圾收集器?
- 啟動的時候,都執行了多少次GC?
- 能不能對Eclipse的啟動速度進行調優?
這篇文章,介紹一下我是如何對Eclipse進行調優,使得它的啟動速度提升了1.5秒的。
你可能會說,才1.5秒,需要說的是,筆者的電腦效能比較牛,優化前啟動Eclipse只需要5953ms,優化結束後是4693ms,提升了21%的速度,這就像百米賽跑,第一名的博爾特和最後一名的差了不到1秒鐘,但已經完全是不同的境界了!
下面讓我們開始提速吧!
環境資訊
- JDK:jdk1.7.0_51
- 機器環境:WIN10, 64位,12G記憶體,i7處理器
調優前的啟動速度
為了方便計算Eclipse的啟動速度,這裡使用了周志明老師寫的一個Eclipse外掛,該外掛可以在Eclipse啟動完成後,計算當前時間和Eclipse開始啟動時間直接的間隔,然後在介面上打印出總的啟動時間,就像這樣:
筆者一開始的eclipse.ini配置是這樣的:
-vm
C:/Program Files/Java/jdk1.7.0_51/bin/javaw.exe
-startup
plugins/org.eclipse.equinox.launcher_1.3.0.v20130327-1440.jar
--launcher.library
plugins/org.eclipse.equinox.launcher.win32.win32.x86_64_1.1.200.v20130521-0416
-product
org.eclipse.epp.package.standard.product
--launcher.defaultAction
openFile
--launcher.XXMaxPermSize
128M
-showsplash
org.eclipse.platform
--launcher.XXMaxPermSize
128M
--launcher.defaultAction
openFile
--launcher.appendVmargs
-vmargs
-Dosgi.requiredJavaVersion=1.6
-Xms40m
-Xmx128M
配置裡面主要是指定了使用JDK7,初始堆大小(-Xms)是40m,最大堆(-Xmx)是128m.
接著,筆者啟動了三次Eclipse,三次的啟動時間分別是5960ms、5945ms、5954ms,取平均值之後,調優前的啟動時間是5953ms.
同時筆者通過使用Visual VM,記錄了調優前虛擬機器的執行狀況:
從Visual VM的監控資訊看,啟動時間主要有三大塊:編譯時間、類載入時間以及垃圾回收的停頓時間。
其中,編譯時間是指JVM的JIT編譯,筆者是64位的機器,只能採用server模式,因此在即時編譯上沒有什麼優化的餘地。
關於JIT編譯器、server模式和client模式,可以參考 解釋執行和即時編譯器
因此,下面主要對耗時3.468秒的類載入時間,以及新生代(Eden Space)總耗時107ms的13次GC和老年代(Old Gen)總耗時156ms的Full GC,進行調優。
類載入時間調優
JVM的類載入,是指將Class檔案,載入到虛擬機器中。類載入的過程,包括載入、驗證、準備、解析、使用、解除安裝等階段。
其中驗證,是由於Class檔案不全都是由Java原始碼編譯而來,Class檔案可以使用任何途徑產生,甚至可以直接使用十六進位制編輯器來編寫。因此虛擬機器要對Class檔案進行驗證。而對於Eclipse來說,虛擬機器要載入的檔案,基本都是我們自己編寫的原始碼,是值得信任的,因此,可以加入引數-Xverify:none將類載入時的驗證階段去掉。
去掉之後,再來看Visual VM裡的類載入時間,可以看到類載入時間一下子下降到2s:
同樣的,再來啟動三次Eclipse,時間分別是4687ms、4700ms、4695ms,取平均值,去掉驗證階段後的Eclipse的啟動時間為4694ms。
垃圾收集的時間調優
再來對垃圾收集進行調優,首先,我們列印一下GC日誌,來看看現在Eclipse採用的是什麼垃圾收集器,在eclipse.ini中加入:
-XX:+PrintGCTimeStamps
-XX:+PrintGCDetails
-Xloggc:gc.log
啟動後檢視gc.log:
0.373: [GC [PSYoungGen: 10752K->1528K(12288K)] 10752K->2853K(39936K), 0.0087200 secs] [Times: user=0.05 sys=0.01, real=0.01 secs]
0.641: [GC [PSYoungGen: 12280K->1512K(23040K)] 13605K->5449K(50688K), 0.0053889 secs] [Times: user=0.00 sys=0.00, real=0.01 secs]
1.205: [GC [PSYoungGen: 23016K->1522K(23040K)] 26953K->13258K(50688K), 0.0089067 secs] [Times: user=0.00 sys=0.00, real=0.01 secs]
1.667: [GC [PSYoungGen: 23026K->1515K(42496K)] 34762K->16585K(70144K), 0.0061016 secs] [Times: user=0.00 sys=0.02, real=0.01 secs]
1.809: [GC [PSYoungGen: 42475K->1515K(42496K)] 57545K->16937K(70144K), 0.0049001 secs] [Times: user=0.02 sys=0.00, real=0.01 secs]
2.372: [GC [PSYoungGen: 42475K->1528K(23040K)] 57897K->24396K(50688K), 0.0109632 secs] [Times: user=0.05 sys=0.02, real=0.01 secs]
2.383: [Full GC [PSYoungGen: 1528K->0K(23040K)] [ParOldGen: 22868K->22517K(51200K)] 24396K->22517K(74240K) [PSPermGen: 23460K->23448K(47104K)], 0.1348976 secs] [Times: user=0.38 sys=0.00, real=0.13 secs]
2.970: [GC [PSYoungGen: 21504K->8905K(30720K)] 44021K->31422K(81920K), 0.0067912 secs] [Times: user=0.00 sys=0.00, real=0.01 secs]
3.309: [GC [PSYoungGen: 30409K->9243K(30720K)] 52926K->31760K(81920K), 0.0084435 secs] [Times: user=0.05 sys=0.00, real=0.01 secs]
3.715: [GC [PSYoungGen: 27675K->12787K(31232K)] 50192K->36581K(82432K), 0.0124344 secs] [Times: user=0.06 sys=0.00, real=0.01 secs]
4.478: [GC [PSYoungGen: 31219K->12778K(28160K)] 55013K->36741K(79360K), 0.0183642 secs] [Times: user=0.06 sys=0.00, real=0.02 secs]
4.976: [GC [PSYoungGen: 28138K->12745K(29696K)] 52101K->36707K(80896K), 0.0122746 secs] [Times: user=0.06 sys=0.00, real=0.01 secs]
通過其中的PSYoungGen和PSPermGen,可以知道,採用的是新生代Parallel New + 老年代Parallell Old的吞吐量優先的組合,讓我們來看一下下面這張圖:
兩個收集器之間有連線,代表他們可以組合使用,考慮到Eclipse經常需要進行互動,因此吞吐量優先,這種適合後臺執行的應用的組合,顯得沒什麼必要,我們可以採用新生代ParNew + 老年代CMS的降低停頓優先組合。
我們往eclipse.ini加入如下配置:
-XX:+UseConcMarkSweepGC
-XX:+UseParNewGC
接著啟動Eclipse,觀察Visual VM:
有點懵逼了,新生代的GC次數一下子去到了22次,老年代的GC也從一次暴漲到了10次,不過,雖然GC次數暴漲了,但是垃圾收集的時間並沒有增加太多,看來這個組合的收集器還是很給力的,現在我們看一下GC日誌,分析一下發生那麼多次GC的原因:
0.404: [GC0.404: [ParNew: 10944K->1344K(12288K), 0.0061580 secs] 10944K->2856K(39616K), 0.0062909 secs] [Times: user=0.06 sys=0.00, real=0.01 secs]
0.698: [GC0.698: [ParNew: 12288K->1344K(12288K), 0.0072989 secs] 13800K->5854K(39616K), 0.0073625 secs] [Times: user=0.06 sys=0.00, real=0.01 secs]
1.051: [GC1.051: [ParNew: 12288K->1344K(12288K), 0.0083077 secs] 16798K->9368K(39616K), 0.0083701 secs] [Times: user=0.00 sys=0.00, real=0.01 secs]
1.369: [GC1.369: [ParNew: 12288K->1344K(12288K), 0.0082115 secs] 20312K->13721K(39616K), 0.0082795 secs] [Times: user=0.05 sys=0.00, real=0.01 secs]
1.699: [GC1.699: [ParNew: 12288K->1344K(12288K), 0.0066972 secs] 24665K->16288K(39616K), 0.0067814 secs] [Times: user=0.06 sys=0.00, real=0.01 secs]
1.706: [GC [1 CMS-initial-mark: 14944K(27328K)] 16460K(39616K), 0.0011819 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
1.707: [CMS-concurrent-mark-start]
1.728: [CMS-concurrent-mark: 0.021/0.021 secs] [Times: user=0.05 sys=0.00, real=0.02 secs]
1.729: [CMS-concurrent-preclean-start]
1.729: [CMS-concurrent-preclean: 0.000/0.000 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
1.729: [CMS-concurrent-abortable-preclean-start]
1.786: [GC1.786: [ParNew: 12288K->934K(12288K), 0.0031670 secs] 27232K->16666K(39616K), 0.0032384 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
1.832: [GC1.832: [ParNew: 11878K->490K(12288K), 0.0012284 secs] 27610K->16222K(39616K), 0.0013088 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
1.869: [GC1.869: [ParNew: 11434K->622K(12288K), 0.0008751 secs] 27166K->16354K(39616K), 0.0009302 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
1.902: [GC1.902: [ParNew: 11566K->754K(12288K), 0.0008866 secs] 27298K->16486K(39616K), 0.0009452 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
1.934: [GC1.934: [ParNew: 11698K->891K(12288K), 0.0009875 secs] 27430K->16622K(39616K), 0.0010413 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
1.966: [GC1.966: [ParNew: 11835K->699K(12288K), 0.0010225 secs] 27566K->16431K(39616K), 0.0011007 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
2.079: [CMS-concurrent-abortable-preclean: 0.048/0.350 secs] [Times: user=0.53 sys=0.02, real=0.35 secs]
2.079: [GC[YG occupancy: 6449 K (12288 K)]2.079: [Rescan (parallel) , 0.0031854 secs]2.082: [weak refs processing, 0.0001384 secs]2.083: [scrub string table, 0.0004222 secs] [1 CMS-remark: 15731K(27328K)] 22180K(39616K), 0.0038528 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
2.083: [CMS-concurrent-sweep-start]
2.088: [CMS-concurrent-sweep: 0.005/0.005 secs] [Times: user=0.00 sys=0.00, real=0.01 secs]
2.088: [CMS-concurrent-reset-start]
2.089: [CMS-concurrent-reset: 0.000/0.000 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
2.269: [GC2.269: [ParNew: 11643K->1344K(12288K), 0.0078219 secs] 20634K->13437K(39616K), 0.0078808 secs] [Times: user=0.00 sys=0.00, real=0.01 secs]
2.484: [GC2.484: [ParNew: 12288K->1344K(12288K), 0.0076834 secs] 24381K->15864K(39616K), 0.0079210 secs] [Times: user=0.01 sys=0.00, real=0.01 secs]
2.718: [GC2.718: [ParNew: 12095K->1344K(12288K), 0.0085918 secs] 26615K->20205K(39616K), 0.0086568 secs] [Times: user=0.00 sys=0.00, real=0.01 secs]
2.727: [GC [1 CMS-initial-mark: 18861K(27328K)] 20455K(39616K), 0.0009695 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
2.728: [CMS-concurrent-mark-start]
2.777: [CMS-concurrent-mark: 0.048/0.049 secs] [Times: user=0.13 sys=0.00, real=0.05 secs]
2.777: [CMS-concurrent-preclean-start]
2.778: [CMS-concurrent-preclean: 0.001/0.001 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
2.779: [GC[YG occupancy: 3358 K (12288 K)]2.779: [Rescan (parallel) , 0.0007499 secs]2.779: [weak refs processing, 0.0001568 secs]2.780: [scrub string table, 0.0004098 secs] [1 CMS-remark: 18861K(27328K)] 22219K(39616K), 0.0013938 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
2.780: [CMS-concurrent-sweep-start]
2.790: [CMS-concurrent-sweep: 0.010/0.010 secs] [Times: user=0.06 sys=0.00, real=0.01 secs]
2.790: [CMS-concurrent-reset-start]
2.791: [CMS-concurrent-reset: 0.000/0.000 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
3.027: [GC3.027: [ParNew: 12288K->1344K(12288K), 0.0070788 secs] 26519K->20052K(39616K), 0.0071626 secs] [Times: user=0.06 sys=0.00, real=0.01 secs]
3.034: [GC [1 CMS-initial-mark: 18708K(27328K)] 20069K(39616K), 0.0016822 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
3.036: [CMS-concurrent-mark-start]
3.080: [CMS-concurrent-mark: 0.044/0.044 secs] [Times: user=0.13 sys=0.00, real=0.04 secs]
3.080: [CMS-concurrent-preclean-start]
3.081: [CMS-concurrent-preclean: 0.001/0.001 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
3.081: [GC[YG occupancy: 3035 K (12288 K)]3.081: [Rescan (parallel) , 0.0014130 secs]3.082: [weak refs processing, 0.0000222 secs]3.082: [scrub string table, 0.0008106 secs] [1 CMS-remark: 18708K(27328K)] 21744K(39616K), 0.0023372 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
3.083: [CMS-concurrent-sweep-start]
3.093: [CMS-concurrent-sweep: 0.009/0.009 secs] [Times: user=0.00 sys=0.00, real=0.01 secs]
3.093: [CMS-concurrent-reset-start]
3.093: [CMS-concurrent-reset: 0.000/0.000 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
3.367: [GC3.367: [ParNew: 12288K->1344K(12288K), 0.0092673 secs] 29323K->21524K(40684K), 0.0093494 secs] [Times: user=0.06 sys=0.00, real=0.01 secs]
3.376: [GC [1 CMS-initial-mark: 20180K(28396K)] 21539K(40684K), 0.0022484 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
3.379: [CMS-concurrent-mark-start]
3.440: [CMS-concurrent-mark: 0.061/0.061 secs] [Times: user=0.23 sys=0.02, real=0.06 secs]
3.440: [CMS-concurrent-preclean-start]
3.442: [CMS-concurrent-preclean: 0.001/0.001 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
3.442: [CMS-concurrent-abortable-preclean-start]
3.493: [GC3.493: [ParNew: 12274K->1343K(12288K), 0.0055261 secs] 32455K->23901K(40684K), 0.0056034 secs] [Times: user=0.00 sys=0.00, real=0.01 secs]
3.696: [GC3.696: [ParNew: 12286K->1344K(12288K), 0.0069481 secs] 34843K->27462K(40876K), 0.0070168 secs] [Times: user=0.06 sys=0.00, real=0.01 secs]
3.703: [CMS-concurrent-abortable-preclean: 0.060/0.262 secs] [Times: user=0.50 sys=0.01, real=0.26 secs]
3.704: [GC[YG occupancy: 1572 K (12288 K)]3.704: [Rescan (parallel) , 0.0025590 secs]3.706: [weak refs processing, 0.0001688 secs]3.706: [scrub string table, 0.0008541 secs] [1 CMS-remark: 26118K(28588K)] 27690K(40876K), 0.0036849 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
3.707: [CMS-concurrent-sweep-start]
3.717: [CMS-concurrent-sweep: 0.009/0.010 secs] [Times: user=0.00 sys=0.00, real=0.01 secs]
3.717: [CMS-concurrent-reset-start]
3.717: [CMS-concurrent-reset: 0.000/0.000 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
4.034: [GC4.034: [ParNew: 12288K->1344K(12288K), 0.0080462 secs] 36118K->28963K(52008K), 0.0081184 secs] [Times: user=0.00 sys=0.00, real=0.01 secs]
4.553: [GC4.553: [ParNew: 12288K->1344K(12288K), 0.0073523 secs] 39907K->31479K(52008K), 0.0074360 secs] [Times: user=0.00 sys=0.00, real=0.01 secs]
4.560: [GC [1 CMS-initial-mark: 30135K(39720K)] 31479K(52008K), 0.0031662 secs] [Times: user=0.03 sys=0.00, real=0.00 secs]
4.564: [CMS-concurrent-mark-start]
4.676: [CMS-concurrent-mark: 0.100/0.112 secs] [Times: user=0.39 sys=0.00, real=0.11 secs]
4.676: [CMS-concurrent-preclean-start]
4.677: [CMS-concurrent-preclean: 0.001/0.001 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
4.677: [CMS-concurrent-abortable-preclean-start]
5.050: [GC5.050: [ParNew: 12288K->1343K(12288K), 0.0058341 secs] 42423K->32844K(52008K), 0.0059602 secs] [Times: user=0.00 sys=0.00, real=0.01 secs]
5.425: [GC5.425: [ParNew: 12287K->1344K(12288K), 0.0041361 secs] 43788K->33574K(52008K), 0.0041972 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
5.429: [CMS-concurrent-abortable-preclean: 0.144/0.752 secs] [Times: user=2.28 sys=0.27, real=0.75 secs]
5.429: [GC[YG occupancy: 1443 K (12288 K)]5.429: [Rescan (parallel) , 0.0018369 secs]5.431: [weak refs processing, 0.0001649 secs]5.431: [scrub string table, 0.0007892 secs] [1 CMS-remark: 32230K(39720K)] 33673K(52008K), 0.0028944 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
5.432: [CMS-concurrent-sweep-start]
5.447: [CMS-concurrent-sweep: 0.014/0.014 secs] [Times: user=0.03 sys=0.00, real=0.01 secs]
5.447: [CMS-concurrent-reset-start]
5.447: [CMS-concurrent-reset: 0.000/0.000 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
25.095: [GC25.096: [ParNew: 12288K->1344K(12288K), 0.0236873 secs] 39467K->29787K(57588K), 0.0239223 secs] [Times: user=0.05 sys=0.00, real=0.02 secs]
我們看到,新生代Eden區的容量非常小,只有12288K,約合10m,老年代也同樣如此(而且CMS由於其演算法的特殊性,是不會等到老年代全部佔滿了才進行Full GC的,原因:CMS收集器)。
在筆者12G的機器下,大可以給Eclipse分配多得多的記憶體,於是將堆的最大容量(-Xmx)設定為1g,初始堆大小(-Xms)也設定為1g,防止執行時自動擴充套件耗費時間,永久代(-XX:PermSize、-XX:MaxPermSize)設定為256m,新生代(-Xmn)設定為512m。
由於這樣設定的話,記憶體一定是足夠的了,因此還可以使用-XX:+DisableExplicitGC來防止Eclipse主動呼叫System.gc():
-Xms1024M
-Xmx1024M
-Xmn512M
-XX:PermSize=256M
-XX:MaxPermSize=256M
-XX:+DisableExplicitGC
修改完之後,再來啟動Eclipse,檢視Visual VM:
可以看到,不管是新生代還是老年代,都不再有GC發生了,再來統計一下啟動時間,三次啟動分別為4590ms、4710ms、4780ms,取平均值,進行垃圾收集器優化之後的啟動時間是4693ms。
總結
最終調優完成後的eclipse.ini是這樣的:
-vm
C:/Program Files/Java/jdk1.7.0_51/bin/javaw.exe
-startup
plugins/org.eclipse.equinox.launcher_1.3.0.v20130327-1440.jar
--launcher.library
plugins/org.eclipse.equinox.launcher.win32.win32.x86_64_1.1.200.v20130521-0416
-product
org.eclipse.epp.package.standard.product
--launcher.defaultAction
openFile
--launcher.XXMaxPermSize
128M
-showsplash
org.eclipse.platform
--launcher.XXMaxPermSize
128M
--launcher.defaultAction
openFile
--launcher.appendVmargs
-vmargs
-Dosgi.requiredJavaVersion=1.6
-Xverify:none
-XX:+PrintGCTimeStamps
-XX:+PrintGCDetails
-Xloggc:gc.log
-XX:+UseConcMarkSweepGC
-XX:+UseParNewGC
-Xms40m
-Xmx128M
從一開始的5953ms,到最後的4693ms,好吧,我不得不承認省下的這一秒鐘啟動時間,並不會對我又多大幫助,不過,通過這個例子,我也演示了JVM調優中的一些套路:
- 藉助Visual VM或者命令列等工具進行分析;
- 從編譯時間、類載入時間、垃圾收集時間三個維度進行優化;
- 根據應用的特點和機器的條件,選擇最合適的垃圾收集器組合;
- 分析GC日誌,減少GC的次數;
這些調優的思路,都是可以應用到生產環境的。
以上,希望能對你有所幫助。