公众号

JDBC内存溢出 排查经历

- - 阅 219

 

转自:https://www.jianshu.com/p/2284b28e47df

 

一、好言

熬得住就出众,熬不住就出局,相信糟糕得日志熬过去了,剩下得就是好运气 。


二、背景

上周一晚上十点多,就开始MQ消息累积然后报警,运维早上找我看,那些消息累积了,然后运维重启服务后消息就消费了,然后过一会又累积了,到上午十一点多的时候,开始报内存过高,然后发现已经又两台服务已经挂了,看了日志,有错误,但是没有很多可用的错误。所以重启,吃完饭服务又挂了,jconsole看到结果如下图:

jconsole-1.png

然后下午的时候内存的爆发简直更加频繁了

jsonsole-2

三:解决

3.1、内容

出现内存溢出问题,所以肯定首要需要dump内存溢出文件,所以先让运维导出*.hprof 文件,然后我也查看日志文件,我们使用kibana进行日志统计了,所以查看其中错误日志,的确又很多错误的信息,redis错误,MQ错误,还有mysql错误。

org.springframework.dao.QueryTimeoutException: Redis command timed out; nested exception is com.lambdaworks.redis.RedisCommandTimeoutException: Command timed out
    at org.springframework.data.redis.connection.lettuce.LettuceExceptionC
onverter.convert(LettuceExceptionConverter.java:66)
    at org.springframework.data.redis.connection.lettuce.LettuceExceptionC
onverter.convert(LettuceExceptionConverter.java:41)
    at org.springframework.data.redis.PassThroughExceptionTranslationStr
ategy.translate(PassThroughExceptionTranslationStrategy.java:37)
[ActiveMQ Transport: tcp://mqtest.com/10.10.10.10:6161@123] org.apache.activemq.transport.failover.FailoverTransport - Transport (tcp://mqtest.com/10.10.10.10:6161) failed, attempting to automatically reconnect
java.io.IOException: Unexpected error occurred: java.lang.OutOfMemoryError: Java heap space
    at org.apache.activemq.transport.tcp.TcpTransport.run(TcpTransport.java:222)
    at java.lang.Thread.run(Thread.java:745)
Caused by: java.lang.OutOfMemoryError: Java heap space

如上两个认为是内存溢出了,造成没有内存可使用没法开线程处理。
看看下面mysql错误

### Cause: com.mysql.jdbc.exceptions.jdbc4.MySQLTransactionRollbackExceptio
n: Lock wait timeout exceeded; try restarting transaction
; SQL []; Lock wait timeout exceeded; try restarting transaction; 
nested exception is 
com.mysql.jdbc.exceptions.jdbc4.MySQLTransactionRollbackExceptio
n: Lock wait timeout exceeded; try restarting transaction
    at org.springframework.jdbc.support.SQLErrorCodeSQLExceptionTransl
ator.doTranslate(SQLErrorCodeSQLExceptionTranslator.java:259)
    at org.springframework.jdbc.support.AbstractFallbackSQLExceptionTran
slator.translate(AbstractFallbackSQLExceptionTranslator.java:73)
    at org.mybatis.spring.MyBatisExceptionTranslator.translateExceptionIfP
ossible(MyBatisExceptionTranslator.java:74)
    at org.mybatis.spring.SqlSessionTemplate$SqlSessionInterceptor.invoke
(SqlSessionTemplate.java:421)
    at com.sun.proxy.$Proxy31.update(Unknown Source)
    at org.mybatis.spring.SqlSessionTemplate.update(SqlSessionTemplate.j
ava:270)
    at org.apache.ibatis.binding.MapperMethod.execute(MapperMethod.java:55)
    at org.apache.ibatis.binding.MapperProxy.invoke(MapperProxy.java:53)
    at com.sun.proxy.$Proxy55.updateByPrimaryKey(Unknown 
Source)
    at com.mouse.moon.app.service.Userervice.update(
UserService.java:26)
    at com.mouse.moon.app.service.Userervice$$FastClassBySpringCGLIB$$3eb1bfc8.invoke(<generated>)
    at org.springframework.cglib.proxy.MethodProxy.invoke(MethodProxy.java:204)
    at org.springframework.aop.framework.CglibAopProxy$CglibMethodInvocation.invokeJoinpoint(CglibAopProxy.java:720)
    at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:157)
    at org.springframework.transaction.interceptor.TransactionInterceptor$1.
