现象
服务内访问数据库超时
分析日志
不断输出如下日志:
2023-05-15 17:50:34.507 ... org.mybatis.spring.MyBatisSystemException: nested exception is org.apache.ibatis.exceptions.PersistenceException:
### Error querying database. Cause: org.springframework.jdbc.CannotGetJdbcConnectionException: Could not get JDBC Connection; nested exception is com.alibaba.druid.pool.GetConnectionTimeoutException: wait millis 60000, active 10, maxActive 10, creating 0
### The error occurred while executing a query
### Cause: org.springframework.jdbc.CannotGetJdbcConnectionException: Could not get JDBC Connection; nested exception is com.alibaba.druid.pool.GetConnectionTimeoutException: wait millis 60000, active 10, maxActive 10, creating 0
...
Caused by: com.alibaba.druid.pool.GetConnectionTimeoutException: wait millis 60000, active 10, maxActive 10, creating 0
at com.alibaba.druid.pool.DruidDataSource.getConnectionInternal(DruidDataSource.java:1512)
at com.alibaba.druid.pool.DruidDataSource.getConnectionDirect(DruidDataSource.java:1255)
at com.alibaba.druid.pool.DruidDataSource.getConnection(DruidDataSource.java:1235)
at com.alibaba.druid.pool.DruidDataSource.getConnection(DruidDataSource.java:1225)
at com.alibaba.druid.pool.DruidDataSource.getConnection(DruidDataSource.java:90)
at org.springframework.jdbc.datasource.DataSourceUtils.doGetConnection(DataSourceUtils.java:111)
at org.springframework.jdbc.datasource.DataSourceUtils.getConnection(DataSourceUtils.java:77)
... 148 common frames omitted
先重启服务先恢复连接。
然后排查代码,发现连接池中没有可用连接,但是并没有找到连接池创建连接的日志。
直到看见下面一段日志后,数据库访问恢复正常。
2023-05-15 18:21:19.764 [Druid-ConnectionPool-Create-565246475] ERROR c.alibaba.druid.pool.DruidDataSource - [TID:N/A] - create connection SQLException, ..., errorCode 0, state 08S01
com.mysql.jdbc.exceptions.jdbc4.CommunicationsException: Communications link failure
The last packet sent successfully to the server was 0 milliseconds ago. The driver has not received any packets from the server.
at sun.reflect.GeneratedConstructorAccessor301.newInstance(Unknown Source)
Caused by: java.net.SocketException: Connection reset
... 30 common frames omitted
分析关键代码
# com.mysql.jdbc.ConnectionImpl#createNewIO
发现此处会对建立连接上锁,建立连接超时了。
进一步分析,发现是连接正常,读取数据超时,即未触发 connectionTimeout,触发了 readTimeout。当 jdbc 未设置 socketTimeout,用到了操作系统的 tcp 超时时间。
结论
数据源配置超时参数:
# 连接超时
connectTimeout=
# 支持重连
autoReconnect=true
# jdbc 不设置,默认采用 操作系统的 tcp 超时时间,/proc/sys/net/ipv4/tcp_keepalive_time
socketTimeout=