apply-log Failed with Small xtrabackup_logfile

Bug #1403237 reported by Jervin R on 2014-12-16
24
This bug affects 4 people
Affects Status Importance Assigned to Milestone
Percona XtraBackup moved to https://jira.percona.com/projects/PXB
Fix Released
High
Sergei Glushchenko
2.2
Fix Released
High
Sergei Glushchenko
2.3
Fix Released
High
Sergei Glushchenko

Bug Description

When running apply-log on a backup taken with 2.2.7 and small xtrabackup_logfile, the process failed.

141216 17:09:26 innobackupex: Starting ibbackup with command: xtrabackup --defaults-file="/mnt/data/localbackup/mysql02-2.hostname.com/full/2014-12-15_23-00-46/backup-my.cnf" --defaults-group="mysqld" --prepare --target-dir=/mnt/data/localbackup/mysql02-2.hostname.com/full/2014-12-15_23-00-46

xtrabackup version 2.2.7 based on MySQL server 5.6.21 Linux (x86_64) (revision id: )
xtrabackup: cd to /mnt/data/localbackup/mysql02-2.hostname.com/full/2014-12-15_23-00-46
xtrabackup: This target seems to be not prepared yet.
xtrabackup: xtrabackup_logfile detected: size=2097152, start_lsn=(6539475748335)
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.3
InnoDB: 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 6041770903387 and 6041770903387 in ibdata files do not match the log sequence number 6539475748335 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: We scanned the log up to 6539475747840. A checkpoint was at 6539475748335 and the maximum LSN on a database page was 0. It is possible that the database is now corrupt!
2014-12-16 17:09:26 7f79175f8720 InnoDB: Error: page 2 log sequence number 6539633980252
InnoDB: is in the future! Current system log sequence number 6539475748335.
InnoDB: Your database may be corrupt or you may have copied the InnoDB
InnoDB: tablespace but not the InnoDB log files. See
InnoDB: http://dev.mysql.com/doc/refman/5.6/en/forcing-innodb-recovery.html
InnoDB: for more information.
[LSN errors continues until Ctrl-C]

[root@mysql02-2 full]# cat 2014-12-15_23-00-46/backup-my.cnf
# This MySQL options file was generated by innobackupex.

# The MySQL server
[mysqld]
innodb_data_file_path=ibdata1:10M:autoextend
innodb_log_files_in_group=2
innodb_log_file_size=6442450944
innodb_fast_checksum=OFF
innodb_page_size=16384
innodb_log_block_size=512

You can see an ib_logfile0 was created with only 2M in size.

[root@mysql02-2 full]# ls -alh 2014-12-15_23-00-46
total 28G
drwxr-xr-x 16 root root 4.0K Dec 16 17:09 .
drwxr-xr-x 4 root root 4.0K Dec 16 17:09 ..
[...]
-rw-r--r-- 1 root root 265 Dec 15 23:00 backup-my.cnf
-rw-r----- 1 root root 28G Dec 16 17:09 ibdata1
-rw-r----- 1 root root 2.0M Dec 16 17:09 ib_logfile0
-rw-r----- 1 root root 93M Dec 16 06:04 ib_lru_dump
drwxr-xr-x 2 root root 4.0K Dec 16 06:04 mysql
drwx------ 2 root root 75 Dec 16 06:04 percona
drwxr-xr-x 2 root root 4.0K Dec 16 06:04 performance_schema
drwx------ 2 root root 122 Dec 16 06:04 test
-rw-r--r-- 1 root root 26 Dec 16 06:04 xtrabackup_binlog_info
-rw-r----- 1 root root 101 Dec 16 06:04 xtrabackup_checkpoints
-rw-r--r-- 1 root root 633 Dec 16 06:04 xtrabackup_info

Here's one more backup previously taken with the same version, notice the difference in ibdata1 size:

[root@mysql02-2 full]# ls -alh 2014-12-14_13-04-31
total 17G
drwxr-xr-x 16 root root 4.0K Dec 15 21:31 .
drwxr-xr-x 4 root root 4.0K Dec 16 17:09 ..
[...]
-rw-r--r-- 1 root root 265 Dec 14 13:04 backup-my.cnf
-rw-r----- 1 root root 2.1G Dec 15 21:31 ibdata1
-rw-r--r-- 1 root root 6.0G Dec 15 21:31 ib_logfile0
-rw-r--r-- 1 root root 6.0G Dec 15 21:31 ib_logfile1
-rw-r----- 1 root root 92M Dec 14 19:38 ib_lru_dump
drwxr-xr-x 2 root root 4.0K Dec 14 19:38 mysql
drwx------ 2 root root 75 Dec 14 19:38 percona
drwxr-xr-x 2 root root 4.0K Dec 14 19:38 performance_schema
drwx------ 2 root root 122 Dec 14 19:38 test
-rw-r--r-- 1 root root 25 Dec 14 19:38 xtrabackup_binlog_info
-rw-r--r-- 1 root root 42 Dec 15 21:31 xtrabackup_binlog_pos_innodb
-rw-r----- 1 root root 101 Dec 15 21:31 xtrabackup_checkpoints
-rw-r--r-- 1 root root 632 Dec 14 19:38 xtrabackup_info
-rw-r----- 1 root root 2.5G Dec 15 21:03 xtrabackup_logfile