proceedWithInvocation(TransactionInterceptor.java:99)
    at org.springframework.transaction.interceptor.TransactionAspectSuppor
t.invokeWithinTransaction(TransactionAspectSupport.java:281)
    at org.springframework.transaction.interceptor.TransactionInterceptor.inv
oke(TransactionInterceptor.java:96)
    at org.springframework.aop.framework.ReflectiveMethodInvocation.proc
eed(ReflectiveMethodInvocation.java:179)
    at org.springframework.aop.framework.CglibAopProxy$DynamicAdvised
Interceptor.intercept(CglibAopProxy.java:655)
    at com.mouse.moon.app.service.UserService$$EnhancerBySpringCGLIB$$31a8197.update(<generated>)
    at com.mouse.moon.app.service.userService.dealUser(MobileAppRegisterService.java:154)
    at com.mouse.moon.app.service.UserService.(userService.java:104)
    at com.mouse.moon.app.service.UserService$$FastClassBySpringCGLIB$$a99b8cf4.invoke(<generated>)
    at org.springframework.cglib.proxy.MethodProxy.invoke(MethodProxy.java:204)
    at org.springframework.aop.framework.CglibAopProxy$CglibMethodInvocation.invokeJoinpoint(CglibAopProxy.java:720)
    at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:157)
    at org.springframework.transaction.interceptor.TransactionInterceptor$1.proceedWithInvocation(TransactionInterceptor.java:99)
    at org.springframework.transaction.interceptor.TransactionAspectSupport.invokeWithinTransaction(TransactionAspectSupport.java:281)
    at org.springframework.transaction.interceptor.TransactionInterceptor.invoke(TransactionInterceptor.java:96)
    at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:179)
    at org.springframework.aop.interceptor.AsyncExecutionInterceptor$1.call(AsyncExecutionInterceptor.java:115)
    at java.util.concurrent.FutureTask.run(FutureTask.java:262)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
    at java.lang.Thread.run(Thread.java:745)
Caused by: com.mysql.jdbc.exceptions.jdbc4.MySQLTransactionRollbackException: Lock wait timeout exceeded; try restarting transaction
    at sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method)
    at sun.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:57)
    at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45)
    at java.lang.reflect.Constructor.newInstance(Constructor.java:526)
    at com.mysql.jdbc.Util.handleNewInstance(Util.java:404)
    at com.mysql.jdbc.Util.getInstance(Util.java:387)
    at com.mysql.jdbc.SQLError.createSQLException(SQLError.java:946)
    at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:3878)
    at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:3814)
    at com.mysql.jdbc.MysqlIO.sendCommand(MysqlIO.java:2478)
    at com.mysql.jdbc.MysqlIO.sqlQueryDirect(MysqlIO.java:2625)
    at com.mysql.jdbc.ConnectionImpl.execSQL(ConnectionImpl.java:2551)
    at com.mysql.jdbc.MultiHostMySQLConnection.execSQL(MultiHostMySQLConnection.java:157)
    at sun.reflect.GeneratedMethodAccessor306.invoke(Unknown Source)
    at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
    at java.lang.reflect.Method.invoke(Method.java:606)
    at com.mysql.jdbc.LoadBalancedConnectionProxy.invokeMore(LoadBalancedConnectionProxy.java:484)
    at com.mysql.jdbc.MultiHostConnectionProxy.invoke(MultiHostConnectionProxy.java:452)
    at com.sun.proxy.$Proxy63.execSQL(Unknown Source)
    at com.mysql.jdbc.MultiHostMySQLConnection.execSQL(MultiHostMySQLConnection.java:157)
    at com.mysql.jdbc.PreparedStatement.executeInternal(PreparedStatement.java:1861)
    at com.mysql.jdbc.PreparedStatement.execute(PreparedStatement.java:1192)
    at sun.reflect.GeneratedMethodAccessor314.invoke(Unknown Source)
    at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
    at java.lang.reflect.Method.invoke(Method.java:606)
    at com.mysql.jdbc.MultiHostConnectionProxy$JdbcInterfaceProxy.invoke(MultiHostConnectionProxy.java:103)
    at com.sun.proxy.$Proxy68.execute(Unknown Source)

