本文为辽宁振兴银行DBA团队投稿。
作者:roidba、流转的时光。
行内数据库备份在使用某备份软件,使用的数据库版本MySQL 8.0
社区版,全备使用mysqldump
进行,DBA早上巡检发现有一套数据库全备份失败,心里一疙瘩怎么回事呢?来看看如下报错
[mysqldump: Error: 'Lost connection to MySQL server during query' when trying to dump tablespaces mysqldump: couldn't execute 'SHOW VARIABLES LIKE 'ndbinfo'\_version' MySQL server has gone away (2006)]
肯定有同学有疑问?
为什么mysqldump会出现丢失连接?带着该问题进行以下分析:
对整个备份系统进行排查,虽然备份系统任务多,但并没有出现性能瓶颈导致数据库备份时超时,备份软件也没有设置备份超时时间自动断开的相关配置
2020-10-26T01:31:14.465387+08:00 149718 [Note] [MY-010914] [Server] Aborted connection 149718 to db: 'unconnected' user: 'root' host: 'localhost' (Got an error reading communication packets).
通过数据库错误日志发现同备份软件报错一样,对于这个错误,MOS上有一个比较好的解释如下:
不管怎么样我们后面先来看备份软件触发了些什么语句。
从上述检查来看,报错处是Got an error reading而不是timeout,关于timeout的触发方式我们最后总结。首先从备份软件架构,备份软件在数据库中部署agent,所以连接属于交互式连接受到参数interactive_timeout的影响,那么为什么导致的超时丢失连接的呢?我们可以进行问题复现,使用备份软件对数据库发起重新备份,对数据库进行监控
SQL语句:
SELECT LOGFILE_GROUP_NAME, FILE_NAME, TOTAL_EXTENTS, INITIAL_SIZE, ENGINE, EXTRA FROM INFORMATION_SCHEMA.FILES WHERE FILE_TYPE = 'UNDO LOG' AND FILE_NAME IS NOT NULL AND LOGFILE_GROUP_NAME IS NOT NULL AND LOGFILE_GROUP_NAME IN (SELECT DISTINCT LOGFILE_GROUP_NAME FROM INFORMATION_SCHEMA.FILES WHERE FILE_TYPE = 'DATAFILE' AND TABLESPACE_NAME IN (SELECT DISTINCT TABLESPACE_NAME FROM INFORMATION_SCHEMA.PARTITIONS WHERE TABLE_SCHEMA IN ('xxx'))) GROUP BY LOGFILE_GROUP_NAME, FILE_NAME, ENGINE, TOTAL_EXTENTS, INITIAL_SIZE ORDER BY LOGFILE_GROUP_NAME;
注意这里的状态为checking permissions,并且这个语句长期处于这个状态。我们以前理解的这个就是在鉴权,我们一般的认知是下面一些顺序:
我们能够看到,鉴权实际上在比较靠前的位置,是不是说这里语句还没真正的开始执行呢?我们先放一放。
由此可以推测发现,备份软件在发起备份时会发起4个连接,而其中一个连接执行SQL比较久,而另外3个sleep连接在超过interactive_timeout后断开,导致agent整体退出关闭所有的数据库连接,执行的SQL也终止,所以报错Got an error reading。但是奇怪的是我们在日志并没有找到Got timeout reading communication packets的日志。
我们知道join cache 一般用在两表join连接,被驱动表没有索引的情况下,将驱动表的数据放到join cache中,当join cache满了以后驱动一次被驱动表,以此来减少被驱动表全表扫描的次数,进而提高性能。
其次我们需要知道的MySQL虽然某一个线程负载高但是,一个线程只能使用CPU核心,我们监控监控的是整体的CPU,因此虽然一个CPU已经达到99%的高负载,但是整体平均下来也不那么明显,这是我行以后监控需要持续改进的地方。
很明显上面的分析我们发现语句实际已经执行了,但是为什么处于checking permissions状态呢?为了解开这个疑惑,我们需要将断点放到THD::enter_stage和JOIN_CACHE::read_record_field上,当然这部分我们没有深入的研究,只看debug状态,debug 什么呢,只要证明状态 executing 后进入了checking permissions状态且在checking permissions状态下执行了JOIN_CACHE::read_record_field即可如下:
这里证明了语句已经进入了执行阶段,但是每次读取一行join cache的记录转换一次状态为checking permissions,栈如下:
我们来看红色函数的注释如下:
INFORMATION_SCHEMA picks metadata from new DD using system views.
显然这里和访问information_schema中的数据有关,因为这里涉及到information_schema和数据字典的实现,过于庞大,我们不做研究了。
但是我们得出一个结论,对于访问字典视图,出现比较奇怪的状态,我们应该用perf top或者pstack获取信息,而不能停留在常规的认知上。
至此,我们已经找到优化思路,调整数据库join_buffer_size来解决,肯定有同学问,这个也不能随便调整啊,因为这是一个session级别的参数,可能导致MySQLD使用内存大幅增加。但是,我们架构中设计的这个库是专门用于全备的,没有任何应用连接,所以可以调整该参数。再次发起数据库备份,观察几天时间,该问题不再发现。透过事物看本质发现,mysql中在有大量的表或分区情况下,在通过内部试图、数据字典读取操作系统中文件时可能会存在有各种性能问题,对于某些查询操作我们可以在备库进行,尽量减少对主库的冲击。
接下来我们也研究了几个timeout参数, 如果出现超时遇到了日志是Got timeout reading communication packets,而不是Got an error reading communication packets。实际上几个timeout 参数都是通过poll的timeout参数实现的,我们稍微总结了一下如下:
因此总结一下: