innobackupex apply-log error for fullbackup

MySQL & MariaDB Percona XtraBackup
1

I am taking a fullbackup using

My Data directory are on local directory and I am taking backup on NFS mount point.

innobackupex --slave-info --safe-slave-backup /gwire_dw/extradbbackuptest/

please note : /gwire_dw/ is a netapp mount point

backup is successful.

next when I go to prepare the fullbackup

using

innobackupex --defaults-file=/etc/my.cnf --apply-log --use-memory=8G /gwire_dw/extradbbackuptest/2013-12-30_16-39-55

it fails

here is the prepare log

InnoDB Backup Utility v1.5.1-xtrabackup; Copyright 2003, 2009 Innobase Oy
and Percona LLC and/or its affiliates 2009-2013. All Rights Reserved.

This software is published under
the GNU GENERAL PUBLIC LICENSE Version 2, June 1991.

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

131230 21:16:10 innobackupex: Starting ibbackup with command: xtrabackup_55 --defaults-file=“/etc/my.cnf” --defaults-group=“mysqld” --prepare --target-dir=/gwire_dw/extradbbackuptest/2013-12-30_16-39-55 --use-memory=8G --tmpdir=/tmp

xtrabackup_55 version 2.1.5 for Percona Server 5.5.31 Linux (x86_64) (revision id: 680)
xtrabackup: cd to /gwire_dw/extradbbackuptest/2013-12-30_16-39-55
xtrabackup: This target seems to be not prepared yet.
xtrabackup: xtrabackup_logfile detected: size=3633463296, start_lsn=(1417494366104)
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 = 3633463296
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 = 3633463296
xtrabackup: Starting InnoDB instance for recovery.
xtrabackup: Using 8589934592 bytes for buffer pool (set by --use-memory parameter)
131230 21:16:17 InnoDB: The InnoDB memory heap is disabled
131230 21:16:17 InnoDB: Mutexes and rw_locks use GCC atomic builtins
131230 21:16:17 InnoDB: Compressed tables use zlib 1.2.3
131230 21:16:17 InnoDB: Initializing buffer pool, size = 8.0G
131230 21:16:17 InnoDB: Completed initialization of buffer pool
131230 21:16:17 InnoDB: highest supported file format is Barracuda.
InnoDB: Log scan progressed past the checkpoint lsn 1417494366104
131230 21:16:17 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 1417499608576 (0 %)
…
InnoDB: Doing recovery: scanned up to log sequence number 1420723979776 (99 %)
InnoDB: Doing recovery: scanned up to log sequence number 1420724108086 (99 %)
131230 21:17:30 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 131230 21:18:55 InnoDB: Assertion failure in thread 140345562953472 in file rem0rec.c line 569
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: [url]http://dev.mysql.com/doc/refman/5.5/en/forcing-innodb-recovery.html[/url]
InnoDB: about forcing recovery.
innobackupex: Error:
innobackupex: ibbackup failed at /usr/bin/innobackupex line 2517.

I checked these 2 lines from the log

xtrabackup: cd to /gwire_dw/extradbbackuptest/2013-12-30_16-39-55
xtrabackup: This target seems to be not prepared yet.

but this directory exists.

Please help I am trying this for last 2-3 days and its not working .

2

My.cnf looks like this

[mysqld]
log-bin = /var/lib/mysqllogs/bin.log
log-bin-index = /var/lib/mysqllogs/log-bin.index
performance_schema
datadir=/var/lib/mysql
relay-log=/var/lib/mysqllogs/relay.log
relay-log-index=/var/lib/mysqllogs/relay-log
user=mysql
symbolic-links=0
max_connections=500
skip-slave-start
max_allowed_packet=100M
innodb_file_format=Barracuda
innodb_flush_log_at_trx_commit = 2
innodb-log-buffer-size=16M
innodb_buffer_pool_size=10G
innodb_log_file_size=64M
innodb_file_per_table
innodb_flush_method=O_DIRECT
table_cache = 3000
skip-name-resolve
thread_cache_size =150
innodb_buffer_pool_instances=10

3

