xtrabackup 2.1 against percona server 5.6 hangs during incremental --apply-log-only

[George Ormond Lorch III]

While attempting to prepare an incremental backup taken from Percona Server 5.6 which had an RQG load on it at the time, xtrabackup_56 appears to hang:

InnoDB Backup Utility v1.5.1-xtrabackup; Copyright 2003, 2009 Innobase Oy
and Percona Ireland Ltd 2009-2012. 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!".

130508 05:14:47 innobackupex: Starting ibbackup with command: xtrabackup_56 --defaults-file="/mnt/var/cpb/test-3/mysql.1/my.cnf" --defaults-group="mysqld" --prepare --target-dir=/mnt/var/cpb/test-3/restore-working --apply-log-only --incremental-dir=/mnt/var/c
pb/test-3/backup-0.2 --tmpdir=/mnt/var/cpb/test-3/mysql.1/tmp

xtrabackup_56 version 2.1.0beta1 for MySQL server 5.6.10 Linux (x86_64) (revision id: undefined)
incremental backup from 718023213 is enabled.
xtrabackup: cd to /mnt/var/cpb/test-3/restore-working
xtrabackup: This target seems to be already prepared.
xtrabackup: xtrabackup_logfile detected: size=56983552, start_lsn=(718263135)
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 = /mnt/var/cpb/test-3/backup-0.2
xtrabackup: innodb_log_files_in_group = 1
xtrabackup: innodb_log_file_size = 56983552
InnoDB: Allocated tablespace 18, old maximum was 0
xtrabackup: page size for /mnt/var/cpb/test-3/backup-0.2/ibdata1.delta is 16384 bytes
Applying /mnt/var/cpb/test-3/backup-0.2/ibdata1.delta to ./ibdata1...
xtrabackup: page size for /mnt/var/cpb/test-3/backup-0.2/rqg1/r.ibd.delta is 16384 bytes
Applying /mnt/var/cpb/test-3/backup-0.2/rqg1/r.ibd.delta to ./rqg1/r.ibd...
xtrabackup: page size for /mnt/var/cpb/test-3/backup-0.2/rqg1/table500_innodb_dynamic.ibd.delta is 16384 bytes
xtrabackup: Renaming rqg1/table500_innodb_dynamic to rqg1/xtrabackup_tmp_#16.ibd
Applying /mnt/var/cpb/test-3/backup-0.2/rqg1/table500_innodb_dynamic.ibd.delta to ./rqg1/table500_innodb_dynamic.ibd...
xtrabackup: page size for /mnt/var/cpb/test-3/backup-0.2/rqg1/table500_innodb_default.ibd.delta is 16384 bytes
Applying /mnt/var/cpb/test-3/backup-0.2/rqg1/table500_innodb_default.ibd.delta to ./rqg1/table500_innodb_default.ibd...
xtrabackup: page size for /mnt/var/cpb/test-3/backup-0.2/rqg1/table500_innodb_compressed_int.ibd.delta is 16384 bytes
xtrabackup: Renaming rqg1/table500_innodb_compressed_int to rqg1/xtrabackup_tmp_#20.ibd
Applying /mnt/var/cpb/test-3/backup-0.2/rqg1/table500_innodb_compressed_int.ibd.delta to ./rqg1/table500_innodb_compressed_int.ibd...
xtrabackup: page size for /mnt/var/cpb/test-3/backup-0.2/rqg1/table500_innodb_dynamic_int_autoinc.ibd.delta is 16384 bytes
xtrabackup: Renaming rqg1/table500_innodb_dynamic_int_autoinc to rqg1/xtrabackup_tmp_#22.ibd
Applying /mnt/var/cpb/test-3/backup-0.2/rqg1/table500_innodb_dynamic_int_autoinc.ibd.delta to ./rqg1/table500_innodb_dynamic_int_autoinc.ibd...
xtrabackup: page size for /mnt/var/cpb/test-3/backup-0.2/rqg1/h.ibd.delta is 16384 bytes
Applying /mnt/var/cpb/test-3/backup-0.2/rqg1/h.ibd.delta to ./rqg1/h.ibd...
xtrabackup: page size for /mnt/var/cpb/test-3/backup-0.2/rqg1/table100_innodb_default_int.ibd.delta is 16384 bytes
xtrabackup: Renaming rqg1/table100_innodb_default_int to rqg1/xtrabackup_tmp_#11.ibd
Applying /mnt/var/cpb/test-3/backup-0.2/rqg1/table100_innodb_default_int.ibd.delta to ./rqg1/table100_innodb_default_int.ibd...
xtrabackup: page size for /mnt/var/cpb/test-3/backup-0.2/rqg1/table100_innodb_dynamic.ibd.delta is 16384 bytes
xtrabackup: Renaming rqg1/table100_innodb_dynamic to rqg1/xtrabackup_tmp_#6.ibd
Applying /mnt/var/cpb/test-3/backup-0.2/rqg1/table100_innodb_dynamic.ibd.delta to ./rqg1/table100_innodb_dynamic.ibd...
xtrabackup: page size for /mnt/var/cpb/test-3/backup-0.2/rqg1/n.ibd.delta is 16384 bytes
Applying /mnt/var/cpb/test-3/backup-0.2/rqg1/n.ibd.delta to ./rqg1/n.ibd...
xtrabackup: page size for /mnt/var/cpb/test-3/backup-0.2/rqg1/table100_innodb_compressed.ibd.delta is 16384 bytes
Applying /mnt/var/cpb/test-3/backup-0.2/rqg1/table100_innodb_compressed.ibd.delta to ./rqg1/table100_innodb_compressed.ibd...
xtrabackup: page size for /mnt/var/cpb/test-3/backup-0.2/rqg1/table500_innodb_dynamic_int.ibd.delta is 16384 bytes
xtrabackup: Renaming rqg1/table500_innodb_dynamic_int to rqg1/xtrabackup_tmp_#19.ibd
Applying /mnt/var/cpb/test-3/backup-0.2/rqg1/table500_innodb_dynamic_int.ibd.delta to ./rqg1/table500_innodb_dynamic_int.ibd...
xtrabackup: page size for /mnt/var/cpb/test-3/backup-0.2/rqg1/table500_innodb_default_int.ibd.delta is 16384 bytes
xtrabackup: Renaming rqg1/table500_innodb_default_int to rqg1/xtrabackup_tmp_#21.ibd
Applying /mnt/var/cpb/test-3/backup-0.2/rqg1/table500_innodb_default_int.ibd.delta to ./rqg1/table500_innodb_default_int.ibd...
xtrabackup: page size for /mnt/var/cpb/test-3/backup-0.2/rqg1/table500_innodb_compressed.ibd.delta is 16384 bytes
xtrabackup: Renaming rqg1/table500_innodb_compressed to rqg1/xtrabackup_tmp_#17.ibd
Applying /mnt/var/cpb/test-3/backup-0.2/rqg1/table500_innodb_compressed.ibd.delta to ./rqg1/table500_innodb_compressed.ibd...
xtrabackup: page size for /mnt/var/cpb/test-3/backup-0.2/rqg1/table100_innodb_default_int_autoinc.ibd.delta is 16384 bytes
xtrabackup: Renaming rqg1/table100_innodb_default_int_autoinc to rqg1/xtrabackup_tmp_#15.ibd
Applying /mnt/var/cpb/test-3/backup-0.2/rqg1/table100_innodb_default_int_autoinc.ibd.delta to ./rqg1/table100_innodb_default_int_autoinc.ibd...
xtrabackup: page size for /mnt/var/cpb/test-3/backup-0.2/rqg1/table100_innodb_compressed_int_autoinc.ibd.delta is 16384 bytes
xtrabackup: Renaming rqg1/table100_innodb_compressed_int_autoinc to rqg1/xtrabackup_tmp_#14.ibd
Applying /mnt/var/cpb/test-3/backup-0.2/rqg1/table100_innodb_compressed_int_autoinc.ibd.delta to ./rqg1/table100_innodb_compressed_int_autoinc.ibd...
xtrabackup: page size for /mnt/var/cpb/test-3/backup-0.2/rqg1/table100_innodb_dynamic_int.ibd.delta is 16384 bytes
xtrabackup: Renaming rqg1/table100_innodb_dynamic_int to rqg1/xtrabackup_tmp_#9.ibd
Applying /mnt/var/cpb/test-3/backup-0.2/rqg1/table100_innodb_dynamic_int.ibd.delta to ./rqg1/table100_innodb_dynamic_int.ibd...
xtrabackup: page size for /mnt/var/cpb/test-3/backup-0.2/rqg1/o.ibd.delta is 16384 bytes
Applying /mnt/var/cpb/test-3/backup-0.2/rqg1/o.ibd.delta to ./rqg1/o.ibd...
xtrabackup: page size for /mnt/var/cpb/test-3/backup-0.2/rqg1/e.ibd.delta is 16384 bytes
Applying /mnt/var/cpb/test-3/backup-0.2/rqg1/e.ibd.delta to ./rqg1/e.ibd...
xtrabackup: page size for /mnt/var/cpb/test-3/backup-0.2/rqg1/y.ibd.delta is 16384 bytes
Applying /mnt/var/cpb/test-3/backup-0.2/rqg1/y.ibd.delta to ./rqg1/y.ibd...
xtrabackup: page size for /mnt/var/cpb/test-3/backup-0.2/rqg1/table100_innodb_default.ibd.delta is 16384 bytes
xtrabackup: Renaming rqg1/table100_innodb_default to rqg1/xtrabackup_tmp_#8.ibd
Applying /mnt/var/cpb/test-3/backup-0.2/rqg1/table100_innodb_default.ibd.delta to ./rqg1/table100_innodb_default.ibd...
xtrabackup: page size for /mnt/var/cpb/test-3/backup-0.2/rqg1/table500_innodb_default_int_autoinc.ibd.delta is 16384 bytes
xtrabackup: Renaming rqg1/table500_innodb_default_int_autoinc to rqg1/xtrabackup_tmp_#24.ibd
Applying /mnt/var/cpb/test-3/backup-0.2/rqg1/table500_innodb_default_int_autoinc.ibd.delta to ./rqg1/table500_innodb_default_int_autoinc.ibd...
xtrabackup: page size for /mnt/var/cpb/test-3/backup-0.2/rqg1/table500_innodb_compressed_int_autoinc.ibd.delta is 16384 bytes
xtrabackup: Renaming rqg1/table500_innodb_compressed_int_autoinc to rqg1/xtrabackup_tmp_#23.ibd
Applying /mnt/var/cpb/test-3/backup-0.2/rqg1/table500_innodb_compressed_int_autoinc.ibd.delta to ./rqg1/table500_innodb_compressed_int_autoinc.ibd...
xtrabackup: page size for /mnt/var/cpb/test-3/backup-0.2/rqg1/table100_innodb_compressed_int.ibd.delta is 16384 bytes
xtrabackup: Renaming rqg1/table100_innodb_compressed_int to rqg1/xtrabackup_tmp_#10.ibd
Applying /mnt/var/cpb/test-3/backup-0.2/rqg1/table100_innodb_compressed_int.ibd.delta to ./rqg1/table100_innodb_compressed_int.ibd...
xtrabackup: page size for /mnt/var/cpb/test-3/backup-0.2/mysql/slave_relay_log_info.ibd.delta is 16384 bytes
Applying /mnt/var/cpb/test-3/backup-0.2/mysql/slave_relay_log_info.ibd.delta to ./mysql/slave_relay_log_info.ibd...
xtrabackup: page size for /mnt/var/cpb/test-3/backup-0.2/mysql/slave_master_info.ibd.delta is 16384 bytes
Applying /mnt/var/cpb/test-3/backup-0.2/mysql/slave_master_info.ibd.delta to ./mysql/slave_master_info.ibd...
xtrabackup: page size for /mnt/var/cpb/test-3/backup-0.2/mysql/innodb_table_stats.ibd.delta is 16384 bytes
Applying /mnt/var/cpb/test-3/backup-0.2/mysql/innodb_table_stats.ibd.delta to ./mysql/innodb_table_stats.ibd...
xtrabackup: page size for /mnt/var/cpb/test-3/backup-0.2/mysql/slave_worker_info.ibd.delta is 16384 bytes
Applying /mnt/var/cpb/test-3/backup-0.2/mysql/slave_worker_info.ibd.delta to ./mysql/slave_worker_info.ibd...
xtrabackup: page size for /mnt/var/cpb/test-3/backup-0.2/mysql/innodb_index_stats.ibd.delta is 16384 bytes
Applying /mnt/var/cpb/test-3/backup-0.2/mysql/innodb_index_stats.ibd.delta to ./mysql/innodb_index_stats.ibd...
xtrabackup: page size for /mnt/var/cpb/test-3/backup-0.2/PERCONA_SCHEMA/backup_test_mark.ibd.delta is 16384 bytes
Applying /mnt/var/cpb/test-3/backup-0.2/PERCONA_SCHEMA/backup_test_mark.ibd.delta to ./PERCONA_SCHEMA/backup_test_mark.ibd...
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 = /mnt/var/cpb/test-3/backup-0.2
xtrabackup: innodb_log_files_in_group = 1
xtrabackup: innodb_log_file_size = 56983552
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: CPU does not support crc32 instructions
InnoDB: Initializing buffer pool, size = 100.0M
InnoDB: Completed initialization of buffer pool
InnoDB: Highest supported file format is Barracuda.
InnoDB: Log scan progressed past the checkpoint lsn 718263135
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 723505664 (10%)
InnoDB: Doing recovery: scanned up to log sequence number 728748544 (20%)
InnoDB: Doing recovery: scanned up to log sequence number 733991424 (31%)
InnoDB: Doing recovery: scanned up to log sequence number 739234304 (41%)
InnoDB: Doing recovery: scanned up to log sequence number 744477184 (51%)
InnoDB: Doing recovery: scanned up to log sequence number 749720064 (62%)
InnoDB: Doing recovery: scanned up to log sequence number 754962944 (72%)
InnoDB: Doing recovery: scanned up to log sequence number 760205824 (82%)
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

