JVM调优:对eclipse启动调优纪实(1)

Eclipse.ini里面很久以前为了让程序运行快点改过堆分配大小，其参数配置的改变只是固定了堆的大小，为此增加了两行：

-Xms512
-Xmx512m

今天突然想玩玩调优，稍微看来一点资料打算就开干了，我也不喜欢纸上谈兵那种只在没意思，也想把这个过程记录下来和大家分享一下，实现说明一下我对JVM的内存分配方式和GC机制只是稍微有点了解，如果有说错的地方请不要拍砖，请指正，也可以给我发邮件，[email protected]我的邮箱。

首先，增加了GC日志，在eclipse.ini后面加上四行：

--XX:+PrintGCTimeStamps   //打应垃圾收集的时间情况
--XX:+PrintGCDetails      //显示GC的详细信息
--verbose:gc              //开启GC日志
--Xloggc:gc.log           //日志路径

关闭eclipse所有项目，然后重启
此时在eclipse目录下会出现gc.log这个日志文件，以下是内容：

2.321: [Full GC 2.321: [Tenured: 0K->19557K(349568K), 0.1294009 secs] 95872K->19557K(506816K), [Perm : 16383K->16383K(16384K)], 0.1295350 secs] [Times: user=0.13 sys=0.00, real=0.13 secs]
3.120: [Full GC 3.120: [Tenured: 19557K->23549K(349568K), 0.1181982 secs] 41448K->23549K(506816K), [Perm : 20479K->20479K(20480K)], 0.1183178 secs] [Times: user=0.11 sys=0.00, real=0.12 secs]
3.739: [Full GC 3.739: [Tenured: 23549K->25797K(349568K), 0.1315133 secs] 46185K->25797K(506816K), [Perm : 24575K->24575K(24576K)], 0.1316401 secs] [Times: user=0.14 sys=0.00, real=0.13 secs]
4.362: [Full GC 4.362: [Tenured: 25797K->27900K(349568K), 0.2115846 secs] 44532K->27900K(506816K), [Perm : 28671K->28656K(28672K)], 0.2117293 secs] [Times: user=0.22 sys=0.00, real=0.21 secs]
4.867: [Full GC 4.868: [Tenured: 27900K->29988K(349568K), 0.1893515 secs] 47980K->29988K(506816K), [Perm : 32767K->32767K(32768K)], 0.1894289 secs] [Times: user=0.19 sys=0.00, real=0.19 secs]
6.369: [Full GC 6.369: [Tenured: 29988K->31921K(349568K), 0.2102871 secs] 126978K->31921K(506816K), [Perm : 36863K->36863K(36864K)], 0.2103653 secs] [Times: user=0.22 sys=0.00, real=0.21 secs]
6.888: [Full GC 6.888: [Tenured: 31921K->33672K(349568K), 0.2228748 secs] 51123K->33672K(506816K), [Perm : 40959K->40959K(40960K)], 0.2229558 secs] [Times: user=0.22 sys=0.00, real=0.22 secs]
27.078: [Full GC 27.078: [Tenured: 33672K->34801K(349568K), 0.2983971 secs] 69505K->34801K(506816K), [Perm : 45055K->45046K(45056K)], 0.2984842 secs] [Times: user=0.30 sys=0.00, real=0.30 secs]

首先解释一下这个日志的格式

时间点   [GC开始时间:[动态分配:初始值->分配值(可用值) ,  消耗时间     ] 初始值->回收后占用值(可用值),消耗时间]

拿第一行来做例子：

2.321: [Full GC 2.321: [Tenured: 0K->19557K(349568K), 0.1294009 secs] 95872K->19557K(506816K), [Perm : 16383K->16383K(16384K)], 0.1295350 secs] [Times: user=0.13 sys=0.00, real=0.13 secs]

2.321：是时间点，网上没有找到这个具体的定义，但是估计是从系统启动到执行这条GC的时间。

Full GC 2.321 ：是指明GC方式，通常将对新生代迚行的回收称为Minor GC；对旧生代迚行的回收称为Major GC，但由于Major GC除并发GC外均需对整个堆以及持久代逆行扫描和回收，因此又称为Full GC。

