MySQL TimeOut分析

引言

在做日常mysql数据库维护过程，时长会遇到关于mysql timeout的相关报错，了解mysql的连接过程和常见的错误类型，知己知彼，可以更好去运维mysql，做到心中有数。

MySQL连接参数

和网络超时相关的参数，这里做下简单说明：

interactive_timeout

服务器在关闭之前等待交互式连接的超时时间，交互式客户端定义为在mysql_real_connect()中使用CLIENT_INTERACTIVE选项的客户端。像mysql客户端是交互式客户端。

wait_timeout

服务器关闭非交互式连接之前等待活动的秒数，在线程启动时，根据全局wait_timeout值或全局interactive_timeout值初始化会话wait_timeout值，取决于客户端类型(由mysql_real_connect()的连接选项CLIENT_INTERACTIVE定义)。像java使用的jdbc连接，php使用pdo连接等都是非交互式连接。

net_read_timeout

1	在终止读之前，从一个连接获得数据而等待的时间秒数；当服务正在从客户端读取数据时，net_read_timeout控制何时超时。例如load data local infile语句。

net_write_timeout

1	在终止写之前，等待多少秒把block写到连接，当服务正在写数据到客户端时，net_write_timeout控制何时超时

connect_timeout

1	在连接认证阶段的网络交互超时时间(ref login_connection)。

MySQL连接过程

其中

connect_timeout 在获取连接阶段（authenticate）起作用
interactive_timeout和wait_timeout 在连接空闲阶段（sleep）起作用
net_read_timeout和net_write_timeout 则是在连接繁忙阶段（query）起作用。
mysql通信协议
mysql 客户端和服务端之间的通信协议是”半双工”，在任何一个时刻，要么是由服务端向客户端发送数据，要么是由客户端向服务端发送数据，这两个动作不能同时发生。参数max_allowed_packet在做导入数据的时候，net_buffer_length在缓冲数据的时候就很重要了。
connect_timeout
1
2
Connect_timeout
The number of seconds that the mysqld server waits for a connect packet before responding with Bad handshake

MySQL连接一次连接需求经过6次“握手”方可成功，任意一次“握手”失败都有可能导致连接失败，前三次握手可以简单理解为TCP建立连接所必须的三次握手，MySQL无法控制，更多的受制于不TCP协议的不同实现，后面的三次握手过程超时与connect_timeout有关。

建立连接步骤：

客户端向DB发起TCP握手
三次握手成功，由DB发送HandShake信息，这个Packet里面包含了MySql的能力、加密seed等信息。
客户端根据HandShake包里面的加密seed对MySql登录密码进行摘要后，构造Auth认证包发送给DB。
DB接收到客户端发过来的Auth包后会对密码摘要进行比对，从而确认是否能够登录。如果能，则发送Okay包返回。
客户端与DB的连接至此完毕。

net_read_timeout && net_write_timeout

当connect建立后，读取命令的流程如下：

read_packet 通过函数my_net_read读取数据包，如果一次读不完成，则调用函数net_read_raw_loop进行循环读取，读取的超时由wait_timeout决定
1）会先读取packet header，一个普通的packet header包含4个字节，压缩协议下则另外再加3个字节
2）再从packet header中提取剩下的packet长度，继续从socket读取
vio_read_buff vio封装了所有对socket的操作,当read_packet完成后，进入到vio相关的函数做封装处理，包括vio_init, vio_read_buffer,vio_read等。
my_net_write mysql通过read_packet做过相关处理后，通过my_net_write函数将数据先拷贝到NET缓冲区，当长度大于MAX_PACKET_LENGTH(即4MB-1字节)会对Packet进行拆分成多个packet。每个Packet的头部都会留4个字节，其中：1~3字节，存储该packet的长度，第4个字节存储当前的packet的序号，每存储一次后递增net->pkt_nr。
每个Net对象有一个Buff(net->buff)，即将发送的数据被拷贝到这个buffer中，当Buffer满时需要立刻发出到客户端。如果Buffer足够大，则只做memcpy操作。net->write_pos被更新到写入结束的位置偏移量 (net_write_buff)。
如果一次写入的数据被拆分成多个Packet，那么net->pkt_nr也对应的递增多次. pkt_nr的作用是在客户端解析时，防止包发送乱序。
net_flush 在my_net_write函数中，如果net->buff不够用，已经会做网络写了，net_flush最终保证所有在buff中的数据被写到网络。
net_write_raw_loop 当packet准备好发送后，调用函数net_write_raw_loop开始进行数据发送。
1）在发送模式受vio->write_timeout影响(通过参数net_write_timeout控制)；当该参数被设置成大于等于0时，使用非阻塞模式send数据包(MSG_DONTWAIT)
2）若网络发送被中断（EINTR），会去尝试重传
3）使用非阻塞模式send，每次并不保证数据全部发送完毕，因此需要循环的调用直到所有的数据都发送完毕
4）当输出缓冲区满时，获得错误码EWOULDBLOCK/EAGAIN,则阻塞等待(vio_socket_io_wait)，最大等待时间为net_write_timeout，超时则返回错误

