20170718一次内存溢出排查经历

一、好言

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

---

二、背景

上周一晚上十点多，就开始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有了接触。所以有些经历真的是不可求的。因此才有了经验之说。努力吧，骚年。