AIX 6.1环境IBM Java1.6内存泄露分析

1
现象

场景：LoadRunner 10用户并发，无思考时间，每个用户顺序执行59个交易。
现象：压测10-15分钟之后，LoadRunner客户端发现大量失败交易，查看错误信息“无法连接应用服务器”。应用服务器发现产生大量heapdump.***.phd和javacore.***.txt文件。

2
初步定位

分析应用日志ltts-app1.out，发现存在如下错误信息：

Throwable occurred: java.lang.OutOfMemoryError: Java heap space at java.net.PlainSocketImpl.accept(PlainSocketImpl.java:480) at java.net.ServerSocket.implAccept(ServerSocket.java:479) at java.net.ServerSocket.accept(ServerSocket.java:447) at sun.rmi.transport.tcp.TCPTransport$AcceptLoop.executeAcceptLoop(TCPTransport.java:381) at sun.rmi.transport.tcp.TCPTransport$AcceptLoop.run(TCPTransport.java:353) at java.lang.Thread.run(Thread.java:738)

同时，在应用程序启动目录下发现存在多个javacore*.txt、heapdump*.phd文件，初步定为为堆内存泄露问题。

3
问题还原

增加应用JVM启动选项，降低堆最大内存大小至1024m来减少问题暴露的时间。

--堆内存大小 -Xms768m -Xmx2048m --开启jconsole监控端口 -Dcom.sun.management.jmxremote.port=8999 -Dcom.sun.management.jmxremote.ssl=false -Dcom.sun.management.jmxr emote.authenticate=false --开启verbosegc -verbose:gc -Xverbosegclog:gc.log --自定义heapdump事件和格式 -Xdump:heap:events=user

应用启动成功后，通过jconsole连接上去查看初始堆内存大小。

此时，通过“kill -3 pid”主动产生javacore和heapdump转储文件，作为基线参考。

接着，开始通过Load Runner压测，过了3分钟、5分钟左右，通过“kill -3 pid”主动产生javacore和heapdump转储文件，作为时点数据可以与基线数据进行比较。

Load Runner压测10-15分钟左右，通过jconsole跟踪发现堆内存持续增长，垃圾回收也无法释放内存。

另外，通过AIX命令tprof命令“tprof -s -k -x sleep 60”跟踪java进程cpu使用情况。

Process Freq Total Kernel UserShared Other ======= ==== ===== ====== ==== ====== ===== wait 16 53.07 53.07 0.00 0.00 0.00 /usr/java5/jre/bin/java 38 45.66 1.06 0.00 42.00 2.60 可以看出Shared（即动态库cpu占比很高），接下来查看哪些动态库占用cpu较多呢？ Total % For All Processes (SH-LIBs) = 42.06 Shared Object % ============= ====== /usr/java6_64/jre/lib/ppc64/default/libj9gc24.so 40.90 /usr/java6_64/jre/lib/ppc64/default/libj9jit24.so 0.54 /usr/lib/libpthreads.a[shr_xpg5_64.o] 0.19 /usr/java6_64/jre/lib/ppc64/default/libj9vm24.so 0.18 从上述列表可以看出gc（垃圾回收）占比很高（40.90%）

LR再持续运行一段时间之后，响应时间越来越长，而且出现大量错误“无法连接应用服务器”，此时在服务器上查看应用日志发现存在大量OutOfMemoryError错误。

多次测试发现该类问题可以重现，可重现的问题相对于无法重现的问题总是比较好解决的。好吧，继续分析gc日志、javacore*.txt和heapdump*.txt文件。

使用IBM Pattern Modeling and Analysis Tool for Java Garbage Collector分析垃圾回收日志文件，查看Graph View Part图表。

这个图表有些看不懂，先留着后续继续分析。

通过IBM Thread and Monitor Dump Analyzer for Java工具分析产生的javacore*.txt文件。

