记一次MySQL连接超时问题 - removeAbandonedTimeout

空歌白石丶
986 阅读7分钟

问题

生产上有个应用上线已经有一年多了，但是某天突然服务频繁的抛出org.mybatis.spring.MyBatisSystemException的异常，于是决定探究一下究竟是什么原因造成的。

org.mybatis.spring.MyBatisSystemException: nested exception is org.apache.ibatis.executor.result.ResultMapException: Error attempting to get column 'id' from result set.  Cause: java.lang.NullPointerException
	at org.mybatis.spring.MyBatisExceptionTranslator.translateExceptionIfPossible(MyBatisExceptionTranslator.java:77)
	at org.mybatis.spring.SqlSessionTemplate$SqlSessionInterceptor.invoke(SqlSessionTemplate.java:446)
	at com.sun.proxy.$Proxy102.selectList(Unknown Source)
	at org.mybatis.spring.SqlSessionTemplate.selectList(SqlSessionTemplate.java:230)
	at org.apache.ibatis.binding.MapperMethod.executeForMany(MapperMethod.java:139)
	at org.apache.ibatis.binding.MapperMethod.execute(MapperMethod.java:76)
	at org.apache.ibatis.binding.MapperProxy.invoke(MapperProxy.java:59)
	at com.sun.proxy.$Proxy106.queryAllByIdRanges(Unknown Source)
	at sun.reflect.GeneratedMethodAccessor252.invoke(Unknown Source)
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
	at java.lang.reflect.Method.invoke(Method.java:498)
	at org.springframework.aop.support.AopUtils.invokeJoinpointUsingReflection(AopUtils.java:333)
	at org.springframework.aop.framework.ReflectiveMethodInvocation.invokeJoinpoint(ReflectiveMethodInvocation.java:190)
	at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:157)
	at org.springframework.dao.support.PersistenceExceptionTranslationInterceptor.invoke(PersistenceExceptionTranslationInterceptor.java:136)
	at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:179)
	at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:213)
	at com.sun.proxy.$Proxy107.queryAllByIdRanges(Unknown Source)
	// 空歌白石：省略业务堆栈
	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:282)
	at org.springframework.transaction.interceptor.TransactionInterceptor.invoke(TransactionInterceptor.java:96)
	at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:179)
	at org.springframework.aop.framework.CglibAopProxy$DynamicAdvisedInterceptor.intercept(CglibAopProxy.java:655)
	// 空歌白石：省略业务堆栈
	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
	at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
	at java.lang.reflect.Method.invoke(Method.java:498)
	// 空歌白石：省略业务堆栈
	at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
	at java.util.concurrent.FutureTask.run(FutureTask.java:266)
	// 空歌白石：省略业务堆栈
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
	at java.lang.Thread.run(Thread.java:748)
