暂无图片
暂无图片
10
暂无图片
暂无图片
暂无图片

MySQL#排障 错误日志里的那些Aborted connection

神谕的暗影长廊 2020-12-24
17282

公有云RDS用户在MySQL错误日志中常遇到一些Aborted connection的问题,过来咨询。于是乎整理了一下关于此类“报错”的笔记。
测试基于MySQL 5.7.28。

错误日志可能有如下几种情况:

① [Note] Aborted connection xx to db: 'db' user: 'root' 
host: 'localhost' (Got timeout reading communication packets)

② [Note] ... (Got timeout writing communication packets)

③ [Note] ... (Got an error reading communication packets)

④ [Note] ... (Got an error writing communication packets)

⑤ [Note] Got timeout reading communication packets

可以看到,读写均有可能出现“timeout”和“error”两种情况。  
且⑤的情况,并没有输出Aborted connection xx,可以理解为鉴权前就挂了。  
-- 注,5.7以前,这个日志级别可能为[Warning]

直接的意思看起来是读/写包时超时,然后连接断开了。
先说一句话的小结,这并不一定代表着在执行事务的过程中被断开了连接。(不一定影响业务)

先了解一下MySQL与网络超时有关的几个Variables
Status

Variables:

  • 空闲连接断开相关:

    • wait_timeout:
      针对非交互式连接的超时参数,理解为各程序通过如jdbc连MySQL建立的会话。
    • interactive_timeout:
      针对交互式连接的超时参数,指通过mysql-client连接的会话
    • 简单的说,用于断开xx秒后没干活的空闲连接。
  • 网络读写时相关:

    • net_read_timeout:
      中止读取之前,从连接中等待更多数据的超时时间。
    • net_write_timeout:
      中止写入之前,等待将块写入连接更多数据的超时时间。
  • 建立连接相关:

    • connect_timeout:
      响应握手认证的超时时间。

Status:

  • Aborted_clients:
    简单理解为没有正常关闭的客户端(如意外终止),被干掉的次数。

  • Aborted_connects:
    简单理解为尝试访问mysql server,但因各种原因导致访问失败了的次数。(如鉴权失败、超过connect_timeout等)

  • Connection_error%:
    这类status的增长遇到的比较少,手册里的大概意思是:和TCP连接无关,发生在建立连接之前。和host cache
    发生错误时的时候增加。随机扫了一些实例,发现此类值均为0,下次如果遇到再学习一下。(偷懒)

  mysql> SHOW STATUS LIKE 'Connection_error%';       
+-----------------------------------+-------+
| Variable_name                     | Value |
+-----------------------------------+-------+
| Connection_errors_accept          | 0     |
| Connection_errors_internal        | 0     |
| Connection_errors_max_connections | 0     |
| Connection_errors_peer_address    | 0     |
| Connection_errors_select          | 0     |
| Connection_errors_tcpwrap         | 0     |
+-----------------------------------+-------+
6 rows in set (0.00 sec)


读超时

读超时是最常见的日志,经常会被errorlog刷屏,常见原因是空闲连接被干掉:

mysql> SET GLOBAL interactive_timeout = 5;

登录新一个客户端,tail -f
检查错误日志,过一会儿会打印:

2020-10-30T07:47:11.136611Z 55 [Note] Aborted connection 55 to db: 'unconnected' user: 'root' host: 'localhost' (Got timeout reading communication packets)

错误日志中大量刷这个,并不100%代表数据库或者网络出现了问题。
相关参数为interactive_timeout
wait_timeout

也有一个特殊场景可能会刷这个日志,需要调大net_read_timeout
,如在做LOAD DATA LOCAL FILE
时。(google时白嫖到的场景)

另,如果打印内容为

⑤ [Note] Got timeout reading communication packets

可能是因为建立连接时超时(还未建立连接)。

模拟一下也比较简单,将connect_timeout
设置为较低的值,比如2,或者默认10也行,telnet
一下等待connect_timeout
秒,就可以看到如上输出了。:

# telnet 127.0.0.1 3357
Trying 127.0.0.1...
Connected to 127.0.0.1.
Escape character is '^]'.
N
5.7.28-logNo5NlR^n&"_&lc@      
kpmysql_native_passwordConnection closed by foreign host.

如果不等了,直接ctrl+c,会输出

[Note] Got packets out of order

读错误

这个错误也是十分常见的,遇到过一个实例大量刷error reading
,引导客户检查一下业务代码没有正常关闭连接。这个在MySQL手册中也有提到:

The client program did not call mysql_close() before exiting.

