xtrabackup 2.3 does not respect innodb_log_file_size stored in backup-my.cnf

[Sergei Glushchenko]

Test case:

###

MYSQLD_EXTRA_MY_CNF_OPTS="
innodb-log-files-in-group=4
innodb-log-file-size=2M
"

start_server

xtrabackup --backup --target-dir=$topdir/backup

cat $topdir/backup/backup-my.cnf

${XB_BIN} --prepare --target-dir=$topdir/backup

stop_server

rm -rf ${mysql_datadir}

xtrabackup --move-back --target-dir=$topdir/backup

start_server

cat ${MYSQLD_ERRFILE}

###

backup-my.cnf:

###

[mysqld]
innodb_checksum_algorithm=innodb
innodb_log_checksum_algorithm=innodb
innodb_data_file_path=ibdata1:12M:autoextend
innodb_log_files_in_group=4
innodb_log_file_size=2097152
innodb_fast_checksum=false
innodb_page_size=16384
innodb_log_block_size=512
innodb_undo_directory=.
innodb_undo_tablespaces=0

###

From prepare log:

xtrabackup: using the following InnoDB configuration for recovery:
xtrabackup: innodb_data_home_dir = ./
xtrabackup: innodb_data_file_path = ibdata1:10M:autoextend
xtrabackup: innodb_log_group_home_dir = ./
xtrabackup: innodb_log_files_in_group = 2
xtrabackup: innodb_log_file_size = 50331648

...

InnoDB: Setting log file ./ib_logfile101 size to 48 MB
InnoDB: Setting log file ./ib_logfile1 size to 48 MB
InnoDB: Renaming log file ./ib_logfile101 to ./ib_logfile0
InnoDB: New log files created, LSN=1626007

###

From server startup log:

###

2015-12-17 13:43:57 52535 [Warning] InnoDB: Resizing redo log from 2*3072 to 4*128 pages, LSN=1626134
2015-12-17 13:43:57 52535 [Warning] InnoDB: Starting to delete and rewrite log files.
2015-12-17 13:43:57 52535 [Note] InnoDB: Setting log file ./ib_logfile101 size to 2 MB
2015-12-17 13:43:57 52535 [Note] InnoDB: Setting log file ./ib_logfile1 size to 2 MB
2015-12-17 13:43:57 52535 [Note] InnoDB: Setting log file ./ib_logfile2 size to 2 MB
2015-12-17 13:43:57 52535 [Note] InnoDB: Setting log file ./ib_logfile3 size to 2 MB
2015-12-17 13:43:57 52535 [Note] InnoDB: Renaming log file ./ib_logfile101 to ./ib_logfile0
2015-12-17 13:43:57 52535 [Warning] InnoDB: New log files created, LSN=1626134

###

[Steffen Boehme (boemm)]

I also hit this problem and it figured out, that this behavior also applies to percona cluster setups which is more critical in my opinion.

When a cluster node is restarted / first started and joins the cluster with a full sync then a innobackupex process is used to sync the data from a donor to the joiner.

Even in this case the prepare step just prepares the synced data with the default innodb settings (or even with the one which are stored under /etc/mysql/my.cnf) which differs from our live settings ...
Moreover we have more then one cluster node running on 1 dedicated server it might be that the innodb settings differs per instance.

So with the new behavior the full sync of a cluster node failed and the node was not able to join the cluster, which is pretty critical in production environments.

I fixed this while it happens with adding the correct settings to the /etc/mysql/my.cnf file, but this cannot be the final solution ...

Can you please take that in mind when checking this bug ...

Thanks
Steffen

[Sergei Glushchenko (sergei.glushchenko)]

Hi Steffen,

Can you please be more specific of which setting are ignored?

[Steffen Boehme (boemm)]

Of course,

my innobackupex config files looks like this:

# This MySQL options file was generated by innobackupex.

