xtrabackup throttle参数及相关问题分析

percona提供的在线物理备份工具xtrabackup相信玩mysql的同学都不陌生。其实现原理和潜在的风险网上已经有很多描述(12)。在此不造轮子。本篇文章从一个备份出错例子出发,分析throttle参数对备份的影响。


问题描述

看看xtrabackup备份出错日志:

xtrabackup: uses posix_fadvise().

xtrabackup: cd to /xxx/mysql_data

xtrabackup: open files limit requested 65534, set to 65535

xtrabackup: using the following InnoDB configuration:

xtrabackup: innodb_data_home_dir = .

xtrabackup: innodb_data_file_path = ibdata1:512M:autoextend

xtrabackup: innodb_log_group_home_dir = ./

xtrabackup: innodb_log_files_in_group = 4

xtrabackup: innodb_log_file_size = 2147483648

xtrabackup: using O_DIRECT

InnoDB: Number of pools: 1

xtrabackup: error: log block numbers mismatch:

xtrabackup: error: expected log block no. 402310195, but got no. 419087395 from the log file.

xtrabackup: error: it looks like InnoDB log has wrapped around before xtrabackup could process all records due to either log copying being too slow, or log files being too small.

xtrabackup: Error: xtrabackup_copy_logfile() failed.


看起来还没有开始备份数据就出错了。出错信息很明确,就是读取的日志block number跟预期的block number不一致,进一步得出结论是可能redo拷贝速度比redo产生速度慢,或者举例更好的例子,在ring buffer下,消费速度赶不上生产速度,被生产者套圈了。对应的源码在xtrabackup_scan_log_recs()里,如下:

如果读取的redo log的lsn换算成的block number与预期的block number不等,但redo log的校验没有问题,则进入到if代码块中。如果读到的block number比预期小,且刚好小一轮,那么说明已经拷完所有的redo,也就是当前的redo log是旧的,对于类似的情况,可以结束redo拷贝(后面还会提到)。否则,先提示mismatch错误:

xtrabackup: error: log block numbers mismatch:

xtrabackup: error: expected log block no. 402310195, but got no. 419087395 from the log file.

进一步判断block number是否比预期大一轮,是的话提示redo log被覆盖:

xtrabackup: error: it looks like InnoDB log has wrapped around before xtrabackup could process all records due to either log copying being too slow, or log files being too small.


问题分析

从这个图(虽然目前已经不用innobackupex,但原理是一样的)可以看出,xtrabackup启动时会创建redo和ibd文件拷贝线程,这样,redo拷贝和ibd数据文件可以同时进行。拷贝ibd数据时会打印:

Copying ./ibdata1 to /xxx/backuptest/2018-09-06_11-23-35/ibdata1

Copying ./mysql/plugin.ibd to /xxx/backuptest/2018-09-06_11-23-35/mysql/plugin.ibd

那么问题来了,从日志上看,都还没有开始备份数据,怎么就出现redo被覆盖的错误呢?


复现问题

由于xtrabackup提示redo被覆盖,于是用iostat看了下系统负载情况,发现io利用率一直百分百,写入维持在100MB/s以上。这意味着,redo被覆盖的可能性是存在的。再看看xtrabackup备份参数:

sudo innobackupex --defaults-file=/xxx/my.cnf --slave-info --safe-slave-backup --safe-slave-backup-timeout=3600 --lock-wait-timeout=3600 --lock-wait-threshold=5 --throttle=40 --lock-wait-query-type=all --socket=/tmp/mysql.sock --user=xxx --password=xxx /xxx/backuptest

重新执行一遍,还是上述错误,但发现在打印了日志“InnoDB: Number of pools: 1”,经过了数分钟才打印后续的错误信息。尝试将throttle参数去掉后,xtrabackup正常开始备份。重复几遍均是如此,基本上可以确定跟throttle参数有关。


出错前在做什么

现在的问题是:加--throttle=40后报错前这段时间xtrabackup在做什么呢? 使用gdb多次attach到xtrabackup进程上,每次的调用栈信息均如下所示:

