POI导出excel的时候出现gc overhead limit

问题现象

项目中需要一个数据导出excel功能，因为导出的文件需要是正式excel格式，包含多个sheet页，采用csv等方式无法满足需求，所以采用poi方式。考虑到poi方式会占用较多的内存，所以限制每次最多可以导出10000条数据，并且在开发环境自测的时候用可允许的最大的数据进行测试正常，通过jvisualvm观察内存使用情况发现old区内的最多的时候占用到200M左右，属于需求可接受范围。但是在测试环境测试的时候同样的数据会报异常，异常如下：

2011-01-05 10:32:03,783 [] WARN  support.DefaultExceptionMonitor - Unexpected exception.
java.lang.OutOfMemoryError: GC overhead limit exceeded
        at java.util.HashMap.newKeyIterator(HashMap.java:840)
        at java.util.HashMap$KeySet.iterator(HashMap.java:874)
        at java.util.HashSet.iterator(HashSet.java:153)
        at sun.nio.ch.SelectorImpl.processDeregisterQueue(SelectorImpl.java:127)
        at sun.nio.ch.EPollSelectorImpl.doSelect(EPollSelectorImpl.java:69)
        at sun.nio.ch.SelectorImpl.lockAndDoSelect(SelectorImpl.java:69)
        at sun.nio.ch.SelectorImpl.select(SelectorImpl.java:80)
        at org.apache.mina.transport.socket.nio.SocketIoProcessor$Worker.run(SocketIoProcessor.java:480)
        at org.apache.mina.util.NamePreservingRunnable.run(NamePreservingRunnable.java:51)
        at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)
        at java.lang.Thread.run(Thread.java:619)

GC overhead limit：This message means that for some reason the garbage collector is taking an excessive amount of time (by default 98% of all CPU time of the process) and recovers very little memory in each run (by default 2% of the heap).

即意味着CPU的大多数时间在执行GC，但是GC回收到的内存很少。也就是程序不再去执行其他的工作而一直在进行GC。

问题原因调查

程序结构：

getDataList();        注：取得10000条数据

generateWorkBook();   注：构建excelbook

write();              注：调用workBook的write方法，将excel写入输出流中

1. 调试发现，是进行write（）的时候报出异常。初步定位：有可能poi中的write方法有问题，但是这不能解释为什么开发环境不会出现这个问题

 

2. 查看程序执行过程中的GC情况

（1）. jps -v：打印出当前java进程的相信信息，找到需要的pid

（2）. jstat -gc pid 500：每隔0.5秒，打印GC情况

得到GC情况如下（节选），可见其实在生成workbook的时候已经把内存都占用了，在后续的时候一直在疯狂的执行fullGC，但是确没有办法回收掉内存，导致报异常：

0C      S1C      S0U    S1U      EC       EU        OC         OU       PC       PU         YGC    YGCT  FGC     FGCT     GCT
<!-----------------------------查询数据 start----------------------------------------->
29312.0 30784.0  0.0   12495.0 111296.0 81878.4   157248.0   107377.5  131072.0 58695.9     17    0.259   2      0.256    0.515
29312.0 29632.0 17012.5  0.0   114240.0   0.0     157248.0   107377.5  131072.0 61570.7     18    0.281   2      0.256    0.537
29312.0 29632.0 17012.5  0.0   114240.0 113694.2  157248.0   107377.5  131072.0 62525.5     18    0.281   2      0.256    0.537
30848.0 29632.0  0.0   29602.5 114240.0 17769.8   157248.0   117265.5  131072.0 62525.5     19    0.309   2      0.256    0.565
30848.0 29632.0  0.0   29602.5 114240.0 82492.0   157248.0   117265.5  131072.0 66869.2     19    0.309   2      0.256    0.565
30848.0 40640.0 27969.2  0.0   93440.0   2684.5   157248.0   129150.4  131072.0 69366.5     20    0.335   2      0.256    0.591
30848.0 40640.0 27969.2  0.0   93440.0  33808.0   157248.0   129150.4  131072.0 69492.5     20    0.335   2      0.256    0.591
30848.0 40640.0 27969.2  0.0   93440.0  88751.4   157248.0   129150.4  131072.0 69538.6     21    0.335   2      0.256    0.591
40640.0 40640.0  0.0    0.0   93440.0  25459.3   250368.0   157248.0  131072.0 69576.3     21    0.359   3      0.687    1.046
40640.0 55360.0 39744.0  0.0   64000.0  38072.3   250368.0   157248.0  131072.0 69599.2     22    0.389   3      0.687    1.076
<!------------------------------查询数据end------------------------------------------->