# The MySQL server
[mysqld]
innodb_checksum_algorithm=innodb
innodb_log_checksum_algorithm=innodb
innodb_data_file_path=ibdata1:10M:autoextend
innodb_log_files_in_group=3
innodb_log_file_size=268435456
innodb_fast_checksum=false
innodb_page_size=16384
innodb_log_block_size=512
innodb_undo_directory=.
innodb_undo_tablespaces=0

Especially the innodb_log_files_* options are important and are not respected by the innobackupex apply step unless the backup-my.cnf is explicit given by the --defaults-file option.

If no defaults file is given as parameter the backup-my.cnf located in the data directory is just ignored and the /etc/mysql/my.cnf file (if exist) is applied.
If it not exists mysql defaults will be used which differs in number and size of the innodb_log_files.

This is the output of the innobackueb apply with no special options (like its called in the cluster synchronization procedure):
As you can see, there are 2 file with size 48 MB created ...

11:35 root@sbo-test [cgn]:/local/mysql/dumps/test$ innobackupex --apply-log data
151218 11:35:59 innobackupex: Starting the apply-log operation

IMPORTANT: Please check that the apply-log run completes successfully.
           At the end of a successful apply-log run innobackupex
           prints "completed OK!".

innobackupex version 2.3.3 based on MySQL server 5.6.24 Linux (x86_64) (revision id: 525ca7d)
xtrabackup: cd to /local/mysql/dumps/test/data
xtrabackup: This target seems to be not prepared yet.
xtrabackup: xtrabackup_logfile detected: size=2097152, start_lsn=(234837625)
xtrabackup: using the following InnoDB configuration for recovery:
xtrabackup: innodb_data_home_dir = ./
xtrabackup: innodb_data_file_path = ibdata1:10M:autoextend
xtrabackup: innodb_log_group_home_dir = ./
xtrabackup: innodb_log_files_in_group = 1
xtrabackup: innodb_log_file_size = 2097152
xtrabackup: using the following InnoDB configuration for recovery:
xtrabackup: innodb_data_home_dir = ./
xtrabackup: innodb_data_file_path = ibdata1:10M:autoextend
xtrabackup: innodb_log_group_home_dir = ./
xtrabackup: innodb_log_files_in_group = 1
xtrabackup: innodb_log_file_size = 2097152
xtrabackup: Starting InnoDB instance for recovery.
xtrabackup: Using 104857600 bytes for buffer pool (set by --use-memory parameter)
InnoDB: Using atomics to ref count buffer pool pages
InnoDB: The InnoDB memory heap is disabled
InnoDB: Mutexes and rw_locks use GCC atomic builtins
InnoDB: Memory barrier is not used
InnoDB: Compressed tables use zlib 1.2.8
InnoDB: Not using CPU crc32 instructions
InnoDB: Initializing buffer pool, size = 100.0M
InnoDB: Completed initialization of buffer pool
InnoDB: Highest supported file format is Barracuda.
InnoDB: The log sequence numbers 151311211 and 151311211 in ibdata files do not match the log sequence number 234837625 in the ib_logfiles!
InnoDB: Database was not shutdown normally!
InnoDB: Starting crash recovery.
InnoDB: Reading tablespace information from the .ibd files...
InnoDB: Restoring possible half-written data pages
InnoDB: from the doublewrite buffer...
InnoDB...

[Steffen Boehme (boemm)]

Here is how it processes with the backup-my.cnf file specified:

11:38 root@sbo-test [cgn]:/local/mysql/dumps/test$ innobackupex --defaults-file=data/backup-my.cnf --apply-log data
151218 11:38:34 innobackupex: Starting the apply-log operation

IMPORTANT: Please check that the apply-log run completes successfully.
           At the end of a successful apply-log run innobackupex
           prints "completed OK!".

