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

Bug #1527081 reported by Sergei Glushchenko on 2015-12-17
20
This bug affects 3 people
Affects Status Importance Assigned to Milestone
Percona XtraBackup moved to https://jira.percona.com/projects/PXB
Status tracked in 2.4
2.3
Fix Released
High
Sergei Glushchenko
2.4
Fix Released
High
Sergei Glushchenko

Bug Description

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) wrote :

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

Hi Steffen,

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

Steffen Boehme (boemm) wrote :
Download full text (4.9 KiB)

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...

Read more...

Steffen Boehme (boemm) wrote :
Download full text (4.0 KiB)

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...

Read more...

Steffen Boehme (boemm) wrote :

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?

It looks like a bug

Pat Suwalski (pat-suwalski) wrote :

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

Steffen Boehme (boemm) wrote :

Great thanks a lot for the fix!

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

To post a comment you must log in.
This report contains Public information  Edit
Everyone can see this information.

Duplicates of this bug

Other bug subscribers