OutOfMemoryError.docx

运行环境：AIX5.3，WebSphere Portal Server V6.1Oracle 10g技术平台：J2EE项目上线后平稳运行大概半年时间，没有出过问题，但随着客户方的推广，用户量逐渐上升，某日下午，was终于hang死，因为应用同时在为另外一个平台提供接口服务，而对方应用没有设置通讯超时时间参数，请求无法收到响应，导致大量线程挂起，最终将对方服务也拖垮。因为拖垮的服务本身优先级高于本项目，而且两个不同的平台同时宕机，还都是直接面向用户的公众性服务，客户方非常重视，于是立即着手分析查找问题。打开应用日志，发现日志已经在was服务hang死的时间停止记录，在本应用目录下发现was自动生成的heapdump.phd文件和javacore文件，初步判断是内存溢出，随后在was日志中发现OutOfMemoryError字样，验证了上一步的推论，而我这艰苦的与OutOfMemoryError斗争的步伐才刚刚开始。一使用IBMHeapAnalyzer打开heapdump文件，发现如下结果：1,396,325,544(99%) 32 2 class org/eclipse/osgi/framework/log/FrameworkLogEntry 0x1133230101,396,324,816 (99%) 32 7 classjava/lang/Object 0x113098b08 1,395,031,480 (99%) 32 29 classjava/lang/Integer 0x113123f60 1,394,975,680 (99%) 32 58 classjava/lang/System 0x113117e40 1,394,818,496 (99%) 32 16 classcom/ibm/jvm/io/ConsolePrintStream 0x1131ec568 1,394,818,040 (99%) 32 9 classjava/io/OutputStream 0x1131e9db0 1,394,817,880 (99%) 32 4 classjava/lang/IndexOutOfBoundsException 0x1130a0228 1,394,817,784 (99%) 32 27 classjava/lang/Throwable 0x11309f350 1,394,817,008 (99%) 32 44 classjava/io/ObjectOutputStream 0x1136ff5b0 1,394,757,096 (99%) 32 21 classjava/io/ObjectStreamField 0x1130e65d0 1,394,733,792 (99%) 32 13 classjava/lang/reflect/Field 0x1131c7168 1,394,731,896 (99%) 32 19 classjava/lang/reflect/AccessibleObject 0x1131c6958 1,394,731,504 (99%) 32 3 classjava/lang/reflect/ReflectPermission 0x1131c8118 1,394,731,408 (99%) 32 12 classjava/security/BasicPermission 0x1130e74a0 1,394,731,328 (99%) 32 21 classjava/security/BasicPermissionCollection 0x11334e600 1,394,729,008 (99%) 32 44class java/util/Hashtable 0x11313ce50 1,394,728,192 (99%) 32 72class java/io/ObjectInputStream 0x1136e4430 1,394,725,656 (99%) 32 8class java/lang/ClassCastException 0x1130e99f0 1,394,725,544 (99%) 32 9class com/ibm/oti/util/Msg 0x1141a3c98 1,394,716,736 (99%) 32 58class java/util/ResourceBundle 0x1134e5620 1,394,163,288 (99%) 32 6class java/lang/ref/ReferenceQueue 0x113260df8 1,394,163,192 (99%) 3212 class sun/misc/Cleaner 0x1158d6168 1,394,163,024 (99%) 725 sun/misc/Cleaner 0x70000005fa52968 1,394,161,776 (99%) 726 sun/misc/Cleaner 0x70000005fa524b8 1,394,161,568 (99%)72 6 sun/misc/Cleaner 0x70000005f34e908WAS服务器设置的JVM最大堆为1536MB，但heapdump文件中显示名为org/eclipse/osgi/framework/log/FrameworkLogEntry的对象占据了近1.3GB的堆，最终导致JVM堆无空间可用，发生OOM。导致OOM的直接元凶已经找到，接着分析如何会产生如此异常的大对象。org/eclipse/osgi/framework/log/FrameworkLogEntry对象是OSGI部分，而OSGI是WAS内置组件，从IBM技术工程师处证实，WAS6.1不支持自定义OSGI包的应用程序，综合分析之后有如下两个方向：1、 程序中是否采用了OSGI方式开发，或者是否直接或间接地调用了OSGI相应的包或对象经过确认，程序中并未采用OSGI方式开发，也并未直接或者间接调用OSGI相应的包和对象，但是在OSGI的线程调用过程，发现com/ibm/jvm/io/ConsolePrintStream对象，推测问题与程序log打印到Console有关。查看之后发现，程序中有使用客户方提供的一个jar包，而在这个jar包已经封装了log4j包装的日志模块，查看之后发现如下配置文件： 而在本程序也已经单独配置了日志模块，于是笔者推断，程序的log模块与jar里的log模块冲突，同时加载并且生效，导致日志混乱输出到Console的，并不断累计，导致最后把JVM占用完，而且在应用日志也发现混乱答应的日志，证实了这一点判断。2、WAS补丁版本过低，升级到较新的WAS补丁当前WAS服务器使用的版本是V，从IBM技术工程师处得知，此版本是2006年5月份发布的，在这6年的时间内，仅补丁包版本号就已经积累到V3，计23个补丁包，解决产品问题2000多个，其中包括大量的OSGI相关的问题。综合分析之后，做出如下方案：1、因为引入的jar包是作为一种备份方案而存在，并不影响应用的运行与功能，评估后意义不大，于是将此jar包与其关联的内容全部删除。2、将was版本从V升级到V3。二经过上述的解决方案之后，程序平稳运行一段时间，但是到二十多日之后，又发生宕机事故。到达现场之后，在was目录下又发现自动生成的heapdump文件和javacore文件，日志中显示，服务hang死停止响应，难道又是OOM？于是使用IBM Pattern Modeling and Analysis Tool for Java Garbage Collector打开GC日志native_stderr.log，如下图： 典型的OOM，一头黑线呐，擦了擦汗之后迅速投入到寻找分析问题过程中。使用IBMThread and Monitor DumpAnalyzer for Java打开javacore文件: Cause of thread dump : Dump Event uncaught (00008000) Detail java/lang/OutOfMemoryError received证实了gc日志中曲线奔向OOM的推断。继续查找溢出的元凶。使用IBMHeapAnalyzer打开heapdump文件，发现如下结果：1,539,014,248304 166 class cn/ajifeiji/mbs/server/trades/fee/FeeManager 0x116a761e81,536,425,744 304 41 classcn/ajifeiji/mbs/server/pub/sms/SmsSendUtil 0x11871b5e0 1,536,393,176 304 12 classorg/mvel2/templates/TemplateRuntime 0x117be0f28 1,536,385,312 304 6 class org/mvel2/templates/res/Node0x117be31b8 1,536,385,008 304 58 classorg/mvel2/util/ParseTools 0x117da75c0 1,536,324,448 304 19 classorg/mvel2/ast/ASTNode 0x117e22960 1,536,320,496 304 35 classorg/mvel2/optimizers/OptimizerFactory 0x118095eb8 1,536,316,616 304 29 classorg/mvel2/optimizers/impl/asm/ASMAccessorOptimizer 0x118145e98 1,536,293,264 168 8org/mvel2/optimizers/dynamic/DynamicClassLoader 0x70000000413dcd0 1,536,292,024 64 2java/util/LinkedList 0x70000000413ee80 1,536,291,960 64 3java/util/LinkedList$Entry 0x70000000413eeb0 1,536,289,384 64 4java/util/LinkedList$Entry 0x70000005fd87c28 1,536,286,928 64 4java/util/LinkedList$Entry 0x70000005fd878b8 1,536,284,448 64 4java/util/LinkedList$Entry 0x70000005fd86d00 1,536,281,992 64 4java/util/LinkedList$Entry 0x70000005fd855c0内存快照显示，cn/ajifeiji/mbs/server/pub/sms/SmsSendUtil对象占用了1,539,014,248字节的heap，java/util/LinkedList$Entry对象一直循环。继续分析heap快照。 根据上述图示，明显的可以判断，OOM跟mvel表达式有关，而且项目中确实使用的大量的mvel2表达式编译解析xml报文，方向进一步明确。项目中使用TemplateRuntime.eval处理xml报文，难道mvel2表达式中TemplateRuntime.eval有bug ?于是准备测试一下，代码如下：DataTable t1 =new DataTable(); SortedMap row =t1.addRow(); row.put(accNo,1); row.put(amount,100); row = t1.addRow(); row.put(accNo,2); row.put(amount,200); HashMap ctx = newHashMap(); ctx.put(t1, t1); String template = foreachitem :t1.rowsitem.accNo,item.amountend; long ll = 0; /产生内存泄漏的方式 for (;) String output = (String)TemplateRuntime.eval(template, ctx);System.out.println(ll=+(ll+); 默认的JVM参数下，运行“ll=22611”左右，就会出现OutOfMemory。谷姐度娘之后发现TemplateRuntime.eval包含对表达式进行编译的处理,如下图： 而编译处理过程会产生不能快速释放的的内存占用，导致不断调用后，内存一直增加，直到OOM。但是，项目中大量的依赖mvel表达式，该如何是好？继续谷姐度娘，原来mvel表达式编译和获取文本是可以分开两步步骤执行，于是修改如上代码，进行测试，代码如下： DataTablet1 = new DataTable(); SortedMap row =t1.addRow(); row.put(accNo,1); row.put(amount,100); row = t1.addRow(); row.put(accNo,2); row.put(amount,200); HashMap ctx = newHashMap(); ctx.put(t1, t1); String template = foreachitem :t1.rowsitem.accNo,item.amountend; long ll = 0; /不产生内存泄漏的方式 CompiledTemplate compiled =TemplateCpileTemplate(template); for (;) String output =(String)TemplateRuntime.execute(compiled, ctx);System.out.println(ll=+(ll+); 测试代码运行20分钟后，没有发现内存减少的情况，问题解决。综合之上的结论，整理出结果方案：把TemplateRuntime.eval方法分离为TemplateCpileTemplate和TemplateRuntime.execute两个步骤进行，增加MvelCompilers.java类，对TemplateCpileTemplate和TemplateRuntime.execute进行封装处理，对外提供.eval接口，该类对表达式的compileTemplate做缓存处理，避免重复调用。最后，代码修正完毕后替换项目中所有老的mvel表达式调用，重启was服务，系统正常运行。三上次的问题修复后，服务平稳运行超过一个月没有出问题，笔者徜徉在幸福的时光中，直到在某一个周末的早晨，睡梦中笔者被一个电话吵醒，生产运行室保障：程序报错【获取不到数据库连接】。两分钟起床两分钟洗漱完毕后直奔机房，到达现场后，首先打开应用日志，服务并没有hang死，仍然在不停的接受到请求，但是一到数据库操作的部分，就报错：获取不到数据库连接。于是使用PL/SQL登陆数据库，测试一条查询语句，数据库一切正常。努力镇静下来后一想，这可能的情况实在太多，客户方催着要立即恢复服务，不可能一直在生产现场来查找问题，于是便Kill -3杀出javacore文件，连同日志一起down到测试环境分析。打开was日志：上下文实现：com.ibm.ws.naming.java.javaURLContextRoot上下文方法：lookup(Name)上下文名称：java:目标名称：comp/env/jdbc/mbs其他数据：异常堆栈跟踪：com.ibm.websphere.naming.CannotInstantiateObjectException:An enexpected error occurred while attempting to deserialize retrieved object.Root exception is java.lang.OutOfMemoryError atcom.ibm.ws.naming.util.HcessSerializedObjectForLookupExt(Helpers.java:829) atcom.ibm.ws.naming.urlbase.UrlContextHcessBoundObjectForLookup(UrlContextHelper.java:191) atcom.ibm.ws.naming.java.javaURLContextRcessBoundObjectForLookup(javaURLContextRoot.java:407) atcom.ibm.ws.naming.urlbase.UrlContextImpl.lookup(UrlContextImpl.java:1280) atcom.ibm.ws.naming.java.javaURLContextImpl.lookup(javaURLContextImpl.java:384) atcom.ibm.ws.naming.java.javaURLContextRoot.lookup(javaURLContextRoot.java:205) atcom.ibm.ws.naming.java.javaURLContextRoot.lookup(javaURLContextRoot.java:145) atjavax.naming.InitialContext.lookup(InitialContext.java:363) atcn.test.core.db.SqlExecutor.getConnection(SqlExecutor.java:772) atcn.test.core.db.SqlExecutor._query(SqlExecutor.java:335) atcn.test.core.db.SqlExecutor.query(SqlExecutor.java:327) atcn.test.core.db.SqlExecutor.query(SqlExecutor.java:407) atcn.test.core.db.Dao.execQuery(Dao.java:141) atcn.ajifeiji.mbs.server.pub.Sequence.getJournalSeq(Unknown Source) m.HostJournal.LogHostBizRecord(Unknown Source) m.NbsComm.callBack(NbsComm.java:177) m.AbstractComm.connect(AbstractComm.java:68) m.NbsComm.doTrade(NbsComm.java:52) atcn.ajifeiji.mbs.server.trades.transfer.Transfer.addPayee(Unknown Source) atsun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) atsun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:64) atsun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) atjava.lang.reflect.Method.invoke(Method.java:615) atcn.test.core.app.Ioc._invokeMethod(Ioc.java:172) atcn.test.core.app.Ioc.invokeMethod(Ioc.java:158) atcn.test.core.app.Ioc.invoke(Ioc.java:153) atcn.test.core.app.TradeHandler._execute(TradeHandler.java:143) atcn.test.core.app.TradeHandler.execute(TradeHandler.java:79) atcn.test.core.app.Switcher.execute(Switcher.java:44) atcn.test.core.app.AppServer.execProc(AppServer.java:21) atcn.test.core.mvc.c.Controller.tradeProcess(Controller.java:412) atcn.test.core.mvc.c.Controller._exec(Controller.java:110) atcn.test.core.mvc.c.Controller.exec(Controller.java:77) atcn.test.core.mvc.c.RequestHcess(RequestHandle.java:65) atcn.test.core.mvc.c.RequestHandle.doGet(RequestHandle.java:38) atcn.test.core.mvc.c.RequestHandle.doPost(RequestHandle.java:43) atjavax.servlet.http.HttpServlet.service(HttpServlet.java:763) atjavax.servlet.http.HttpServlet.service(HttpServlet.java:856) atcom.ibm.ws.webcontainer.servlet.ServletWrapper.service(ServletWrapper.java:1213) atcom.ibm.ws.webcontainer.servlet.ServletWrapper.handleRequest(ServletWrapper.java:658) atcom.ibm.ws.wswebcontainer.servlet.ServletWrapper.handleRequest(ServletWrapper.java:526) at com.ibm.ws.webcontainer.servlet.CacheServletWrapper.handleRequest(CacheServletWrapper.java:90) atcom.ibm.ws.webcontainer.WebContainer.handleRequest(WebContainer.java:764) atcom.ibm.ws.wswebcontainer.WebContainer.handleRequest(WebContainer.java:1478) atcom.ibm.ws.webcontainer.channel.WCChannelLink.ready(WCChannelLink.java:133) atcom.ibm.ws.http.channel.inbound.impl.HttpInboundLink.handleDiscrimination(HttpInboundLink.java:457) atcom.ibm.ws.http.channel.inbound.impl.HttpInboundLink.handleNewRequest(HttpInboundLink.java:515) atcom.ibm.ws.http.channel.inbound.impl.HttpInboundLcessRequest(HttpInboundLink.java:300) atcom.ibm.ws.http.channel.inbound.impl.HttpICLReadCplete(HttpICLReadCallback.java:102) atcom.ibm.ws.tcp.channel.impl.AioReadCompletionListener.futureCompleted(AioReadCompletionListener.java:165) atcom.ibm.io.async.AbstractAsyncFuture.invokeCallback(AbstractAsyncFuture.java:217) atcom.ibm.io.async.AsyncChannelFuture.fireCompletionActions(AsyncChannelFuture.java:161) atcom.ibm.io.async.AsyncFpleted(AsyncFuture.java:136) atcom.ibm.io.async.ResultHplete(ResultHandler.java:196) atcom.ibm.io.async.ResultHandler.runEventProcessingLoop(ResultHandler.java:751) at com.ibm.io.async.ResultHandler$2.run(ResultHandler.java:881) atcom.ibm.ws.util.ThreadPool$Worker.run(ThreadPool.java:1560)Caused by: java.lang.OutOfMemoryError atcom.ibm.oti.vm.VM.initializeClassLoader(Native Method) atjava.lang.ClassLoader.(ClassLoader.java:114) atsun.reflect.ClassDefiner$1.run(ClassDefiner.java:60) atjava.security.AccessController.doPrivileged(AccessController.java:192) atsun.reflect.ClassDefiner.defineClass(ClassDefiner.java:57) atsun.reflect.MethodAccessorGenerator$1.run(MethodAccessorGenerator.java:399) atjava.security.AccessController.doPrivileged(AccessController.java:192) atsun.reflect.MethodAccessorGenerator.generate(MethodAccessorGenerator.java:395) atsun.reflect.MethodAccessorGenerator.generateSerializationConstructor(MethodAccessorGenerator.java:113) atsun.reflect.ReflectionFactory.newConstructorForSerialization(ReflectionFactory.java:341) atjava.io.ObjectStreamClass.getSerializableConstructor(ObjectStreamClass.java:1354) at java.io.ObjectStreamClass.access$1400(ObjectStreamClass.java:103) atjava.io.ObjectStreamClass$2.run(ObjectStreamClass.java:475) atjava.security.AccessController.doPrivileged(AccessController.java:192) atjava.io.ObjectStreamClass.(ObjectStreamClass.java:455) atjava.io.ObjectStreamClass.lookup(ObjectStreamClass.java:350) atjava.io.ObjectStreamClass.initNonProxy(ObjectStreamClass.java:586) atjava.io.ObjectInputStream.readNonProxyDesc(ObjectInputStream.java:1561) atjava.io.ObjectInputStream.readClassDesc(ObjectInputStream.java:1475) atjava.io.ObjectInputStream.readOrdinaryObject(ObjectInputStream.java:1708) atjava.io.ObjectInputStream.readObject0(ObjectInputStream.java:1314) atjava.io.ObjectInputStream.defaultReadFields(ObjectInputStream.java:1927) atjava.io.ObjectInputStream.readSerialData(ObjectInputStream.java:1851) atjava.io.ObjectInputStream.readOrdinaryObject(ObjectInputStream.java:1728) atjava.io.ObjectInputStream.readObject0(ObjectInputStream.java:1314) atjava.io.ObjectInputStream.readArray(ObjectInputStream.java:1643) atjava.io.ObjectInputStream.readObject0(ObjectInputStream.java:1308) atjava.io.ObjectInputStream.defaultReadFields(ObjectInputStream.java:1927) atjava.io.ObjectInputStream.readSerialData(ObjectInputStream.java:1851) atjava.io.ObjectInputStream.readOrdinaryObject(ObjectInputStream.java:1728) atjava.io.ObjectInputStream.readObject0(ObjectInputStream.java:1314) atjava.io.ObjectInputStream.defaultReadFields(ObjectInputStream.java:1927) at java.io.ObjectInputStream.readSerialData(ObjectInputStream.java:1851) atjava.io.ObjectInputStream.readOrdinaryObject(ObjectInputStream.java:1728) atjava.io.ObjectInputStream.readObject0(ObjectInputStream.java:1314) atjava.io.ObjectInputStream.readObject(ObjectInputStream.java:354) atcom.ibm.ws.naming.util.Serialization$1.run(Serialization.java:106) atcom.ibm.ws.security.util.AccessController.doPrivileged(AccessController.java:118) at com.ibm.ws.naming.util.Serialization.deserializeObject(Serialization.java:102) atcom.ibm.ws.naming.util.HcessSerializedObjectForLookupExt(Helpers.java:795) . 56moreOutOfMemoryError！又见OutOfMemoryError，哥的眼睛不敢相信，又是这个头疼的问题，这让哥情何以堪呐！无奈之下，只得开始重头找问题。此次在was目录下并未发现常见OutOfMemoryError发生时自动产生的heapdump文件，kill -3也只生成了javacore文件，于是打开仅有的javacore文件。 IBM Thread andMonitor DumpAnalyzer for Java下查看javacore的内存统计：并未发现有OutOfMemory的迹象，这是什么情况？打开GC日志： 哥迷茫了，堆内存的使用并未出现异常情况，相对于1536m的Maximum Java heap， 只能说这条曲线相当的正常。仔细查看javacore，希望能找到点蛛丝马迹，发现如下提示： NOTE: Only for Java 5.0 Service Refresh 4 (build date:February 1st, 2007) and older. When you use delegated class loaders, the JVM can create a large number of ClassLoader objects. On IBM Java 5.0 Service Refresh 4 and older, the number of class loaders that are permitted is limited to 8192 by default and an OutOfMemoryError exception is thrown when this limit is exceeded. Use the -Xmxcl parameter to increase the number of class loaders allowed to avoid this problem, for example to 25000, by setting -Xmxcl25000, until the problem is resolved.Please examine the current thread stack trace to check whether a class loader is being loaded if there is an OutOfMemoryError. For example, the following stack trace indicates that a class loader is being loaded:at com/ibm/oti/vm/VM.initializeClassLoader(Native Method)at java/lang/ClassLoader.(ClassLoader.java:120)原来IBM JDK中对class loaders的数量有限制，而Java 5.0 ServiceRefresh 4及更早版本中这个限制的值默认是8192，如果超过这个值，就可能会报错：OutOfMemoryError。会不会跟这个有关系呢？首先验证jdk的版本，javacore中有标识： Java version : J2RE 5.0 IBM J9 2.3 AIX ppc64-64 build j9vmap6423-20060504 Virtual machine version : VM build 20060501_06428_BHdSMr Just-In-Time(JIT) compiler switch, Ahead-Of-Time (AOT) compiler switch, Compiler version : JIT enabled - 20060428_1800_r8Jdk是06年5月版本的符合这个情况，接下来得知道java heap中的class loaders的数量有多少个，在javacore中找到如下： Number of loaded classes in Java heap : 25,953 Number of classloaders in Java heap: 8,153很明显，java heap中的classloaders数量并未超过8192的限制，虽然不能证明是这个问题引起的，但是两个数字差距不大，不过也还是只能心存疑点的向其他的方向找线索。笔者仔细整理了下现在即