Can you please try to prepare backup without --defaults-file=/etc/my.cnf option and check if it works.
For further details check highlighted “Note” section in documentation here [url]Preparing the backup

4

I tried running prepare without --defaults-file=/etc/my.cnf and its same error

Assertion failure in thread 140336965527296 in file rem0rec.c line 569

5

Please share source MySQL version from where you took the backup and version of xtrabackup you are trying with. Also, try with latest xtrabackup version and post full backup log in case if error persists.

6

so it failed again though this time with another error

extrabacup version percona-xtrabackup-2.1.6-702.rhel6.x86_64
MySQL version 5.5.34-log

Data Directory Size 409 GB

Tables are compressed .

Backup taken by running this command

innobackupex --slave-info --safe-slave-backup /gwire_dw/extradbbackuptest/ 2>&1 | tee /tmp/backup3rdjan2004.txt

backup log

InnoDB Backup Utility v1.5.1-xtrabackup; Copyright 2003, 2009 Innobase Oy
and Percona LLC and/or its affiliates 2009-2013. All Rights Reserved.

This software is published under
the GNU GENERAL PUBLIC LICENSE Version 2, June 1991.

Get the latest version of Percona XtraBackup, documentation, and help resources:
http://www.percona.com/xb/p

140102 20:40:55 innobackupex: Connecting to MySQL server with DSN ‘dbi:mysql:;mysql_read_default_group=xtrabackup’ as ‘bkpuser’ (using password: YES).
140102 20:40:55 innobackupex: Connected to MySQL server
140102 20:40:55 innobackupex: Executing a version check against the server…

A software update is available:

* The current version for MySQL Community Server (GPL) is 5.5.35.

140102 20:40:56 innobackupex: Done.
IMPORTANT: Please check that the backup run completes successfully.
At the end of a successful backup run innobackupex
prints “completed OK!”.

innobackupex: Using mysql server version 5.5.34-log

innobackupex: Created backup directory /gwire_dw/extradbbackuptest/2014-01-02_20-40-57

140102 20:40:57 innobackupex: Starting ibbackup with command: xtrabackup_55 --defaults-group=“mysqld” --backup --suspend-at-end --target-dir=/gwire_dw/extradbbackuptest/2014-01-02_20-40-57 --tmpdir=/tmp
innobackupex: Waiting for ibbackup (pid=7231) to suspend
innobackupex: Suspend file ‘/gwire_dw/extradbbackuptest/2014-01-02_20-40-57/xtrabackup_suspended_2’

xtrabackup_55 version 2.1.6 for Percona Server 5.5.31 Linux (x86_64) (revision id: 702)
xtrabackup: uses posix_fadvise().
xtrabackup: cd to /gwire_dw/mysql_app278/mysql
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 = 67108864
xtrabackup: using O_DIRECT

log scanned up to (1464649810058)
140102 20:41:01 InnoDB: Warning: allocated tablespace 44, old maximum was 9
[01] Copying ./ibdata1 to /gwire_dw/extradbbackuptest/2014-01-02_20-40-57/ibdata1
[01] xtrabackup: Page 64 is a doublewrite buffer page, skipping.
…
[01] xtrabackup: Page 188 is a doublewrite buffer page, skipping.
log scanned up to (1464649973184)

log scanned up to (1464661518012)
[01] …done
[01] Copying ./test/pankaj.ibd to /gwire_dw/extradbbackuptest/2014-01-02_20-40-57/test/pankaj.ibd
[01] …done
[01] Copying ./hydra/url_count.ibd to /gwire_dw/extradbbackuptest/2014-01-02_20-40-57/hydra/url_count.ibd
[01] …done
[01] Copying ./hydra/hydra_es_index.ibd to /gwire_dw/extradbbackuptest/2014-01-02_20-40-57/hydra/hydra_es_index.ibd
[01] …done
[01] ./hydra/hydra_content.ibd is compressed with page size = 8192 bytes
[01] Copying ./hydra/hydra_content.ibd to /gwire_dw/extradbbackuptest/2014-01-02_20-40-57/hydra/hydra_content.ibd
log scanned up to (1464661839410)
…

