Percona XtraBackup moved to https://jira.percona.com/projects/PXB

xtrabackup-2.2.5 + Percona 5.6.21 log-apply is crashing

Bug #1383284 reported by Yarikdot
10
This bug affects 1 person
Affects Status Importance Assigned to Milestone
Percona XtraBackup moved to https://jira.percona.com/projects/PXB
Incomplete
Undecided
Unassigned
percona-xtrabackup (CentOS)
New
Undecided
Unassigned

Bug Description

After upgrading from percona-xtrabackup-20-2.0.8-587.rhel6.x86_64 to percona-xtrabackup-2.2.5-5027.el6.x86_64, xtrabackup doesn't apply log anymore.

We backup our databases with this script:
BACKUPDIR=/mnt/nfs/backup/`hostname -f`/
innobackupex --user=**** --password=..... --no-timestamp $BACKUPDIR
sleep 10
echo; echo; echo; echo; echo; echo;
innobackupex --user=***** --password=..... --apply-log --use-memory=1G $BACKUPDIR

After upgrading xtrabackup, first step still works, but the second one crashes:

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

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

141020 14:37:08 innobackupex: Starting ibbackup with command: xtrabackup --defaults-file="/...../10-20-2014_14-31-11/backup-my.cnf" --defaults-group="mysqld" --prepare --target-dir=/..../10-20-2014_14-31-11 --use-memory=1G --tmpdir=/tmp

xtrabackup version 2.2.5 based on MySQL server 5.6.21 Linux (x86_64) (revision id: )
xtrabackup: cd to /...../10-20-2014_14-31-11
xtrabackup: This target seems to be not prepared yet.
xtrabackup: xtrabackup_logfile detected: size=2949120, start_lsn=(125020934417)
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 = 2949120
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 = 2949120
xtrabackup: Starting InnoDB instance for recovery.
xtrabackup: Using 1073741824 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 = 1.0G
InnoDB: Completed initialization of buffer pool
InnoDB: Highest supported file format is Barracuda.
InnoDB: Log scan progressed past the checkpoint lsn 125020934417
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: Doing recovery: scanned up to log sequence number 125023552704 (99%)
InnoDB: Starting an apply batch of log records to the database...
InnoDB: Progress in percent: 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: Last MySQL binlog file position 0 12638937, file name mysql-bin.000154
InnoDB: 128 rollback segment(s) are active.
InnoDB: Waiting for purge to start
InnoDB: 5.6.21 started; log sequence number 125023552704

[notice (again)]
  If you use binary log and don't use any hack of group commit,
  the binary log position seems to be:
InnoDB: Last MySQL binlog file position 0 12638937, file name mysql-bin.000154

xtrabackup: starting shutdown with innodb_fast_shutdown = 1
12:37:29 UTC - xtrabackup got signal 11 ;
This could be because you hit a bug or data is corrupted.
This error can also be caused by malfunctioning hardware.
We will try our best to scrape up some info that will hopefully help
diagnose the problem, but since we have already crashed,
something is definitely wrong and this may fail.

Thread pointer: 0x0
Attempting backtrace. You can use the following information to find out
where mysqld died. If you see no messages after this, something went
terribly wrong...
stack_bottom = 0 thread_stack 0x10000
xtrabackup(my_print_stacktrace+0x35) [0x9f2a9c]
xtrabackup(handle_fatal_signal+0x2bb) [0x7f5cd3]
/lib64/libpthread.so.0() [0x3a4b60f500]

Please report a bug at https://bugs.launchpad.net/percona-xtrabackup
innobackupex: Error:
innobackupex: ibbackup failed at /usr/bin/innobackupex line 2619.

When I straced it, I could see segfault there, but I wasn't able to find why. Downgrade fixed this issue.

What we backup:
 - 80GB database
 - Most of the tables are InnoDB
 - We use Percona server 5.6
 - Everything is installed from RPM
 - We use FULLTEXT index on InnoDB
 - We have several very wide tables - we had to use innodb file format Barracuda and those big tables have ROW_FORMAT = Dynamic (othervise we got out of 8k per row)

Feel free to get in touch, I will provide you with more information.

Revision history for this message
Yarikdot (yarikdot) wrote :
Download full text (3.5 KiB)

Package percona-xtrabackup-21.x86_64 is also crashing:

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

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

141020 15:13:45 innobackupex: Starting ibbackup with command: xtrabackup_56 --defaults-file="/...../10-20-2014_15-07-38/backup-my.cnf" --defaults-group="mysqld" --prepare --target-dir=/...../10-20-2014_15-07-38 --use-memory=1G --tmpdir=/tmp

xtrabackup_56 version 2.1.9 for MySQL server 5.6.17 Linux (x86_64) (revision id: 746)
xtrabackup: cd to /mnt/backup/client_dbs_innodb/db20-slave/10-20-2014_15-07-38
xtrabackup: This target seems to be not prepared yet.
xtrabackup: xtrabackup_logfile detected: size=2097152, start_lsn=(125029042395)
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 1073741824 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: Compressed tables use zlib 1.2.3
InnoDB: Using CPU crc32 instructions
InnoDB: Initializing buffer pool, size = 1.0G
InnoDB: Completed initialization of buffer pool
InnoDB: Highest supported file format is Barracuda.
InnoDB: Log scan progressed past the checkpoint lsn 125029042395
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: Doing recovery: scanned up to log sequence number 125029793146 (40%)
InnoDB: Starting an apply batch of log records to the database...
InnoDB: Progress in percent: 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: Last MySQL binlog file position 0 18619084, file name mysql-bin.000154
InnoDB: 128 rollback segment(s) are active.
InnoDB: Waiting for purge to start
InnoDB: 5.6.17 started; log se...

Read more...

Revision history for this message
Nilnandan Joshi (nilnandan-joshi) wrote :
Download full text (9.1 KiB)

Unable to reproduce the same with PS 5.6.21 , Xtrabackup 2.2.5 and 1M reccords. There is one bug related to this. I'm not sure its the same. https://bugs.launchpad.net/percona-xtrabackup/+bug/1368846

Can you provide the my.cnf and full output of apply-log?

nilnandan@Dell-XPS:~$ sudo innobackupex --apply-log -use-memory=1G /home/nilnandan/backup/2014-10-28_11-10-52

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

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

141028 11:11:31 innobackupex: Starting ibbackup with command: xtrabackup --defaults-file="/home/nilnandan/backup/2014-10-28_11-10-52/backup-my.cnf" --defaults-group="mysqld" --prepare --target-dir=/home/nilnandan/backup/2014-10-28_11-10-52 --use-memory=1G --tmpdir=/tmp

xtrabackup version 2.2.5 based on MySQL server 5.6.21 Linux (x86_64) (revision id: )
xtrabackup: cd to /home/nilnandan/backup/2014-10-28_11-10-52
xtrabackup: This target seems to be not prepared yet.
xtrabackup: xtrabackup_logfile detected: size=97845248, start_lsn=(6599591145)
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 = 97845248
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 = 97845248
xtrabackup: Starting InnoDB instance for recovery.
xtrabackup: Using 1073741824 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: Using CPU crc32 instructions
InnoDB: Initializing buffer pool, size = 1.0G
InnoDB: Completed initialization of buffer pool
InnoDB: Highest supported file format is Barracuda.
InnoDB: Log scan progressed past the checkpoint lsn 6599591145
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: Doing recovery: scanned up to log sequence number 6604833792 (6%)
InnoDB: Doing recovery: scanned up to log sequence number 6610076672 (12%)
InnoDB: Doing recovery: scanned up to log sequence number 6615319552 (18%)
InnoDB: Doing recovery: scanned up to log sequence number 6620562432 (24%)
InnoDB: Doing reco...

Read more...

Changed in percona-xtrabackup:
status: New → Incomplete
Revision history for this message
Yarikdot (yarikdot) wrote :

Please find my.cnf in the attachment.

Revision history for this message
Yarikdot (yarikdot) wrote :
Download full text (3.5 KiB)

Updated xtrabackup to 2.2.7 seems like it helped a little bit. It now doesn't crash on every execution, however it still crashes with following error:

141216 11:23:05 innobackupex: Restarting xtrabackup with command: xtrabackup --defaults-file="/mnt/backup/client_dbs_innodb/db29-slave/12-16-2014_10-55-34/backup-my.cnf" --defaults-group="mysqld" --prepare --target-dir=/mnt/backup/client_dbs_innodb/db29-slave/12-16-2014_10-55-34 --use-memory=1G
for creating ib_logfile*

xtrabackup version 2.2.7 based on MySQL server 5.6.21 Linux (x86_64) (revision id: )
xtrabackup: cd to /mnt/backup/client_dbs_innodb/db29-slave/12-16-2014_10-55-34
xtrabackup: This target seems to be already prepared.
xtrabackup: notice: xtrabackup_logfile was already used to '--prepare'.
xtrabackup: using the following InnoDB configuration for recovery:
xtrabackup: innodb_data_home_dir = ./
xtrabackup: innodb_data_file_path = ibdata1:12M:autoextend
xtrabackup: innodb_log_group_home_dir = ./
xtrabackup: innodb_log_files_in_group = 2
xtrabackup: innodb_log_file_size = 134217728
xtrabackup: using the following InnoDB configuration for recovery:
xtrabackup: innodb_data_home_dir = ./
xtrabackup: innodb_data_file_path = ibdata1:12M:autoextend
xtrabackup: innodb_log_group_home_dir = ./
xtrabackup: innodb_log_files_in_group = 2
xtrabackup: innodb_log_file_size = 134217728
xtrabackup: Starting InnoDB instance for recovery.
xtrabackup: Using 1073741824 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 = 1.0G
InnoDB: Completed initialization of buffer pool
InnoDB: Setting log file ./ib_logfile101 size to 128 MB
InnoDB: Progress in MB: 100
InnoDB: Setting log file ./ib_logfile1 size to 128 MB
InnoDB: Progress in MB: 100
InnoDB: Renaming log file ./ib_logfile101 to ./ib_logfile0
InnoDB: New log files created, LSN=487320310587
InnoDB: Highest supported file format is Barracuda.
InnoDB: 128 rollback segment(s) are active.
InnoDB: Waiting for purge to start
InnoDB: 5.6.21 started; log sequence number 487320310796

[notice (again)]
  If you use binary log and don't use any hack of group commit,
  the binary log position seems to be:
InnoDB: Last MySQL binlog file position 0 33456780, file name mysql-bin.001793

xtrabackup: starting shutdown with innodb_fast_shutdown = 1
10:23:21 UTC - xtrabackup got signal 11 ;
This could be because you hit a bug or data is corrupted.
This error can also be caused by malfunctioning hardware.
We will try our best to scrape up some info that will hopefully help
diagnose the problem, but since we have already crashed,
something is definitely wrong and this may fail.

