【问题标题】：go-sql-driver: get invalid connection when wait_timeout is 8h as defaultgo-sql-driver：当 wait_timeout 默认为 8h 时获取无效连接
【发布时间】：2021-03-23 00:19:38
【问题描述】：

一句话

当MaxOpenConns 丰富且wait_timeout 为8h 时，得到MySQL invalid connection 问题。

详细

我有一个脚本打算从表 A 中读取所有记录，进行一些转换，然后将结果记录写入表 B。代码是这样工作的：

一个 goroutine 扫描表 A，将记录放入通道中；
其他四个 goroutine（数量可配置）同时从上述通道消费，累积 50 行（批量大小可配置）插入表 B，然后再累积 50 行，依此类推。
扫描器 goroutine 拥有一个 *sql.DB，而插入器 goroutine 共享另一个 *sql.DB
go-sql-driver：版本 1.4.1 (2018-11-14) 或版本 1.5 (2020-01-07)

（1.4.1遇到的问题，可复现demo，见下文，使用1.5）

Go 版本：go1.13.15 darwin/amd64

invalid connection 问题几乎可以稳定地重现。

在特定的运行案例中，表 A 有 67227 条记录，通道大小设置为 100000，表 A 扫描器（1 个 goroutine）一次读取 1000 个，表 B 插入器（4 个 goroutine）写入 50。它最终在表 B 中得到 67127 条记录（丢失 2*50），并在控制台中输出 2 行错误：

[mysql] 2020/12/11 21:54:18 packets.go:36: read tcp x.x.x.x:64062->x.x.x.x:3306: read: operation timed out
[mysql] 2020/12/11 21:54:21 packets.go:36: read tcp x.x.x.x:64070->x.x.x.x:3306: read: operation timed out

（我重现时错误行数不同，通常是1、2或3。N错误行与N*50记录插入失败到表B中。）

从我的日志文件中，它打印出invalid connection：

2020/12/11 21:54:18 main.go:135: [goroutine 56] BatchExecute: BatchInsertPlace(): SqlDb.ExecContext(): invalid connection
Stats={MaxOpenConnections:0 OpenConnections:4 InUse:3 Idle:1 WaitCount:0 WaitDuration:0s MaxIdleClosed:14 MaxLifetimeClosed:0}
2020/12/11 21:54:21 main.go:135: [goroutine 55] BatchExecute: BatchInsertPlace(): SqlDb.ExecContext(): invalid connection
Stats={MaxOpenConnections:0 OpenConnections:4 InUse:3 Idle:1 WaitCount:0 WaitDuration:0s MaxIdleClosed:14 MaxLifetimeClosed:0}

试验和观察

通过在日志中打印带有 goroutine id 的每个成功/失败写入操作，当所有 4 个插入 goroutine 中的任何一个在 2 次连续写入之间的间隔超过约 45 秒时，似乎总是会发生错误。我认为在将它们插入表 B 之前累积 50 条记录只需要这么长时间。
相比之下，当我碰巧进行了更改，使 4 个插入的 goroutine 平均写入一些（即没有一个比其他的写入间隔长得多）时，看不到错误。重复 3 次。
看起来一个错误只影响一个批次的写操作，后面的批次运行良好。那么为什么不重试出错的批次呢？我想重试一次，它会通过。不过，我不介意继续重试直到成功：

var retryExecTillSucc = func(goroutineId int, records []*MyDto) {
   err := inserter.BatchInsert(records)
   for { // retry until success. This is a workaround for 'invalid connection' issue
      if err == nil { break }
      logger.Printf("[goroutine %v] BatchExecute: %v \nStats=%+v\n", goroutineId, err, inserter.RdsClient.SqlDb.Stats())
      err = inserter.retryBatchInsert(records)
   }
   logger.Printf("[goroutine %v] BatchExecute: Success \nStats=%+v\n", goroutineId, inserter.RdsClient.SqlDb.Stats())
}

令人惊讶的是，随着这种变化，错误批次的重试不断出错并且永远不会成功......

总结

当错误发生时，一个（空闲）连接看起来很明显，但我的问题是：

MySQL wait_timeout 设置为 8h，为什么连接超时这么快？
由于未设置 MaxOpenConns，因此不应成为限制，尤其是考虑到日志中只有 4 个 OpenConnections。
还有什么要检查的潜在根本原因？

（太长了，不过希望能说清楚，多指教~）

更新

Minimal, reproducible example，包括：

代码
一个示例日志文件
MySQL 错误日志

【问题讨论】：

1. 8 小时超时有什么意义？ 2. 不管你的超时时间如何，你都不应该假设所有的连接都是有效的。有无数与超时无关的原因，连接可能会关闭或断开。
@Flimzy 超时由输出建议：[mysql] 2020/12/11 21:54:18 packets.go:36: read tcp x.x.x.x:64062->x.x.x.x:3306: read: operation timed out 。也很疑惑，因为我在我们的生产服务中没有遇到过这种情况，但是在这个脚本中，它却经常发生。如果并非所有连接都始终有效，那么异常应该非常罕见吧？
您的“解决方法”实际上是从根本上正确的做法。所有数据库操作都应该被假定为错误的，因此您的应用程序必须能够处理故障。在许多情况下，重试是一种很好的方法。您还可以通过先执行 ping 使其更加健壮，以确保您从池中获取的连接仍然有效，但这可能与此特定问题无关。
那我不知道。你的问题中没有足够的代码来调试，真的。 Minimal, reproducible example 会很有帮助。
传递上下文？ -- 没有。HTTP 请求？ -- 没有。代码和例子，好点，我稍等更新~

标签： mysql go

【解决方案1】：

你不使用上下文吗？我想读取超时是由上下文超时引起的，或者readTimeout参数。

MySQL 不提供安全有效的取消机制。当上下文被取消或到达readTimeout 时，DB.ExecContext 返回而不使用连接终止。下次使用连接时会导致“无效连接”。

如果你想限制长查询的执行时间，你可以使用MAX_EXECUTION_TIME提示而不是上下文。参考https://dev.mysql.com/doc/refman/5.7/en/optimizer-hints.html#optimizer-hints-execution-time。

【讨论】：