#0 0x00007f721838d344 in pthread_cond_wait@@GLIBC_2.3.2 () from /lib/x86_64-linux-gnu/libpthread.so.0

#1 0x0000000000aa991b in wait (this=<optimized out>)

at /home/rds-user/percona-xtrabackup/storage/innobase/os/os0event.cc:165

#2 os_event::wait_low (this=0x27384f0, reset_sig_count=<optimized out>)

at /home/rds-user/percona-xtrabackup/storage/innobase/os/os0event.cc:335

#3 0x00000000008e53dd in xtrabackup_copy_logfile (from_lsn=910958226733, is_last=is_last@entry=0 '\000')

at /home/rds-user/percona-xtrabackup/storage/innobase/xtrabackup/src/xtrabackup.cc:3075

#4 0x00000000008e6406 in xtrabackup_backup_func ()

at /home/rds-user/percona-xtrabackup/storage/innobase/xtrabackup/src/xtrabackup.cc:4762

#5 0x00000000008bfe65 in main (argc=<optimized out>, argv=<optimized out>)

at /home/rds-user/percona-xtrabackup/storage/innobase/xtrabackup/src/xtrabackup.cc:8702

对应代码:

xtrabackup每次从redo log文件读取数据(log_group_read_log_seg())前都会执行xtrabackup_io_throttling(),函数实现如下:

如果设置了throttle,那么会对io_ticket执行建议操作,如果值小于0,那么就会重置wait_throttle event,并等待其被设置。而wait_throttle是在另一个线程io_watching_thread上被设置。

该线程每隔1s将io_throttle设置为用户设置的throttle值,并设置wait_throttle。

结合gdb attach的信息和代码,以及throttle官方解释,可以得出:此时xtrabackup在拷贝redo,但由于throttle的限制,每秒的绝大部分时间都花在os_event_wait(wait_throttle)上了。这就回答了xtrabackup在出错前都在干什么的问题。进一步地,由于拷贝速度比redo产生速度慢,从而导致所需拷贝的redo被新日志覆盖。


问题解释

为何仅拷贝redo

那么另一个问题,为什么这段时间只拷贝redo,而不拷贝idb数据文件呢?这其实是目前网上对xtrabackup备份流程进行分析时都没有详细说明的地方。仔细分析代码发现执行redo拷贝任务的函数xtrabackup_copy_logfile()在2个地方调用到,一处是大家熟悉的redo拷贝线程log_copying_thread,而另一处是在xtrabackup备份主函数,即下图红框处:

该函数什么时候返回由xtrabackup_scan_log_recs()确定,在文章分析错误日志时已经提及。正常情况下,只有拷贝完所有新的redo日志才返回,如下:


xtrabackup备份流程细化

根据上面的描述,xtrabackup的备份流程进一步细化开来是这样的:

1、先获取innodb最后一次checkpoint对应的redo log lsn;

2、xtrabackup主线程从checkpoint lsn开始将之后新产生的redo都拷贝到xtrabackup_logfile上;

3、只有拷完所有的redo日志后,才会开启redo拷贝线程和ibd拷贝线程。并行执行redo和ibd数据拷贝;

4、ibd拷贝线程完成所有数据拷贝;

5、xtrabackup执行flush table with read lock,拷贝MyISAM表等非事务表数据;

6、获取Binlog文件及偏移位置,获取gtid_executed等信息;

7、执行FLUSH NO_WRITE_TO_BINLOG ENGINE LOGS;

8、等待redo拷贝进程退出;

9、执行unlock tables;

10、执行备份所需其他操作后退出;


throttle参数设置

所以,正确设置throttle很关键,过小的throttle会由于redo拷贝不及时而被覆盖,过大的throttle或不设置会导致备份操作影响线上业务性能。一般来说,throttle的设置需要评估MySQL数据盘的IO性能,盘的性能越好,相对的每秒产生的redo量可能越多,throttle需要更大。将数据盘从HDD升级为SSD后,一定要调整原有xtrabackup备份脚本的throttle参数,否则极有可能出现由于redo被覆盖导致备份出错的问题。

编辑于 2018-09-06

文章被以下专栏收录