实习记录(四)

这次更新日志距离上次已经很久了，因为期间回学校的考试差不多耽误了一个月，本周才正是回来上班。

这周上班的主要任务有两个，其一就是继续进行业务的拆分，其二就是针对GC的优化。

业务拆分最大的难度就是对于依赖模块的处理，如果依赖深的话似乎拆分并没有很大意义，依赖浅的话实现难度又会比较大，怎么样做一个折中的处理是我们工作的重点。在这个过程中普遍学习的是一种对于服务化模块构建的思想。

1.要思考什么内容应该自己独立提供，什么东西应该从原来的系统中拷贝出来直接使用，直接使用会不会导致代码的紊乱，影响其他的调用。

2.什么内容应该放在什么地方，比如我写一个简单的TimeUtils工具出来，是应该放在api中还是放在provider中呢?我们要把任何一个代码放在哪里有一个明显的判断原则，就是需不需要对外提供调用，就比如这个TimeUtils，显然应该是我们自己使用的本地工具，不应该暴露出去供其他人调用的，所以就应该放在provider中。再假如我们有个Person(Bean)的类，这个Person如果在我们的提供的服务中出现，比如我们提供的接口中有这么一个接口，public Person getPerson(String id).那么明显这个Person也是要被服务调用者使用的，因此我们就应该放在api中。所以，我们的代码应该出现在是什么位置都是要有一个明显的参考的！

3.要注意提供服务时减少冗余字段。因为我们提供的服务都是需要其他模块通过网络来调用的，并不像我们本地那样方便。好处我就不一一介绍了，现在说的减少冗余字段，因为网络是有带宽的，所以每一个冗余字段都会消耗一定的带宽，这种消耗会在访问量越大的时候越明显；对于冗余字段的序列化和反序列化也是会影响性能的，因为序列化的反序列化的操作都是直接跟IO相关的，这时候如果我们有一个很大的冗余字段需要序列化的话性能下降就比较明显。所以我们在构建服务的时候尽量将对象的提供精简化，可以采用一层一层包装的模式去做（但是具体还是要看业务需求的）。

下面就重点说说GC优化的事情。

这件事情其实是一波三折的，最初的时候我看到的GC日志是这样子的：

-Xms2048m -Xmx3072m -XX:MaxPermSize=256m 

