xtrabackup prepare失败: innodb_init(): Error occured.

原创大大刺猬 9小时前

导读

在某环境使用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 prepare过程

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相关变量(2次?)
初始化innodb buffer pool
设置page cleaner线程优先级失败(没权限).
发现ib_logfile1和其它redo日志大小不一样
插件(innodb)初始化失败
innodb初始化失败,退出

从日志里面能分析出来的也就这样了, 基本上可以确定是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失败分析

通过日志和源码我们知道了prepare失败是因为多了个ib_logfile1导致的, 那么为啥有这个文件呢? 先来看下这次失败的恢复流程:

将备份恢复到NAS,将NAS挂载到目标环境,解压(qpress)并prepare,然后move/copy-back.

这个流程已经跑过很多次了, 所以流程是没有问题的. 那么就可能是人工拷贝ib_logfile1到xbk备份目录, 或者恢复到nas的时候由于网络之类的情况导致目标环境多了个文件. 由于整个过程都是自动化的,所以不存在人工干预的情况(理论上), 那就是文件传输的时候出的问题了.

总结

通过上述日志分析和源码得到本次prepare报错是因为文件传输的时候多了个ib_logfile1导致的, 重新传输备份文件到NAS并挂载到目标环境后,prepare正常.

至于为什么传输的时候会多一个文件,是否是人为操作的就不得而知了.

墨力计划 mysql

「喜欢这篇文章，您的关注和赞赏是给作者最好的鼓励」

关注作者

xtrabackup prepare失败: innodb_init(): Error occured.

导读

分析xtrabackup prepare过程

日志分析

源码分析

prepare失败分析

总结

评论