Percona Server moved to https://jira.percona.com/projects/PS

xTtrabackup failed with Assertion failure on Innodb

Asked by sriram ramakrishnan

We are trying to do proof-of-concept of Percona products and in the process of testing xTrabackup with Community server MySQL.

1. Scenario 1:

No load + backup + prepare -> Works fine. No Errors

2. Scenario 2:

Generate load using HammerOra with around 300K tpm
Backup phase is good
Prepare phase fails with assertion errors.

Here is the error

[root@pasundbavm4 bin]# ./xtrabackup --prepare --target-dir=/mysql/backup
./xtrabackup version 2.0.0 for Percona Server 5.1.59 unknown-linux-gnu (x86_64) (revision id: undefined)
xtrabackup: cd to /mysql/backup
xtrabackup: This target seems to be not prepared yet.
120427 10:29:10 InnoDB: Operating system error number 2 in a file operation.
InnoDB: The error means the system cannot find the path specified.
xtrabackup: Warning: cannot open ./xtrabackup_logfile. will try to find.
  xtrabackup: 'ib_logfile0' seems to be 'xtrabackup_logfile'. will retry.
xtrabackup: xtrabackup_logfile detected: size=93732864, start_lsn=(4598867512)
xtrabackup: Temporary instance for recovery is set as followings.
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 = 93732864
xtrabackup: Starting InnoDB instance for recovery.
xtrabackup: Using 104857600 bytes for buffer pool (set by --use-memory parameter)
InnoDB: The InnoDB memory heap is disabled
InnoDB: Mutexes and rw_locks use GCC atomic builtins
InnoDB: Compressed tables use zlib 1.2.3
InnoDB: Warning: innodb_file_io_threads is deprecated. Please use innodb_read_io_threads and innodb_write_io_threads instead
120427 10:29:10 InnoDB: Initializing buffer pool, size = 100.0M
120427 10:29:10 InnoDB: Completed initialization of buffer pool
120427 10:29:10 InnoDB: highest supported file format is Barracuda.
InnoDB: Log scan progressed past the checkpoint lsn 4598867512
120427 10:29:10 InnoDB: Database was not shut down normally!
InnoDB: Starting crash recovery.
InnoDB: Reading tablespace information from the .ibd files...
InnoDB: Doing recovery: scanned up to log sequence number 4604110336 (6 %)
InnoDB: Doing recovery: scanned up to log sequence number 4609353216 (12 %)
InnoDB: Doing recovery: scanned up to log sequence number 4614596096 (18 %)
InnoDB: Doing recovery: scanned up to log sequence number 4619838976 (25 %)
InnoDB: Doing recovery: scanned up to log sequence number 4625081856 (31 %)
InnoDB: Doing recovery: scanned up to log sequence number 4630324736 (37 %)
120427 10:29:13 InnoDB: Starting an apply batch of log records to the database...
InnoDB: Progress in percents: 0 1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42 43 44 45 46 47 48 49 50 51 52 53 54 55 56 57 58 59 60 61 62 63 64 65 66 67 68 69 70 71 72 73 74 75 76 77 78 79 80 81 82 83 84 85 86 87 88 89 90 91 92 93 94 95 96 97 98 99
InnoDB: Apply batch completed
InnoDB: Doing recovery: scanned up to log sequence number 4635567616 (44 %)
InnoDB: Doing recovery: scanned up to log sequence number 4640810496 (50 %)
InnoDB: Doing recovery: scanned up to log sequence number 4646053376 (56 %)
InnoDB: Doing recovery: scanned up to log sequence number 4651296256 (62 %)
InnoDB: Doing recovery: scanned up to log sequence number 4656539136 (69 %)
InnoDB: Doing recovery: scanned up to log sequence number 4661782016 (75 %)
120427 10:29:21 InnoDB: Starting an apply batch of log records to the database...
InnoDB: Progress in percents: 0 1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42 43 44 45 46 47 48 49 50 51 52 53 54 55 56 57 58 59 60 61 62 63 64 65 66 67 68 69 70 71 72 73 74 75 76 77 78 79 80 81 82 83 84 85 86 87 88 89 90 91 92 93 94 95 96 97 98 99
InnoDB: Apply batch completed
InnoDB: Doing recovery: scanned up to log sequence number 4667024896 (81 %)
InnoDB: Doing recovery: scanned up to log sequence number 4672267776 (88 %)
InnoDB: Doing recovery: scanned up to log sequence number 4672933870 (88 %)
InnoDB: 12 transaction(s) which must be rolled back or cleaned up
InnoDB: in total 82 row operations to undo
InnoDB: Trx id counter is 37600
120427 10:29:27 InnoDB: Starting an apply batch of log records to the database...
InnoDB: Progress in percents: 120427 10:29:27 InnoDB: Assertion failure in thread 1122167104 in file ibuf/ibuf0ibuf.c line 1323
InnoDB: Failing assertion: len % DATA_NEW_ORDER_NULL_TYPE_BUF_SIZE <= 1
InnoDB: We intentionally generate a memory trap.
InnoDB: Submit a detailed bug report to http://bugs.mysql.com.
InnoDB: If you get repeated assertion failures or crashes, even
InnoDB: immediately after the mysqld startup, there may be
InnoDB: corruption in the InnoDB tablespace. Please refer to
InnoDB: http://dev.mysql.com/doc/refman/5.1/en/forcing-innodb-recovery.html
InnoDB: about forcing recovery.
Aborted
[root@pasundbavm4 bin]# df -h

Any ideas?

Question information

Language:
English Edit question
Status:
Answered
For:
Percona Server moved to https://jira.percona.com/projects/PS Edit question
Assignee:
No assignee Edit question
Last query:
Last reply:
Revision history for this message
Launchpad Janitor (janitor) said : 		#1

This question was expired because it remained in the 'Open' state without activity for the last 15 days.

Revision history for this message
Alexey Kopytov (akopytov) said : 		#2

The assertion failure is most likely a result of using a wrong xtrabackup binary to prepare a backup. Data files created with MySQL 5.5 or Percona Server 5.5 should be processed by the 'xtrabackup_55' binary rather than 'xtrabackup'. Please make sure you're using a correct binary and report a bug if the problem persists.

Can you help with this problem?

Provide an answer of your own, or ask sriram ramakrishnan for more information if necessary.

To post a message you must log in.