这个地方的错误我在网上也搜过,其实基本是锁等待超时问题,这个一个同事之前遇到过,跟他交流了下,这个错误说明我的事物太大了,造成事物等待超时,并且有查处和更新相同数据造成的。这个现在想想这里代码的业务逻辑的确是存在这种问题,由于数据量大,如果按照现在的查询条件,地区会查询出相同数据,并且由于事物放在servicec层,在for循环中update数据的时候,会造成事物最后一起提交,所以造成锁等待超时问题。所以最后更新代码业务如下
1:对查询代码顺序做优化

List list = ...
if(符合条件){
   list = ...(select ...where)
}

由于数据库数据量有4500w左右,上述代码先查询,然后再判断条件,所以有可能会查询两次数据库,所以代码优化,处理代码顺序,先判断条件。

2:对加在service的事物移动到dao层,每次更新一次提交一次,把事物缩小。

3:对于一些处理可以做异步处理

4:做限流操作(使用hystrix做限流)

5:<a href =”http://www.jianshu.com/p/82c27c58e0b6″>对消费做消费速度限制</a>

3.2:dump文件分析
由于之前系统是假死状态,每次冲上去之后,过十几分钟或者半小时后,可能又会慢慢回收。所以每次爆的时候并没有dump文件,<a href=”http://www.jianshu.com/p/05e9f46e3f09″>脚本</a>
每次没dump,最后我们在内存上升期间,只用使用

#查看内存
jmap -heap pid 
jmap -dump:format=b,file=$dumpfile pid
图片.png

导出文件,查看如下

图1.png

上图是在没有处理完sql错误时倒出的hprof文件。
下图是处理完sql异常导出的文件

图2.png

图二我们可以看到一个很大的对象,就是我画红色的部分,点进去看,有三百多万个对象,占用内存三百多兆,并且我们看到老年代使用的量特别大,基本没回收样。怎么会有这么大的对象了,根据对象我们找到代码位置,确定是查询问题,造成大量对象产生,并且也是之前大量更新,并且数据有重复的概率,所以造成占用大量内存。其实这种发生也是要有数据量的情况下才会出现,发生溢出.下面几张是检测到的日志信息数据:

log-1.png
log-2.png
log-3.png

最后简单总结下处理的过程,首先需要排除所有可能造成该问题的问题,也就是先解决掉看到的错误,然后查看导出dump文件中的大对象,根据大对象查看代码,进一步分析问题。其实在这个中间,做了很多各种处理看效果,比如MQ限流消费处理等。但是现在看来,最终原因应该还是出在数据库层面。

四:感触

其实之前没怎么解决过内存溢出问题,这算是自己第一次全程经历此次内存溢出并解决,不过首先说,这代码并不是我写的代码,是我被按排接手的项目,所以还的感谢这之前写这代码的人,才使得我有这么一次经历,通过这次经历,也会让自己对于一个内存溢出问题的解决思路更佳清晰,思考问题更佳全面,处理问题更佳稳重,并且对于一些工具的使用,比如MAT,Jprofile有了接触。所以有些经历真的是不可求的。因此才有了经验之说。努力吧,骚年。

作者:吴世浩
链接:https://www.jianshu.com/p/2284b28e47df
來源:简书
著作权归作者所有。商业转载请联系作者获得授权,非商业转载请注明出处。

0

本文转载 " "

原文地址 " "

相关文章!