MySQL网络写超时分析

MySQL

网络写超时分析

PART 01

问题现象

某客户使用TDSQL MySQL8.0版本，在跑批场景下出现连接中断现象。业务反馈的错误信息如下：

ERROR c.a.d.p.DruidPooledPreparedStatement - getMaxFieldSize error
java.sql.SQLException: No operations allowed after statement closed.
...

客户跑批场景是每次从数据库流式获取 2000 条数据，完成相应业务逻辑后再继续获取下一批数据，每批数据之间的间隔约 30s。

PART 02

问题分析

首先查看MySQL相关日志，error log中没有对应时间连接断连的信息；然后查看slow log中记录相关SQL，发现对应时间存在Errno状态为1161的SQL：

# Query_time: 602.623354 Lock_time: 0.000556 Usecs_wait_tp_wq: 0 Rows_sent: 17176 Rows_examined: 268505 Thread_id: 3180834 
Errno: 1161 Killed: 0 Bytes_received: 0 Bytes_sent: 3236280 Read_first: 0 Read_last: 0 Read_key: 33 
Read_next: 0 Read_prev: 0 Read_rnd: 0 Read_rnd_next: 167 Sort_merge_passes: 0 Sort_range_count: 0 
Sort_rows: 0 Sort_scan_count: 0 Created_tmp_disk_tables: 0 Created_tmp_tables: 0 
Start: 2023-05-10T10:29:09.170404+08:00 End: 2023-05-10T10:39:11.793758+08:00

通过MySQL错误码1161，可以判定是由于 MySQL写超时（ER_NET_WRITE_INTERRUPTED）导致语句执行失败。

# perror 1161
MySQL error code MY-001161 (ER_NET_WRITE_INTERRUPTED): Got timeout writing communication packets

此时DBA会想到MySQL中多个超时相关的参数，其中参数net_write_timeout是控制server端返回给client端超时时间，具体解释可翻阅MySQL官方文档。

查看数据库当前配置是600s，那么问题基本理清楚。解决方案可以调整业务逻辑，也可以调整MySQL的net_write_timeout参数，或者调整JDBC连接串中的netTimeoutForStreamingResults参数。

那么MySQL如何产生 1161 的逻辑？查看MySQL 8.0源代码寻找答案，当且仅当操作系统返回 ETIMEDOUT 时可能会产生 1161 错误。

MySQL执行写入的具体调用链路为：vio_write -> mysql_socket_send, vio_socket_io_wait -> vio_io_wait。

即 MySQL 在发送消息到 socket 的过程中，除了调用 send() 外，在多次重试超过 net_retry_times 发生 EAGAIN 的情况后，也会调用 poll。

而 poll() 明确指出在超时情况下（tcp 底层内存不足，在申请内存过程中超时）会返回 0。MySQL 会将这个 poll 的 timeout 也等同于 ETIMEDOUT 进行处理。

当packet准备好发送后，会调用net_write_raw_loop函数开始进行发送数据，如果发送数据过程异常，则返回 ER_NET_WRITE_INTERRUPTED 或 ER_NET_ERROR_ON_WRITE。

最终是通过vio_was_timeout函数确认发送中断是否为ETIMEDOUT引起。

其中ER_NET_WRITE_INTERRUPTED和ER_NET_ERROR_ON_WRITE均是宏定义，分别对应错误码1161和1160。

net_write_timeout参数是从第一次遇到阻塞开始计时，如果中间又有写入成功的情况，会重新开始计时。客户在调大net_write_timeout参数为10800后，1161引发业务异常的情况得到缓解。

不过在slow log中依旧存在少量30s左右的1161异常的SQL，耗时远远低于net_write_timeout参数值，说明还有其他场景会触发ETIMEDOUT场景。

# Query_time: 28.221121 Lock_time: 0.000006 Usecs_wait_tp_wq: 0 Rows_sent: 5809 Rows_examined: 268505 Thread_id: 13364592 
Errno: 1161 Killed: 0 Bytes_received: 0 Bytes_sent: 1060392 Read_first: 1 Read_last: 0 Read_key: 1 
Read_next: 0 Read_prev: 0 Read_rnd: 0 Read_rnd_next: 167 Sort_merge_passes: 0 Sort_range_count: 0 
Sort_rows: 0 Sort_scan_count: 0 Created_tmp_disk_tables: 0 Created_tmp_tables: 0 
Start: 2023-05-13T15:13:50.683868+08:00 End: 2023-05-13T15:14:18.904989+08:00