Caused by: org.apache.ibatis.executor.result.ResultMapException: Error attempting to get column 'id' from result set.  Cause: java.lang.NullPointerException
	at org.apache.ibatis.type.BaseTypeHandler.getResult(BaseTypeHandler.java:68)
	at org.apache.ibatis.executor.resultset.DefaultResultSetHandler.applyAutomaticMappings(DefaultResultSetHandler.java:520)
	at org.apache.ibatis.executor.resultset.DefaultResultSetHandler.getRowValue(DefaultResultSetHandler.java:401)
	at org.apache.ibatis.executor.resultset.DefaultResultSetHandler.handleRowValuesForSimpleResultMap(DefaultResultSetHandler.java:355)
	at org.apache.ibatis.executor.resultset.DefaultResultSetHandler.handleRowValues(DefaultResultSetHandler.java:330)
	at org.apache.ibatis.executor.resultset.DefaultResultSetHandler.handleResultSet(DefaultResultSetHandler.java:303)
	at org.apache.ibatis.executor.resultset.DefaultResultSetHandler.handleResultSets(DefaultResultSetHandler.java:196)
	at org.apache.ibatis.executor.statement.PreparedStatementHandler.query(PreparedStatementHandler.java:64)
	at org.apache.ibatis.executor.statement.RoutingStatementHandler.query(RoutingStatementHandler.java:79)
	at org.apache.ibatis.executor.SimpleExecutor.doQuery(SimpleExecutor.java:63)
	at org.apache.ibatis.executor.BaseExecutor.queryFromDatabase(BaseExecutor.java:326)
	at org.apache.ibatis.executor.BaseExecutor.query(BaseExecutor.java:156)
	at org.apache.ibatis.executor.BaseExecutor.query(BaseExecutor.java:136)
	at org.apache.ibatis.session.defaults.DefaultSqlSession.selectList(DefaultSqlSession.java:148)
	at org.apache.ibatis.session.defaults.DefaultSqlSession.selectList(DefaultSqlSession.java:141)
	at sun.reflect.GeneratedMethodAccessor253.invoke(Unknown Source)
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
	at java.lang.reflect.Method.invoke(Method.java:498)
	at org.mybatis.spring.SqlSessionTemplate$SqlSessionInterceptor.invoke(SqlSessionTemplate.java:433)
	... 50 more
Caused by: java.lang.NullPointerException
	at com.mysql.jdbc.ResultSetImpl.findColumn(ResultSetImpl.java:1044)
	at com.mysql.jdbc.ResultSetImpl.getLong(ResultSetImpl.java:2757)
	at sun.reflect.GeneratedMethodAccessor227.invoke(Unknown Source)
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
	at java.lang.reflect.Method.invoke(Method.java:498)
	at org.apache.ibatis.logging.jdbc.ResultSetLogger.invoke(ResultSetLogger.java:68)
	at com.sun.proxy.$Proxy130.getLong(Unknown Source)
	at org.apache.ibatis.type.LongTypeHandler.getNullableResult(LongTypeHandler.java:37)
	at org.apache.ibatis.type.LongTypeHandler.getNullableResult(LongTypeHandler.java:26)
	at org.apache.ibatis.type.BaseTypeHandler.getResult(BaseTypeHandler.java:66)
	... 68 more

除以上异常外，还包含另外一个java.sql.SQLException: Connection has already been closed.的异常，核心堆栈和上述异常堆栈基本一致，但是可以看出是mybatis抛出的，而上述异常是应用自己主动catch的异常堆栈。

Application exception overridden by rollback exception
org.springframework.jdbc.UncategorizedSQLException: 
### Error updating database.  Cause: java.sql.SQLException: Connection has already been closed.
// 空歌白石：省略业务堆栈
### Cause: java.sql.SQLException: Connection has already been closed.
; uncategorized SQLException for SQL []; SQL state [null]; error code [0]; Connection has already been closed.; nested exception is java.sql.SQLException: Connection has already been closed.
	at org.springframework.jdbc.support.AbstractFallbackSQLExceptionTranslator.translate(AbstractFallbackSQLExceptionTranslator.java:84)
	at org.springframework.jdbc.support.AbstractFallbackSQLExceptionTranslator.translate(AbstractFallbackSQLExceptionTranslator.java:81)
	at org.springframework.jdbc.support.AbstractFallbackSQLExceptionTranslator.translate(AbstractFallbackSQLExceptionTranslator.java:81)
	at org.mybatis.spring.MyBatisExceptionTranslator.translateExceptionIfPossible(MyBatisExceptionTranslator.java:73)
	at org.mybatis.spring.SqlSessionTemplate$SqlSessionInterceptor.invoke(SqlSessionTemplate.java:446)
	at com.sun.proxy.$Proxy102.update(Unknown Source)
	at org.mybatis.spring.SqlSessionTemplate.update(SqlSessionTemplate.java:294)
	at org.apache.ibatis.binding.MapperMethod.execute(MapperMethod.java:63)
	at org.apache.ibatis.binding.MapperProxy.invoke(MapperProxy.java:59)
	at com.sun.proxy.$Proxy108.update(Unknown Source)
	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
	at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
	at java.lang.reflect.Method.invoke(Method.java:498)
	at org.springframework.aop.support.AopUtils.invokeJoinpointUsingReflection(AopUtils.java:333)
	at org.springframework.aop.framework.ReflectiveMethodInvocation.invokeJoinpoint(ReflectiveMethodInvocation.java:190)
	at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:157)
	at org.springframework.dao.support.PersistenceExceptionTranslationInterceptor.invoke(PersistenceExceptionTranslationInterceptor.java:136)
	at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:179)
	at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:213)
	at com.sun.proxy.$Proxy109.update(Unknown Source)
	// 空歌白石：省略业务堆栈
	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:282)
	at org.springframework.transaction.interceptor.TransactionInterceptor.invoke(TransactionInterceptor.java:96)
	at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:179)
	at org.springframework.aop.framework.CglibAopProxy$DynamicAdvisedInterceptor.intercept(CglibAopProxy.java:655)
	// 空歌白石：省略业务堆栈
	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
	at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
	at java.lang.reflect.Method.invoke(Method.java:498)
	// 空歌白石：省略业务堆栈
	at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
	at java.util.concurrent.FutureTask.run(FutureTask.java:266)
	// 空歌白石：省略业务堆栈
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
	at java.lang.Thread.run(Thread.java:748)
