今天和同事一起处理了一个奇怪的MySQL空间异常问题,从这个问题的处理中可以找到一些问题处理的方式。
问题的背景是有一个实例的备份总是失败,在排查了多次之后,在保证Slave可用的情况先搁置了,刚好借着这几天的时间做了下收尾和梳理。
备份失败的报错提示信息是:
代码语言:javascript复制innobackupex: Error writing file '/tmp/xbtempevLQbf' (Errcode: 28 - No space left on device)
xtrabackup: Error: write to logfile failed
xtrabackup: Error: xtrabackup_copy_logfile() failed.
看起来多直白的问题,空间不足嘛,是不是空间配置的问题。
但是在本地进行模拟测试的时候,使用了如下的脚本开启本机测试。
代码语言:javascript复制/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没有太直接的联系,那一定是在根目录的使用过程中的其他目录产生了异常。
于是我开始了第二次测试,这一次我着重关注根目录的整体使用,看看到底是哪个目录的使用异常了,但是尴尬的是,尽管做了脚本的快速采集,竟然没有发现在我们常见的目录下有空间异常。
代码语言:javascript复制332K ./home
411M ./lib
26M ./lib64
16K ./lost found
4.0K ./media
4.0K ./misc
4.0K ./mnt
0 ./net
184M ./opt
du: cannot access `./proc/40102/task/40102/fd/4': No such file or directory
du: cannot access `./proc/40102/task/40102/fdinfo/4': No such file or directory
du: cannot access `./proc/40102/fd/4': No such file or directory
du: cannot access `./proc/40102/fdinfo/4': No such file or directory
0 ./proc
2.3G ./root
56K ./tmp
。。。
所以从目前的情况来看,应该是/proc相关的目录下的空间异常了。
事情到了这个时候,似乎可用的方式已经不多了。
我排查了脚本,排查了参数文件,整体来看没有和其他环境相比明显的问题,但是有一个细节引起了我的注意,那就是使用top的时候,看到这个实例的内存使用了6G(服务器内存是8G),但是buffer pool的配置才是3G左右,这是一个从库环境,也没有应用连接,所以也不大可能存在太多的连接资源消耗,所以综合来看,应该是和服务器的内存异常有关。
这个时候尝试了在线resize,发现已经没有收缩的空间了。因为是从库服务,于是我开始重启从库的服务。
但是意外的是重启数据库的时候卡住了,大概过了有2分钟,只是看到一些输出的小数点,大概输出了两行,还是没有反应,查看后台日志没有任何输出,于是我开始尝试plan B,准备Kill 进程重启服务。
这一次kill操作生效了,过一会服务启动起来了。但是报出了从库复制异常。
代码语言:javascript复制 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端修复步骤如下:
代码语言:javascript复制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或者配置异常等)导致了不合理的现象。
在这一块还是可以借鉴的是分析的整体思路,而不是这个问题本身。