JVM调优案例分析-Eclipse启动

为什么要进行JVM调优

运行在JVM上的程序都会进行内存分配以及垃圾回收,在这个过程中设置合理的内存大小及垃圾回收算法能显著提高应用的响应速度及运行效率,相反不合理的JVM参数设置会造成应用程序响应不稳定并导致整个应用程序挂掉。

如何JVM调优

不同类型应用程序的JVM参数设置都不一样,如何设置最优的JVM参数不仅需要对GC机制有一定的了解,而且还要反复的试验才能得出最合适的JVM参数值。
例如:某些系统要求运行稳定、并且响应速度高,这类应用就需要通过调整其JVM参数来减少内存大小调整及垃圾回收所占用的时间,以尽量的提高响应速度。报表类及容易产生大对象对响应速度要求不是很高的系统,可以把堆空间设置较大些。
除了了解GC的机制外等一些基本调优方法外,往往还需要借助一些监控工具来进行JVM参数调优,例:Jprofiler 、VisualVM、Jconsole等,通过这些工具可以监控JVM运行时内存分配情况,线程状态、数量,堆空间类、对象数量类型信息等,此外还可以借助分析垃圾回收日志对JVM进行优化。

JVM调优参数配置

1
2
3
4
5
6
7
8
9
10
11
12
13
14
-verbose:gc (开启打印垃圾回收日志)
-Xloggc:eclipse_gc.log (设置垃圾回收日志打印的文件,文件名称可以自定义)
-XX:+PrintGCTimeStamps (打印垃圾回收时间信息时的时间格式)
-XX:+PrintGCDetails (打印垃圾回收详情)
-Xms50m(堆最小值)
–Xmx200m
-XX:PermSize=30m
(JDK8 = -XX:MetaspaceSize=256m)
-XX:MaxPermSize=60m
//添加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

Eclipse启动调优

系统环境

1
2
3
4
5
CPU:Intel I5-4590 @3.30GHz
内存:8G
系统:win7 @64位
Eclipse:Luna Service Release 1 (4.4.1)
JDK:8

调优示例

初始化加载

eclipse.ini配置

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
-startup
plugins/org.eclipse.equinox.launcher_1.3.0.v20140415-2008.jar
--launcher.library
plugins/org.eclipse.equinox.launcher.win32.win32.x86_64_1.1.200.v20140603-1326
-product
org.eclipse.epp.package.jee.product
--launcher.defaultAction
openFile
--launcher.XXMaxPermSize
256M
-showsplash
org.eclipse.platform
--launcher.XXMaxPermSize
512m
--launcher.defaultAction
openFile
--launcher.appendVmargs
-vmargs
-Dosgi.requiredJavaVersion=1.6
-javaagent:lombok.jar
-verbose:gc
-Xloggc:eclipse_test_gc.log
-XX:+PrintGCTimeStamps
-XX:+PrintGCDetails