Caused by: java.sql.SQLException: Connection has already been closed.
	at org.apache.tomcat.jdbc.pool.ProxyConnection.invoke(ProxyConnection.java:117)
	at org.apache.tomcat.jdbc.pool.JdbcInterceptor.invoke(JdbcInterceptor.java:109)
	at org.apache.tomcat.jdbc.pool.interceptor.AbstractCreateStatementInterceptor.invoke(AbstractCreateStatementInterceptor.java:67)
	at org.apache.tomcat.jdbc.pool.JdbcInterceptor.invoke(JdbcInterceptor.java:109)
	at org.apache.tomcat.jdbc.pool.interceptor.ConnectionState.invoke(ConnectionState.java:153)
	at org.apache.tomcat.jdbc.pool.JdbcInterceptor.invoke(JdbcInterceptor.java:109)
	at org.apache.tomcat.jdbc.pool.TrapException.invoke(TrapException.java:41)
	at org.apache.tomcat.jdbc.pool.JdbcInterceptor.invoke(JdbcInterceptor.java:109)
	at org.apache.tomcat.jdbc.pool.DisposableConnectionFacade.invoke(DisposableConnectionFacade.java:80)
	at com.sun.proxy.$Proxy126.prepareStatement(Unknown Source)
	// 空歌白石：省略业务堆栈
	at org.apache.ibatis.executor.statement.PreparedStatementHandler.instantiateStatement(PreparedStatementHandler.java:87)
	at org.apache.ibatis.executor.statement.BaseStatementHandler.prepare(BaseStatementHandler.java:88)
	at org.apache.ibatis.executor.statement.RoutingStatementHandler.prepare(RoutingStatementHandler.java:59)
	at org.apache.ibatis.executor.SimpleExecutor.prepareStatement(SimpleExecutor.java:85)
	at org.apache.ibatis.executor.SimpleExecutor.doUpdate(SimpleExecutor.java:49)
	at org.apache.ibatis.executor.BaseExecutor.update(BaseExecutor.java:117)
	at org.apache.ibatis.session.defaults.DefaultSqlSession.update(DefaultSqlSession.java:198)
	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
	at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
	at java.lang.reflect.Method.invoke(Method.java:498)
	at org.mybatis.spring.SqlSessionTemplate$SqlSessionInterceptor.invoke(SqlSessionTemplate.java:433)
	... 47 more

排查

最直观的，从堆栈来看，一开始认为是服务的代码被修改过，于是查看git上代码commit的记录，发现相关的.xml以及mapper近期并没有做过改动。

