Teach you an easy way to speed up your Eclipse startup by 1.5 seconds!

Have you ever thought about the Eclipse you use every day

  • What kind of garbage collector does it use?
  • How many GC S have been executed at startup?
  • Can you tune its startup speed?

In this article, I will introduce how I can tune Eclipse to make its startup speed increase by 1.5 seconds.

You may say that it's only 1.5 seconds. It needs to be said that my computer performance is relatively good. It only takes 5953ms to start Eclipse before optimization and 4693ms after optimization, which has increased the speed by 21%. It's like a 100 meter race. The first place bolt and the last place are less than 1 second, but they are totally different!

Let's speed up now!

environmental information

Startup speed before tuning

To facilitate the calculation of eclipse startup speed, an Eclipse Plug-in written by Mr. Zhou Zhiming is used here. After eclipse startup, the plug-in can calculate the direct interval between the current time and eclipse startup time, and then print the total startup time on the interface, as follows:

My initial eclipse.ini configuration was as follows:

-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 is specified, the initial heap size (- Xms) is 40m, and the maximum heap (- Xmx) is 128m
Then, I started Eclipse three times. The three times are 5960ms, 5945ms and 5954ms respectively. After taking the average value, the time before tuning is 5953ms
At the same time, I used Visual VM to record the health of the virtual machine before tuning:

From the Visual VM monitoring information, the start-up time mainly includes three parts: compile time, class load time and garbage collection pause time.
Among them, compile time refers to JIT compilation of JVM. I am a 64 bit machine, and can only use server[^footnote] mode, so there is no room for optimization in instant compilation.

Therefore, the following mainly focuses on the class loading time of 3.468 seconds, as well as the 13 GC times of 107 MS for the new generation (Eden Space) and the Full GC times of 156 MS for the old generation (Old Gen).

Class load time

Class loading of JVM refers to loading class file into virtual machine. The process of class loading includes loading, verifying, preparing, parsing, using and unloading.

Among them, verification is because class files are not all compiled from Java source code. Class files can be generated in any way, or even written directly using the hex editor. Therefore, the virtual machine needs to verify the class file. For Eclipse, the files to be loaded by the virtual machine are basically our own source code, which is trustworthy. Therefore, you can add the parameter - Xverify:none to remove the verification phase when the class is loaded.

After removal, look at the class loading time in Visual VM. You can see that the class loading time suddenly drops to 2s:

Similarly, start Eclipse three times, with the time of 4687ms, 4700ms and 4695ms respectively. Take the average value, the start-up time of Eclipse after the verification phase is removed is 4694ms.

Garbage collection time

Let's tune the garbage collection. First, let's print the GC log to see what kind of garbage collector Eclipse uses now. Add it to eclipse.ini:

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

Check gc.log after startup:

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] 

Through PSYoungGen and PSPermGen, we can know that the throughput priority combination of the new generation Parallel New + the old generation Parallel old is adopted. Let's take a look at the following figure:

There is a connection between the two collectors, which means they can be used in combination. Considering that Eclipse often needs to interact, throughput takes priority. This combination of applications suitable for background operation is unnecessary. We can use the combination of new generation ParNew + old age CMS to reduce pause priority.

We add the following configuration to eclipse.ini:

-XX:+UseConcMarkSweepGC
-XX:+UseParNewGC

Then start Eclipse and observe the Visual VM:

A little muddled, the new generation of GC went to 22 times at a time, and the GC of the old era also surged to 10 times. However, although the number of GC has skyrocketed, the time of garbage collection has not increased too much. It seems that the collector is still very powerful. Now let's take a look at the GC log and analyze the reasons for so many 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] 

We can see that the capacity of the new generation Eden area is very small, only 12288K, about 10m, the same for the old generation (and because of the particularity of its algorithm, CMS will not wait until the old age is fully occupied before Full GC, reason: CMS collector).

Under my 12G machine, Eclipse can be allocated much more memory, so the maximum heap capacity (- Xmx) is set to 1g, and the initial heap size (- Xms) is also set to 1g, to prevent automatic expansion of the runtime from consuming time. The permanent generation (- XX:PermSize, - XX:MaxPermSize) is set to 256m, and the new generation (- Xmn) is set to 512m.
Because of this setting, the memory must be enough, so you can also use - XX:+DisableExplicitGC to prevent Eclipse from actively calling System.gc():

-Xms1024M
-Xmx1024M
-Xmn512M
-XX:PermSize=256M
-XX:MaxPermSize=256M
-XX:+DisableExplicitGC

After modification, start Eclipse again, and check Visual VM:

It can be seen that there is no GC in the new generation or the old generation. Let's count the start-up time again. The three starts are 4590ms, 4710ms and 4780ms respectively. Take the average value and the start-up time after optimizing the garbage collector is 4693ms.

After the final tuning, eclipse.ini is as follows:

-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

From the 5953ms at the beginning to the 4693ms at the end, well, I have to admit that the saved startup time in one second will not help me much. However, through this example, I also demonstrate some routines in JVM tuning:

  • Analyze with Visual VM or command line;
  • It is optimized from three dimensions: compile time, class load time and garbage collection time;
  • According to the characteristics of the application and the conditions of the machine, the most suitable combination of garbage collectors is selected;
  • Analyze GC log to reduce the number of GC;

These things can also be applied to the living environment.

Above, I hope it can help you.

Tags: Java Eclipse jvm JDK

Posted on Thu, 06 Feb 2020 22:12:29 -0800 by svanderclock