Thread pointer: 0x0
Attempting backtrace. You can use the following information to find out
where mysqld died. If you see no messages after this, something went
terribly wrong...
stack_bottom = 0 thread_stack 0x10000
xtrabackup(my_print_stacktrace+0x35) [0x9f34bc]
xtrabackup(ha...

Read more...

Revision history for this message
Nilnandan Joshi (nilnandan-joshi) wrote :

Hi,

Can you please provide the content of this file? "/mnt/backup/client_dbs_innodb/db29-slave/12-16-2014_10-55-34/backup-my.cnf"
Also /var/log/messages file, xtrabackup might be logging error details there.

Revision history for this message
Yarikdot (yarikdot) wrote :

Please find it below. Very interesting thing is that according to strace it segfaults during reading FTS_...INDEX_1.idb.

The second interesting thing is, that if I restart mysql instance, the script works perfectly. If server runs let's say 24 hours, backup crashes.

backup-my.cnf (tested with 128M memory also with 1GB of memory, the result is the same).
# 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=2
innodb_log_file_size=134217728
innodb_fast_checksum=0
innodb_page_size=16384
innodb_log_block_size=512
innodb_undo_tablespaces=0

/var/log/messages
Feb 11 00:23:39 db yum[11094]: Erased: MySQL-server
Feb 11 00:24:43 db yum[11154]: Erased: MySQL-client
Feb 11 00:25:00 db yum[11177]: Updated: openssl-1.0.1e-30.el6_6.5.x86_64
Feb 11 00:25:01 db yum[11177]: Installed: Percona-Server-shared-56-5.6.22-rel72.0.el6.x86_64
Feb 11 00:25:03 db yum[11177]: Installed: Percona-Server-client-56-5.6.22-rel72.0.el6.x86_64
Feb 11 00:25:10 db yum[11177]: Installed: Percona-Server-server-56-5.6.22-rel72.0.el6.x86_64
Feb 11 00:35:53 db yum[14190]: Installed: percona-xtrabackup-21-2.1.9-746.rhel6.x86_64
Feb 11 16:16:38 db kernel: xtrabackup_56[64910]: segfault at 0 ip (null) sp 00007f8c4d7fac98 error 14 in xtrabackup_56[400000+989000]
Feb 11 16:16:43 db abrt[64911]: Saved core dump of pid 64878 (/usr/bin/xtrabackup_56) to /var/spool/abrt/ccpp-2015-02-11-16:16:39-64878 (800116736 bytes)
Feb 11 16:16:43 db abrtd: Directory 'ccpp-2015-02-11-16:16:39-64878' creation detected
Feb 11 16:16:47 db abrtd: Package 'percona-xtrabackup-21' isn't signed with proper key
Feb 11 16:16:47 db abrtd: 'post-create' on '/var/spool/abrt/ccpp-2015-02-11-16:16:39-64878' exited with 1
Feb 11 16:16:47 db abrtd: Corrupted or bad directory /var/spool/abrt/ccpp-2015-02-11-16:16:39-64878, deleting
Feb 11 17:11:30 db kernel: xtrabackup_56[10892]: segfault at 0 ip (null) sp 00007fb95ebfcc98 error 14 in xtrabackup_56[400000+989000]
Feb 11 17:11:34 db abrt[11154]: Saved core dump of pid 10869 (/usr/bin/xtrabackup_56) to /var/spool/abrt/ccpp-2015-02-11-17:11:30-10869 (508923904 bytes)
Feb 11 17:11:34 db abrtd: Directory 'ccpp-2015-02-11-17:11:30-10869' creation detected
Feb 11 17:11:36 db abrtd: Package 'percona-xtrabackup-21' isn't signed with proper key
Feb 11 17:11:36 db abrtd: 'post-create' on '/var/spool/abrt/ccpp-2015-02-11-17:11:30-10869' exited with 1
Feb 11 17:11:36 db abrtd: Corrupted or bad directory /var/spool/abrt/ccpp-2015-02-11-17:11:30-10869, deleting

Alexey Kopytov (akopytov)
Changed in percona-xtrabackup:
status: Incomplete → New
Revision history for this message
Nilnandan Joshi (nilnandan-joshi) wrote :

Hi,

Can you try to check with latest version of Xtrabackup? Please let us know if you still face the same issue.
https://www.percona.com/downloads/XtraBackup/LATEST/

Changed in percona-xtrabackup:
status: New → Incomplete
Revision history for this message
Priyanka (priyanka-bhayani) wrote :

Hello Team,
We are still getting same error with MySQL version: 5.7.13 and Percona Xtrabackup: 2.3.4
We have a Master-Slave environment where we are taking Percona backup from Slave with --safe-slave-backup option, while trying to apply log for incremental backup following error appears
--------------------------------------------------------------------------------------
11:03:54 UTC - xtrabackup got signal 11 ;
This could be because you hit a bug or data is corrupted.
This error can also be caused by malfunctioning hardware.
Attempting to collect some information that could help diagnose the problem.
As this is a crash and something is definitely wrong, the information
collection process might fail.

Thread pointer: 0x0
Attempting backtrace. You can use the following information to find out
where mysqld died. If you see no messages after this, something went
terribly wrong...
stack_bottom = 0 thread_stack 0x10000
innobackupex(my_print_stacktrace+0x2c)[0xc4e5ec]
innobackupex(handle_fatal_signal+0x262)[0xa548a2]
/lib/x86_64-linux-gnu/libpthread.so.0(+0x10330)[0x7fae2a8c9330]
innobackupex(_Z32page_cur_search_with_match_bytesPK11buf_block_tPK12dict_index_tPK8dtuple_t15page_cur_mode_tPmS9_S9_S9_P10page_cur_t+0x168)[0x9d18a8]
innobackupex(_Z27btr_cur_search_to_nth_levelP12dict_index_tmPK8dtuple_t15page_cur_mode_tmP9btr_cur_tmPKcmP5mtr_t+0x1044)[0x9870c4]
innobackupex(_Z22row_search_index_entryP12dict_index_tPK8dtuple_tmP10btr_pcur_tP5mtr_t+0x11f)[0x85319f]
innobackupex[0xc77d84]
innobackupex[0xc78da8]
innobackupex(_Z14row_purge_stepP9que_thr_t+0x345)[0xc792a5]
innobackupex(_Z15que_run_threadsP9que_thr_t+0x4f2)[0x9b35b2]
innobackupex(srv_worker_thread+0x2f1)[0x7fb8b1]
/lib/x86_64-linux-gnu/libpthread.so.0(+0x8184)[0x7fae2a8c1184]
/lib/x86_64-linux-gnu/libc.so.6(clone+0x6d)[0x7fae28ee937d]

Please report a bug at https://bugs.launchpad.net/percona-xtrabackup

I want to know the possible reasons that I am getting this error

Revision history for this message
Shahriyar Rzayev (rzayev-sehriyar) wrote :

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

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

Other bug subscribers

Bug attachments

Remote bug watches

Bug watches keep track of this bug in other bug trackers.