***WARNING*** Java heap is almost exhausted : 0% free Java heap Please enable verbosegc trace and use IBM Pattern Modeling and Analysis Tool(http://www.alphaworks.ibm.com/tech/pmat) to analyze garbage collection activities. If heapdumps are generated at the same time, please use IBM HeapAnalyzer(http://www.alphaworks.ibm.com/tech/heapanalyzer) to analyze Java heap.

上述日志描述堆内存已消耗殆尽，进一步分析可打开verbosegc选项或则通过HeapAnalyzer工具分析heapdump*.txt文件。

接着，通过IBM HeapAnalyzer工具分析heapdump*.txt文件。

HeapAnalyzer工具“Subponea Leak Suspect”可列出内存泄露可疑点。从上述可疑点可以推断DataMappingUtil2类存在ConcurrentHashMap对象持续在增长。

4
问题修复

通过分析DataMappingUtil2类程序，发现只存在1个全局缓存对象，用于缓存数据映射逻辑。

public static final Map<MappingKey, ComplexTypeMapping> mappings = new ConcurrentHashMap<MappingKey, ComplexTypeMapping>(); public static ComplexTypeMapping getMapping(Class<?> type, List<? extends Element> fromElmts, List<? extends Element> toElmts, DataMapping mapping, boolean lazymapping, boolean validate, boolean mappingNullField) { if (mapping == null) mapping = DataMapping.Default; MappingKey key = new MappingKey(type, fromElmts, toElmts, mapping, lazymapping, validate, mappingNullField); ComplexTypeMapping ret = mappings.get(key); if (ret == null) { ret = createComplexTypeMapping(key, fromElmts, null, null, null, null, null, mapping == null ? false : mapping.isMappingByInterfaceDefault()); mappings.put(key, ret); } return ret; }

根据HeapAnalyzer分析结果，只有可能MappingKey一直在变化，才会导致缓存内容越来越多。

分析MappingKey的hashCode方法，hash值是由对象组合“type, fromElmts, toElmts, mapping, lazymapping, validate, mappingNullField”计算而得的。

public int hashCode() { ProfileUtil.start_record("dataMapping.hashCode"); try { final int prime = 31; int result = 1; result = prime * result + ((type == null) ? 0 :type.hashCode()); result = prime * result + ((destElmts == null) ? 0 :destElmts.hashCode()); result = prime * result + (lazymapping ? 1231 : 1237); result = prime * result + (validate ? 1231 : 1237); result = prime * result + (mappingNullField ? 1231 : 1237); result = prime * result + ((mapping == null) ? 0 :mapping.hashCode()); result = prime * result + ((srcElmts == null) ? 0 :srcElmts.hashCode()); return result; } finally { ProfileUtil.end_record("dataMapping.hashCode"); } }

这7个对象都是模型数据对象，应该是在应用启动首次加载模型之后就确定的，是不会有变化的，但是….

只能继续找到所有程序调用点，分析每处的代码，终于，找到一处可疑点：

--调用堆栈 DataMappingUtil.dataMapping -> DataMappingUtil2.dataMapping -> DataMappingUtil2.getMapping DataMappingUtil.dataMapping( subtran.getDataInterface().getInputAndProperty().getElements(), node.getCmbkConfig().getDataInterface().getInputAndProperty().getElements(), subtran.getDataArea().getInput(), cmbkArea.getInput(), node.getInMapping()); --查看SubTransactionRT.getDataInterface()方法。 class SubTransactionRT { public DataInterface getDataInterface() { return this.config.getSubtranObj().getDataInterface(); } } --跟踪getSubtranObj().getDatainterface()方法，在此处发现在“客户化机制”的情况下，子交易接口有可能会重新构建。 class SubTranConf public DataInterface getDataInterface() { if (CustomManager.get() != null) return CustomManager.get().getDataInterface(this, this.dataInterface); return dataInterface; } } --跟踪下去，发现特定的情况时，接口对象会重新copy（即new）一份，这将导致“subtran.getDataInterface().getInputAndProperty().getElements()”对象也是新的，计算hash值也变成新的。 class CustomManager { public static DataInterface getDataInterface(String currentSubTranId, List<CustomElement> customs, SubTranConf subtran, DataInterface orig, boolean needCreatNewDataInterface) { if (currentSubTranId == null) return orig; DataInterface ret = orig; if(needCreatNewDataInterface) ret = orig.copy(); for (CustomElement custom : customs) { if (custom instanceof CustomDataInterface && subtran.getId().equals(((CustomDataInterface)custom).getSubtran())) { initCustomDataInterface((CustomDataInterface)custom, ret); } } return ret; } } public class DataInterface { public DataInterface copy() { DataInterface ret =newDataInterface(); ret.input.setElements(new ArrayList<DataInterfaceElement>(this.input.getElements())); ret.output.setElements(new ArrayList<DataInterfaceElement>(this.output.getElements())); ret.property.setElements(new ArrayList<DataInterfaceElement>(this.property.getElements())); return ret; } }

问题找到了，在客户化子交易接口的情况下，子交易数据接口对象每次都会重新构建，这会导致缓存数据映射逻辑的时，每次计算的MappingKey值不一样，缓存的数据越来越多。那问题的解决思路就是减少重新构建的次数，最好是能只需构建一次。

public class SubTransactionRT { private static Map<String, DataInterface> customInterfaces = new ConcurrentHashMap<String, DataInterface>(); public DataInterface getDataInterface() { // 2013-09-05仅赋值一次 DataInterface ret = this.config.getDataInterface(); if (ret ==null) { ret = this.config.getSubtranObj().getDataInterface(); this.config.setDataInterface(ret); } return ret; } }

5
修复后测试

打包重新部署，继续测试。启动应用服务器之后，通过jconsole查看初始堆内存大小。

通过LR压测10-15分钟。

通过jconsole查看堆内存使用情况。

LR交易响应时间图。，响应时间基本不变。

通过tprof命令“tprof -s -k -x sleep 60”收集进程cpu耗时信息。

Process Freq Total Kernel User Shared Other ======= ==== ===== ====== ==== ====== ===== /usr/java5/jre/bin/java 60 46.06 4.08 0.00 20.74 21.23 Total % For All Processes (SH-LIBs) = 21.20 Shared Object % ============= ====== /usr/java6_64/jre/lib/ppc64/default/libj9gc24.so 16.06 /usr/java6_64/jre/lib/ppc64/default/libj9jit24.so 2.30 Total % For All Processes (/usr/java6_64/jre/lib/ppc64/default/libj9gc24.so) = 16.06 Subroutine % Source ========== ====== ====== ncrementalScanCacheBySlot(MM_EnvironmentStandard*) 8.12 arallelScavenger.cpp EnvironmentStandard*,MM_ScavengerForwardedHeader*) 2.32 arallelScavenger.cpp ngerForwardedHeader::setForwardedObject(J9Object*) 1.50 rForwardedHeader.cpp scanMixedObject(MM_EnvironmentStandard*,J9Object*) 1.09 MarkingScheme.cpp .J9ZeroMemory 0.55 j9memclr.c

分析tprof命令收集结果，可以看出gc还是比较高，估计跟本次测试时最大堆大小配置成1024m有一定关系，还有待进一步排查。

停止LR压测，通过jconsole执行GC操作，发现堆内存可以释放出来。

测试结果可以看出，修改的代码还是有作用的。

6
总结

(1) 通过“kill -3”采集多个时点的heap转储文件，对比分析效果会更佳。
(2)
线上系统最好能开启jconsole服务，可实时监控gc信息
(3) 结合操作系统提供的命令ps、nmon、tprof，可进一步精确定位问题所在。