vlambda博客
学习文章列表

MySQL备份失败,一波三折的问题分析和处理

这是学习笔记的第 2196 篇文章

读完需要

10
分钟

速读仅需7分钟

今天和同事一起处理了一个奇怪的MySQL空间异常问题,从这个问题的处理中可以找到一些问题处理的方式。

问题的背景是有一个实例的备份总是失败,在排查了多次之后,在保证Slave可用的情况先搁置了,刚好借着这几天的时间做了下收尾和梳理。

备份失败的报错提示信息是:

innobackupex: Error writing file '/tmp/xbtempevLQbf' (Errcode: 28 - No space left on device)xtrabackup: Error: write to logfile failedxtrabackup: Error: xtrabackup_copy_logfile() failed.

看起来多直白的问题,空间不足嘛,是不是空间配置的问题。

但是在本地进行模拟测试的时候,使用了如下的脚本开启本机测试。

/usr/local/mysql_tools/percona-xtrabackup-2.4.8-Linux-x86_64/bin/innobackupex --defaults-file=/data/mysql_4308/my.cnf --user=xxxx --password=xxxx --socket=/data/mysql_4308/tmp/mysql.sock --stream=tar /data/xxxx/mysql/xxxx_4308/2020-02-11 > /data/xxxx/mysql/xxxx_4308/2020-02-11.tar.gz

发现所在的/tmp目录却没有空间异常的情况,而相反是根目录的空间使用出现了异常,这是测试中截取到的一个空间异常的截图。

而在抛出异常之后,备份失败,空间使用率马上恢复。

MySQL备份失败,一波三折的问题分析和处理

综合目前得到的信息,我的直观感觉是问题貌似和/tmp没有太直接的联系,那一定是在根目录的使用过程中的其他目录产生了异常。

于是我开始了第二次测试,这一次我着重关注根目录的整体使用,看看到底是哪个目录的使用异常了,但是尴尬的是,尽管做了脚本的快速采集,竟然没有发现在我们常见的目录下有空间异常。

332K ./home411M ./lib26M ./lib6416K ./lost+found4.0K ./media4.0K ./misc4.0K ./mnt0 ./net184M ./optdu: cannot access `./proc/40102/task/40102/fd/4': No such file or directorydu: cannot access `./proc/40102/task/40102/fdinfo/4': No such file or directorydu: cannot access `./proc/40102/fd/4': No such file or directorydu: cannot access `./proc/40102/fdinfo/4': No such file or directory0 ./proc2.3G ./root56K     ./tmp。。。

所以从目前的情况来看,应该是/proc相关的目录下的空间异常了。

事情到了这个时候,似乎可用的方式已经不多了。

我排查了脚本,排查了参数文件,整体来看没有和其他环境相比明显的问题,但是有一个细节引起了我的注意,那就是使用top的时候,看到这个实例的内存使用了6G(服务器内存是8G),但是buffer pool的配置才是3G左右,这是一个从库环境,也没有应用连接,所以也不大可能存在太多的连接资源消耗,所以综合来看,应该是和服务器的内存异常有关。

这个时候尝试了在线resize,发现已经没有收缩的空间了。因为是从库服务,于是我开始重启从库的服务。

但是意外的是重启数据库的时候卡住了,大概过了有2分钟,只是看到一些输出的小数点,大概输出了两行,还是没有反应,查看后台日志没有任何输出,于是我开始尝试plan B,准备Kill 进程重启服务。

这一次kill操作生效了,过一会服务启动起来了。但是报出了从库复制异常。

 Last_IO_Error: Got fatal error 1236 from master when reading data from binary log: 'The slave is connecting using CHANGE MASTER TO MASTER_AUTO_POSITION = 1, but the master has purged binary logs containing GTIDs that the slave requires.'。。。 Master_Server_Id: 190 Master_UUID: 570dcd0e-f6d0-11e8-adc3-005056b7e95f。。。 Slave_SQL_Running_State: Slave has read all relay log; waiting for more updates Master_Retry_Count: 86400 Master_Bind:       Last_IO_Error_Timestamp: 200211 14:20:57 Retrieved_Gtid_Set: 570dcd0e-f6d0-11e8-adc3-005056b7e95f:821211986-2157277214 Executed_Gtid_Set: 570dcd0e-f6d0-11e8-adc3-005056b7e95f:1-820070317:821211986-2157277214

这个错误的信息是比较明显了,是主库的binlog被purge掉了,导致在从库去复制应用的时候失败了。

为什么会有这么奇怪的一个问题呢,因为主库的binlog默认还是保留了一些天数,不至于把1个小时前的binlog删除。

关于GTID的一些变量值如下:

Retrieved_Gtid_Set: 570dcd0e-f6d0-11e8-adc3-005056b7e95f:821211986-2157277214

Executed_Gtid_Set: 570dcd0e-f6d0-11e8-adc3-005056b7e95f:1-820070317:821211986-2157277214

gtid_purged     : 570dcd0e-f6d0-11e8-adc3-005056b7e95f:1-820070317:821211986-2131381624

Master端的GTID_Purged为:

gtid_purged      :570dcd0e-f6d0-11e8-adc3-005056b7e95f:1-2089314252

综合这些信息来看,Slave端的GTID和主库没有完整的衔接起来,也就意味着在之前对这个Slave做过一些操作,导致GTID在Master和Slave端产生了一些偏差。

而这个遗漏的变更部分570dcd0e-f6d0-11e8-adc3-005056b7e95f:821211986保守来估计也是1个月以前了,binlog是肯定没有保留的。

我们在此先暂时修复这个复制问题。

停止Slave没想到又出问题了,一个看似简单的stop Slave操作竟然持续了1分多钟。

>>stop slave;

Query OK, 0 rows affected (1 min 1.99 sec)

尝试减小Buffer pool配置,重启,stop slave,这个操作依然很慢,所以可以在这个方向上排除延迟的问题和Buffer Pool关系不大,而相对和GTID的关系更大一些。

Slave端修复步骤如下:

reset master;stop slave;reset slave all;SET @@GLOBAL.GTID_PURGED='570dcd0e-f6d0-11e8-adc3-005056b7e95f:1-2157277214';CHANGE MASTER TO MASTER_USER='dba_repl', MASTER_PASSWORD='xxxx' , MASTER_HOST='xxxxx',MASTER_PORT=4308,MASTER_AUTO_POSITION = 1;

其中GTID_PURGED的配置是关键。 

修复后,Slave端的延迟问题就解决了,而再次尝试重新备份,在根目录竟然没有了空间消耗。 


小结:

这个过程中主要是要快速解决问题,有些步骤的日志抓取的不够丰富和细致,从问题的分析来说,还是缺少了一些更有说服力的东西,对于问题的原因,本质上还是不合理的问题(比如bug或者配置异常等)导致了不合理的现象。

在这一块还是可以借鉴的是分析的整体思路,而不是这个问题本身。 





7


   

近期热文

你可能也会对以下话题感兴趣。点击链接就可以查看。














8


   

转载热文

你可能也会对以下话题感兴趣,文章来源于转载,点击链接就可以查看。