61637.292: [GC [PSYoungGen: 1045281K->886K(1046528K)] 1166265K->122063K(3143680K), 0.0090450 secs] [Times: user=0.02 sys=0.00, real=0.01 secs]
61767.098: [GC [PSYoungGen: 1045366K->704K(1046528K)] 1166543K->122156K(3143680K), 0.0101050 secs] [Times: user=0.03 sys=0.00, real=0.01 secs]
61924.928: [GC [PSYoungGen: 1045184K->608K(1046528K)] 1166636K->122212K(3143680K), 0.0088940 secs] [Times: user=0.02 sys=0.00, real=0.01 secs]
62054.998: [GC [PSYoungGen: 1045088K->833K(1046528K)] 1166692K->122498K(3143680K), 0.0088390 secs] [Times: user=0.01 sys=0.01, real=0.01 secs]
62230.327: [GC [PSYoungGen: 1045313K->896K(1046528K)] 1166978K->122609K(3143680K), 0.0084400 secs] [Times: user=0.02 sys=0.00, real=0.01 secs]
62308.987: [GC [PSYoungGen: 518683K->705K(1046528K)] 640396K->127835K(3143680K), 0.0091850 secs] [Times: user=0.02 sys=0.00, real=0.01 secs]
62308.996: [Full GC [PSYoungGen: 705K->0K(1046528K)] [ParOldGen: 127129K->116801K(2097152K)] 127835K->116801K(3143680K) [PSPermGen: 98717K->98716K(181760K)], 0.6010970 secs] [Times: user=1.83 sys=0.00, real=0.61 secs]
62371.310: [GC [PSYoungGen: 289908K->784K(1046528K)] 406710K->122706K(3143680K), 0.0090090 secs] [Times: user=0.02 sys=0.00, real=0.01 secs]
62371.319: [Full GC [PSYoungGen: 784K->0K(1046528K)] [ParOldGen: 121921K->116422K(2097152K)] 122706K->116422K(3143680K) [PSPermGen: 98722K->98722K(173056K)], 0.3840130 secs] [Times: user=1.11 sys=0.00, real=0.38 secs]
62438.400: [GC [PSYoungGen: 293053K->976K(1047040K)] 409476K->122518K(3144192K), 0.0094810 secs] [Times: user=0.02 sys=0.00, real=0.02 secs]
62438.410: [Full GC [PSYoungGen: 976K->0K(1047040K)] [ParOldGen: 121542K->116643K(2097152K)] 122518K->116643K(3144192K) [PSPermGen: 98945K->98945K(164352K)], 0.3129850 secs] [Times: user=0.87 sys=0.00, real=0.31 secs]
62495.467: [GC [PSYoungGen: 352780K->704K(1047040K)] 469423K->122468K(3144192K), 0.0093970 secs] [Times: user=0.02 sys=0.00, real=0.01 secs]
62495.477: [Full GC [PSYoungGen: 704K->0K(1047040K)] [ParOldGen: 121763K->116814K(2097152K)] 122468K->116814K(3144192K) [PSPermGen: 98948K->98948K)], 0.4053930 secs] [Times: user=1.18 sys=0.00, real=0.40 secs]
62531.950: [GC [PSYoungGen: 320998K->544K(1047040K)] 437813K->122478K(3144192K), 0.0079630 secs] [Times: user=0.02 sys=0.00, real=0.01 secs]
62531.958: [Full GC [PSYoungGen: 544K->0K(1047040K)] [ParOldGen: 121934K->116732K(2097152K)] 122478K->116732K(3144192K) [PSPermGen: 98952K->98952K(148992K)], 0.2601740 secs] [Times: user=0.64 sys=0.00, real=0.26 secs]
62566.544: [GC [PSYoungGen: 284371K->576K(1047040K)] 401103K->122428K(3144192K), 0.0078320 secs] [Times: user=0.03 sys=0.00, real=0.00 secs]
62566.552: [Full GC [PSYoungGen: 576K->0K(1047040K)] [ParOldGen: 121852K->116571K(2097152K)] 122428K->116571K(3144192K) [PSPermGen: 99056K->99056K(142336K)], 0.2823960 secs] [Times: user=0.74 sys=0.00, real=0.29 secs]
62605.326: [GC [PSYoungGen: 370002K->544K(1047040K)] 486574K->122235K(3144192K), 0.0084870 secs] [Times: user=0.01 sys=0.00, real=0.01 secs]
62605.335: [Full GC [PSYoungGen: 544K->0K(1047040K)] [ParOldGen: 121691K->116500K(2097152K)] 122235K->116500K(3144192K) [PSPermGen: 99063K->99063K(136192K)], 0.2653760 secs] [Times: user=0.63 sys=0.00, real=0.26 secs]
62610.771: [GC [PSYoungGen: 61220K->528K(1047040K)] 177721K->122149K(3144192K), 0.0086490 secs] [Times: user=0.01 sys=0.00, real=0.00 secs]

我尼玛一看这个日志懵逼了，第一次调GC这玩意啊。看了半天死活没看出来是哪里的问题，最后想着误打误撞吧。正好在网上看到一个帖子贴出来的是和我类似的问题，人家说的可能是因为对内存动态调整的时候触发的了full gc，原因就是-Xms 和-Xmx不相等造成的，于是我就抱着试试的想法把自己的想法告诉了主管，然后就按着我这个想法做了试试。

