admin

- locked <0x000000008286bd98> (a com.mysql.jdbc.util.ReadAheadInputStream) 问题
前言很早之前给公司项目写了个晚上定时统计的任务,这几天又新增了一个需要每天统计的数据,所以打算直接加在之前的定时任...
扫描右侧二维码阅读全文
15
2018/08

- locked <0x000000008286bd98> (a com.mysql.jdbc.util.ReadAheadInputStream) 问题

前言

很早之前给公司项目写了个晚上定时统计的任务,这几天又新增了一个需要每天统计的数据,所以打算直接加在之前的定时任务里面。定时统计的 sql 都是经过测试后上线的,结果第二天就发现除了问题:统计的数据少了很多!

分析问题

由于这个定时统计的任务当时也做了个手动执行重新统计的功能,所以直接在系统上想手动执行统计任务先恢复线上的数据,结果,点了重新统计没有任何反应。无奈作罢,只能本地来调试了,直接拿线上的数据来触发统计任务,发现有时能够成功,有时不进行统计,也不报任何错误。
在添加统计任务的代码块打下断点,发现任务队列中的任务没被消费,那么问题很明显了,肯定是统计任务阻塞了,而代码中除了 sql 查询与插入,没有其他加锁的代码,并且还是单线程的。
然后直接 jstack 查看进程的线程信息,发现确实是 jdbc 数据库读取数据的时候阻塞了:

"Thread-10" #65 daemon prio=5 os_prio=0 tid=0x000000001a7a8800 nid=0x547c runnable [0x00000000267cc000]
   java.lang.Thread.State: RUNNABLE
    at java.net.SocketInputStream.socketRead0(Native Method)
    at java.net.SocketInputStream.socketRead(SocketInputStream.java:116)
    at java.net.SocketInputStream.read(SocketInputStream.java:171)
    at java.net.SocketInputStream.read(SocketInputStream.java:141)
    at com.mysql.jdbc.util.ReadAheadInputStream.fill(ReadAheadInputStream.java:100)
    at com.mysql.jdbc.util.ReadAheadInputStream.read(ReadAheadInputStream.java:205)
    at com.mysql.jdbc.MysqlIO.nextRowFast(MysqlIO.java:2074)
    at com.mysql.jdbc.MysqlIO.nextRow(MysqlIO.java:1964)
    at com.mysql.jdbc.MysqlIO.readSingleRowSet(MysqlIO.java:3306)
    at com.mysql.jdbc.MysqlIO.getResultSet(MysqlIO.java:463)
    at com.mysql.jdbc.MysqlIO.readResultsForQueryOrUpdate(MysqlIO.java:3040)
    at com.mysql.jdbc.MysqlIO.readAllResults(MysqlIO.java:2288)
    at com.mysql.jdbc.MysqlIO.sqlQueryDirect(MysqlIO.java:2681)
    at com.mysql.jdbc.ConnectionImpl.execSQL(ConnectionImpl.java:2551)
    - locked <0x0000000082a790d0> (a com.mysql.jdbc.JDBC4Connection)
    at com.mysql.jdbc.PreparedStatement.executeInternal(PreparedStatement.java:1861)
    - locked <0x0000000082a790d0> (a com.mysql.jdbc.JDBC4Connection)
    at com.mysql.jdbc.PreparedStatement.execute(PreparedStatement.java:1192)
    - locked <0x0000000082a790d0> (a com.mysql.jdbc.JDBC4Connection)
    at com.alibaba.druid.filter.FilterChainImpl.preparedStatement_execute(FilterChainImpl.java:3409)
    at com.alibaba.druid.filter.FilterEventAdapter.preparedStatement_execute(FilterEventAdapter.java:440)
    at com.alibaba.druid.filter.FilterChainImpl.preparedStatement_execute(FilterChainImpl.java:3407)
    at com.alibaba.druid.proxy.jdbc.PreparedStatementProxyImpl.execute(PreparedStatementProxyImpl.java:167)
    at com.alibaba.druid.pool.DruidPooledPreparedStatement.execute(DruidPooledPreparedStatement.java:498)
    at sun.reflect.GeneratedMethodAccessor64.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.PreparedStatementLogger.invoke(PreparedStatementLogger.java:62)
    at com.sun.proxy.$Proxy131.execute(Unknown Source)
    at org.apache.ibatis.executor.statement.PreparedStatementHandler.query(PreparedStatementHandler.java:59)
    at org.apache.ibatis.executor.statement.RoutingStatementHandler.query(RoutingStatementHandler.java:73)
    at org.apache.ibatis.executor.SimpleExecutor.doQuery(SimpleExecutor.java:60)
    at org.apache.ibatis.executor.BaseExecutor.queryFromDatabase(BaseExecutor.java:267)
    at org.apache.ibatis.executor.BaseExecutor.query(BaseExecutor.java:137)
    at org.apache.ibatis.executor.CachingExecutor.query(CachingExecutor.java:96)
    at org.apache.ibatis.executor.CachingExecutor.query(CachingExecutor.java:77)
    at sun.reflect.GeneratedMethodAccessor60.invoke(Unknown Source)
    at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
    at java.lang.reflect.Method.invoke(Method.java:498)
    at org.apache.ibatis.plugin.Invocation.proceed(Invocation.java:49)
    at com.github.pagehelper.SqlUtil._processPage(SqlUtil.java:401)
    at com.github.pagehelper.SqlUtil.processPage(SqlUtil.java:374)
    at com.github.pagehelper.PageHelper.intercept(PageHelper.java:254)
    at org.apache.ibatis.plugin.Plugin.invoke(Plugin.java:60)
    at com.sun.proxy.$Proxy129.query(Unknown Source)
    at org.apache.ibatis.session.defaults.DefaultSqlSession.selectList(DefaultSqlSession.java:108)
    at org.apache.ibatis.session.defaults.DefaultSqlSession.selectList(DefaultSqlSession.java:102)
    at org.apache.ibatis.session.defaults.DefaultSqlSession.selectOne(DefaultSqlSession.java:66)
    at sun.reflect.GeneratedMethodAccessor133.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:386)
    at com.sun.proxy.$Proxy27.selectOne(Unknown Source)
    at org.mybatis.spring.SqlSessionTemplate.selectOne(SqlSessionTemplate.java:165)
    at org.apache.ibatis.binding.MapperMethod.execute(MapperMethod.java:68)
    at org.apache.ibatis.binding.MapperProxy.invoke(MapperProxy.java:52)
    at com.sun.proxy.$Proxy53.queryAlarm(Unknown Source)
    at com.klone.yt.module.statistics.alarmHandleLog.task.ReCountTaskService$1.run(ReCountTaskService.java:53)
    at java.lang.Thread.run(Thread.java:748)

