Gorm报invalid connection错误

背景

新上的一个项目，使用gorm进行数据操作，线上报connection invalid错误。

初步分析

从报错信息来看，应该是mysql client连接的问题。看了一些网上类似问题的分析，其中一篇提到了数据库客户端如果长时间不使用，mysql server端会单方面关闭该连接。

可以在mysql服务器上使用以下命令查看：

SHOW VARIABLES LIKE '%timeout%';

+-----------------------------------+----------+
| Variable_name                     | Value    |
+-----------------------------------+----------+
| connect_timeout                   | 10       |
| delayed_insert_timeout            | 300      |
| have_statement_timeout            | YES      |
| innodb_flush_log_at_timeout       | 1        |
| innodb_lock_wait_timeout          | 50       |
| innodb_rollback_on_timeout        | OFF      |
| interactive_timeout               | 28800    |
| lock_wait_timeout                 | 31536000 |
| mysqlx_connect_timeout            | 30       |
| mysqlx_idle_worker_thread_timeout | 60       |
| mysqlx_interactive_timeout        | 28800    |
| mysqlx_port_open_timeout          | 0        |
| mysqlx_read_timeout               | 30       |
| mysqlx_wait_timeout               | 28800    |
| mysqlx_write_timeout              | 60       |
| net_read_timeout                  | 30       |
| net_write_timeout                 | 60       |
| rpl_stop_slave_timeout            | 31536000 |
| slave_net_timeout                 | 60       |
| wait_timeout                      | 28800    |
+-----------------------------------+----------+

其中wait_timeout表示mysql服务最长容忍一个连接idle的时间，单位是秒。上例为8小时。

改进

从中文意思上看invalid connection其实就是表示无效链接的情况。如果是上述原因，很自然的就想到一种解决方案：重试一次。既然本次连接idle掉了，那么我们再发送一次相同的请求，不就可以重联了么？

验证

把改进后的代码重新上线。果不其然，第一次链接时还是会报相同的错误，但是第二次重新执行成功了。那问题真的解决了么？

发展

由于这条命令每天只会执行一次，我们还需要多关注几天以确定问题得到解决。不幸的是，在第二天的观察到的现象中两次操作均以失败告终。看来我并没有真正解决掉这个问题。除此之外，我心里还有两处疑问：

1是同样的代码在测试环境运行正常，但线上出错；

2是代码中有很多地方也存在数据库操作，但未观察到有相同的错误发生；

进一步分析

我们看一下出问题的这条sql，它大致是这样子的。

select * from table1 where field1="xxx" and field2="yyy" and id>num order by id asc limit 100;

使用explain来看一下mysql是怎么执行它的

+----+-------------+-------------------+------------+-------+---------------+---------+---------+------+------+----------+-------------+
| id | select_type | table             | partitions | type  | possible_keys | key     | key_len | ref  | rows | filtered | Extra       |
+----+-------------+-------------------+------------+-------+---------------+---------+---------+------+------+----------+-------------+
|  1 | SIMPLE      | table1s.          | NULL       | range | PRIMARY       | PRIMARY | 8       | NULL |   11 |    12.50 | Using where |
+----+-------------+-------------------+------------+-------+---------------+---------+---------+------+------+----------+-------------+

这个解释非常具有迷惑性，因为它告诉我这次查询走的是索引（我的另一篇博文对explain命令有详解--https://blog.csdn.net/zhanglehes/article/details/110523519）。但仔细分析了一下，id是自增主键，虽然mysql在查询时走的是primary key，但实质上仍是一个（类）全表扫码，这样的话，本次操作就是非常耗时的。

为了验证以上的猜想成立，我在线上直接使用命令行进行同样的操作

3 rows in set (0.51 sec)

Mysql server的执行时间为510毫秒。

再去确认gorm的配置参数，ReadTimeoutMs这个参数的值正好为500。

再一次改进

有了上述分析后，问题应该是mysql客户端获取数据超时导致的。提升查询效率最直接的办法肯定就是建立索引。对field1和field2建立一个联合索引，取名为idx_actid。

再使用explain来看一下mysql是怎么执行同一条sql语句的

+----+-------------+-------------------+------------+-------+-------------------+-----------+---------+------+------+----------+------------------------------------+
| id | select_type | table             | partitions | type  | possible_keys     | key       | key_len | ref  | rows | filtered | Extra                              |
+----+-------------+-------------------+------------+-------+-------------------+-----------+---------+------+------+----------+------------------------------------+
|  1 | SIMPLE      | table1s           | NULL       | range | PRIMARY,idx_actid | idx_actid | 202     | NULL |    1 |    12.50 | Using index condition; Using where |
+----+-------------+-------------------+------------+-------+-------------------+-----------+---------+------+------+----------+------------------------------------+

我们看到实际使用的key已经由primary转化新创建的索引idx_actid。

同样在线上直接使用命令行进行同样的操作

3 rows in set (0.04 sec)

Mysql server的执行时间由原先的510毫秒降低为40毫秒。

问题到此得到解决。

问答

1、在未创建新索引时，为何第一次改动上线后能在部分情况下成功？

答：mysql server端对应同一条sql的执行应该会有部分缓存，我尝试过多次执行同一条命令，后续执行的时间都会比第一次执行要低。另外线上配置的mysql客户端的超时时间与sql真实执行的时间相近，也会造成同一条指令偶尔成功的情况。

2、为何测试环境没有问题？

答：数据量小

3、本次改动是否具有通用性？

答：不具有。Mysql中会存储一些统计信息。一条sql执行时，如果有多条索引存在，mysql会预先评估每条索引执行的时间，选取效率最高的那个。因此可能存在添加新索引后，mysql还是判断原先索引执行较快，这时就不会得到性能提升了。