果不其然，JVM又开始报警了，其实有很多连续的full gc。鉴于上次我的建议被采纳额，这次主管直接找到我希望我能负责这件事，说实话我其实蛮感兴趣的，于是就抱着试一试的心态去做吧。

然后我就这么大概看了一下午日志，死活没看出来内存有其他问题啊。。。。当晚10点半我才回去，然后在路上我就在想这个事情，你说明显的Young和Old区域都有这么大空间啊，不可能是这里的问题，我再三告诉自己不是这里的问题，希望自己从另外的点出发已满陷入死胡同。然后第二天早上我老早就来了公司，直接把问题定位到PermGen，我再次看上面的GC日志的时候发现了一点问题，每一次full gc的时候PermGen的大小都会缩小，每次缩小80M左右，然后我又看到后面的日志:

416784.543: [GC [PSYoungGen: 1045810K->512K(1046528K)] 1170523K->125272K(3143680K), 0.0088850 secs] [Times: user=0.02 sys=0.00, real=0.01 secs]
417143.780: [GC [PSYoungGen: 1044992K->720K(1046528K)] 1169752K->125513K(3143680K), 0.0092960 secs] [Times: user=0.03 sys=0.00, real=0.01 secs]
417613.239: [GC [PSYoungGen: 1045200K->769K(1046528K)] 1169993K->125594K(3143680K), 0.0115210 secs] [Times: user=0.02 sys=0.00, real=0.01 secs]
417799.925: [GC [PSYoungGen: 665775K->867K(1046528K)] 790600K->130852K(3143680K), 0.0105780 secs] [Times: user=0.01 sys=0.01, real=0.01 secs]
417799.936: [Full GC [PSYoungGen: 867K->0K(1046528K)] [ParOldGen: 129985K->122098K(2097152K)] 130852K->122098K(3143680K) [PSPermGen: 102534K->102454K(102912K)], 0.4039370 secs] [Times: user=1.11 sys=0.00, real=0.40 secs]
417803.336: [GC [PSYoungGen: 54856K->483K(1046528K)] 176954K->127701K(3143680K), 0.0069450 secs] [Times: user=0.01 sys=0.00, real=0.01 secs]
417803.343: [Full GC [PSYoungGen: 483K->0K(1046528K)] [ParOldGen: 127218K->121488K(2097152K)] 127701K->121488K(3143680K) [PSPermGen: 102454K->102454K(102912K)], 0.2938830 secs] [Times: user=0.69 sys=0.00, real=0.29 secs]
417874.879: [GC [PSYoungGen: 331713K->512K(1046528K)] 453202K->127120K(3143680K), 0.0087730 secs] [Times: user=0.02 sys=0.00, real=0.01 secs]
417874.889: [Full GC [PSYoungGen: 512K->0K(1046528K)] [ParOldGen: 126608K->121505K(2097152K)] 127120K->121505K(3143680K) [PSPermGen: 102454K->102454K(102912K)], 0.2782730 secs] [Times: user=0.70 sys=0.00, real=0.28 secs]
417902.822: [GC [PSYoungGen: 109855K->602K(1046528K)] 231360K->127227K(3143680K), 0.0080930 secs] [Times: user=0.02 sys=0.00, real=0.01 secs]
417902.830: [Full GC [PSYoungGen: 602K->0K(1046528K)] [ParOldGen: 126625K->121539K(2097152K)] 127227K->121539K(3143680K) [PSPermGen: 102454K->102454K(102912K)], 0.2775650 secs] [Times: user=0.67 sys=0.00, real=0.28 secs]
417905.984: [GC [PSYoungGen: 37710K->352K(1046528K)] 159250K->127012K(3143680K), 0.0077960 secs] [Times: user=0.02 sys=0.00, real=0.01 secs]
417905.992: [Full GC [PSYoungGen: 352K->0K(1046528K)] [ParOldGen: 126660K->121545K(2097152K)] 127012K->121545K(3143680K) [PSPermGen: 102454K->102454K(102912K)], 0.2930680 secs] [Times: user=0.67 sys=0.00, real=0.30 secs]
417919.705: [GC [PSYoungGen: 52877K->320K(1046528K)] 174422K->126985K(3143680K), 0.0105670 secs] [Times: user=0.02 sys=0.00, real=0.01 secs]
417919.716: [Full GC [PSYoungGen: 320K->0K(1046528K)] [ParOldGen: 126665K->121532K(2097152K)] 126985K->121532K(3143680K) [PSPermGen: 102455K->102455K(102912K)], 0.2907880 secs] [Times: user=0.71 sys=0.00, real=0.29 secs]
417945.766: [GC [PSYoungGen: 83638K->416K(1047040K)] 205170K->127068K(3144192K), 0.0078010 secs] [Times: user=0.02 sys=0.00, real=0.01 secs]
417945.774: [Full GC [PSYoungGen: 416K->0K(1047040K)] [ParOldGen: 126652K->121627K(2097152K)] 127068K->121627K(3144192K) [PSPermGen: 102455K->102455K(102912K)], 0.2913160 secs] [Times: user=0.70 sys=0.00, real=0.29 secs]
417962.869: [GC [PSYoungGen: 67241K->192K(1046528K)] 188868K->126939K(3143680K), 0.0080460 secs] [Times: user=0.01 sys=0.00, real=0.00 secs]
417962.878: [Full GC [PSYoungGen: 192K->0K(1046528K)] [ParOldGen: 126747K->121514K(2097152K)] 126939K->121514K(3143680K) [PSPermGen: 102455K->102455K(102912K)], 0.2918050 secs] [Times: user=0.68 sys=0.00, real=0.30 secs]
417964.595: [GC [PSYoungGen: 14035K->256K(1047040K)] 135550K->126890K(3144192K), 0.0077220 secs] [Times: user=0.02 sys=0.00, real=0.01 secs]
417964.603: [Full GC [PSYoungGen: 256K->0K(1047040K)] [ParOldGen: 126634K->121513K(2097152K)] 126890K->121513K(3144192K) [PSPermGen: 102455K->102455K(102912K)], 0.2824640 secs] [Times: user=0.68 sys=0.00, real=0.28 secs]
417985.464: [GC [PSYoungGen: 55312K->448K(1047040K)] 176825K->127081K(3144192K), 0.0084980 secs] [Times: user=0.01 sys=0.00, real=0.01 secs]
417985.473: [Full GC [PSYoungGen: 448K->0K(1047040K)] [ParOldGen: 126633K->121640K(2097152K)] 127081K->121640K(3144192K) [PSPermGen: 102455K->102455K(102912K)], 0.2833440 secs] [Times: user=0.70 sys=0.00, real=0.28 secs]
418001.413: [GC [PSYoungGen: 52379K->288K(1047040K)] 174020K->127048K(3144192K), 0.0083470 secs] [Times: user=0.02 sys=0.00, real=0.01 secs]
418001.422: [Full GC [PSYoungGen: 288K->0K(1047040K)] [ParOldGen: 126760K->121514K(2097152K)] 127048K->121514K(3144192K) [PSPermGen: 102455K->102455K(102912K)], 0.2803850 secs] [Times: user=0.67 sys=0.00, real=0.28 secs]

看完后面的日志后我吓到了，PermGen竟然固定了，从200M慢慢缩小的100M然后自己开始固定了，最后的结果就是PermGen的使用率在99%左右，到了这个点上不full gc才怪呢，而且full gc对PermGen又不起作用，于是就造成了连续的full gc。于是我再次给出方案，如下:

-Xms3072m -Xmx3072m -XX:MaxPermSize=512m  -XX:PermSize=512M

心里想着这回PermGen肯定不会在变小了，我看你还full gc不。。。。妈蛋，果然不按套路出牌。

这次倒是PermGen不变小了，占用率一直在30%左右，但是还是不听的full gc，日志如下:

3577.069: [GC [PSYoungGen: 350848K->863K(699392K)] 563755K->214176K(2796544K), 0.0078910 secs] [Times: user=0.02 sys=0.01, real=0.01 secs]
3625.584: [GC [PSYoungGen: 351071K->480K(699392K)] 564384K->213961K(2796544K), 0.0089080 secs] [Times: user=0.01 sys=0.01, real=0.01 secs]
3636.794: [GC [PSYoungGen: 116520K->6569K(700416K)] 330000K->220257K(2797568K), 0.0104340 secs] [Times: user=0.02 sys=0.00, real=0.01 secs]
3636.805: [Full GC [PSYoungGen: 6569K->0K(700416K)] [ParOldGen: 213687K->219037K(2097152K)] 220257K->219037K(2797568K) [PSPermGen: 95205K->95205K(524288K)], 0.6350040 secs] [Times: user=1.86 sys=0.00, real=0.64 secs]
3676.722: [GC [PSYoungGen: 351232K->5857K(699392K)] 570269K->224894K(2796544K), 0.0091390 secs] [Times: user=0.02 sys=0.00, real=0.01 secs]
3677.779: [GC [PSYoungGen: 34022K->5824K(727552K)] 253059K->224861K(2824704K), 0.0078420 secs] [Times: user=0.02 sys=0.00, real=0.00 secs]
3677.787: [Full GC [PSYoungGen: 5824K->0K(727552K)] [ParOldGen: 219037K->218268K(2097152K)] 224861K->218268K(2824704K) [PSPermGen: 95208K->95208K(524288K)], 0.4049850 secs] [Times: user=1.20 sys=0.01, real=0.41 secs]
3682.161: [GC [PSYoungGen: 46208K->5504K(713728K)] 264477K->223772K(2810880K), 0.0080320 secs] [Times: user=0.02 sys=0.00, real=0.01 secs]
3682.169: [Full GC [PSYoungGen: 5504K->0K(713728K)] [ParOldGen: 218268K->218266K(2097152K)] 223772K->218266K(2810880K) [PSPermGen: 95231K->95231K(524288K)], 0.3098970 secs] [Times: user=0.77 sys=0.00, real=0.31 secs]
3733.302: [GC [PSYoungGen: 392704K->528K(756224K)] 610970K->218794K(2853376K), 0.0082770 secs] [Times: user=0.03 sys=0.00, real=0.01 secs]