gc.log

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
0.755: [GC (Allocation Failure) [PSYoungGen: 131584K->3908K(153088K)] 131584K->3916K(502784K), 0.0061911 secs] [Times: user=0.03 sys=0.00, real=0.01 secs] 
1.450: [GC (Allocation Failure) [PSYoungGen: 135492K->20964K(153088K)] 135500K->20988K(502784K), 0.0218611 secs] [Times: user=0.06 sys=0.00, real=0.02 secs]
2.027: [GC (Metadata GC Threshold) [PSYoungGen: 130012K->21489K(153088K)] 130036K->25430K(502784K), 0.0221815 secs] [Times: user=0.06 sys=0.00, real=0.02 secs]
2.049: [Full GC (Metadata GC Threshold) [PSYoungGen: 21489K->0K(153088K)] [ParOldGen: 3940K->25211K(349696K)] 25430K->25211K(502784K),
[Metaspace: 19524K->19524K(1069056K)], 0.0830986 secs] [Times: user=0.27 sys=0.00, real=0.08 secs]
3.775: [GC (Allocation Failure) [PSYoungGen: 131584K->10997K(190464K)] 156795K->36217K(540160K), 0.0247439 secs] [Times: user=0.05 sys=0.00, real=0.02 secs]
4.839: [GC (Metadata GC Threshold) [PSYoungGen: 186429K->20045K(261632K)] 211648K->45272K(611328K), 0.0179861 secs] [Times: user=0.03 sys=0.02, real=0.02 secs]
4.857: [Full GC (Metadata GC Threshold) [PSYoungGen: 20045K->0K(261632K)] [ParOldGen: 25227K->41383K(399360K)] 45272K->41383K(660992K), [Metaspace: 32389K->32389K(1081344K)], 0.1242518 secs] [Times: user=0.36 sys=0.00, real=0.12 secs]
6.307: [GC (Allocation Failure) [PSYoungGen: 241152K->18220K(274432K)] 282535K->59611K(673792K), 0.0172074 secs] [Times: user=0.06 sys=0.00, real=0.02 secs]
7.997: [GC (Allocation Failure) [PSYoungGen: 261420K->25680K(273408K)] 302811K->67079K(672768K), 0.0185006 secs] [Times: user=0.08 sys=0.00, real=0.02 secs]
8.268: [GC (Metadata GC Threshold) [PSYoungGen: 82395K->20501K(347136K)] 123794K->61908K(746496K), 0.0151410 secs] [Times: user=0.01 sys=0.00, real=0.02 secs]
8.284: [Full GC (Metadata GC Threshold) [PSYoungGen: 20501K->0K(347136K)] [ParOldGen: 41407K->56860K(558592K)] 61908K->56860K(905728K), [Metaspace: 53496K->53496K(1099776K)], 0.2932783 secs] [Times: user=0.75 sys=0.00, real=0.29 secs]
10.175: [GC (Allocation Failure) [PSYoungGen: 313856K->17170K(346112K)] 370716K->74039K(904704K), 0.0169520 secs] [Times: user=0.01 sys=0.00, real=0.02 secs]
12.128: [GC (Allocation Failure) [PSYoungGen: 331026K->26531K(394240K)] 387895K->83408K(952832K), 0.0273926 secs] [Times: user=0.06 sys=0.01, real=0.03 secs]
13.499: [GC (Allocation Failure) [PSYoungGen: 390563K->32749K(396800K)] 447440K->93985K(955392K), 0.0303289 secs] [Times: user=0.06 sys=0.02, real=0.03 secs]
14.154: [GC (Metadata GC Threshold) [PSYoungGen: 192786K->34344K(458752K)] 254022K->95587K(1017344K), 0.0309133 secs] [Times: user=0.06 sys=0.02, real=0.03 secs]
14.185: [Full GC (Metadata GC Threshold) [PSYoungGen: 34344K->0K(458752K)] [ParOldGen: 61243K->88940K(785920K)] 95587K->88940K(1244672K), [Metaspace: 89904K->89904K(1134592K)], 0.1934725 secs] [Times: user=0.42 sys=0.00, real=0.19 secs]

启动时间14s,GC=16,其中Full GC=4PSYoungGen GC=12

分析

  • GC次数太多。
  • real-time=0.94s 。
  • 每次Full GC的时候,ParOldGen(老年代)值没有GC操作,说明ParOldGen(老年代)内存足够;Metaspace值也没有GC操作,Metaspace的内存也足够。

0.755s,YoungGen(年轻代)GC前占130m,GC后占3.9m,销毁对象127m,总内存150。从这里可以看出GC操作销毁无用对象占用总内存比例比较高。
解决方式:提高YoungGen(年轻代)内存

第1次调优

eclipse.ini配置

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
-startup
plugins/org.eclipse.equinox.launcher_1.3.0.v20140415-2008.jar
--launcher.library
plugins/org.eclipse.equinox.launcher.win32.win32.x86_64_1.1.200.v20140603-1326
-product
org.eclipse.epp.package.jee.product
--launcher.defaultAction
openFile
--launcher.XXMaxPermSize
256M
-showsplash
org.eclipse.platform
--launcher.XXMaxPermSize
512m
--launcher.defaultAction
openFile
--launcher.appendVmargs
-vmargs
-Dosgi.requiredJavaVersion=1.6
-javaagent:lombok.jar
-verbose:gc
-Xloggc:eclipse_test_gc.log
-XX:+PrintGCTimeStamps
-XX:+PrintGCDetails
-Xms512m
–Xmx512m
-Xmn300m
-XX:MetaspaceSize=512m
-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

初始化堆:512m,最大堆:512m,年轻代:300,survivor0:150m,survivor1=150m,tenured Generation:212m,metaspace=512m
gc.log