interactive_timeout && wait_timeout

当query处理完成后，连接会进入到空闲阶段，此时受interactive_timeout和wait_timeout控制。关于interactive_timeout和wait_timeout，session和global有继承关系，可以自己测试，这里有篇文章，测试的很详细。

MySQL超时类型

Got timeout reading communication packets

连接超时

设置interactive_timeout和wait_timeout，使用mysql客户端连接，等待设置的超时时间后被mysql kill掉，在日志观察详情

准备

设置interactive_timeout和wait_timeout

观察日志

通过观察error log查看连接是否断开

其中，连接的thread_id为2885，超过10s后断开，出现日志详情

1	2018-08-03T10:11:48.650754+08:00 2885 [Note] [MY-010914] [Server] Aborted connection 2885 to db: 'unconnected' user: 'root' host: 'localhost' (Got timeout reading communication packets).

其他

其他常见的错误，可以参考官方文档，有详情的介绍，也可根据实际测试结果来验证。

Got an error reading communication packets

客户端异常退出(数据包异常)

使用pt-kill工具监控mysql的语句，通过在mysql确认pt-kill守护进程存在，kill掉此进程，观察日志的详情

准备

pt-kill安装
安装pt-kill工具，测试机使用ubuntu 16.04机器，直接使用以下命令：

1 2	wget -c https://www.percona.com/downloads/percona-toolkit/3.0.10/binary/debian/xenial/x86_64/percona-toolkit_3.0.10-1.xenial_amd64.deb dpkg -i percona-toolkit_3.0.10-1.xenial_amd64.deb

pt-kill测试

运行pt-kill进程
命令：

pt-kill --no-version-check --host localhost --port 3306 --user root --password 111111 --socket /opt/mysql/data/mysql.sock --match-host="127.0.0.1|localhost" --match-user="root" --match-db="sysbench|test" --match-command="Query" --match-state="statistics" --match-info="(?i-xsm:select)" --victim all --interval 1  --kill-query --daemonize --print --log=/tmp/pt-kill.log

查看pt-kill进程

查看mysql相关pt-kill进程

Kill掉pt-kill进程

观察日志

1 2	2018-08-02T15:21:32.254962+08:00 62476 [Note] [MY-010914] [Server] Aborted connection 62476 to db: 'unconnected' user: 'root' host: 'localhost' (Got an error readin g communication packets).

网络错误

准备

使用linux自带的tc命令篡改数据包，设置网卡随机产生30%的损坏数据包，也可使用tc的其他场景，比如数据包重复等待去做各种测试，这里仅使用2种场景分别测试损坏数据包时，是否产生Got an error writing communication packets的情况

设置tc数据包修改: 命令，由于测试的机器包括多块网卡，这里全部设置：

1
2
3

tc  qdisc  add  dev  eth0  root  netem  corrupt  30% 
tc  qdisc  add  dev  eth1  root  netem  corrupt  30%
tc  qdisc  add  dev  lo  root  netem  corrupt  30%

ping结果查看: 通过ping查看，tc的设置已经生效，出现了损坏数据包

sysbench测试

通过在sysbench压测过程中，人工设置，模拟网络出现问题的情况，观察日志

sysbench压测

/usr/local/bin/sysbench --db-driver=mysql --mysql-socket=/opt/mysql/data/mysql.sock --tables=1 --table_size=1000000 --report-interval=10 --time=3600 --mysql-port=3306 --mysql-user=root --mysql-password=111111 --mysql-db=sysbench --mysql-host=10.30.167.90 --max-requests=0 /usr/local/share/sysbench/oltp_read_write.lua --threads=4 run

压测结果：

观察error log

已经出现了Got an error writing communication packets相关告警信息

2018-08-02T16:35:51.858793+08:00 65764 [Note] [MY-010914] [Server] Aborted connection 65764 to db: 'sysbench' user: 'root' host: 'localhost' (Got an error writing communication packets).
2018-08-02T16:35:51.899059+08:00 65767 [Note] [MY-010914] [Server] Aborted connection 65767 to db: 'sysbench' user: 'root' host: 'localhost' (Got an error writing communication packets).
2018-08-02T16:35:51.899260+08:00 65765 [Note] [MY-010914] [Server] Aborted connection 65765 to db: 'sysbench' user: 'root' host: 'localhost' (Got an error writing communication packets).
2018-08-02T16:35:51.899339+08:00 65766 [Note] [MY-010914] [Server] Aborted connection 65766 to db: 'sysbench' user: 'root' host: 'localhost' (Got an error writing communication packets).

php测试

通过以运行php代码的形式来访问数据，人工设置，模拟网络出现问题的情况，观察日志