15428.492: [GC [PSYoungGen: 1038194K->5108K(1041408K)] 1160542K->127572K(3138560K), 0.0100600 secs] [Times: user=0.02 sys=0.01, real=0.00 secs]
15787.899: [GC [PSYoungGen: 1039348K->4433K(1041408K)] 1161812K->127036K(3138560K), 0.0143380 secs] [Times: user=0.03 sys=0.00, real=0.02 secs]
16159.819: [GC [PSYoungGen: 1038673K->4593K(1041920K)] 1161276K->127408K(3139072K), 0.0096750 secs] [Times: user=0.02 sys=0.00, real=0.01 secs]
16196.703: [GC [PSYoungGen: 122568K->4542K(1041408K)] 245383K->132969K(3138560K), 0.0090810 secs] [Times: user=0.03 sys=0.00, real=0.01 secs]
16196.712: [Full GC [PSYoungGen: 4542K->0K(1041408K)] [ParOldGen: 128426K->116325K(2097152K)] 132969K->116325K(3138560K) [PSPermGen: 96727K->96534K(524288K)], 0.6279450 secs] [Times: user=1.84 sys=0.01, real=0.63 secs]
16316.366: [GC [PSYoungGen: 351064K->6195K(1040896K)] 467390K->122520K(3138048K), 0.0117110 secs] [Times: user=0.02 sys=0.00, real=0.02 secs]
16316.378: [Full GC [PSYoungGen: 6195K->0K(1040896K)] [ParOldGen: 116325K->115884K(2097152K)] 122520K->115884K(3138048K) [PSPermGen: 96534K->96534K(524288K)], 0.3684260 secs] [Times: user=1.03 sys=0.00, real=0.36 secs]
16335.794: [GC [PSYoungGen: 74165K->6159K(1041408K)] 190050K->122043K(3138560K), 0.0072340 secs] [Times: user=0.02 sys=0.00, real=0.01 secs]
16335.802: [Full GC [PSYoungGen: 6159K->0K(1041408K)] [ParOldGen: 115884K->116321K(2097152K)] 122043K->116321K(3138560K) [PSPermGen: 96536K->96536K(524288K)], 0.2855300 secs] [Times: user=0.63 sys=0.00, real=0.29 secs]
16653.922: [GC [PSYoungGen: 1034240K->2198K(1040384K)] 1150561K->118520K(3137536K), 0.0114790 secs] [Times: user=0.02 sys=0.00, real=0.01 secs]