[George Ormond Lorch III (gl-az)]

my.cnf:

[client]
port=10000
socket=/mnt/var/cpb/test-3/mysql.1/mysql.sock
[mysqld]
basedir=/mnt/bin/ps-5.6-log-archive
datadir=/mnt/var/cpb/test-3/mysql.1/data
tmpdir=/mnt/var/cpb/test-3/mysql.1/tmp
port=10000
socket=/mnt/var/cpb/test-3/mysql.1/mysql.sock
pid-file=/mnt/var/cpb/test-3/mysql.1/mysql.pid
console
user=root
server-id=1
innodb_buffer_pool_size=1G
innodb_file_format=antelope
innodb_file_per_table=1
innodb_log_file_size=512M

[George Ormond Lorch III (gl-az)]

Attached via gdb and obtained backtrace:

Thread 11 (Thread 0x7fc1775fe700 (LWP 1692)):
#0 0x0000003e5140b43c in pthread_cond_wait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0
#1 0x00000000005bd6d3 in os_cond_wait (event=0x26d3c70, reset_sig_count=1) at /mnt/xb-2.1-log-archive/mysql-5.6/storage/innobase/os/os0sync.cc:214
#2 os_event_wait_low (event=0x26d3c70, reset_sig_count=1) at /mnt/xb-2.1-log-archive/mysql-5.6/storage/innobase/os/os0sync.cc:610
#3 0x000000000055cbfa in os_aio_simulated_handle (global_segment=0, message1=0x7fc1775fdd98, message2=0x7fc1775fdd90, type=0x7fc1775fdd88) at /mnt/xb-2.1-log-archive/mysql-5.6/storage/innobase/os/os0file.cc:5437
#4 0x00000000005704e3 in fil_aio_wait (segment=0) at /mnt/xb-2.1-log-archive/mysql-5.6/storage/innobase/fil/fil0fil.cc:5547
#5 0x000000000059e178 in io_handler_thread (arg=<value optimized out>) at /mnt/xb-2.1-log-archive/mysql-5.6/storage/innobase/srv/srv0start.cc:478
#6 0x0000003e51407851 in start_thread () from /lib64/libpthread.so.0
#7 0x0000003e50ce890d in clone () from /lib64/libc.so.6

