适用范围
Linux环境下使用MySQLShell工具中的util中的dumpInstance对MySQL(5.7或者8.0版本)进行逻辑备份。
问题概述
客户生产环指定好备份策略后对MySQL进行备份脚本的部署,每天凌晨4点进行备份。在前几天观察中备份正常,平均备份时间为10分钟,经过一段时间后,业务发现备份任务第二天上午还没有完成,影响正常业务运行,备份时间超过8小时,有时备份时间长达10多个小时,明显异常,故对备份任务进行排查。
问题分析
1. 定时任务
MySQL定时任务如下所示:
[root@localhost mysql]# crontab -l
07 1 * * * /bin/bash /data/mysql/mysqlshellbackup.sh
[root@localhost mysql]# cat /data/mysql/mysqlshellbackup.sh
backupdate=`date +%Y%m%d`
mkdir -p /backup/backup_${backupdate}
backupdir=/backup/backup_${backupdate}
/data/mysqlshell8036/bin/mysqlsh -uroot p'password' -S /data/mysql/3306/run/mysql.sock -- util dump-instance ${backupdir}/dbdump --excludeSchemas='dbname' --threads=8 > ${backupdir}/backup.log 2>&1
#删除15天之前的备份
find /backup/ -name 'backup_*' -type d -mtime +15 -exec rm -rf {}\; >/dev/null 2>&1
说明:备份脚本在开始几天运行正常稳定没有发现异常现象。
2. 执行日志
[root@localhost backup]# cat backup_20240504/backup.log
WARNING: Using a password on the command line interface can be insecure.
Initializing...
NOTE: Backup lock is not supported in MySQL 5.7 and DDL changes will not be blocked. The dump may fail with an error if schema changes are made while dumping.
Acquiring global read lock
Global read lock acquired
Initializing - done
Gathering information...
4 out of 9 schemas will be dumped and within them 23021 tables, 0 views, 11 routines.
5 out of 7 users will be dumped.
Gathering information - done
All transactions have been started
Global read lock has been released
Writing global DDL files
Writing users DDL
Writing schema metadata...
Writing DDL...
Writing table metadata...
Writing schema metadata - done
Running data dump using 12 threads.
Dumping data...
Writing DDL - done
Writing table metadata - done
Starting data dump
Dumping data - done
Dump duration: 18:49:06s
Total duration: 18:49:45s
Schemas dumped: 4
Tables dumped: 23021
Uncompressed data size: 351.61 GB
Compressed data size: 67.44 GB
Compression ratio: 5.2
Rows written: 1220025586
Bytes written: 67.44 GB
Average uncompressed throughput: 5.19 MB/s
Average compressed throughput: 995.47 KB/s
[root@localhost backup]#
--说明:从备份日志中可以看出,总计备份时间长达18小时49分钟!严重不符合预期(之前只需要10多分钟左右)
以下为正常时间4月24日的备份日志为例:总共备份时间只需要11分钟!
[root@localhost backup]# cat backup_20240424/backup.log
WARNING: Using a password on the command line interface can be insecure.
Initializing...
NOTE: Backup lock is not supported in MySQL 5.7 and DDL changes will not be blocked. The dump may fail with an error if schema changes are made while dumping.
Acquiring global read lock
Global read lock acquired
Initializing - done
Gathering information...
4 out of 9 schemas will be dumped and within them 23050 tables, 0 views, 11 routines.
5 out of 7 users will be dumped.
Gathering information - done
All transactions have been started
Global read lock has been released
Writing global DDL files
Writing users DDL
Writing schema metadata...
Writing DDL...
Writing table metadata...
Writing schema metadata - done
Running data dump using 12 threads.
Dumping data...
Writing DDL - done
Writing table metadata - done
Starting data dump
Dumping data - done
Dump duration: 00:10:52s
Total duration: 00:11:08s
Schemas dumped: 4
Tables dumped: 23050
Uncompressed data size: 351.40 GB
Compressed data size: 67.42 GB
Compression ratio: 5.2
Rows written: 1222167539
Bytes written: 67.42 GB
Average uncompressed throughput: 538.29 MB/s
Average compressed throughput: 103.27 MB/s
[root@localhost backup]#
3. 进一步观察分析:
在备份时间点暂停备份任务,手动进行备份观察状态排查问题:
执行备份:发现最后一行没有进度,显示数值都为0,正常情况应该实时显示进度信息才对。
观察磁盘IO:发现有读,没有写!SSD磁盘,不应该数据这么小 正常情况应该读写速度在百兆左右。
观察主机性能:通过top信息(这里忘记截图)看结果,主机负责正常,内存正常,进程也没有异常现象。
观察MySQL当前状态:当前MySQL实例中只存在dumpSQL信息,并没有其他业务在跑。
当时并没有发现什么异常的点,还以为是磁盘IO出了问题,以为磁盘读IO有数据,写IO出现异常(因为没有写IO的数据),特意做了一个测试 本地磁盘文件进行本地的CP测试,发现对一个大文件CP 后看iostat状态,发现也确实有数据,每秒钟几百兆的读和写IO ,这表明磁盘IO是没有问题的,可能问题点还是在备份的过程中。
同样的脚步在从库中进行手动备份测试,就没有问题,可以顺利的执行下去。
4. 对比异常:
从以上的观察中并没有发现问题原因,主库备份就一直卡在哪里不动,但从主从库手动执行备份脚本的日志截图中发现了问题点:从库可以执行下去,但是主库没有继续执行下去,卡在了这个环节中:
主库备份时:
从库备份时:
5. 发现端倪:
细看上面截图中主库和从库备份日志可以发现,主库在日志最后一行就卡主了,不再进行继续输出,一直等待状态,这时候我们会发现,输出的英文提示信息是:12 thds chunking, 0 dumping…
仔细分析这段话:就是12个线程正在chunking 分块!没有线程在导出数据,这也反向证明了刚才IO状态监控的时候没写IO 只有读IO的原因,它还没有进行数据输出呢,所以还没有到导出数据这个步骤。也就是说现在卡在了 分块chunking 这个步骤上,换句话说就是备份进度在对表分块的时候,还没有分完…
正常情况下应该像从库这样,chunking完了之后,就进行dumping了!
6. 对chunking的解释:
通常情况下,库中表的大小不一,有些表会很大。在这种情况下,添加更多线程不会加快转储过程,为了克服这个问题,表中的数据可以分为更小的块chunk,每个块将由一个线程转储到单独的文件中。
chunking分块是MySQLShell备份的一个特性,默认会对表进行分块处理,为了多线程同时对大表进行数据导出,增加并行度,加快导出时间,MySQL Shell 会默认将导出文件按64兆为单位进行数据导出。
MySQLShell分块算法是根据统计信息值(表大小,表的行数等信息)和默认的分块大小通过主键/唯一键来将表进行数据拆分,虽然统计信息可能不准,但对于分块的目的来说它已经足够快速对大表进行拆分导出了。
问题原因
至此我们已经发现了问题,是卡在了分块chunking这个步骤上,导致备份时间超长!因为迟迟无法完成chunking分块,这个步骤上等待了太长时间。
为什么分块如此之慢呢?通过对表结果的查看,发现很多表都是联合主键:
这种联合主键在做数据导出时对每个chunk进行分数据的过程中需要对数据边界进行分界排序查询,如下:
如上图所示,这种数据拆分条件显然要比单独的数值自增id主键要慢的多,这里来拿一个单独主键的表作对比如下:直接通过主键my_row_id查找最快:
通过该案例可以得出,在MySQL表中,如果表没有主键或者表主键为字符类型联合主键的情况下,尤其对大表进行数据逻辑导出时(特指MySQL Shell 进行逻辑导出)可能会出现卡顿现象,因为在分块的过程中不能快速完成对表的分块过程(通过联合索引进行数据边界分块查询时可能会很慢)。
解决方案
在备份脚本中添加参数 --chunking=false 选项来避免之前备份时在 ‘分块儿’ chunking过程中卡主的现象(在大表中含有无主键表或联合主键的情况下)。
参考文档
https://dev.mysql.com/doc/mysql-shell/8.0/en/mysql-shell-utilities-dump-instance-schema.html
https://dev.mysql.com/blog-archive/mysql-shell-8-0-21-speeding-up-the-dump-process/