还是不停的有连续full gc出现，这次我还是使劲盯着日志去看，但是什么都很足啊，为什么还是会full gc。

看了这些后我感觉还不够，于是我通过监控系统去看具体的内存区域变化，首先我先在自己心中给出了自己对于每个区域大致大小的定位:

Eden:Survivor默认是8:1，也就是说1G新生代的话应该有800M Eden区域和100M From+100M To，然后我看监控时候发现了诡异的东西。为何From区域只有4M？？？

100M为什么变为4M，而且每次full gc的时候都是Eden变大或者缩小的时候，这尼玛还动态调整？于是我上网查看PS垃圾回收器的内容，参见这篇文章:http://blog.mgm-tp.com/2013/03/garbage-collection-tuning/ 

 果然这个垃圾回收器竟然会自动调整区域的大小，平时线上比较空闲的时候From区域都比较小，维持在4M左右，一旦在高分期有人使用了，Eden快速增长的时候就开始触发频繁的full gc，每次都会导致From区域的变大或者变小。但是终究都在10M以内，这么点内容尼玛不full gc才怪呢。然后再次给出解决方案:

-Xms3072m -Xmx3072m -XX:MaxPermSize=512m  -XX:PermSize=512M -XX:NewSize=1024M -XX:MaxNewSize=1024M -XX:SurvivorRatio=8

这次提出的方案还暂时没有运用到线上，不过应该就是这个问题了(坑！！！)。

---------------------------------------------------------------------

大约10天过去了，GC问题依然缠绕着我。。上次说道感觉固定Eden的比例就应该没问题了，谁知道设置到线上之后依然出问题，还是频发的FULL GC，更甚的时候每隔一秒一次，就跟上面的日志一模一样。摸不着头脑啊，冥思苦想一周后大概看了看PS算法的源码，然并卵。。。根本看不明白，各种C++ 的代码虐得我要死，各种求助大神都没人鸟，StackOverFlow，Google都求助一遍依然然并卵。然后就想这下子必须要看一下内存具体情况了，于是周一向PE申请了线上的权限，下午就开始继续倒腾。

JSack打出来线程情况之后发现还是一脸懵逼，首先FULL GC明显不是因为内存不足引起的，所以看到线程情况又能怎样；其次，打印出来的只是一个时刻的线程情况，没法连续捕获GC前后的情况来做出对比。于是想到用Jmap看看内存实际的情况，哪个对象具体有多少个，占用了多少内存。但是这个代价有点大，一个Jmap文件大概有几兆大，如果连续打印太多的话不仅要浪费IO害怕拉低服务器性能，线上的东西我可不敢乱动，要不然直接回家种地了。于是就在纠结到底要怎么办呢？？？？？？

这时候摆在我面前的就是一个问题，要怎么统计GC前后的内存状态，但是还不能消耗太多资源。

