一、问题
5-15号晚上对 fundx-web prod 环境的整体集群做了一次压力测试,期间有数次数据库错误报警,如下:
1. org.springframework.jdbc.CannotGetJdbcConnectionException: Failed to obtain JDBC Connection; nested exception is java.sql.SQLExcep
tion: wait millis 508, active 33, maxActive 100, creating 0
...
2. org.springframework.jdbc.CannotGetJdbcConnectionException: Failed to obtain JDBC Connection; nested exception is java.sql.SQLExcep
tion: wait millis 502, active 26, maxActive 100, creating 1, createElapseMillis 125, runningSqlCount 1:
...
//此处怀疑是两个问题场景,属于 druid datasource 相关逻辑,暂时没有结论
二、代码排查
首先查看报错节点的异常栈,这些错误的 Caused by 都是同一段代码:
Caused by: java.sql.SQLException: wait millis 542, active 29, maxActive 100, creating 1, createElapseMillis 2, runningSqlCount 1 : select ts from user_message_read where uid=?
runningSqlCount 1 : select count(1) from user_message where uid = ? and truncated = ? and ts > ?
runningSqlCount 1 : select fd.* from fund_derived fd, fund f where fd.fd_code=f.fd_code and fd.fd_type = ? and f.source = ? and nav_grl1y is not null order by nav_grl1y desc limit ?,?
at com.xueqiu.infra.rwsplitter.datasource.ReadWriteSplitDataSource.tryGetDataSource(ReadWriteSplitDataSource.java:119)
at com.xueqiu.infra.rwsplitter.datasource.ReadWriteSplitDataSource.doGetConnection(ReadWriteSplitDataSource.java:101)
at com.xueqiu.infra.rwsplitter.datasource.ReadWriteSplitDataSource.getConnection(ReadWriteSplitDataSource.java:48)
at org.springframework.jdbc.datasource.DataSourceUtils.fetchConnection(DataSourceUtils.java:151)
at org.springframework.jdbc.datasource.DataSourceUtils.doGetConnection(DataSourceUtils.java:115)
at org.springframework.jdbc.datasource.DataSourceUtils.getConnection(DataSourceUtils.java:78)
... 119 more
于是检查了 rwsplitter 组件,基本可以排除是组件的问题,报错是因为获取数据库连接错误,也找到了对应的组件日志,如下:
stdout.2020-05-15.gz:2020-05-15 21:10:05.029|INFO|c.x.i.r.d.ReadWriteSplitDataSource|e10631169894d8ff.e10631169894d8ff<:e10631169894d8ff|failed count more than 3, notify checker thread. key: read1
stdout.2020-05-15.gz:2020-05-15 21:10:05.030|INFO|c.x.i.r.d.ReadWriteSplitDataSource|0b17111acb521758.0b17111acb521758<:0b17111acb521758|failed count more than 3, notify checker thread. key: read1
stdout.2020-05-15.gz:2020-05-15 21:10:05.030|INFO|c.x.i.r.d.ReadWriteSplitDataSource|4200c24270791fc7.4200c24270791fc7<:4200c24270791fc7|failed count more than 3, notify checker thread. key: read1
//从日志可以看出报错的都是 read1,从库
接着是研究 druid Datasource 获取连接相关的代码,没有明显线索,需要更深入的研究,暂时搁置
三、监控排查
主要排查了 fundx-web 监控、数据库本身的监控、数据库所在物理机的监控,有几个异常的点
X.X.9.15 MySQL 从库所在物理机的上下文切换指标,超过1万了,是一个值得关注的点
MySQL 主从同步延时,已经超过20多秒,可以认为 MySQL 是不健康的
MySQL 从库 db191 的线程数指标有异常
// 主从延时是一个比较确定的线索;上下文切换指标没有实际的经验值可供参考,进一步排查需要复现问题且同时进行系统层的监控和排查,暂时搁置;MySQL 线程的相关资料较多,且和上下文切换指标是关联的,作为着手点排查
四、MySQL 线程
查询 数据库配置,线程模型是 one-thread-per-connection

综上:
- fundx 数据库是 one-thread-per-connection 模型
- MySQL 线程模型应该选择 one-thread-per-connection 还是 pool,这里没有结论
- one-thread-per-connection 模型下,瞬间创建大量连接是需要避免的
- 回头再看 MySQL 的监控图,会发现 threads_connected 达到 1000 之后,threads_running 还是维持在10-20之间的,1000:10 这个大概率是不合理的
五、初步的优化建议
- initialSize minIdle maxActive 保持相等或相近,再进行压测观察效果,避免在任何场景下瞬间创建大量连接
- maxActive=100 目测是偏大的,合理的最佳值和业务场景有关,可通过压测评估最佳值
六、其他
- fundx-web 目前使用的 rwsplitter 组件版本是 1.0,建议升级到最新版本
- 最开始的 creating 0 和 creating 1 的问题,creating=1对应的是建立物理连接,可以确定和 MySQL 性能下降有关;creating=0 暂时无结论,先解决首要问题再看
- 查看 fundx-web 监控时,JVM threads_count 2k 左右,个人觉得这个值太大了,需要结合业务代码优化
《MySQL挑战:建立10万连接》这篇文章mysql创建10万并发链接中描述了
从one-thread-per-connection到pool-of-threads模式时,25k个链接(QPS未知,这个是为了测试连接性能) P95从从3690 ms降到了979 ms,当然这是别人的实验
而且其中提供了Linux的句柄数、端口、IP配置相关的参数