php代码运行
这里以互联网在线模拟为例子，地址：https://www.dooccn.com/php/

代码详情：

<?php
header('content-type:text/html;charset=utf-8');
try {  
    $db = new PDO('mysql:host=118.190.67.67;dbname=mysql', 'root', 'xxx');  
    //查询  
	$rows = $db->query('SELECT sleep(100)')->fetch(PDO::FETCH_ASSOC);
	$rs = array();
    foreach($rows as $row) {  
        $rs[] = $row; 
    }  
    $db = null;  
} catch (PDOException $e) {  
    print "Error!: " . $e->getMessage() . "<br/>";  
    die();  
}
print_r($rs);

观察error log

已经出现了Got an error writing communication packets相关告警信息

1	2018-08-02T16:37:31.183490+08:00 66089 [Note] [MY-010914] [Server] Aborted connection 66089 to db: 'mysql' user: 'root' host: '106.14.17.222' (Got an error reading communication packets).

max_prepared_stmt_count

max_prepared_stmt_count
此参数限制了同一时间在mysqld上所有session中prepared 语句的上限。一般做压力测试的prepare阶段可以会遇到此参数设置较小的问题，同时日志中会返回Got an error reading communication packets的错误，这里不再测试，在做压力测试时，需要将此参数设置大些。

准备

设置max_prepared_stmt_count

sysbench测试

运行压力测试

/usr/local/bin/sysbench --db-driver=mysql --mysql-socket=/opt/mysql/data/mysql.sock --tables=1 --table_size=1000000 --report-interval=10 --time=3600 --mysql-port=3306 --mysql-user=root --mysql-password=111111 --mysql-db=sysbench --mysql-host=10.30.167.90 --max-requests=0 /usr/local/share/sysbench/oltp_read_write.lua --threads=4 run

查看sysbench日志

在11.04的时候运行的压力测试

查看mysql log

1
2
3

2018-08-03T11:04:07.696809+08:00 5366 [Note] [MY-010914] [Server] Aborted connection 5366 to db: 'sysbench' user: 'root' host: 'localhost' (Got an error reading communication packets).
2018-08-03T11:04:07.696884+08:00 5365 [Note] [MY-010914] [Server] Aborted connection 5365 to db: 'sysbench' user: 'root' host: 'localhost' (Got an error reading communication packets).
2018-08-03T11:04:07.696959+08:00 5364 [Note] [MY-010914] [Server] Aborted connection 5364 to db: 'sysbench' user: 'root' host: 'localhost' (Got an error reading communication packets).

其他

其他常见的错误，可以参考官方文档，有详情的介绍，也可根据实际测试结果来验证。

Lost connection to MySQL server during query

超时connect_timeout

使用linux自带的tc命令设置网络延迟，达到测试所需要的效果

准备

设置tc数据包延迟：命令，由于测试的机器包括多块网卡，这里全部设置：
1
2
tc qdisc add dev eth1 root netem delay 11000ms
tc qdisc add dev eth0 root netem delay 11000ms

登录连接测试

通过远程连接其他mysql服务器，查看登录效果，超过了默认connect_timeout的10s，报Lost connection to MySQL server during query错误

客户端异常退出(数据包正常)

开启2个session窗口，连接同一个mysql实例，第1个session开启查询，第2个session去kill掉第一个session

准备

Session1开启查询

手动kill

Session2查看processlist

session2 手动kill session1连接

session1查看查询

其他

其他常见的错误，可以参考官方文档，有详情的介绍，也可根据实际测试结果来验证。

MySQL server has gone away

设置mysql的interactive_timeout，使用mysql客户端开启一个窗口

准备

设置interactive_timeout的值

执行查询

在同一窗口内执行查询select sleep(10)

等待超过interactive_timeout时间后，再次执行查询

已经出现的错误日志：MySQL server has gone away

其他

其他常见的错误，可以参考官方文档，有详情的介绍，也可根据实际测试结果来验证。

参考

http://mysql.taobao.org/monthly/2016/07/04/
http://mysql.taobao.org/monthly/2017/05/04/
http://www.importnew.com/29055.html
https://www.cnblogs.com/cchust/p/5025880.html
https://my.oschina.net/alchemystar/blog/833598

引言

MySQL连接参数

MySQL连接过程

mysql通信协议

connect_timeout

net_read_timeout && net_write_timeout

interactive_timeout && wait_timeout

MySQL超时类型

Got timeout reading communication packets

连接超时

准备

观察日志

其他

Got an error reading communication packets

客户端异常退出(数据包异常)

准备

pt-kill测试

网络错误

准备

sysbench测试

php测试

max_prepared_stmt_count

准备

sysbench测试

其他

Lost connection to MySQL server during query

超时connect_timeout

准备

登录连接测试

客户端异常退出(数据包正常)

准备

手动kill

其他

MySQL server has gone away

MySQL server has gone away

准备

执行查询

其他

参考