Thread 10 (Thread 0x7fc177fff700 (LWP 1693)):
#0 0x0000003e5140b43c in pthread_cond_wait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0
#1 0x00000000005bd6d3 in os_cond_wait (event=0x26d3d00, reset_sig_count=1) at /mnt/xb-2.1-log-archive/mysql-5.6/storage/innobase/os/os0sync.cc:214
#2 os_event_wait_low (event=0x26d3d00, reset_sig_count=1) at /mnt/xb-2.1-log-archive/mysql-5.6/storage/innobase/os/os0sync.cc:610
#3 0x000000000055cbfa in os_aio_simulated_handle (global_segment=1, message1=0x7fc177ffed98, message2=0x7fc177ffed90, type=0x7fc177ffed88) at /mnt/xb-2.1-log-archive/mysql-5.6/storage/innobase/os/os0file.cc:5437
#4 0x00000000005704e3 in fil_aio_wait (segment=1) at /mnt/xb-2.1-log-archive/mysql-5.6/storage/innobase/fil/fil0fil.cc:5547
#5 0x000000000059e178 in io_handler_thread (arg=<value optimized out>) at /mnt/xb-2.1-log-archive/mysql-5.6/storage/innobase/srv/srv0start.cc:478
#6 0x0000003e51407851 in start_thread () from /lib64/libpthread.so.0
#7 0x0000003e50ce890d in clone () from /lib64/libc.so.6