Related branches

Jervin R (revin) wrote :
Download full text (5.2 KiB)

Without hitting Ctrl-C, I'd eventually get an assertion, the full command was: innobackupex --apply-log 2014-12-16_18-02-25

141217 16:21:42 innobackupex: Starting ibbackup with command: xtrabackup --defaults-file="/mnt/data/localbackup/mysql06-2.hostname.com/full/2014-12-16_18-02-25/backup-my.cnf" --defaults-group="mysqld" --prepare --target-dir=/mnt/data/localbackup/mysql06-2.hostname.com/full/2014-12-16_18-02-25

xtrabackup version 2.2.7 based on MySQL server 5.6.21 Linux (x86_64) (revision id: )
xtrabackup: cd to /mnt/data/localbackup/mysql06-2.hostname.com/full/2014-12-16_18-02-25
xtrabackup: This target seems to be not prepared yet.
xtrabackup: xtrabackup_logfile detected: size=2097152, start_lsn=(6542575355872)
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.3
InnoDB: 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 6041770903387 and 6041770903387 in ibdata files do not match the log sequence number 6542575355872 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: We scanned the log up to 6542575355392. A checkpoint was at 6542575355872 and the maximum LSN on a database page was 0. It is possible that the database is now corrupt!
[...]
2014-12-17 16:21:44 7f9506c08720 InnoDB: Error: page 98345 log sequence number 6542647464609
InnoDB: is in the future! Current system log sequence number 6542575355872.
InnoDB: Your database may be corrupt or you may have copied the InnoDB
InnoDB: tablespace but not the InnoDB log files. See
InnoDB: http://dev.mysql.com/doc/refman/5.6/en/forcing-innodb-recovery.html
InnoDB: for more information.
InnoDB: 125 transaction(s) which must be rolled back or cleaned up
InnoDB: in total 0 row operations to undo
InnoDB: Trx id counter is 32925002752
InnoDB: Last MySQL binlog file position 0 1019564159, file name /mnt/data/master/bin-log.003375
InnoDB: Cleaning up trx with id 32945843215
2014-12-17 16:21:44 7f9506c08720 InnoDB: Assertion failure in thread 14...

Read more...

Jervin R (revin) wrote :

Also for some reason, though I was not able to save it - the backup only got 2.0K of xtrabackup_logfile I suspect this may be where the problem is coming from.

The issue is following

Server is Percona Server 5.5 with log_file_size = 6G. There is no support for log files larger than 4G in total in MySQL 5.5.

Percona Server 5.5 does support log files larger than >4G. XtraBackup 2.1 based on PS 5.5 can handle such files.

MySQL 5.6 introduced support for large log files, but these files are not compatible with PS 5.5 log files. For example LOG_CHECKPOINT_OFFSET is stored at different offset.

This makes value of group->lsn_offset invalid in xtrabackup 2.2. Which then used in log_group_calc_lsn_offset to find an offset in log file to read from. So, xtrabackup log copying thread simply cannot position itself correctly in server log files.

Peiran Song (peiran-song) wrote :

Another customer #49275 experienced backup failure after upgrade to 2.2.6/7.

The failure was during backup step, symptom was that log copying thread stuck at one sequence number and never move forward. Eventually, it reported error:

xtrabackup: error: log block numbers mismatch:
xtrabackup: error: expected log block no. 882663131, but got no. 891051735 from the log file.
xtrabackup: Error: xtrabackup_copy_logfile() failed.
innobackupex: got a fatal error with the following stacktrace: at /usr/bin/innobackupex line 2695
        main::wait_for_ibbackup_file_create('/tmp/xtrabackup_suspended_2') called at /usr/bin/innobackupex line 2715
        main::wait_for_ibbackup_suspend('/tmp/xtrabackup_suspended_2') called at /usr/bin/innobackupex line 1968
        main::backup() called at /usr/bin/innobackupex line 1592
innobackupex: Error: The xtrabackup child process has died at /usr/bin/innobackupex line 2695.

Innodb log file size is at 8G total, and server is PS 5.5.40. Test with Xtrabackup 2.1.9 always success, while with 2.2.7, half failure, half success. What Sergei explained above seems to apply to the case.

50% is expected failure rate for 8G log files. Lower bits of last checkpoint LSN are stored at the same offsets in both PS 5.5 and MySQL 5.6. Last checkpoint LSN is in lower 4G 50% of time. I think this issue has the same root cause.

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

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

Other bug subscribers