记一次mysql数据库超时分析和优化

一、背景

服务器出现大量报错，错误消息如下

com.mysql.cj.jdbc.exceptions.CommunicationsException: Communications link failure

The last packet successfully received from the server was 10,010 milliseconds ago. The last packet sent successfully to the server was 10,010 milliseconds ago.
	at com.mysql.cj.jdbc.exceptions.SQLError.createCommunicationsException(SQLError.java:174)
	at com.mysql.cj.jdbc.exceptions.SQLExceptionsMapping.translateException(SQLExceptionsMapping.java:64)
	at com.mysql.cj.jdbc.ClientPreparedStatement.executeInternal(ClientPreparedStatement.java:916)
	at com.mysql.cj.jdbc.ClientPreparedStatement.execute(ClientPreparedStatement.java:354)
	at com.alibaba.druid.filter.FilterChainImpl.preparedStatement_execute(FilterChainImpl.java:3461)
	at com.alibaba.druid.filter.FilterEventAdapter.preparedStatement_execute(FilterEventAdapter.java:440)
	at com.alibaba.druid.filter.FilterChainImpl.preparedStatement_execute(FilterChainImpl.java:3459)
	at com.alibaba.druid.proxy.jdbc.PreparedStatementProxyImpl.execute(PreparedStatementProxyImpl.java:167)
	at com.alibaba.druid.pool.DruidPooledPreparedStatement.execute(DruidPooledPreparedStatement.java:497)
	at org.apache.ibatis.executor.statement.PreparedStatementHandler.update(PreparedStatementHandler.java:46)
	at org.apache.ibatis.executor.statement.RoutingStatementHandler.update(RoutingStatementHandler.java:74)
	at org.apache.ibatis.executor.SimpleExecutor.doUpdate(SimpleExecutor.java:50)
	at org.apache.ibatis.executor.BaseExecutor.update(BaseExecutor.java:117)
	at org.apache.ibatis.executor.CachingExecutor.update(CachingExecutor.java:76)
	at sun.reflect.GeneratedMethodAccessor156.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.Plugin.invoke(Plugin.java:63)
	at com.sun.proxy.$Proxy125.update(Unknown Source)
	at org.apache.ibatis.session.defaults.DefaultSqlSession.update(DefaultSqlSession.java:198)
	at sun.reflect.GeneratedMethodAccessor189.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)
	
	
com.mysql.cj.jdbc.exceptions.CommunicationsException: Communications link failure

The last packet successfully received from the server was 10,008 milliseconds ago. The last packet sent successfully to the server was 10,008 milliseconds ago.
	at com.mysql.cj.jdbc.exceptions.SQLError.createCommunicationsException(SQLError.java:174)
	at com.mysql.cj.jdbc.exceptions.SQLExceptionsMapping.translateException(SQLExceptionsMapping.java:64)
	at com.mysql.cj.jdbc.ClientPreparedStatement.executeInternal(ClientPreparedStatement.java:916)
	at com.mysql.cj.jdbc.ClientPreparedStatement.execute(ClientPreparedStatement.java:354)
	at com.alibaba.druid.filter.FilterChainImpl.preparedStatement_execute(FilterChainImpl.java:3461)
	at com.alibaba.druid.filter.FilterEventAdapter.preparedStatement_execute(FilterEventAdapter.java:440)
	at com.alibaba.druid.filter.FilterChainImpl.preparedStatement_execute(FilterChainImpl.java:3459)
	at com.alibaba.druid.proxy.jdbc.PreparedStatementProxyImpl.execute(PreparedStatementProxyImpl.java:167)
	at com.alibaba.druid.pool.DruidPooledPreparedStatement.execute(DruidPooledPreparedStatement.java:497)
	at org.apache.ibatis.executor.statement.PreparedStatementHandler.update(PreparedStatementHandler.java:46)
	at org.apache.ibatis.executor.statement.RoutingStatementHandler.update(RoutingStatementHandler.java:74)
	at org.apache.ibatis.executor.SimpleExecutor.doUpdate(SimpleExecutor.java:50)
	at org.apache.ibatis.executor.BaseExecutor.update(BaseExecutor.java:117)
	at org.apache.ibatis.executor.CachingExecutor.update(CachingExecutor.java:76)

看报错消息就是最近一次从mysql服务器收到的数据库是10010毫秒之前，最近一次发送到mysql服务器也是10010毫秒之前

二、分析过程

2.1
看日志，第一感觉是不是mysql服务器出现网络异常不稳定，导致报了大量日志，以及报错持续了几个小时，正常情况下mysql服务器网络不会如此异常这么久，
登录mysql监控系统查看以及运维的反馈，反馈当时数据库网络正常，，故排除是msyql网络异常原因

2.2
排查定时器，发现定时器执行update一个大表的数据，update table set status = 1 where biz_id = 1, 涉及解析的行数有300w，sql执行需要14秒，
分析了下该sql是走了索引的，既是说走了索引也需要耗时这么久

2.3
疑问，该方法函数不是http接口触发，按理说不是springcloud zuul网关触发超时熔断,而且超时熔断也不是报这错，因此排除这个原因

2.4
根据报错received from the server was 10,010 milliseconds ago，思考为啥是10010，而不是其他数，继续看日志，发现有

The last packet successfully received from the server was 10,011 milliseconds ag
The last packet successfully received from the server was 10,003 milliseconds ago
The last packet successfully received from the server was 10,004 milliseconds ago
The last packet successfully received from the server was 10,006 milliseconds ago

规律都在10000毫秒左右，那是不是哪里的配置有这个10000毫秒的配置呢，

2.5
继续排查，发现数据库配置确实有10000的配置，

spring:
  datasource:
    druid:
      url: jdbc:mysql://127.0.0.1:3306/my_database?zeroDateTimeBehavior=convertToNull&useUnicode=true&characterEncoding=utf8&autoReconnectForPools=true&allowMultiQueries=true&connectTimeout=2000&socketTimeout=10000&useSSL=false&autoReconnect=true
      username: my_username
      password: my_password

      
查询该配置的含义如下
在MySQL数据库的连接URL中，socketTimeout连接参数，它们的作用如下：
socketTimeout：socketTimeout参数指定了在尝试建立连接或执行查询时，等待数据库服务器响应的超时时间，单位为毫秒。如果在指定的时间内没有收到来自数据库服务器的响应，连接将被中断。
这个参数通常用于控制数据库操作的超时时间，避免长时间等待导致应用程序出现性能问题。
那就符合上文背景提高的The last packet successfully received from the server was 10,008 milliseconds ago。

2.6
至于为啥不是整数10000毫秒，而是有稍微大于10000的数出现10010， 100008等，
猜测每次进行sql执行时，mysql server有一个时间统计，统计时间大于配置的时间，就会把sql进行拦截报错，并发超时的数据抛出来，因此结合mysql本身统计的耗时，整体会大于10000毫秒
 

三、结论

虽然java可以配置@transaction注解管理事物，且默认情况下timeout配置是-1，但是事务还会被sql响应时间影响既socket_timeout配置，在开发中需要合理配置该socket-timeout的配置，对于耗时长的sql需要进行优化。
优化方法有合理配置索引，分批执行，异步执行等