innobackupex version 2.3.3 based on MySQL server 5.6.24 Linux (x86_64) (revision id: 525ca7d)
xtrabackup: cd to /local/mysql/dumps/test/data
xtrabackup: This target seems to be not prepared yet.
xtrabackup: xtrabackup_logfile detected: size=2097152, start_lsn=(234837625)
xtrabackup: using the following InnoDB configuration for recovery:
xtrabackup: innodb_data_home_dir = ./
xtrabackup: innodb_data_file_path = ibdata1:10M:autoextend
xtrabackup: innodb_log_group_home_dir = ./
xtrabackup: innodb_log_files_in_group = 1
xtrabackup: innodb_log_file_size = 2097152
xtrabackup: using the following InnoDB configuration for recovery:
xtrabackup: innodb_data_home_dir = ./
xtrabackup: innodb_data_file_path = ibdata1:10M:autoextend
xtrabackup: innodb_log_group_home_dir = ./
xtrabackup: innodb_log_files_in_group = 1
xtrabackup: innodb_log_file_size = 2097152
xtrabackup: Starting InnoDB instance for recovery.
xtrabackup: Using 104857600 bytes for buffer pool (set by --use-memory parameter)
InnoDB: Using atomics to ref count buffer pool pages
InnoDB: The InnoDB memory heap is disabled
InnoDB: Mutexes and rw_locks use GCC atomic builtins
InnoDB: Memory barrier is not used
InnoDB: Compressed tables use zlib 1.2.8
InnoDB: Not using CPU crc32 instructions
InnoDB: Initializing buffer pool, size = 100.0M
InnoDB: Completed initialization of buffer pool
InnoDB: Highest supported file format is Barracuda.
InnoDB: The log sequence numbers 151311211 and 151311211 in ibdata files do not match the log sequence number 234837625 in the ib_logfiles!
InnoDB: Database was not shutdown normally!
InnoDB: Starting crash recovery.
InnoDB: Reading tablespace information from the .ibd files...
InnoDB: Restoring possible half-written data pages
InnoDB: from the doublewrite buffer...
InnoDB: 128 rollback segment(s) are active.
InnoDB: Waiting for purge to start
InnoDB: 5.6.24 started; log sequence number 234837625
xtrabackup: Last MySQL binlog file position 0, file name /local/mysql/message_service/log/master-bin.000004

xtrabackup: Recovered WSREP position: 00000000-0000-0000-0000-000000000000:-1
xtrabackup: starting shutdown with innodb_fast_shutdown = 1
InnoDB: FTS optimize thread exiting.
InnoDB: Starting shutdown...
InnoDB: Shutdown completed; log sequence number 234838323
xtrabackup: using the following InnoDB configuration for recovery:
xtrabackup: innodb_data_home_dir = ./
xtrabackup: innodb_data_file_path = ibdata1:10M:autoextend
xtrabackup: innodb_log_group_home_dir = ./
xtrabackup: innodb_log_files_in_group = 3
xtrabackup: innodb_log_file_size = 268435456
InnoDB: Using atomics to ref count buffer pool pages
InnoDB: The InnoDB memory heap is disabled
InnoDB: Mutexes and rw_locks use GCC atomic builtins
InnoDB: Memory barrier is not use...

[Steffen Boehme (boemm)]

If there would be some option for the joiner which forces the use of this backup-my.cnf file this would probably also work, but its unnecessary complicated in my opinion.

Was the behavior changed intentionally or is this a bug!?
If it changed intentionally ... whats the reason for the change?

[Sergei Glushchenko (sergei.glushchenko)]

It looks like a bug

[Pat Suwalski (pat-suwalski)]

I added some thoughts to the comments of bug #1528271 that may be useful.

[Sergei Glushchenko (sergei.glushchenko)]

https://github.com/percona/percona-xtrabackup/pull/148

[Steffen Boehme (boemm)]

Great thanks a lot for the fix!

[Shahriyar Rzayev (rzayev-sehriyar)]

Percona now uses JIRA for bug reports so this bug report is migrated to: https://jira.percona.com/browse/PXB-450