于是就用jstat写 一个脚本，每秒执行一次。这样就可以知道GC前后内存到底变化了多少，这尼玛不看不知道，一看吓一跳。大家瞅瞅

差点没给宝宝吓死，竟！然！看！到！了！System.gc(),然后我就观察了所有的Full GC时刻的情况，尼玛全都是System.gc()！！！！！！

真是亮瞎我的狗眼啊，搞了这么久为什么是这个原因，为什么日志里不会显示GC的类型，在网上参考别人的GC日志的时候人家的System.gc()

都会出现System关键字啊，我们的日志就没有啊。抱着这种操蛋的信息我上服务器试了一把，看看我手动触发System.gc的时候会不会出现System关键字。

public static void main(String[] args){
    int _1M = 1024 * 1024;
    int _5M = 5*_1M;
    Map<String,Object> map=new HashMap<String,Object>();
    for(int i=0;i<10;i++){
        for(int j=0;j<3;j++){
            System.out.println("test");

            map.put(new Random().nextInt(100)+"asd",new byte[_5M]);

           //增加强引用，这里会触发一定的minor gc
        }
    }
    for(int i=0;i<10;i++){
        System.gc();
        System.out.println("System GC" + "---"+i);
    }
}

这是我的测试代码。

java -server -Xms256m -Xmx256m -XX:MaxPermSize=64m -verbose:gc -XX:+PrintGCDetails -XX:+PrintGCTimeStamps TestForFullGC 走你。

