xtrabackup 2.2.3 failed: expected log block no. 435565628, but got no. 439759928 from the log file

Bug #1365835 reported by Peiran Song on 2014-09-05
14
This bug affects 2 people
Affects Status Importance Assigned to Milestone
Percona XtraBackup moved to https://jira.percona.com/projects/PXB
Fix Released
High
Sergei Glushchenko
2.0
Won't Fix
Undecided
Unassigned
2.1
Fix Released
High
Sergei Glushchenko
2.2
Fix Released
High
Sergei Glushchenko

Bug Description

Customer reported that xtrabackup 2.2.3 fails on taking incremental backups on one slave. Previous version of xtrabackup worked fine on this server before. And if the replication is stopped during the backup, backup would succeed.

Backup command:
----------------------------------------
innobackupex --incremental --incremental-lsn=41380448403316 /mnt/staging/mysqlA/aus-dbs16/5133 --no-timestamp --ibbackup=xtrabackup_55 --user=xxxx --password=XXXXXXX --slave-info --safe-slave-backup --tmpdir=/tmp/xbm-4135527 --throttle=0 --defaults-file=/var/lib/mysql/A/mysqlA.cnf --socket=/var/lib/mysql/A/mysqlA.sock --no-lock

Output:
----------------
140904 13:24:59 innobackupex: Starting ibbackup with command: xtrabackup_55 --defaults-file="/var/lib/mysql/A/mysqlA.cnf" --defaults-group="mysqld" --backup --suspend-at-end --target-dir=/mnt/staging/mysqlA/aus-dbs16/5133 --tmpdir=/tmp/xbm-4135527 --extra-lsndir='/tmp/xbm-4135527' --incremental-lsn='41380448403316'
                                        innobackupex: Waiting for ibbackup (pid=23021) to suspend innobackupex: Suspend file '/mnt/staging/mysqlA/aus-dbs16/5133/xtrabackup_suspend
ed_2'

                                        xtrabackup_55 version 2.2.3 based on MySQL server 5.6.17 Linux (x86_64) (revision id: )
                                        incremental backup from 41380448403316 is enabled.
                                        xtrabackup: uses posix_fadvise().
                                        xtrabackup: cd to /var/lib/mysql/A
                                        xtrabackup: open files limit requested 0, set to 96000
                                        xtrabackup: using the following InnoDB configuration:
                                        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 = 3221225472
                                        xtrabackup: using O_DIRECT
                                        >> log scanned up to (41454695642624)
                                        xtrabackup: using the full scan for incremental backup
                                        [01] Copying ./ibdata1 to /mnt/staging/mysqlA/aus-dbs16/5133/ibdata1.delta
                                        >> log scanned up to (41454695642624)
                                        >> log scanned up to (41454695642624)
....
...
                                        >> log scanned up to (41454695642624)
                                        >> log scanned up to (41454695642624)
                                        xtrabackup: error: log block numbers mismatch:
                                        xtrabackup: error: expected log block no. 435565628, but got no. 439759928 from the log file.
                                        xtrabackup: Error: xtrabackup_copy_logfile() failed.
                                        innobackupex: Error: The xtrabackup child process has died at /usr/bin/innobackupex line 2672.

Variables:
---------------------
innodb_log_block_size 512
innodb_log_buffer_size 16777216
innodb_log_file_size 3221225472
innodb_log_files_in_group 2

Status:
------------------
xtrabackup started at 13:24:59, failed at 13:58:06

At 13:28:05
Log sequence number 41454814261866
Log flushed up to 41454814255943
Last checkpoint at 41454812819846

At 13:54:04
Log sequence number 41456453356468
Log flushed up to 41456453355760
Last checkpoint at 41455591826645

Note:
--------------
1) This error looks similar to https://bugs.launchpad.net/percona-xtrabackup/+bug/1206309. However, in this case, the log block number is not near the wrap around position (1073741823).

2) The two xtrabackup outputs from the customer(one above, the other one in comment #8 of bug #1073741823) showed the same number of different log blocks between the expected no. and got no., which is 4194300.

3) Xtrabackup output showed that the log sequence number started from 41454695642624 and never move beyond it.

Related branches

tags: added: i45208
Alexey Kopytov (akopytov) wrote :

Please make sure that innodb_log_file_size used by the server and the value in my.cnf are the same.

One possible explanation for this bug could be that innodb_log_file_size value got changed in my.cnf without restarting the server. So InnoDB and PXB (which reads my.cnf) disagree on its value.

Changed in percona-xtrabackup:
status: New → Incomplete
Peiran Song (peiran-song) wrote :

Alexey,

That should be the same.

From the xtrabackup output:

xtrabackup: innodb_log_files_in_group = 2
xtrabackup: innodb_log_file_size = 3221225472

From show variables:

innodb_log_file_size 3221225472
innodb_log_files_in_group 2

