昨天下午4:30,系统发生了有史以来最刺激的崩溃,一开始是2台挂了(线上共5台),这个基本上很少见,一般情况下都是偶尔一台挂掉。
赶紧手动重启,搞笑的是重启起来的机器里马也挂了,结果就出现了一种尴尬的局面,我们不停的重启,机器不断地报警,不断地挂,整个过程持续了20多分钟。
其实上个礼拜系统就挂过两次,第1次挂了无任何信息没有出现常见的hs*.log这样的jvm crash日志,cpu、内存、流量等指标也没有异常,打算打开ulimit -c 获取系统core,还没弄上去第二次crash又发生了,于是把所有能看得日志都查了一遍,也在/var/log/messages中找到了
"Jul510:25:46cms-web1kernel:java[24016]:segfaultat00000000457ebd28rip00002aaab75a35cdrsp00000000457ebd10error6"
臭名昭著的segfault出现了,于是赶紧在每台机器加上了ulimit -c unlimited
20分钟的忙碌终于过去了,于是赶紧分析core日志
gdb java core-java-**.log
看到重要信息
Corewasgeneratedby`/usr/xx/java/bin/java-Dprogram.name=run.sh-server-Xmx2g-Xms2g-Xmn512m'.
Programterminatedwithsignal11,Segmentationfault.
接下来通过gdb的bt看栈信息
(gdb)bt
#00x00002aaab6cc75cdinJava_java_net_SocketOutputStream_socketWrite0()from/usr/xx/install/jdk1.6.0_25/jre/lib/amd64/libnet.so
#10x00002aaaab041b0cin??()
#20x0000000000000000in??()
只能看到最后在访问网络的时候挂了,但栈信息太少了
于是通过jstack/path/to/javacoredumpfile 终于看到了有用的信息
Thread26089:(state=IN_NATIVE)
-java.net.SocketOutputStream.socketWrite0(java.io.FileDescriptor,byte[],int,int)@bci=0(Interpretedframe)
-java.net.SocketOutputStream.socketWrite(byte[],int,int)@bci=44,line=92(Interpretedframe)
-java.net.SocketOutputStream.write(byte[],int,int)@bci=4,line=136(Interpretedframe)
-oracle.net.ns.DataPacket.send(int)@bci=50(Interpretedframe)
-oracle.net.ns.NetOutputStream.flush()@bci=15(Interpretedframe)
-oracle.net.ns.NetInputStream.getNextPacket()@bci=41(Interpretedframe)
-oracle.net.ns.NetInputStream.read(byte[],int,int)@bci=33(Compiledframe)
-oracle.net.ns.NetInputStream.read(byte[])@bci=5(Compiledframe)
-oracle.net.ns.NetInputStream.read()@bci=5(Compiledframe)
-oracle.jdbc.driver.T4CMAREngine.unmarshalUB1()@bci=6,line=1099(Compiledframe)
-oracle.jdbc.driver.T4CMAREngine.unmarshalSB1()@bci=1,line=1070(Interpretedframe)
-oracle.jdbc.driver.T4C8Oall.receive()@bci=52,line=478(Interpretedframe)
-oracle.jdbc.driver.T4CPreparedStatement.doOall8(boolean,boolean,boolean,boolean)@bci=619,line=216(Interpretedframe)
-oracle.jdbc.driver.T4CPreparedStatement.executeForRows(boolean)@bci=16,line=955(Interpretedframe)
-oracle.jdbc.driver.OracleStatement.executeMaybeDescribe()@bci=154,line=1060(Interpretedframe)
-oracle.jdbc.driver.T4CPreparedStatement.executeMaybeDescribe()@bci=11,line=839(Interpretedframe)
-oracle.jdbc.driver.OracleStatement.doExecuteWithTimeout()@bci=132,line=1132(Interpretedframe)
-oracle.jdbc.driver.OraclePreparedStatement.executeInternal()@bci=94,line=3316(Interpretedframe)
-oracle.jdbc.driver.OraclePreparedStatement.executeQuery()@bci=17,line=3361(Interpretedframe)
-com.xx.druid.filter.FilterChainImpl.preparedStatement_executeQuery(com.xx.druid.proxy.jdbc.PreparedStatementProxy)@bci=29,line=2564(Interpretedframe)
-com.xx.druid.filter.FilterAdapter.preparedStatement_executeQuery(com.xx.druid.filter.FilterChain,com.xx.druid.proxy.jdbc.PreparedStatementProxy)@bci=2,line=931(Interpretedframe)
-com.xx.druid.filter.FilterEventAdapter.preparedStatement_executeQuery(com.xx.druid.filter.FilterChain,com.xx.druid.proxy.jdbc.PreparedStatementProxy)@bci=14,line=459(Interpretedframe)
-com.xx.druid.filter.FilterChainImpl.preparedStatement_executeQuery(com.xx.druid.proxy.jdbc.PreparedStatementProxy)@bci=17,line=2561(Interpretedframe)
-com.xx.druid.proxy.jdbc.PreparedStatementProxyImpl.executeQuery()@bci=5,line=83(Interpretedframe)
-org.jboss.resource.adapter.jdbc.CachedPreparedStatement.executeQuery()@bci=4,line=90(Interpretedframe)
-org.jboss.resource.adapter.jdbc.WrappedPreparedStatement.executeQuery()@bci=12,line=236(Interpretedframe)
-com.xx.china.cmshollywood.cms.engine.resourceloader.PreviewTemplateResourceLoader.getResourceStream(java.lang.String)@bci=80,line=65(Interpretedframe)
-org.apache.velocity.Template.process()@bci=20,line=98(Interpretedframe)
-com.xx.china.cmshollywood.cms.engine.resourceloader.PreviewResourceManagerImpl.loadResource(java.lang.String,int,java.lang.String)@bci=115,line=116(Interpretedframe)
-org.apache.velocity.runtime.resource.ResourceManagerImpl.getResource(java.lang.String,int,java.lang.String)@bci=132,line=354(Interpretedframe)
-org.apache.velocity.runtime.RuntimeInstance.getTemplate(java.lang.String,java.lang.String)@bci=11,line=1400(Interpretedframe)
-org.apache.velocity.runtime.RuntimeInstance.getTemplate(java.lang.String)@bci=6,line=1380(Interpretedframe)
-org.apache.velocity.app.VelocityEngine.getTemplate(java.lang.String)@bci=5,line=401(Interpretedframe)
-com.xx.china.cmshollywood.cms.engine.DefaultVelocityTemplateEngine.mergeTemplate(org.apache.velocity.context.Context,java.lang.String,int)@bci=15,line=415(Interpretedframe)
-com.xx.china.cmshollywood.cms.engine.DefaultVelocityTemplateEngine.previewTemplate(java.util.Map,java.lang.String,int)@bci=13,line=310(Interpretedframe)
-com.xx.china.cmshollywood.cms.biz.tdprender.OfferRender.getOfferAndTradeInfoByOfferIds(java.lang.String,java.lang.String,java.lang.String,java.lang.String)@bci=129,line=275(Interpretedframe)
-sun.reflect.GeneratedMethodAccessor283.invoke(java.lang.Object,java.lang.Object[])@bci=64(Interpretedframe)
-sun.reflect.DelegatingMethodAccessorImpl.invoke(java.lang.Object,java.lang.Object[])@bci=6,line=25(Compiledframe)
-java.lang.reflect.Method.invoke(java.lang.Object,java.lang.Object[])@bci=161,line=597(Compiledframe)
-org.apache.velocity.util.introspection.UberspectImpl$VelMethodImpl.doInvoke(java.lang.Object,java.lang.Object[])@bci=6,line=389(Interpretedframe)
-org.apache.velocity.util.introspection.UberspectImpl$VelMethodImpl.invoke(java.lang.Object,java.lang.Object[])@bci=66,line=378(Interpretedframe)
-org.apache.velocity.runtime.parser.node.ASTMethod.execute(java.lang.Object,org.apache.velocity.context.InternalContextAdapter)@bci=449,line=270(Interpretedframe)
-org.apache.velocity.runtime.parser.node.ASTReference.execute(java.lang.Object,org.apache.velocity.context.InternalContextAdapter)@bci=192,line=252(Compiledframe)
-org.apache.velocity.runtime.parser.node.ASTReference.render(org.apache.velocity.context.InternalContextAdapter,java.io.Writer)@bci=30,line=332(Interpretedframe)
-org.apache.velocity.runtime.parser.node.SimpleNode.render(org.apache.velocity.context.InternalContextAdapter,java.io.Writer)@bci=21,line=336(Interpretedframe)
-org.apache.velocity.Template.merge(org.apache.velocity.context.Context,java.io.Writer,java.util.List)@bci=251,line=328(Interpretedframe)
-org.apache.velocity.Template.merge(org.apache.velocity.context.Context,java.io.Writer)@bci=4,line=235(Interpretedframe)
-com.xx.china.cmshollywood.cms.engine.DefaultVelocityTemplateEngine.mergeTemplate(org.apache.velocity.context.Context,java.lang.String,int)@bci=25,line=416(Interpretedframe)
-com.xx.china.cmshollywood.cms.engine.DefaultVelocityTemplateEngine.previewTemplate(java.util.Map,java.lang.String,int)@bci=13,line=310(Interpretedframe)
-com.xx.china.cmshollywood.cms.biz.tdprender.OfferRender.getOfferAndTradeInfoByOfferIds(java.lang.String,java.lang.String,java.lang.String,java.lang.String)@bci=129,line=275(Interpretedframe)
-sun.reflect.GeneratedMethodAccessor283.invoke(java.lang.Object,java.lang.Object[])@bci=64(Interpretedframe)
-sun.reflect.DelegatingMethodAccessorImpl.invoke(java.lang.Object,java.lang.Object[])@bci=6,line=25(Compiledframe)
-java.lang.reflect.Method.invoke(java.lang.Object,java.lang.Object[])@bci=161,line=597(Compiledframe)
-org.apache.velocity.util.introspection.UberspectImpl$VelMethodImpl.doInvoke(java.lang.Object,java.lang.Object[])@bci=6,line=389(Interpretedframe)
-org.apache.velocity.util.introspection.UberspectImpl$VelMethodImpl.invoke(java.lang.Object,java.lang.Object[])@bci=66,line=378(Interpretedframe)
-org.apache.velocity.runtime.parser.node.ASTMethod.execute(java.lang.Object,org.apache.velocity.context.InternalContextAdapter)@bci=449,line=270(Interpretedframe)
-org.apache.velocity.runtime.parser.node.ASTReference.execute(java.lang.Object,org.apache.velocity.context.InternalContextAdapter)@bci=192,line=252(Compiledframe)
-org.apache.velocity.runtime.parser.node.ASTReference.render(org.apache.velocity.context.InternalContextAdapter,java.io.Writer)@bci=30,line=332(Interpretedframe)
-org.apache.velocity.runtime.parser.node.SimpleNode.render(org.apache.velocity.context.InternalContextAdapter,java.io.Writer)@bci=21,line=336(Interpretedframe)
-org.apache.velocity.Template.merge(org.apache.velocity.context.Context,java.io.Writer,java.util.List)@bci=251,line=328(Interpretedframe)
-org.apache.velocity.Template.merge(org.apache.velocity.context.Context,java.io.Writer)@bci=4,line=235(Interpretedframe)
-com.xx.china.cmshollywood.cms.engine.DefaultVelocityTemplateEngine.mergeTemplate(org.apache.velocity.context.Context,java.lang.String,int)@bci=25,line=416(Interpretedframe)
-com.xx.china.cmshollywood.cms.engine.DefaultVelocityTemplateEngine.previewTemplate(java.util.Map,java.lang.String,int)@bci=13,line=310(Interpretedframe)
-com.xx.china.cmshollywood.cms.biz.tdprender.OfferRender.getOfferAndTradeInfoByOfferIds(java.lang.String,java.lang.String,java.lang.String,java.lang.String)@bci=129,line=275(Interpretedframe)
............
标绿的这段代码执行了101次,整个栈的长度到1500层,看上去是进入一个循环递归的过程,导致最后栈溢出挂掉
于是接下来开始查找代码,发现了问题
在一个velocity的模板a.vm中写了一段代码$xxmethod("a.vm","params")
这个方法会获取数据在渲染a.vm,于是造成了死循环,这个死循环连jvm都未感知到就被操作系统给终结了
小结
- 看起来velocity必须小心使用
- 获取core日志也是必须的,否则没那么容易定位问题
- 系统挂的时候在访问网络,这个会让人误解为在访问网络出了什么问题(虽然很多时候都是挂的时候的最后那个方法出了问题),其实此时只是系统在常规的压栈,但碰巧在这个时候,栈溢出了