紧接着google相关的异常堆栈，很多人都在说此异常是因为没有配置无参构造方法引起，很多时候是因为lombok中缺少部分注解引起。

org.mybatis.spring.MyBatisSystemException: nested exception is org.apache.ibatis.executor.result.ResultMapException: Error attempting to get column 'id' from result set.  Cause: java.lang.NullPointerException

于是查看代码，发现我们业确实使用了lombok来生成getter、setter、以及NoArgsConstructor。由于已经还有NoArgsConstructor的注解，到这里可以排除是因为缺少无参构造方法的原因了。

@Getter
@Setter
@NoArgsConstructor

此时也有怀疑是否是lombok版本近期被升级过，但是确认相关代码后，发现也未进行升级。

到这里排查有些陷入僵局，感觉无从下手，后续也做了很多尝试，主要包括以下几个步骤：

  1. 将lombok注解去掉，手写getter、setter、NoArgsConstructor方法。
    • 重新发布后，无效。
  2. 怀疑是否因为数据原因导致NPE，于是减少批量查询的size。
    • 发现出问题的区间数据并不存在null值，而且每次尝试都是出问题的位置并不一致，这个尝试也是无效的。
  3. 增加每次查询的间隔
    • 在每次查询结束后，sleep一下，重新发布后，仍然无效。

但是上述尝试都是无效的。

定位到问题

经过上述的分析，已经代码层面排查后，基本可以确定并不是代码的原因引起的了。但是为什么又会有异常呢？于是决定通过debug的方法，跟踪到异常代码的位置，看下倒地是什么情况忽悠上述异常抛出。

打上断点，debug开始，但是执行了几次查询后，抛出了一个ConnectionException，这个链接超时的异常是MySQL的连接超时异常。一开始以为是debug原因引起的超时，但是后续想了下，我们需要读取的数据有1200W的数据，会不会一开始我们遇到的问题也是因为连接超时，导致mybatis只拿到了部分数据，因为在做ResultSet转换时，引起null呢？

于是我们做了一个尝试，就是修改app在datasource层面的removeAbandonedTimeout超时配置，从removeAbandonedTimeout=65调整为removeAbandonedTimeout=1800。

修改jdbc相关配置需要重启应用才能生效，于是我们将服务重启。

我们发现服务正常的运行了起来。至此上述的问题从应用层面得到解决。

DBCP连接池

当公司有团队专门负责数据库访问层的相关框架时，绝大部分情况下应用方式不用太过于关注MySQL的DataSource原生配置的，但是当table的数据量级达到一定规模后，一些DBA提供的默认配置实际上并不太适用了，就需要专门的进行针对性的优化和调整，我们这次遇到的问题是关于这方面的问题。