网上去搜这个问题,有人说是 mysql 的 recvBuff 接收缓冲区设置太小的原因,结果缓存 1M 还是不行,又有人说这个问题的根本所在是因为数据库连接池中获取到了不可用(已断开)的连接,没有进行断开检查直接去读数据库导致的,仔细一想,确实这种可能性很大,项目中使用的是阿里的 Druid 数据源,发现设置 queryTimeout 根本不起作用,后来直接在 jdbc 的 url 上加上socketTimeout参数才起的作用,这样一来至少不会一直阻塞了,也就是说可以捕获超时异常来重新查询统计了,但这种做法治标不治本,关键还是项目中有很多这样的问题,经常出现获取到断开的数据库连接,看到有人说 Druid 不会进行数据库连接的断开检测,于是干脆换成 c3p0 数据源,但还是然并卵!
公司用的是 Mycat,自从使用 Mycat 中间件后出现各种奇葩问题,真是欲哭无泪,这次不知道是不是也是这个原因。
最后直接将统计任务加上 @Transactional 注解,把它当做一个事务来执行,这样一来除非一开始拿到的就是断开的数据库连接,否则整个统计任务将使用这同一个数据库连接来执行任务,这样一来,问题勉强得以解决(这是因为获取到断开连接的概率比较小才能这么做)。

Last modification:August 16th, 2018 at 05:27 pm
If you think my article is useful to you, please feel free to appreciate

Leave a Comment