写这样一个难看的py,然后执行一下,MySQL错误日志再看一下。

#!/usr/local/bin/python3
import pymysql
conn = pymysql.connect(host='127.0.0.1'
    port=3357, user='root', password='mima')
cursor = conn.cursor()
cursor.execute("SELECT 1;")

日志打印出:

2020-10-30T08:19:46.568752Z 17 [Note] Aborted connection 17 to db: 'unconnected' user: 'root' host: 'localhost' (Got an error reading communication packets)

写超时

遇到的比较少,在Stack Overflow
上搜了一下,也没几个Got timeout writing
的帖子。如果遇到了,考虑调大net_write_timeout
。但最好还是分析一下网络环境,默认值60秒我认为已经挺大的了。

写错误

遇到的比较少,归类下来是俩种可能:

1、网络异常
2、客户端异常退出

模拟一个写得很差的SQL,然后干掉客户端就可以了

mysql test -e "SELECT a.*, b.* FROM a, b;"

因为这俩表我弄了很多数据,造了个笛卡尔积(会执行很久),在shell环境中kill掉这个会话,日志输出:

2020-10-30T08:28:18.715370Z 18 [Note] Aborted connection 18 to db: 'test' user: 'root' host: 'localhost' (Got an error writing communication packets)

其他

翻一下相关函数,上述的几个日志输出,除了timeout
本身,其他的情况都归类为了error
,没有再细化分类。所以生产环境如果遇到error
类问题,可能需要再分析。

if (vio_was_timeout(net->vio))
  net->last_errno= ER_NET_WRITE_INTERRUPTED;
else
  net->last_errno= ER_NET_ERROR_ON_WRITE;
  
-- 注,读也如此。

小结

  • 读超时:
    首先,interactive_timeout
    wait_timeout
    设置为较低值本身也是优化手段,为了及时释放sleep连接,所以有因此而产生的日志输出,不一定是坏事,重连即可,总之还是跟着业务场景和数据库负载来。LOAD DATA LOCAL FILE
    场景可能需要检查net_read_timeout
  • 读错误:
    优先检查业务代码,看一下是否没有优雅关闭数据库连接。
  • 写超时:
    检查网络环境。
  • 写错误:
    检查客户端是否意外退出(比如我遇到过客户端发生OOM被干掉),且可能要检查网络环境。


补充阅读一下,此处我参考了percona的一篇博客,翻译并修改了一部分如下:

1、处于sleep的线程,依靠wait_timeout来关闭连接。
2、网络TIME_WAIT,从netstat里捕捉的,建议确认在应用程序端可以很好地关闭连接。
3、max_allowed_packet可能过小。
4、客户端应用程序中止,如PHP将选项max_execution_time设置成5秒,则增加mysql的参数connecte_timeout也没用。其他编程语言和环境可能也具有类似的安全选项。
5、引起连接延迟的另外一个原因是DNS问题,检查是否启用了跳过名称解析,以及主机是否针对其IP地址而不是其主键名进行身份验证。
6、尝试增加MySQL的系统变量net_read_timeout和net_write_timeout的值,看看是否会减少错误的数量,一般没问题,除非网络非常差。
7、网络问题,排查思路参考原文(文末有原文url)

另,5.7+有一个新功能,干掉执行时间超过max_execution_time
query
,这个玩意和上面说的都没关系哈,具体可以看一下手册。该功能类似于pt-kill

至于为啥会打印这些Note
或者Warning
error log
中,可额外去翻一下手册的这俩参数,不同数据库版本日志级别也有所不同:

log_warnings 
log_error_verbosity(5.7.2+)

参考文档

  • 内核月报 - MySQL 的那些网络超时错误
    http://mysql.taobao.org/monthly/2017/05/04/
  • 手册(Communication Errors and Aborted Connections)
    https://dev.mysql.com/doc/refman/5.7/en/communication-errors.html
  • percona的一篇博客,包括了网络问题的排查思路,推荐阅读
    https://www.percona.com/blog/2016/05/16/mysql-got-an-error-reading-communication-packet-errors/
    (上面这篇文章,知数堂有个翻译项目,什么都会的DBA晨亮老哥翻译了,可直接白嫖,移步连接:https://github.com/zhishutech/tech-blog-en2zh/blob/master/mysql/28-mysql-got-an-error-reading-communication-packet-errors.md)





-- the end --





阅读原文查看历史推送。

文章转载自神谕的暗影长廊,如果涉嫌侵权,请发送邮件至:contact@modb.pro进行举报,并提供相关证据,一经查实,墨天轮将立刻删除相关内容。

评论