
在某环境使用xtrabackup做恢复的时候, prepare(命令参考:xtrabackup --prepare --target-dir=/data/backup/full_back/2026-05-11_14-34-12)报错如下: xtrabackup: innodb_init(): Error occured
InnoDB: Completed initialization of buffer pool
InnoDB: If the mysqld execution user is authorized, page cleaner thread priority can be changed. See the man page of setpriority().
InnoDB: Log file ./ib_logfile1 is of different size 134217728 bytes than other log files 9437184 bytes!
InnoDB: Plugin initialization aborted with error Generic error
xtrabackup: innodb_init(): Error occured.从报错来看就是ib_logfile1的大小和其它redo的大小不一样导致innodb初始化失败.
xtrabackup的输出日志非常的全面,所以分析起来比较方便. 当然我们还得和源码对比一下(稳一点).
我们先来完整的看下xtrabackup preparer日志:
xtrabackup: recognized client arguments: --prepare=1 --target-dir=/data/backup/full_back/2026-05-11_14-34-12
xtrabackup version 2.4.27 based on MySQL server 5.7.40 Linux (x86_64) (revision id: aae8e82)
xtrabackup: cd to /data/backup/full_back/2026-05-11_14-34-12/
xtrabackup: This target seems to be not prepared yet.
InnoDB: Number of pools: 1
xtrabackup: xtrabackup_logfile detected: size=9437184, start_lsn=(748089915)
xtrabackup: using the following InnoDB configuration for recovery:
xtrabackup: innodb_data_home_dir = .
xtrabackup: innodb_data_file_path = ibdata1:12M:autoextend
xtrabackup: innodb_log_group_home_dir = .
xtrabackup: innodb_log_files_in_group = 1
xtrabackup: innodb_log_file_size = 9437184
xtrabackup: using the following InnoDB configuration for recovery:
xtrabackup: innodb_data_home_dir = .
xtrabackup: innodb_data_file_path = ibdata1:12M:autoextend
xtrabackup: innodb_log_group_home_dir = .
xtrabackup: innodb_log_files_in_group = 1
xtrabackup: innodb_log_file_size = 9437184
xtrabackup: Starting InnoDB instance for recovery.
xtrabackup: Using 104857600 bytes for buffer pool (set by --use-memory parameter)
InnoDB: PUNCH HOLE support available
InnoDB: Mutexes and rw_locks use GCC atomic builtins
InnoDB: Uses event mutexes
InnoDB: GCC builtin __atomic_thread_fence() is used for memory barrier
InnoDB: Compressed tables use zlib 1.2.12
InnoDB: Number of pools: 1
InnoDB: Using CPU crc32 instructions
InnoDB: Initializing buffer pool, total size = 100M, instances = 1, chunk size = 100M
InnoDB: Completed initialization of buffer pool
InnoDB: If the mysqld execution user is authorized, page cleaner thread priority can be changed. See the man page of setpriority().
InnoDB: Log file ./ib_logfile1 is of different size 134217728 bytes than other log files 9437184 bytes!
InnoDB: Plugin initialization aborted with error Generic error
xtrabackup: innodb_init(): Error occured.从上述日志中我们得到xtrabackup prepare的流程为:
从日志里面能分析出来的也就这样了, 基本上可以确定是redo log文件大小不统一导致的.
为啥redo log大小不一致呢?
我们查看备份目录下(已经做过prepare了)的文件:
-rw-r----- 1 mysql mysql 496 May 11 14:34 backup-my.cnf
drwxr-x--- 2 mysql mysql 8192 May 11 14:34 db1
drwxr-x--- 2 mysql mysql 102 May 11 14:34 db2
drwxr-x--- 2 mysql mysql 82 May 11 14:34 db3
drwxr-x--- 2 mysql mysql 4096 May 11 14:34 db4
-rw-r----- 1 mysql mysql 985 May 11 14:34 ib_buffer_pool
-rw-r----- 1 mysql mysql 146800640 May 11 14:34 ibdata1
-rw-r----- 1 mysql mysql 134217728 May 13 18:05 ib_logfile1
drwxr-x--- 2 mysql mysql 4096 May 11 14:34 mysql
drwxr-x--- 2 mysql mysql 8192 May 11 14:34 performance_schema
drwxr-x--- 2 mysql mysql 8192 May 11 14:34 sys
drwxr-x--- 2 mysql mysql 20 May 11 14:34 test2
-rw-r----- 1 mysql mysql 64 May 11 14:34 xtrabackup_binlog_info
-rw-r----- 1 mysql mysql 141 May 11 14:34 xtrabackup_checkpoints
-rw-r----- 1 mysql mysql 652 May 11 14:34 xtrabackup_info
-rw-r----- 1 mysql mysql 9437184 May 14 13:19 xtrabackup_logfile发现ib_logfile1的大小是134217728, xtrabackup_logfile的大小是9437184, 和报错中的描述(InnoDB: Log file ./ib_logfile1 is of different size 134217728 bytes than other log files 9437184 bytes)吻合.
熟悉xbk工具的同学应该会疑惑为啥会有个ib_logfile1文件, 我们通常备份出来是没有这个文件的(redo是放在xtrabackup_logfile文件的).
那就是因为多了个ib_logfile1导致的? 且看后面的源码分析
我们再从源码简单的看下prepare过程
xtrabackup.cc:main
if (xtrabackup_prepare) {
xtrabackup_prepare_func(server_argc, server_defaults);
}main函数直接就调xtrabackup_prepare_func去做prepare.
xtrabackup.cc:xtrabackup_prepare_func
mysql_mutex_init()
xtrabackup_read_metadata() # 读取元数据信息(主要是metadata_type,来源是xtrabackup_checkpoints(文本文件))
/* Create logfiles for recovery from 'xtrabackup_logfile', before start InnoDB */
os_event_global_init()
sync_check_init()
os_thread_init()
trx_pool_init()
ut_crc32_init()
xb_filters_init()
xtrabackup_init_temp_log() # 生成ib_logfile0的
innodb_init_param() # 初始化参数的(redo和ibdata1)
xb_tablespace_keys_exist() # key相关的, 一般都没加密
/* Expand compacted datafiles */
xb_normalize_init_values()
fil_close()
trx_pool_close()
os_thread_free()
sync_check_close()
innodb_free_param()
innodb_init_param() # 没想到吧, 再来了一遍, 这也解释了为啥日志里面显示了两次信息
innodb_init() # 本次的报错就是这
....初始化了一堆, 也检查了一堆, 直到innodb_init函数就报错了(结合日志也能知道是这个函数)
xtrabackup.cc:innodb_init
os_event_global_init()
if innobase_start_or_create_for_mysql(){
msg("xtrabackup: innodb_init(): Error occured.\n")
}innodb的初始化是调用的innobase_start_or_create_for_mysql来实现的
srv0start.cc:innobase_start_or_create_for_mysql
for (i = 0; i < SRV_N_LOG_FILES_MAX; i++){
size >>= UNIV_PAGE_SIZE_SHIFT (512)
if (i == 0) {
srv_log_file_size = size;
} else if (size != srv_log_file_size) {
ib::error() << "Log file " << logfilename
<< " is of different size "
<< (size << UNIV_PAGE_SIZE_SHIFT)
<< " bytes than other log files "
<< (srv_log_file_size
<< UNIV_PAGE_SIZE_SHIFT)
<< " bytes!";
return(srv_init_abort(DB_ERROR));
}
}如果i(redo文件号)不是第0个(ib_logfile0), 就判断其大小是否和xtrabackup_logfile(被当作了redo文件,虽然确实是记录的redo)相等, 若不相等就报错:Log file ./ib_logfile1 is of different size 134217728 bytes than other log files 9437184 bytes!
符合我们看到的日志信息, 也就是因为凭空多出来的ib_logfile1导致prepare失败.
设置线程优先级失败就会有如下提示(不影响后续操作):, mysql用户没有设置线程优先级的权限, 如果使用root则不会遇到这个提示.
/* linux might be able to set different setting for each thread.
worth to try to set high priority for page cleaner threads */
if (buf_flush_page_cleaner_set_priority(
buf_flush_page_cleaner_priority)) {
ib::info() << "page_cleaner coordinator priority: "
<< buf_flush_page_cleaner_priority;
} else {
ib::info() << "If the mysqld execution user is authorized,"
" page cleaner thread priority can be changed."
" See the man page of setpriority().";
}通过日志和源码我们知道了prepare失败是因为多了个ib_logfile1导致的, 那么为啥有这个文件呢? 先来看下这次失败的恢复流程:
将备份恢复到NAS,将NAS挂载到目标环境,解压(qpress)并prepare,然后move/copy-back.
这个流程已经跑过很多次了, 所以流程是没有问题的. 那么就可能是人工拷贝ib_logfile1到xbk备份目录, 或者恢复到nas的时候由于网络之类的情况导致目标环境多了个文件. 由于整个过程都是自动化的,所以不存在人工干预的情况(理论上), 那就是文件传输的时候出的问题了.
通过上述日志分析和源码得到本次prepare报错是因为文件传输的时候多了个ib_logfile1导致的, 重新传输备份文件到NAS并挂载到目标环境后,prepare正常.
至于为什么传输的时候会多一个文件,是否是人为操作的就不得而知了.
原创声明:本文系作者授权腾讯云开发者社区发表,未经许可,不得转载。
如有侵权,请联系 cloudcommunity@tencent.com 删除。
原创声明:本文系作者授权腾讯云开发者社区发表,未经许可,不得转载。
如有侵权,请联系 cloudcommunity@tencent.com 删除。