---Test---
---Test---
---Test---
---Test---
---Test---
---Test---
---Test---
---Test---
---Test---
---Test---
---Test---
---Test---
---Test---
0.098: [GC [PSYoungGen: 64082K->10544K(76800K)] 64082K->51504K(251904K), 0.0165000 secs] [Times: user=0.04 sys=0.02, real=0.02 secs] 
---Test---
---Test---
---Test---
---Test---
---Test---
---Test---
---Test---
---Test---
---Test---
---Test---
---Test---
---Test---
0.127: [GC [PSYoungGen: 74653K->10592K(76800K)] 115613K->107872K(251904K), 0.0216110 secs] [Times: user=0.05 sys=0.03, real=0.02 secs] 
---Test---
---Test---
---Test---
---Test---
---Test---
---Test---
---Test---
---Test---
---Test---
---Test---
---Test---
---Test---
0.161: [GC [PSYoungGen: 72475K->10592K(76800K)] 169755K->169312K(251904K), 0.0199240 secs] [Times: user=0.03 sys=0.04, real=0.02 secs] 
0.181: [Full GC [PSYoungGen: 10592K->0K(76800K)] [ParOldGen: 158720K->143587K(175104K)] 169312K->143587K(251904K) [PSPermGen: 2396K->2396K(21504K)], 0.0236070 secs] [Times: user=0.06 sys=0.00, real=0.02 secs]  //这里是内存分配不足引起的FULL GC
---Test---
---Test---
---Test---
---Test---
---Test---
---Test---
---Test---
---Test---
---Test---
---Test---
---Test---
---Test---
0.216: [Full GC [PSYoungGen: 61731K->5120K(76800K)] [ParOldGen: 143587K->174307K(175104K)] 205318K->179427K(251904K) [PSPermGen: 2396K->2396K(21504K)], 0.0252400 secs] [Times: user=0.06 sys=0.01, real=0.03 secs] 
---Test---
0.244: [Full GC [PSYoungGen: 15551K->10240K(76800K)] [ParOldGen: 174307K->174307K(175104K)] 189859K->184547K(251904K) [PSPermGen: 2396K->2396K(21504K)], 0.0143550 secs] [Times: user=0.03 sys=0.00, real=0.02 secs]  这里是System.gc引起的Full GC，因为存在强引用所以清理不掉
System Gc---0
0.258: [Full GC [PSYoungGen: 10431K->10240K(76800K)] [ParOldGen: 174307K->174307K(175104K)] 184739K->184547K(251904K) [PSPermGen: 2396K->2396K(21504K)], 0.0068290 secs] [Times: user=0.01 sys=0.00, real=0.00 secs] 
System Gc---1
0.266: [Full GC [PSYoungGen: 10431K->10240K(76800K)] [ParOldGen: 174307K->174307K(175104K)] 184739K->184547K(251904K) [PSPermGen: 2396K->2396K(21504K)], 0.0086430 secs] [Times: user=0.01 sys=0.00, real=0.01 secs] 
System Gc---2
0.275: [Full GC [PSYoungGen: 10431K->10240K(76800K)] [ParOldGen: 174307K->174307K(175104K)] 184739K->184547K(251904K) [PSPermGen: 2396K->2396K(21504K)], 0.0064060 secs] [Times: user=0.01 sys=0.01, real=0.01 secs] 
System Gc---3
0.282: [Full GC [PSYoungGen: 10431K->10240K(76800K)] [ParOldGen: 174307K->174307K(175104K)] 184739K->184547K(251904K) [PSPermGen: 2396K->2396K(21504K)], 0.0076150 secs] [Times: user=0.01 sys=0.00, real=0.01 secs] 
System Gc---4
0.289: [Full GC [PSYoungGen: 10431K->10240K(76800K)] [ParOldGen: 174307K->174307K(175104K)] 184739K->184547K(251904K) [PSPermGen: 2396K->2396K(21504K)], 0.0056370 secs] [Times: user=0.01 sys=0.00, real=0.00 secs] 
System Gc---5
0.295: [Full GC [PSYoungGen: 10431K->10240K(76800K)] [ParOldGen: 174307K->174307K(175104K)] 184739K->184547K(251904K) [PSPermGen: 2396K->2396K(21504K)], 0.0091700 secs] [Times: user=0.01 sys=0.00, real=0.01 secs] 
System Gc---6
0.305: [Full GC [PSYoungGen: 10431K->10240K(76800K)] [ParOldGen: 174307K->174307K(175104K)] 184739K->184547K(251904K) [PSPermGen: 2396K->2396K(21504K)], 0.0073210 secs] [Times: user=0.01 sys=0.00, real=0.01 secs] 
System Gc---7
0.313: [Full GC [PSYoungGen: 10431K->10240K(76800K)] [ParOldGen: 174307K->174307K(175104K)] 184739K->184547K(251904K) [PSPermGen: 2396K->2396K(21504K)], 0.0072460 secs] [Times: user=0.01 sys=0.00, real=0.01 secs] 
System Gc---8
0.321: [Full GC [PSYoungGen: 10431K->10240K(76800K)] [ParOldGen: 174307K->174307K(175104K)] 184739K->184547K(251904K) [PSPermGen: 2396K->2396K(21504K)], 0.0070930 secs] [Times: user=0.01 sys=0.00, real=0.01 secs] 
System Gc---9

尼玛根本没有System关键字出现啊，这就埋下了一个坑。从一开始就被我排除的原因原来可能是最后的原因。

这样一想所有的GC日志都可以解释了，为什么内存充足时候也会频繁FULL GC呢，就是因为这时候依赖里面有的类会手动调用System.gc(但是我们并不知情)，而且总是在使用某些操作的时候触发特定的Full GC，管你内存足不足，我就是手动触发。FUCK

那么现在情况应该很明了啦，以前的情况可能都用可能，但是这个才是根本的原因！！！于是准备明天让PE禁了System.gc试试看，如果还不行的话我就要切腹自尽了。。。

敬请期待下一回。

============================================================

问题已经解决，就是System.gc的原因，禁止之后就再也没有发生过Full GC的原因了。昨天经过师兄的帮助也成功定位到了问题的所在，在使用jxl包的时候，由于关闭文件操作可能会触发System.gc()导致，以后在使用这个包做一些Excel的操作时候可是要长点心了呐，海燕。。。。。。。