1
2
3
4
5
6
7
8
9
10
1.475: [GC (Allocation Failure) [PSYoungGen: 269312K->20675K(313856K)] 269312K->20699K(479744K), 0.0258210 secs] [Times: user=0.06 sys=0.01, real=0.03 secs] 
4.139: [GC (Allocation Failure) [PSYoungGen: 289987K->36912K(313856K)] 290011K->36944K(479744K), 0.0751285 secs] [Times: user=0.20 sys=0.01, real=0.08 secs]
5.792: [GC (Allocation Failure) [PSYoungGen: 306224K->44540K(313856K)] 306256K->48936K(479744K), 0.0568584 secs] [Times: user=0.17 sys=0.02, real=0.06 secs]
7.648: [GC (Allocation Failure) [PSYoungGen: 313852K->44523K(313856K)] 318248K->62079K(479744K), 0.0543820 secs] [Times: user=0.14 sys=0.00, real=0.05 secs]
9.127: [GC (Allocation Failure) [PSYoungGen: 313835K->44531K(313856K)] 331391K->79425K(479744K), 0.0544645 secs] [Times: user=0.13 sys=0.00, real=0.05 secs]
10.753: [GC (Allocation Failure) [PSYoungGen: 313843K->44533K(242176K)] 348737K->93038K(408064K), 0.0475107 secs] [Times: user=0.16 sys=0.00, real=0.05 secs]
12.530: [GC (Allocation Failure) [PSYoungGen: 242165K->39059K(278016K)] 290670K->106623K(443904K), 0.0549795 secs] [Times: user=0.17 sys=0.00, real=0.06 secs]
13.380: [GC (Allocation Failure) [PSYoungGen: 236691K->30476K(281600K)] 304255K->113511K(447488K), 0.0335930 secs] [Times: user=0.13 sys=0.00, real=0.03 secs]
14.123: [GC (Allocation Failure) [PSYoungGen: 234252K->26140K(280576K)] 317287K->118931K(446464K), 0.0381255 secs] [Times: user=0.09 sys=0.00, real=0.04 secs]
15.143: [GC (Allocation Failure) [PSYoungGen: 229916K->14606K(279552K)] 322707K->123709K(445440K), 0.0284687 secs] [Times: user=0.08 sys=0.00, real=0.03 secs]

启动时间15s,GC=10,其中Full GC=0PSYoungGen GC=10

分析

  • real-time=0.48s,时间已经比初始化时减少50%。
  • Full GC已经没有了,说明堆内存变大。
  • PSYoungGen内存依然不够大,GC次数高达10次。

解决方式:继续提高堆内存,提高PSYoungGen内存。

第2次调优

eclipse.ini配置

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
-startup
plugins/org.eclipse.equinox.launcher_1.3.0.v20140415-2008.jar
--launcher.library
plugins/org.eclipse.equinox.launcher.win32.win32.x86_64_1.1.200.v20140603-1326
-product
org.eclipse.epp.package.jee.product
--launcher.defaultAction
openFile
--launcher.XXMaxPermSize
256M
-showsplash
org.eclipse.platform
--launcher.XXMaxPermSize
512m
--launcher.defaultAction
openFile
--launcher.appendVmargs
-vmargs
-Dosgi.requiredJavaVersion=1.6
-javaagent:lombok.jar
-verbose:gc
-Xloggc:eclipse_test_gc.log
-XX:+PrintGCTimeStamps
-XX:+PrintGCDetails
-Xms1024m
–Xmx1024m
-Xmn768m
-XX:MetaspaceSize=512m
-XX:+UseConcMarkSweepGC

初始化堆:1024m,最大堆:1024m,年轻代:768,survivor0:384m,survivor1=384m,tenured Generation:256m,metaspace=512m
gc.log

1
2
3
4
5
6
7
8
9
10
11
12
3.590: [GC (Allocation Failure) 3.590: [ParNew: 629248K->41257K(707840K), 0.0421096 secs] 629248K->41257K(969984K), 0.0423289 secs] [Times: user=0.11 sys=0.02, real=0.04 secs] 
9.514: [GC (Allocation Failure) 9.514: [ParNew: 670505K->51460K(707840K), 0.1455994 secs] 670505K->84357K(969984K), 0.1457105 secs] [Times: user=0.47 sys=0.02, real=0.14 secs]
15.587: [GC (Allocation Failure) 15.587: [ParNew: 680708K->43195K(707840K), 0.0751499 secs] 713605K->99746K(969984K), 0.0755409 secs] [Times: user=0.20 sys=0.02, real=0.08 secs]
18.992: [GC (Allocation Failure) 18.992: [ParNew: 672443K->64909K(707840K), 0.0494642 secs] 728994K->121459K(969984K), 0.0496048 secs] [Times: user=0.16 sys=0.00, real=0.05 secs]
Heap
par new generation total 707840K, used 373763K [0x0000000081800000, 0x00000000b1800000, 0x00000000b1800000)
eden space 629248K, 49% used [0x0000000081800000, 0x000000009459d7b0, 0x00000000a7e80000)
from space 78592K, 82% used [0x00000000a7e80000, 0x00000000abde3518, 0x00000000acb40000)
to space 78592K, 0% used [0x00000000acb40000, 0x00000000acb40000, 0x00000000b1800000)
concurrent mark-sweep generation total 262144K, used 56550K [0x00000000b1800000, 0x00000000c1800000, 0x0000000100000000)
Metaspace used 97509K, capacity 106568K, committed 106752K, reserved 1140736K
class space used 11967K, capacity 14761K, committed 14848K, reserved 1048576K