Changed in percona-xtrabackup:
status: Incomplete → New
Changed in percona-xtrabackup:
assignee: nobody → Sergei Glushchenko (sergei.glushchenko)
Download full text (9.5 KiB)

Tried to verify with Xtrabackup 2.2.3 on PS 5.6.17. First take a fullbackup and then incremental on slave while running sysbench on master server for heavy load. I couldn't able to reproduce it.

Set variables :
innodb_log_block_size 512
innodb_log_buffer_size 16777216
innodb_log_file_size 50331648
innodb_log_files_in_group 2

Sysbench command on master:

sysbench --test=oltp --oltp-table-size=100000 --oltp-test-mode=complex --oltp-read-only=off --num-threads=100 --max-time=120 --max-requests=0 --mysql-db=dbtest --mysql-user=root --mysql-password=msandbox --mysql-socket=/tmp/mysql_sandbox20082.sock run

Take fullbackup:

nilnandan@Dell-XPS:~$ sudo innobackupex --defaults-file=/home/nilnandan/sandboxes/rsandbox_Percona-Server-5_6_17/node1/my.sandbox.cnf --user=root --password=msandbox --socket=/tmp/mysql_sandbox20083.sock /home/nilnandan/backup/
....
...
140909 15:37:27 innobackupex: Starting to backup non-InnoDB tables and files
innobackupex: in subdirectories of '/home/nilnandan/sandboxes/rsandbox_Percona-Server-5_6_17/node1/data'
innobackupex: Backing up files '/home/nilnandan/sandboxes/rsandbox_Percona-Server-5_6_17/node1/data/mysql/*.{frm,isl,MYD,MYI,MAD,MAI,MRG,TRG,TRN,ARM,ARZ,CSM,CSV,opt,par}' (74 files)
>> log scanned up to (215795275)
innobackupex: Backing up files '/home/nilnandan/sandboxes/rsandbox_Percona-Server-5_6_17/node1/data/performance_schema/*.{frm,isl,MYD,MYI,MAD,MAI,MRG,TRG,TRN,ARM,ARZ,CSM,CSV,opt,par}' (53 files)
innobackupex: Backing up file '/home/nilnandan/sandboxes/rsandbox_Percona-Server-5_6_17/node1/data/nil/db.opt'
innobackupex: Backing up file '/home/nilnandan/sandboxes/rsandbox_Percona-Server-5_6_17/node1/data/dbtest/db.opt'
innobackupex: Backing up file '/home/nilnandan/sandboxes/rsandbox_Percona-Server-5_6_17/node1/data/dbtest/sbtest.frm'
140909 15:37:28 innobackupex: Finished backing up non-InnoDB tables and files

140909 15:37:28 innobackupex: Executing LOCK BINLOG FOR BACKUP...
140909 15:37:28 innobackupex: Executing FLUSH ENGINE LOGS...
140909 15:37:28 innobackupex: Waiting for log copying to finish

xtrabackup: The latest check point (for incremental): '195285221'
xtrabackup: Stopping log copying thread.
.>> log scanned up to (215852629)

xtrabackup: Creating suspend file '/home/nilnandan/backup/2014-09-09_15-37-25/xtrabackup_log_copied' with pid '28997'
xtrabackup: Transaction log of lsn (195181186) to (215852629) was copied.
140909 15:37:29 innobackupex: Executing UNLOCK BINLOG
140909 15:37:29 innobackupex: Executing UNLOCK TABLES
140909 15:37:29 innobackupex: All tables unlocked

innobackupex: Backup created in directory '/home/nilnandan/backup/2014-09-09_15-37-25'
innobackupex: MySQL binlog position: filename 'mysql-bin.000002', position 120
140909 15:37:29 innobackupex: Connection to database server closed
140909 15:37:29 innobackupex: completed OK!

Checked xtrabackup_checkpoints

cat xtrabackup_checkpoints
backup_type = full-backuped
from_lsn = 0
to_lsn = 195285221
last_lsn = 215852629
compact = 0

Take incremental backup with to_lsn

nilnandan@Dell-XPS:~$ sudo sudo innobackupex --incremental --incremental-lsn=195285221 /home/nilnandan/backup/2014-09-09_15-37-25/incremental --slave-inf...

Read more...

Changed in percona-xtrabackup:
status: New → Incomplete
egezon (egezon-berisha) wrote :

Note that our MySQL version is 5.5.29, and the xtrabackup verison is 2.2.3

> select @@version;
+-----------------+
| @@version |
+-----------------+
| 5.5.29-29.4-log |
+-----------------+
1 row in set (0.00 sec)

> exit;
Bye

$ xtrabackup --version
xtrabackup version 2.2.3 based on MySQL server 5.6.17 Linux (x86_64) (revision id: )

Changed in percona-xtrabackup:
status: Incomplete → New

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

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

Other bug subscribers