Thread 9 (Thread 0x7fc17d4b1700 (LWP 1694)):
#0 0x0000003e5140b43c in pthread_cond_wait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0
#1 0x00000000005bd6d3 in os_cond_wait (event=0x26d3d90, reset_sig_count=1442) at /mnt/xb-2.1-log-archive/mysql-5.6/storage/innobase/os/os0sync.cc:214
#2 os_event_wait_low (event=0x26d3d90, reset_sig_count=1442) at /mnt/xb-2.1-log-archive/mysql-5.6/storage/innobase/os/os0sync.cc:610
#3 0x000000000055cbfa in os_aio_simulated_handle (global_segment=2, message1=0x7fc17d4b0d98, message2=0x7fc17d4b0d90, type=0x7fc17d4b0d88) at /mnt/xb-2.1-log-archive/mysql-5.6/storage/innobase/os/os0file.cc:5437
#4 0x00000000005704e3 in fil_aio_wait (segment=2) at /mnt/xb-2.1-log-archive/mysql-5.6/storage/innobase/fil/fil0fil.cc:5547
#5 0x000000000059e178 in io_handler_thread (arg=<value optimized out>) at /mnt/xb-2.1-log-archive/mysql-5.6/storage/innobase/srv/srv0start.cc:478
#6 0x0000003e51407851 in start_thread () from /lib64/libpthread.so.0
#7 0x0000003e50ce890d in clone () from /lib64/libc.so.6

Thread 8 (Thread 0x7fc17cab0700 (LWP 1695)):
#0 0x0000003e5140b43c in pthr...

[George Ormond Lorch III (gl-az)]

Still happening, see https://bugs.launchpad.net/percona-xtrabackup/+bug/1186422

[Alexey Kopytov (akopytov)]

The stacktraces in #1186422 and here are different. The stacktrace in this bug suggests it is fixed with the patch for bug #1079700. Restoring the duplicate status. Please reopen if you hit a hang with exactly the same stacktrace.