我们梳理下相关DataSource有哪些配置呢：

  • maxActive
    • 最大活动连接
    • 连接池在同一时间能够分配的最大活动连接的数量
    • 如果设置为非正数则表示不限制
    • 默认值：8
  • minIdle
    • 最小空闲连接
    • 连接池中容许保持空闲状态的最小连接数量,低于这个数量将创建新的连接
    • 如果设置为0则不创建
    • 默认值：0
  • maxIdle
    • 最大空闲连接
    • 连接池中容许保持空闲状态的最大连接数量,超过的空闲连接将被释放
    • 如果设置为负数表示不限制
    • 默认值：8
  • initialSize
    • 初始化连接数量
    • 默认值：0
  • logAbandoned
    • 连接被泄露时是否打印
    • 标记当Statement或连接被泄露时是否打印程序的stack traces日志。
    • 被泄露的Statements和连接的日志添加在每个连接打开或者生成新的Statement。因为需要生成stack trace。
    • 默认值：false
    • 一般生产环境都会设置为false。
  • removeAbandoned
    • 是否自动回收超时连接，标记是否删除泄露的连接
    • 如果他们超过了removeAbandonedTimout的限制.
      • 如果设置为true, 连接被认为是被泄露并且可以被删除
      • 设置为true可以为写法糟糕的没有关闭连接的程序修复数据库连接
    • 默认值：false
  • removeAbandonedTimeout
    • 泄露的连接可以被删除的超时值
    • 单位秒
  • maxWait
    • 最大等待时间:当没有可用连接时,连接池等待连接被归还的最大时间(以毫秒计数),超过时间则抛出异常
    • 如果设置为-1表示无限等待
    • 默认值：-1
  • timeBetweenEvictionRunsMillis
    • 在空闲连接回收器线程运行期间休眠的时间值,以毫秒为单位
    • 如果设置为非正数,则不运行空闲连接回收器线程
    • 默认值：-1
  • numTestsPerEvictionRun
    • 在每次空闲连接回收器线程(如果有)运行时检查的连接数量
    • 默认值：3
  • minEvictableIdleTimeMillis
    • 连接在池中保持空闲而不被空闲连接回收器线程
    • (如果有)回收的最小时间值，单位毫秒
    • 默认值：1000 * 60 * 30
  • maxAge
    • 超时等待时间以毫秒为单位
  • serverWaitTimeout
    • 超时等待时间以毫秒为单位
  • logValidationErrors
    • 超时等待时间以毫秒为单位
  • connectionProperties
    • 连接属性
      • sendTimeAsDateTime=false;
      • sendStringParametersAsUnicode=false;
      • rewriteBatchedStatements=true;
      • allowMultiQueries=true;
      • useUnicode=true;
      • characterEncoding=UTF-8;
      • useSSL=false;
      • socketTimeout=100000;
      • connectTimeout=1200;
      • loginTimeout=2
  • validationQuery
    • SQL查询,用来验证从连接池取出的连接,在将连接返回给调用者之前.如果指定,则查询必须是一个SQL SELECT并且必须返回至少一行记录
  • validationQueryTimeout
    • validationQuery的超时时长
  • testOnBorrow
    • 指明是否在从池中取出连接前进行检验,如果检验失败,则从池中去除连接并尝试取出另一个.
    • 设置为true后如果要生效,validationQuery参数必须设置为非空字符串
  • testOnReturn
    • 指明是否在归还到池中前进行检验
    • 注意: 设置为true后如果要生效,validationQuery参数必须设置为非空字符串
    • 默认值：false
  • testWhileIdle
    • 指明连接是否被空闲连接回收器(如果有)进行检验.如果检测失败,则连接将被从池中去除.
    • 注意: 设置为true后如果要生效,validationQuery参数必须设置为非空字符串
    • 默认值：false

推荐配置

testWhileIdle=false
testOnBorrow=true
testOnReturn=false

timeBetweenEvictionRunsMillis=5000
maxActive=100
minIdle=1
maxWait=4000
maxAge=28000000
initialSize=1

removeAbandonedTimeout=1800
removeAbandoned=true
// 空歌白石：如果需要可以打开，设置为true
logAbandoned=true

minEvictableIdleTimeMillis=30000
connectionProperties=sendTimeAsDateTime=false;sendStringParametersAsUnicode=false;rewriteBatchedStatements=true;allowMultiQueries=true;useUnicode=true;characterEncoding=UTF-8;useSSL=false;socketTimeout=100000;connectTimeout=1200;loginTimeout=2

serverWaitTimeout=120
logValidationErrors=false

validationQuery=SELECT 1
validationQueryTimeout=1
validationTimeoutMillis=250
validationInterval=30000
validatorClassName=执行验证的class类全名

总结

上述问题排查中可以发现从最初的exception很难定位到问题的根源。本次问题的解决机缘巧合发现了removeAbandonedTimeout设置过小的问题。这里还有了个问题，为什么连接超时被回收后，会在代码jdbc层面触发NPE的问题，还需要进一步的深挖源码。今天先写到这里吧。

参考文献

avatar
文章
阅读
粉丝