通过tcpdump抓包来看，对应的时间点MySQL还在传数据，然后发个fin包到客户端导致的连接中断。而且netstat -s 发现 proxy 机器上 TCPRcvQDrop 较大，存在 tcp 层存在主动丢包情况。

PART 03

调试分析

短时间内没有找出触发ETIMEDOUT的场景，我们通过在MySQL中增加日志的方式继续分析。

1. 在vio_write函数增加 mysql_socket_send函数（最终是 send() ） 返回值输出，用于确认返回值有哪些。

2. 在vio_io_wait函数增加 poll() 返回值输出，用于确认是否有0值。

3. 通过模拟客户读取数据方式进行复现，在本地TDSQL 8.0的2分片环境，复现后查看日志输出信息

• 查看 poll() 返回值日志均为1，说明没有触发poll() 的超时，也不是参数net_write_timeout影响

# grep -i 'poll ret' /data1/tdengine/log/4008/dblogs/mysqld.err | sort | uniq
TXSQL: The vio_io_wait poll ret is 1.

• 查看系统调用 send() 返回的errno为11、104、110。
  • 11代表EAGAIN，表示写缓冲队列已满，可以做延时后再重试。会进入vio_io_wait函数 poll() 等待唤醒或者超时
  • 104代表ECONNRESET，在客户端服务器程序中，客户端异常退出，并没有回收关闭相关的资源，服务器端会先收到ECONNRESET错误，然后收到EPIPE错误。返回1160错误码
  • 110代表ETIMEDOUT，一般设置了发送接收超时，遇到网络繁忙的情况，就会遇到这种错误。且poll超时时会设定errno为110。返回1161错误码

# grep -i -E 'The error is' /data1/tdengine/log/4008/dblogs/mysqld.err | sort | uniq
TXSQL: The error is 104.
TXSQL: The error is 11.
TXSQL: The error is 110.

服务器 send() 数据，因为客户端已经崩溃，服务器收不到ACK自然会不停的重传。源自Berkeley的重传机制，重传次数受/proc/sys/net/ipv4/tcp_retries2控制，相对第一次传的15分钟后仍没收到ACK，则返回ETIMEDOUT或EHOSTUNREAC错误。如果服务器不理会这个错误，再次调用 send() ，则立马返回Broken Pipe错误。

当前操作系统的配置为6，通常配置为6或者15，6次的超时时间大约在26-27s左右。通过调小tcp_mem=‘1 2 3’参数，可以在本地环境直连DB复现（net_write_time=300s）。

Slow log信息如下，耗时在30s左右：

# Query_time: 26.631368 Lock_time: 0.000629 Usecs_wait_tp_wq: 0 Rows_sent: 167 Rows_examined: 167 Thread_id: 32 
Errno: 1161 Killed: 0 Bytes_received: 0 Bytes_sent: 24576 Read_first: 1 Read_last: 0 Read_key: 1 
Read_next: 0 Read_prev: 0 Read_rnd: 0 Read_rnd_next: 167 Sort_merge_passes: 0 Sort_range_count: 0 
Sort_rows: 0 Sort_scan_count: 0 Created_tmp_disk_tables: 0 Created_tmp_tables: 0 
Start: 2023-05-22T20:54:06.175770+08:00 End: 2023-05-22T20:54:32.807138+08:00

总结

MySQL触发1161的timeout writing的情况有两种：

1. 缓存队列满后进入系统调用 poll() 超过net_write_timeout参数时长（函数vio_io_wait）；
2. 系统调用 send() 时异常触发break（函数vio_write）。

可以使用如下方式规避：

1. 优化业务读取数据逻辑；
2. 适当调大net_write_timeout参数；
3. 调整操作系统下TCP的参数net.ipv4.tcp_mem 最小值6G，压力值8G，最大值12G。

-END-