log scanned up to (1467316471704)
[01] …done
[01] Copying ./monitoring/heartbeat.ibd to /gwire_dw/extradbbackuptest/2014-01-02_20-40-57/monitoring/heartbeat.ibd
[01] …done
log scanned up to (1467316474619)
xtrabackup: Creating suspend file ‘/gwire_dw/extradbbackuptest/2014-01-02_20-40-57/xtrabackup_suspended_2’ with pid ‘7231’
log scanned up to (1467316475067)

140103 02:01:21 innobackupex: Continuing after ibbackup has suspended
innobackupex:: Slave open temp tables: 0
140103 02:01:21 innobackupex: Starting to lock all tables…
140103 02:01:21 innobackupex: All tables locked and flushed to disk

140103 02:01:21 innobackupex: Starting to backup non-InnoDB tables and files
innobackupex: in subdirectories of ‘/gwire_dw/mysql_app278/mysql’
innobackupex: Backing up file ‘/gwire_dw/mysql_app278/mysql/test/pankaj.frm’
innobackupex: Backing up file ‘/gwire_dw/mysql_app278/mysql/hydra/hydra_content.frm’
innobackupex: Backing up file ‘/gwire_dw/mysql_app278/mysql/hydra/hydra_es_index.frm’
innobackupex: Backing up file ‘/gwire_dw/mysql_app278/mysql/hydra/url_count.frm’
innobackupex: Backing up file ‘/gwire_dw/mysql_app278/mysql/hydra/hydra_hash.frm’
innobackupex: Backing up file ‘/gwire_dw/mysql_app278/mysql/hydra/db.opt’
innobackupex: Backing up files ‘/gwire_dw/mysql_app278/mysql/mysql/*.{frm,isl,MYD,MYI,MAD,MAI,MRG,TRG,TRN,ARM,ARZ,CSM,CSV,opt,par}’ (75 files)

log scanned up to (1467316475720)
log scanned up to (1467316476598)
log scanned up to (1467316476598)
innobackupex: Backing up file ‘/gwire_dw/mysql_app278/mysql/monitoring/heartbeat.frm’
innobackupex: Backing up file ‘/gwire_dw/mysql_app278/mysql/monitoring/db.opt’
innobackupex: Backing up files ‘/gwire_dw/mysql_app278/mysql/performance_schema/*.{frm,isl,MYD,MYI,MAD,MAI,MRG,TRG,TRN,ARM,ARZ,CSM,CSV,opt,par}’ (18 files)
log scanned up to (1467316479669)
140103 02:01:26 innobackupex: Finished backing up non-InnoDB tables and files

140103 02:01:26 innobackupex: Waiting for log copying to finish

xtrabackup: The latest check point (for incremental): ‘1467297323880’
xtrabackup: Stopping log copying thread.
.>> log scanned up to (1467316479669)

xtrabackup: Creating suspend file ‘/gwire_dw/extradbbackuptest/2014-01-02_20-40-57/xtrabackup_log_copied’ with pid ‘7231’
xtrabackup: Transaction log of lsn (1464554168682) to (1467316479669) was copied.
140103 02:01:27 innobackupex: All tables unlocked
innobackupex:: Starting slave SQL thread

innobackupex: Backup created in directory ‘/gwire_dw/extradbbackuptest/2014-01-02_20-40-57’
innobackupex: MySQL binlog position: filename ‘bin.000006’, position 107
innobackupex: MySQL slave binlog position: master host ‘10.0.7.79’, filename ‘bin.000186’, position 117927779
140103 02:01:27 innobackupex: Connection to database server closed
140103 02:01:27 innobackupex: completed OK!

so backup was successful

prepare log is …

7

now Preparing backup

command

innobackupex --apply-log --use-memory=8G /gwire_dw/extradbbackuptest/2014-01-02_20-40-57 2>&1 | tee /tmp/prepare3rdjan2004.txt

InnoDB Backup Utility v1.5.1-xtrabackup; Copyright 2003, 2009 Innobase Oy
and Percona LLC and/or its affiliates 2009-2013. All Rights Reserved.

This software is published under
the GNU GENERAL PUBLIC LICENSE Version 2, June 1991.

Get the latest version of Percona XtraBackup, documentation, and help resources:
[url]Percona XtraBackup - MySQL Database Backup Software

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

140103 02:33:56 innobackupex: Starting ibbackup with command: xtrabackup_55 --defaults-file=“/gwire_dw/extradbbackuptest/2014-01-02_20-40-57/backup-my.cnf” --defaults-group=“mysqld” --prepare --target-dir=/gwire_dw/extradbbackuptest/2014-01-02_20-40-57 --use-memory=8G --tmpdir=/tmp

xtrabackup_55 version 2.1.6 for Percona Server 5.5.31 Linux (x86_64) (revision id: 702)
xtrabackup: cd to /gwire_dw/extradbbackuptest/2014-01-02_20-40-57
xtrabackup: This target seems to be not prepared yet.
140103 2:33:56 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=3933044736, start_lsn=(1464554168682)
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 = 3933044736
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 = 3933044736
xtrabackup: Starting InnoDB instance for recovery.
xtrabackup: Using 8589934592 bytes for buffer pool (set by --use-memory parameter)
140103 2:34:03 InnoDB: The InnoDB memory heap is disabled
140103 2:34:03 InnoDB: Mutexes and rw_locks use GCC atomic builtins
140103 2:34:03 InnoDB: Compressed tables use zlib 1.2.3
140103 2:34:03 InnoDB: Initializing buffer pool, size = 8.0G
140103 2:34:03 InnoDB: Completed initialization of buffer pool
140103 2:34:03 InnoDB: highest supported file format is Barracuda.
InnoDB: Log scan progressed past the checkpoint lsn 1464554168682
140103 2:34:04 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 1464559411200 (0 %)
InnoDB: Doing recovery: scanned up to log sequence number 1464564654080 (0 %)
InnoDB: Doing recovery: scanned up to log sequence number 1464569896960 (0 %)
InnoDB: Doing recovery: scanned up to log sequence number 1464575139840 (0 %)
InnoDB: Doing recovery: scanned up to log sequence number 1464580382720 (0 %)
InnoDB: Doing recovery: scanned up to log sequence number 1464585625600 (0 %)
InnoDB: Doing recovery: scanned up to log sequence number 1464590868480 (1 %)
InnoDB: Doing recovery: scanned up to log sequence number 1467316479669 (79 %)
140103 2:35:07 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 InnoDB: Probable data corruption on page 50419077
InnoDB: Original record (compact record)
InnoDB: on that page.
InnoDB: Cannot find the dir slot for record (compact record)
InnoDB: on that page!
140103 2:35:40 InnoDB: Page dump in ascii and hex (16384 bytes):
len 16384; hex 0000000003012373338303263653600000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000700063000001553c72e293; asc U U U<r E ; ! b 7 + infimum supremum@e o _ + B B BLhttp://www.yourtango.com/2013175840/did-seth-macfarlane-go-too-far7f167d57fe2996111c9e05b5ddb7707d P engaged, married, oscars 2013, oscars, seth macfarlane, family guys, sexism, jokes, weight, boobs, single, love buzz, life stylewere his jokes about women sexist or funny? {“lookswelove”:0.12883829496532057}]}]53b4519476cb03b95d942a028b2e2831aac39687ec1097a70a4b966c0b68afeb@ T ( B ;v= V [url]http://www.morphthing.com/setPoints/75424193?pCheck=b47418ea38087beccbccc7d377955e83e1d8aee1e5cb877b885de9942d66ff02[/url] P Q; go Q; gofb45806ba70b2a85d4193080483077e67c4aab7a5dcaee8fcfafa3b273802ce6 p c U<r ;
InnoDB: End of page dump
140103 2:35:40 InnoDB: Page checksum 4130229248 (32bit_calc: 2497019130), prior-to-4.0.14-form checksum 3591539239
InnoDB: stored checksum 0, prior-to-4.0.14-form stored checksum 341
InnoDB: Page lsn 341 1014162067, low 4 bytes of lsn at page end 1014162067
InnoDB: Page number (if stored to page already) 50419077,
InnoDB: space id (if created with >= MySQL-4.1.1 and stored already) 25
InnoDB: Page may be an update undo log page
InnoDB: Page may be an index page where index id is 55
140103 2:35:40 InnoDB: Assertion failure in thread 139802270525184 in file page0page.c line 153
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: [url]http://dev.mysql.com/doc/refman/5.5/en/forcing-innodb-recovery.html[/url]
InnoDB: about forcing recovery.
innobackupex: Error:
innobackupex: ibbackup failed at /usr/bin/innobackupex line 2569.

I am not sure what’s happening here , my.cnf is same what was mentioned earlier . please help.

8

Hi Pankaj Joshi

The root cause of problem could be data corruption.
Let me help you to check if it’s so.

  • create file “ibd_checksum.sh” with source code:

#!/bin/bash
for i in $(ls /var/lib/mysql//.ibd)
do
innochecksum -v $i
done

  • set permissions: chmod +x ibd_checksum.sh
  • run it and save it’s log: sudo ./ibdscript.sh > idb_checksum.log

And attach here idb_checksum.log or send us the output of “sudo ./ibdscript.sh” command

I would also ask you to run this command in mysql:

select
i.index_id, i.name, t.table_id, t.schema, t.name
from
innodb_sys_indexes i
left join innodb_sys_tables t on i.table_id = t.table_id
where index_id=55

If you’ll find that you have a corrupted table then you can try innodb_force_recovery.
http://dev.mysql.com/doc/refman/5.5/…-recovery.html

Add this:
innodb_force_recovery = 1
(you can start from 1 and change it to 6 if needed; this is well described in the URL below)

To your MySQL config (my.cnf) and restart MySQL.
Check MySQL error log for details.

If the culprit is data corruption then after you’ll solve it you should be able to backup your data.
Please check and let us to know.

9

Hello Mixa

thanks for looking into this, I am running the script now and will share the findings .

I am using MySQL version 5.5.34-log so the query which you mentioned is not able to run .

select
i.index_id, i.name, t.table_id, t.schema, t.name
from
innodb_sys_indexes i
left join innodb_sys_tables t on i.table_id = t.table_id
where index_id=55

any alternate query which could get the expected results from above mentioned query.

10

Can you please try this one?
My mistake I didn’t add database name here…
Or run “use mysql;” command before running te previous one.
The point here - it gets data from tables from database with name “mysql”

select
i.index_id, i.name, t.table_id, t.schema, t.name
from
mysql.innodb_sys_indexes i
left join mysql.innodb_sys_tables t on i.table_id = t.table_id
where index_id=55

11

select
i.index_id, i.name, t.table_id, t.schema, t.name
from
mysql.innodb_sys_indexes i
left join mysql.innodb_sys_tables t on i.table_id = t.table_id
where index_id=55

it gives me this error

Table ‘mysql.innodb_sys_indexes’ doesn’t exist .

Please note I am using MySQL version 5.5.34-log

I also ran the script which you sent .

this is the final output

./ibd_checksum.sh > idb_checksum.log
page 0 invalid (fails log sequence number check)

please note we are using compression for tables .

I am attaching the complete log as well.

idb_checksum_test.txt (12.1 KB)

12

Hello mixa/mirfan

can you please look into this and let me know if I can provide any information to be able to fix this issue . thanks in advance.

13

Hello Percona Team.

I upgraded MySQL 5.5.34 to 5.6.11 and was able to take the backup and prepare it successfully with xtrabackup_56 version 2.1.5 . Thank you for all your support really appreciate it.

14

Hi Pankaj,
Glad that it worked for you.
Can you please try to restore backup on some test environment?
Just to be sure that it works and not corrupted or something…

15

Hello Mixa,

Aplogies for delayed response , I restored backup on a server by manually copying the backup directory to another server and it worked. infact I set a new slave by taking backup of existing slave .

Thanks
Pankaj