[Tenured: 0K->19557K(349568K), 0.1294009 secs] 95872K->19557K(506816K)：这个是说明了Thnured generation的回收情况，同理如果是“GC”则是针对Young generation的回收，如果是Perm测试持久代的回收。其中0K->19557K(349568K)说明的是旧生代的分配情况，（这里说明一点，GC不仅是负责垃圾回收的，而且也决定内存的分配）我们可以看到旧生代从0k分配到了19557K，可以分配的空间为34956K,然后是分配时间为0.1294009秒，这里是动态分配的信息，紧跟在后面的是回收的信息，前面是回收时间点的Heap实际的使用量，后面是回收之后的Heap使用量。（后面的Perm的信息也和这一样）。

[Times: user=0.13 sys=0.00, real=0.13 secs] ：这个说明了我并没有找到相应的说明，但是我的理解是回收过程的时间组成,user表示是该用户使用的时间，sys表示的是系统使用的时间，real就是实际使用时间，应该是user和sys的和。

有了以上的说明我可以开始对这个日志做一下分析：
(在word里面拷贝的这个日志会换行，建议拷贝到编辑器里面查看，方便做对比。)

看看三个红框里面的数据这个是可用值,看看这些值的变化规律，只有持久代的可用值在不断的增大，由此基本可以判断出这几次Full GC是由于重新分配持久代的内存空间造成的(当然造成Full GC的原因不止这一种，我现在也没有都记住，还是在实践中加强记忆来得快)。

很明显，持久代的空间在启动的额过程中明显不足，那么就增加持久代的空间分配，要为持久代分配空间就必须使用–XX:PermSize–XX:MaxPermSize这个参数，简单计算一下，这次启动完后没有任何动作的情况下持久代的可用空间使用为45056/1024=44M,那么应该设置为多少最好呢，这得从这个代里面存放的内容入手，这个代里面是JVM的方法区，主要是存放一些方法字节码和静态变量，还会放些什么我暂时也不知道，但是应该不会太多，所以我认为持久代的大小应该是相对比较固定大小的波动不会太大的，在整个程序的运行过程中不会有非常大的变化，由于我使用的eclipse是已经装过插件的，以后再扩展插件的几率很小，所以我选择将–XX:PermSize=64M –XX:MaxPermSize=96M，在运行试试看（中间NG了一次结果和没优化一样，原因是-Xx的前面那个中画线貌似不识别，可能是中文输入法的问题，建议在E文输入法中来敲参数，否则设置错误的话失败了都很难找出问题），感觉启动快多了，看看日志：

3.621: [GC 3.621: [DefNew: 139776K->17472K(157248K), 0.0913702 secs] 139776K->20156K(506816K), 0.0915035 secs] [Times: user=0.08 sys=0.00, real=0.09 secs]
8.728: [GC 8.728: [DefNew: 157248K->6813K(157248K), 0.0851032 secs] 159932K->25970K(506816K), 0.0852304 secs] [Times: user=0.08 sys=0.00, real=0.09 secs]

Heap
 def new generation   total 157248K, used 19646K [0x04b00000, 0x0f5a0000, 0x0f5a0000)
  eden space 139776K,   9% used [0x04b00000, 0x05788208, 0x0d380000)
  from space 17472K,  38% used [0x0d380000, 0x0da27790, 0x0e490000)
  to   space 17472K,   0% used [0x0e490000, 0x0e490000, 0x0f5a0000)
 tenured generation   total 349568K, used 19156K [0x0f5a0000, 0x24b00000, 0x24b00000)
   the space 349568K,   5% used [0x0f5a0000, 0x108553c8, 0x10855400, 0x24b00000)
 compacting perm gen  total 65536K, used 40825K [0x24b00000, 0x28b00000, 0x2ab00000)
   the space 65536K,  62% used [0x24b00000, 0x272de638, 0x272de800, 0x28b00000)
No shared spaces configured.

哈哈，已经不再有Full GC，第一步优化成功启动速度减少了19秒，相当可观，去dota一把了，明天看看还能怎么继续优化。