<!-----------------------------生成workBook start------------------------------------->
58240.0 58240.0  0.0   14400.0 58240.0    0.0     250368.0   229032.0  131072.0 69647.0     25    0.466   4      0.687    1.153
56512.0 58240.0 42912.0  0.0   58240.0   2304.1   349568.0   238586.7  131072.0 69504.9     28    0.508   4      1.305    1.812
55360.0 56960.0  0.0   14336.0 58240.0    0.0     349568.0   310706.7  131072.0 69504.9     31    0.588   5      1.305    1.893
55360.0 56960.0  0.0    0.0   58240.0  58240.0   349568.0   324956.3  131072.0 69504.9     31    0.588   6      1.980    2.568
55360.0 56960.0  0.0    0.0   58240.0  58240.0   349568.0   339142.1  131072.0 69801.6     31    0.588   7      2.751    3.339
55360.0 56960.0  0.0    0.0   58240.0  58240.0   349568.0   349567.9  131072.0 69828.7     31    0.588   8      3.540    4.128
55360.0 56960.0  0.0    0.0   58240.0  44166.5   349568.0   349568.0  131072.0 69821.5     31    0.588   9      4.425    5.014
55360.0 56960.0  0.0    0.0   58240.0  58240.0   349568.0   349568.0  131072.0 69821.6     31    0.588  10      5.293    5.881
55360.0 56960.0  0.0    0.0   58240.0  58240.0   349568.0   349568.0  131072.0 69821.6     31    0.588  11      6.184    6.772
55360.0 56960.0  0.0    0.0   58240.0  58240.0   349568.0   349568.0  131072.0 69821.6     31    0.588  12      7.038    7.626
55360.0 56960.0  0.0    0.0   58240.0  58240.0   349568.0   349568.0  131072.0 69821.6     31    0.588  13      7.894    8.482
55360.0 56960.0  0.0    0.0   58240.0  58240.0   349568.0   349568.0  131072.0 69821.6     31    0.588  14      8.723    9.311
<!-----------------------------.................------------------------------------->

3. 貌似是内存真的不够用了！调整内存大小试下

 

注：开发环境和测试环境启动参数都是-Xms128m -Xmx512m，即内存使用最大512

把参数调整为-Xms1024m -Xmx1024m后执行程序，导出正常。确实是内存不够用了，不过还是不能解释开发环境和测试环境结果不一样的问题

 

4. 打印开发环境的GC情况，发现OU最大的时候也只是到200M之内

 

为什么同样的数据同样的程序在两个环境的使用的内存会不一样呢？

 

5. 在开发和测试环境执行导出时dump内存，查找原因

（1）. jmap -dump:format=b,file=heap.bin <pid>：生成内存快照

（2）. jhat -port 8888 heap.bin：通过jhat把内存快照生成网页文件，并开发端口8888

（3）. 访问http://172.29.61.77:8888
对比两个快照信息后发现有很多相同的对象的大小都不一样，测试环境的明显大些。，查看快照信息（172.29.61.77：测试环境地址）

6. 确定两个环境有那些地方不同

（1）. java版本：java -version

（2）. jvm启动参数：jps -v

（3）. 查看服务器信息：uname -a

发现测试环境是64位，开发环境是32位

通常64位JVM消耗的内存会比32位的大1.5倍，这是因为对象指针在64位架构下，长度会翻倍（更宽的寻址）

8. 验证是否是这个原因引起

 

测试环境jvm启动添加参数-XX:+UseCompressedOops

注：UseCompressedOops：压缩指针，参照http://kenwublog.com/compressedoops

添加参数后，再次执行导出程序，正常。观察GC情况，发现OU最大的时候在二百几十M，虽然还是比开发环境用的内存要大，不过比之前已经小了很多了。

 

 

 

结论

 

之所以在测试环境出现内存异常情况而在开发环境正常原因是64位jvm对内存的消耗要比32位的大出很多，可以通过UseCompressedOops这个参数来进行指针的压缩，不过这个在节约内存的同时会增大jvm的负担，具体是否要为线上添加这个参数需要权衡。

 

 

查找问题过程中遇到的另一个问题

1. 现象

在点击一次"导出"按钮后，在eclipse中进行调试，调试过程中会发现又有另一个同样的请求过来,即每个断点都会执行两次。

2. 分析

• 浏览器自动重新发？

          用firebug观察发出的请求，只有一个，不是

• 其他人也在执行这个操作？

          查看cookielog，仅有一条记录，不是

• mod_jk自动转发

          查看mod_jk的配置：

...
JkWorkerProperty worker.localnode.socket_keepalive=True
JkWorkerProperty worker.localnode.socket_timeout=20
...

socket_timeout：Socket timeout in seconds used for the communication channel between JK and remote host. If the remote host does not respond inside the timeout specified, JK will generate an error, and retry again. If set to zero (default) JK will wait for an infinite amount of time on all socket operations. 即如果转发请求后20秒没有接收到响应，就会返回给用户一个error，同时重新发起一次请求。

http://tomcat.apache.org/connectors-doc/reference/workers.html

莫非是因为本来导出这里就很慢，加上调试的时间超过了预设的20秒，所以导致retry了？

 

3. 验证

 

将socket_timeout设为0，再次进行调试，果然那个神秘的请求没有再出现过！