启动时间18s,GC=4,其中Full GC=0PSYoungGen GC=4

分析

  • real-time=0.31s,时间已经比第1次优化时减少30%。
  • user-time=0.94s,GC时间达到近1s。
  • PSYoungGen内存足够大了,但是GC时间太长和GC的算法有关,第1次调优使用的是:并行收集算法(多线程处理)。根据第1次调优-年轻代:Parallel Scavenge(PS),第2次调优-年轻代:ParNew。
  • UseConcMarkSweepGC配置CMS算法,可能没有启用年轻代的收集。

解决方式:Eclipse.ini加上配置:

1
-XX:CMSInitiatingOccupancyFraction=85

第3次调优

eclipse.ini配置

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
-startup
plugins/org.eclipse.equinox.launcher_1.3.0.v20140415-2008.jar
--launcher.library
plugins/org.eclipse.equinox.launcher.win32.win32.x86_64_1.1.200.v20140603-1326
-product
org.eclipse.epp.package.jee.product
--launcher.defaultAction
openFile
--launcher.XXMaxPermSize
256M
-showsplash
org.eclipse.platform
--launcher.XXMaxPermSize
512m
--launcher.defaultAction
openFile
--launcher.appendVmargs
-vmargs
-Dosgi.requiredJavaVersion=1.6
-javaagent:lombok.jar
-verbose:gc
-Xloggc:eclipse_test_gc.log
-XX:+PrintGCTimeStamps
-XX:+PrintGCDetails
-Xms1024m
–Xmx1024m
-Xmn768m
-XX:MetaspaceSize=512m
-XX:+UseConcMarkSweepGC
-XX:CMSInitiatingOccupancyFraction=85
-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

初始化堆:1024m,最大堆:1024m,年轻代:768,survivor0:384m,survivor1=384m,tenured Generation:256m,metaspace=512m
gc.log

1
2
3
4
5
6
7
8
9
10
11
12
13
4.104: [GC (Allocation Failure) 4.104: [ParNew: 629248K->41260K(707840K), 0.0346760 secs] 629248K->41260K(969984K), 0.0348408 secs] [Times: user=0.09 sys=0.00, real=0.04 secs] 
8.236: [GC (Allocation Failure) 8.236: [ParNew: 670508K->51831K(707840K), 0.1331332 secs] 670508K->84728K(969984K), 0.1332595 secs] [Times: user=0.36 sys=0.01, real=0.13 secs]
12.319: [GC (Allocation Failure) 12.319: [ParNew: 681079K->42928K(707840K), 0.0565921 secs] 713976K->99627K(969984K), 0.0566873 secs] [Times: user=0.14 sys=0.00, real=0.06 secs]
14.646: [GC (Allocation Failure) 14.646: [ParNew: 672176K->56551K(707840K), 0.0357001 secs] 728875K->113251K(969984K), 0.0357838 secs] [Times: user=0.09 sys=0.00, real=0.04 secs]

Heap
par new generation total 707840K, used 391215K [0x0000000081800000, 0x00000000b1800000, 0x00000000b1800000)
eden space 629248K, 53% used [0x0000000081800000, 0x0000000095ed1db0, 0x00000000a7e80000)
from space 78592K, 71% used [0x00000000a7e80000, 0x00000000ab5b9f88, 0x00000000acb40000)
to space 78592K, 0% used [0x00000000acb40000, 0x00000000acb40000, 0x00000000b1800000)
concurrent mark-sweep generation total 262144K, used 56699K [0x00000000b1800000, 0x00000000c1800000, 0x0000000100000000)
Metaspace used 97640K, capacity 106658K, committed 107008K, reserved 1140736K
class space used 11969K, capacity 14727K, committed 14848K, reserved 1048576K

Console Log:启动时间14s,GC=4,其中Full GC=0,PSYoungGen GC=4。

分析

  • real-time=0.27s,时间已经比第2次调优时减少0.04s。
  • user-time=0.68s,GC比第3次调优时减少0.3s。
  • 采用CMS并发垃圾收集算法。
# JVM, Java

评论

Your browser is out-of-date!

Update your browser to view this website correctly. Update my browser now

×