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

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

读完需要

分钟

速读仅需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目录却没有空间异常的情况，而相反是根目录的空间使用出现了异常,这是测试中截取到的一个空间异常的截图。

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

综合目前得到的信息，我的直观感觉是问题貌似和/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或者配置异常等）导致了不合理的现象。

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

• 去IOE or Not?

• 拉里·佩奇（Larry Page）的伟大归来

• 《吊打面试官》系列-Redis基础

• 唯一ID生成算法剖析，看看这篇就够了

• 关于大数据运维能力的一些思考

• DBA菜鸟的进化简史：不忘初心，记工作中踩过的三个坑

• 美女主持直播,被突发意外打断!湾区网友却高喊: 我懂!超甜