InnoDB: Assertion failure in thread <nr> in file log0recv.c line 1105 InnoDB: Failing assertion: !page || (ibool)!!page_is_comp(page) == dict_table_is_comp(index->table)

my.cnf:
[client]
port=10000
socket=/mnt/var/cpb/test-9/mysql.1/mysql.sock
[mysqld]
basedir=/mnt/bin/ps-5.5
datadir=/mnt/var/cpb/test-9/mysql.1/data
tmpdir=/mnt/var/cpb/test-9/mysql.1/tmp
port=10000
socket=/mnt/var/cpb/test-9/mysql.1/mysql.sock
pid-file=/mnt/var/cpb/test-9/mysql.1/mysql.pid
console
user=root
server-id=1
innodb_buffer_pool_size=1G
innodb_file_format=barracuda
innodb_file_per_table=1
innodb_log_file_size=512M
innodb_track_changed_pages=FALSE

Backtrace:
Thread 11 (Thread 0x7fb5e4e29700 (LWP 29110)):
#0 0x0000003b90e7939c in _int_malloc () from /lib64/libc.so.6
#1 0x0000003b90e7a911 in malloc () from /lib64/libc.so.6
#2 0x00000000004a422c in mem_heap_create_block (heap=0x0, n=<value optimized out>, type=0, file_name=0x576af8 "/mnt/xb-2.1/Percona-Server-5.5/storage/innobase/dict/dict0mem.c", line=73) at /mnt/xb-2.1/Percona-Server-5.5/storage/innobase/mem/mem0mem.c:333
#3 0x00000000004667c0 in mem_heap_create_func (name=0x57f8e1 "LOG_DUMMY", space=0, n_cols=1, flags=0) at /mnt/xb-2.1/Percona-Server-5.5/storage/innobase/include/mem0mem.ic:443
#4 dict_mem_table_create (name=0x57f8e1 "LOG_DUMMY", space=0, n_cols=1, flags=0) at /mnt/xb-2.1/Percona-Server-5.5/storage/innobase/dict/dict0mem.c:73
#5 0x00000000004a5b3e in mlog_parse_index (ptr=0x7fb5d76e3340 "/逡", end_ptr=<value optimized out>, comp=<value optimized out>, index=0x7fb5e4e287d8) at /mnt/xb-2.1/Percona-Server-5.5/storage/innobase/mtr/mtr0log.c:565
#6 0x000000000049d87e in recv_parse_or_apply_log_rec_body (type=9 '\t', ptr=<value optimized out>, end_ptr=0x7fb5d76e3397 "", block=0x7fb5d69904c8, mtr=<value optimized out>) at /mnt/xb-2.1/Percona-Server-5.5/storage/innobase/log/log0recv.c:1099
#7 0x00000000004a21eb in recv_recover_page_func (just_read_in=<value optimized out>, block=0x7fb5d69904c8) at /mnt/xb-2.1/Percona-Server-5.5/storage/innobase/log/log0recv.c:1674
#8 0x0000000000442191 in buf_page_io_complete (bpage=0x7fb5d69904c8) at /mnt/xb-2.1/Percona-Server-5.5/storage/innobase/buf/buf0buf.c:4074
#9 0x000000000047439a in fil_aio_wait (segment=5) at /mnt/xb-2.1/Percona-Server-5.5/storage/innobase/fil/fil0fil.c:5744
#10 0x00000000004f3628 in io_handler_thread (arg=<value optimized out>) at /mnt/xb-2.1/Percona-Server-5.5/storage/innobase/srv/srv0start.c:486
#11 0x0000003b91607851 in start_thread () from /lib64/libpthread.so.0
#12 0x0000003b90ee890d in clone () from /lib64/libc.so.6

Thread 10 (Thread 0x7fb5e622d720 (LWP 29093)):
#0 0x0000003b9160ec0d in fsync () from /lib64/libpthread.so.0
#1 0x00000000004a9abb in os_file_fsync (file=10, metadata=<value optimized out>) at /mnt/xb-2.1/Percona-Server-5.5/storage/innobase/os/os0file.c:2081
#2 0x00000000004aa4c9 in os_file_flush_func (file=<value optimized out>, metadata=<value optimized out>) at /mnt/xb-2.1/Percona-Server-5.5/storage/innobase/os/os0file.c:2184
#3 0x000000000046b285 in pfs_os_file_flush_func (space_id=<value optimized out>, metadata=1) at /mnt/xb-2.1/Percona-Server-5.5/storage/innobase/include/os0file.ic:385
#4 fil_flush (space_id=<value optimized out>, metadata=1) at /mnt/xb-2.1/Percona-Server-5.5/storage/innobase/fil/fil0fil.c:5832
#5 0x0000000000473752 in fil_extend_space_to_desired_size (actual_size=0x7fffcdfcb668, space_id=378, size_after_extend=10) at /mnt/xb-2.1/Percona-Server-5.5/storage/innobase/fil/fil0fil.c:5032
#6 0x0000000000474b4b in _fil_io (type=10, sync=<value optimized out>, space_id=378, zip_size=0, block_offset=9, byte_offset=0, len=16384, buf=0x7fb5dc1f8000, message=0x7fb5d69a2000, trx=0x0)
    at /mnt/xb-2.1/Percona-Server-5.5/storage/innobase/fil/fil0fil.c:5442
#7 0x000000000044ef34 in buf_read_page_low (err=0x7fffcdfcb768, ...

Debugging a bit and thought I'd share a little more info:

record type = MLOG_COMP_REC_DELETE
dict_table_is_comp(index->table) is true
the page is not compact as seen by the page header:
(gdb) x/32whx (page + 38)
0x7ff4ec220026: 0x0000 0x0000 0x0000 0x0000 0x0000 0x0000 0x0000 0x0000
0x7ff4ec220036: 0x0000 0x0000 0x0000 0x0000 0x0000 0x0000 0x0000 0x0000
0x7ff4ec220046: 0x0000 0x0000 0x0000 0x0000 0x0000 0x0000 0x0000 0x0000
0x7ff4ec220056: 0x0000 0x0000 0x0000 0x0000 0x0000 0x0000 0x0000 0x0000

Thus the assertion.

Here is the complete log record as passed into recv_parse_or_apply_log_rec_body, 192 bytes:
(gdb) x/192bx (buf)
0x7ff4f17c3878: 0x00 0x5d 0x00 0x01 0x80 0x04 0x80 0x06
0x7ff4f17c3880: 0x80 0x07 0x00 0x03 0x00 0x03 0x00 0x04
0x7ff4f17c3888: 0x00 0x04 0x00 0x00 0x80 0x01 0x7f 0xff
0x7ff4f17c3890: 0x80 0x00 0x00 0x00 0x80 0x03 0x00 0x00
0x7ff4f17c3898: 0x7f 0xff 0x80 0x04 0x00 0x03 0x00 0x01
0x7ff4f17c38a0: 0x7f 0xff 0x00 0x04 0x7f 0xff 0x00 0x00
0x7ff4f17c38a8: 0x00 0x00 0x80 0x03 0xff 0xff 0x80 0x00
0x7ff4f17c38b0: 0x00 0x03 0x00 0x03 0x7f 0xff 0x80 0x00
0x7ff4f17c38b8: 0x00 0x01 0xff 0xff 0xff 0xff 0xff 0xff
0x7ff4f17c38c0: 0x80 0x00 0x80 0x04 0x80 0x01 0x7f 0xff
0x7ff4f17c38c8: 0x7f 0xff 0x80 0x00 0x00 0x04 0xff 0xff
0x7ff4f17c38d0: 0xff 0xff 0x00 0x03 0x80 0x01 0x00 0x04
0x7ff4f17c38d8: 0x80 0x00 0x00 0x00 0x80 0x00 0x80 0x04
0x7ff4f17c38e0: 0x7f 0xff 0x00 0x00 0x7f 0xff 0x7f 0xff
0x7ff4f17c38e8: 0x00 0x04 0x80 0x04 0x00 0x04 0x7f 0xff
0x7ff4f17c38f0: 0x7f 0xff 0x00 0x01 0x00 0x04 0x00 0x00
0x7ff4f17c38f8: 0x00 0x00 0x80 0x00 0x00 0x00 0xff 0xff
0x7ff4f17c3900: 0x7f 0xff 0x7f 0xff 0x00 0x00 0x80 0x04
0x7ff4f17c3908: 0x00 0x04 0x00 0x01 0x80 0x03 0x00 0x00
0x7ff4f17c3910: 0xff 0xff 0x00 0x00 0x00 0x00 0x00 0x00
0x7ff4f17c3918: 0xff 0xff 0x7f 0xff 0x80 0x00 0x7f 0xff
0x7ff4f17c3920: 0x00 0x04 0x00 0x00 0x00 0x04 0x80 0x04
0x7ff4f17c3928: 0x00 0x00 0x00 0x00 0x7f 0xff 0x7f 0xff
0x7ff4f17c3930: 0x00 0x01 0x00 0x04 0x00 0x01 0x0a 0xf4

Something doesn't look right in recv_recover_page_func. The recv_addr->rec_list looks a bit hosed. Really 18410435450981319680 log records for a single page for a small, short, simple test?

(gdb) p recv_addr->rec_list
$18 = {count = 18410435450981319680, start = 0x38000000080, end = 0x10003000480ff7f}
(gdb) p *(recv_addr->rec_list.start)
Cannot access memory at address 0x38000000080

<thinking_aloud>Could it be that we have some memory corruption and are trying to process a bogus log record?</thinking_aloud>

And to continue on that thought train of hosed memory, state looks off as well as the remainder of the addresses:

(gdb) p *recv_addr
$19 = {state = 16801024, space = 109053056, page_no = 50333568, rec_list = {count = 18410435450981319680, start = 0x38000000080, end = 0x10003000480ff7f}, addr_hash = 0xff7f0400ff7f}

OK, the memory corruption seems that it was gdb/optimizations. After building XB and mini-InnoDB with optimizations off, the recv_addr and others look much more rational. Now...

Something is out of sync between the bpage read in the buf_page_io_complete and the actual page...

From buf_page_io_complete:
(gdb)p *bpage
$5 = {space = 24, offset = 3, state = 5, flush_type = 0, io_fix = 1, buf_fix_count = 1, buf_pool_index = 0, zip = {data = 0x7fffe8c26000 "", m_end = 0, m_nonempty = 0, n_blobs = 0, ssize = 4}, hash = 0x0, free = {prev = 0x7fffe7b95a40, next = 0x0},
  flush_list = {prev = 0x0, next = 0x0}, zip_list = {prev = 0x0, next = 0x0}, newest_modification = 0, oldest_modification = 0, LRU = {prev = 0x7fffe7b95a40, next = 0x7fffe7b95f98}, in_LRU_list = 1, old = 0, freed_page_clock = 0, access_time = 3391528442,
  space_was_being_deleted = 0, is_corrupt = 0, is_compacted = 0}

From recv_recover_page_func:
(gdb) p *block
$6 = {page = {space = 24, offset = 3, state = 5, flush_type = 0, io_fix = 1, buf_fix_count = 1, buf_pool_index = 0, zip = {data = 0x7fffe8c26000 "", m_end = 0, m_nonempty = 0, n_blobs = 0, ssize = 4}, hash = 0x0, free = {prev = 0x7fffe7b95a40, next = 0x0},
    flush_list = {prev = 0x0, next = 0x0}, zip_list = {prev = 0x0, next = 0x0}, newest_modification = 0, oldest_modification = 0, LRU = {prev = 0x7fffe7b95a40, next = 0x7fffe7b95f98}, in_LRU_list = 1, old = 0, freed_page_clock = 0, access_time = 3391528442,
    space_was_being_deleted = 0, is_corrupt = 0, is_compacted = 0}, frame = 0x7fffe8c20000 "", unzip_LRU = {prev = 0x7fffe7b95f98, next = 0x7fffe7b95a40}, in_unzip_LRU_list = 1, mutex = {event = 0x10b04a0, lock_word = 0 '\000', waiters = 0, list = {
      prev = 0x7fffe7b95e90, next = 0x7fffe7b95b00}, count_os_wait = 0, cmutex_name = 0x55a471 "&block->mutex", pfs_psi = 0x0}, lock = {lock_word = -1048576, waiters = 0, recursive = 1, writer_thread = 140737198937856, event = 0x10b0520,
    wait_ex_event = 0x10b05a0, list = {prev = 0x7fffe7b95ed0, next = 0x7fffe7b95b40}, pfs_psi = 0x0, count_os_wait = 0, lock_name = 0x55a47f "&block->lock", last_s_file_name = 0x571cf0 "not yet reserved",
    last_x_file_name = 0x564ec0 "/mnt/xb-2.1-valgrind/Percona-Server-5.5/storage/innobase/log/log0recv.c", writer_is_wait_ex = 0, last_s_line = 0, last_x_line = 1580}, lock_hash_val = 28467, check_index_page_at_flush = 0, modify_clock = 0, n_hash_helps = 0,
  n_fields = 1, n_bytes = 0, left_side = 1, is_hashed = 0, curr_n_fields = 0, curr_n_bytes = 0, curr_left_side = 0, index = 0x0, btr_search_latch = 0x0}

(gdb) x/128bx (page)
0x7fffe8c20000: 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00
0x7fffe8c20008: 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00
0x7fffe8c20010: 0x00 0x00 0x00 0x00 0x1b 0x7e 0x25 0x66
0x7fffe8c20018: 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00
0x7fffe8c20020: 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00
0x7fffe8c20028: 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00
0x7fffe8c20030: 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00
0x7fffe8c20038: 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00
0x7fffe8c20040: 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00
0x7fffe8c20048: 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00
0x7fffe8c20050: 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00
...

George -

If that would help somehow, we have redo log and page dumper utility at
lp:~sergei.glushchenko/+junk/percona-pprint

>OK, the memory corruption seems that it was gdb/optimizations. After building XB and mini-InnoDB with optimizations off, the recv_addr and others look much more rational. Now...

I do not think so because when I reproduced the bug with disabled optimization I saw log records list is corrupted. So I think we should not exclude memory corruption. We need test case that reproduce the bug consistently to explore it more deeply.

> Something is out of sync between the bpage read in the buf_page_io_complete and the actual page...

*.delta file for space 24 is null-filled and data file that corresponds to space 24 is absent in base backup. That means space 24 was created between base and first incremental backups.

Maybe the steps that create space in server runtime differ from the steps that are reproduced during log recovery.

The assertion is activated during incremental backup preparing. The tablespace on which assertion is activated is created in xb_space_create_file() . FIL_IBD_FILE_INITIAL_SIZE * UNIV_PAGE_SIZE bytes are reserved in the beginning of .ibd file and only the first page is initialized and flushed, the other pages are null and PAGE_N_HEAP field is null too for that pages. During recovery process that null pages are read from .idb file and log records list for the page on which assertion arises begins with several MLOG_ZIP_WRITE_BLOB_PTR log records and MLOG_COMP_REC_INSERT which checks PAGE_N_HEAP field. As the table is compressed and PAGE_N_HEAP is not set for the page the assertion fails.

The base backup does not contain the .idb file. I.e. the .idb file was created between base and first incremental backup. .delta file for the tablespace is null (except header). That means there are no pages in the .idb file with LSN > base backup last lsn. That can be if pages in the .idb file were not flushed at the moment of .delta file generating.

The PAGE_N_HEAP should be set in page_create() which is invoked if MLOG_PAGE_CREATE log record is applied. But log records list does not contain MLOG_PAGE_CREATE for the page. So the main question - why?

So the crash on "prepare" step happens due to bad generated data on "backup" step. That is why I tried to make the test which would generate such data that would lead to the bug on "prepare" step. I tried the following things:

1) Test with randgen - just launch randgen with percona_qa rules and do incremental backup. The test is attached to this post;

2) buf_flush_list() was modified such a way that it just returns if certain global variable is set, the variable was set just after fil_create_new_single_table_tablespace() was invoked for the newly created compressed table to avoid pages flushing after the tablespace creating, in this case page's recv list contained MLOG_PAGE_CREATE command which invokes page_create_low() and set PAGE_N_HEAP field so the bug was not reproduced.

It seems log file begins to be tracked from wrong start_lsn, but I don't have the ideas how it can be reproduced.

I used percona-redo(lp:~laurynas-biveinis/percona-server/percona-redo) to check once more that log-file in incremental backup direcroty does not contain MLOG_PAGE_CREATE command for the space-page on which the assertion failed. Here is the result (the first several lines of precona-redo output):

{LSN: 17242, len: 27, type: MLOG_ZIP_WRITE_BLOB_PTR, singlerec: 0, space: 24, page: 3, offset: 7729, zip_offset: 7982, blob_ptr: 00 00 00 18 00 00 00 5B 00 00 00 0C 00 00 00 00 00 00 FF FF}
{LSN: 25776, len: 27, type: MLOG_ZIP_WRITE_BLOB_PTR, singlerec: 0, space: 24, page: 3, offset: 5280, zip_offset: 8062, blob_ptr: 00 00 00 18 00 00 01 01 00 00 00 0C 00 00 00 00 00 00 00 00}
{LSN: 34318, len: 27, type: MLOG_ZIP_WRITE_BLOB_PTR, singlerec: 0, space: 24, page: 3, offset: 5280, zip_offset: 8062, blob_ptr: 00 00 00 18 00 00 01 01 00 00 00 0C 00 00 00 00 00 00 2C 30}
{LSN: 42836, len: 27, type: MLOG_ZIP_WRITE_BLOB_PTR, singlerec: 0, space: 24, page: 3, offset: 7671, zip_offset: 8022, blob_ptr: 00 00 00 18 00 00 01 03 00 00 00 0C 00 00 00 00 00 00 00 00}
{LSN: 51378, len: 27, type: MLOG_ZIP_WRITE_BLOB_PTR, singlerec: 0, space: 24, page: 3, offset: 7671, zip_offset: 8022, blob_ptr: 00 00 00 18 00 00 01 03 00 00 00 0C 00 00 00 00 00 00 2C 30}
{LSN: 59896, len: 27, type: MLOG_ZIP_WRITE_BLOB_PTR, singlerec: 0, space: 24, page: 3, offset: 5241, zip_offset: 8082, blob_ptr: 00 00 00 18 00 00 01 05 00 00 00 0C 00 00 00 00 00 00 14 4E}
{LSN: 68430, len: 27, type: MLOG_ZIP_WRITE_BLOB_PTR, singlerec: 0, space: 24, page: 3, offset: 5300, zip_offset: 8042, blob_ptr: 00 00 00 18 00 00 01 06 00 00 00 0C 00 00 00 00 00 00 14 4E}
{LSN: 72057, len: 528, type: MLOG_COMP_REC_INSERT, singlerec: 1, space: 24, page: 3, offset: 2807, end_seg_len: 657, info_status_bits: 0x0, origin_offset: 71, mismatch_index: 0, data: 14 C0 03 01 01 01 00 01 04 14 C0 01 01 01 01 01 01 03 02 04 01 01 01 01 01 01 03 14 C0 01 01 01 01 01 01 04 01 14 C0 01 01 01 03 00 01 05 01 02 01 01 01 01 04 01 01 01 00 01 00 00 00 00 00 C0 12 06 00 00 20 D7 0B 80 00 00 0B 00 00 00 00 05 27 A8 00 00 01 6C 01 28 8F A3 1C 00 00 00 06 64 70 7A 73 8F A9 02 74 68 65 72 65 F3 79 00 00 61 62 69 66 68 8F AA 90 62 65 67 8F A0 D7 8F AD 73 64 6F 6E 27 74 6F 66 64 69 64 61 62 33 06 00 00 67 62 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 68 6C 6F 6F 6B 6A 68 00 00 00 02 61 67 61 00 00 00 00 66 68 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 63 61 6E 80 00 00 09 80 00 00 01 00 00 00 00 72 72 64 C0 45 00 00 74 6A 6C 6B 62 61 63 6B 61 74 61 72 65 63 00 00 00 06 00 00 00 00 64 8F A5 8B 63 62 6B 73 74 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 6D 65 61 6E 74 00 00 00 05 63 61 78 00 00 80 00 00 08 70 70 73 65 65 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 72 80 00 00 00 68}
{LSN: 81107, len: 27, type: MLOG_ZIP_WRITE_BLOB_PTR, singlerec: 0, space: 24, page: 3, offset: 10672, zip_offset: 7947, blob_ptr: 00 00 00 18 00 00 01 07 00 00 00 0C 00 00 00 00 00 00 00 00}
{LSN: 132192, len: 27, type: MLOG_ZIP_WRITE_BLOB_PTR, singlerec: 0, space: 24, page: 3, offset: 10672, zip_offset: 7947, blob_ptr: 00 00 00 18 00 00 01 07 00 00 00 0C 00 00 00 00 00 00 FF FF}
{LSN: 140710, len: 2...

What is the page type for the page 3 in the tablespace? Is it INDEX or something else? If yes, then, then MLOG_PAGE_CREATE should have been written for it. If something else, then no.

If we would have repeatable test case we could check if LSN of MLOG_PAGE_CREATE command for the (space, page) pair is greater then the last checkpoint LSN. If so then the issue is in wrong start LSN calculation inside of xtrabackup, otherwise the issue is in innodb engine because the page was not flushed on checkpoint.

Vlad, if you want to insert some extra debug logging into the XB InnoDB
code we have a sort of easy way to do that, the we can re-run the test
case that eventually reproduces the issue on backup and watch the logs.

On 6/10/2013 12:15 AM, Vlad Lesin wrote:
> If we would have repeatable test case we could check if LSN of
> MLOG_PAGE_CREATE command for the (space, page) pair is greater then the
> last checkpoint LSN. If so then the issue is in wrong start LSN
> calculation inside of xtrabackup, otherwise the issue is in innodb
> engine because the page was not flushed on checkpoint.
>

--
George O. Lorch III
Software Engineer, Percona
+1-888-401-3401 x542 US/Arizona (GMT -7)
skype: george.ormond.lorch.iii

I think the root cause here is that xb_data_files_init() (i.e. loading tablespaces into fil_system) is performed before log copying is started.

Consider the following scenario:

When the full backup is started:

- the server starts to execute CREATE/ALTER TABLE
- xb_data_files_init() is called from xtrabackup_backup_func()
- if the file for the newly created tablespace already exists (i.e. is seen by fil_load_single_tablespaces()), but the first page has not been initialized/flushed yet, xtrabackup complains about tablespace ID being nonsensical and omits the table from the full backup
- the server writes MLOG_FILE_CREATE (and possibly other records corresponding to that tablespace) to the log and performs a checkpoint
- xtrabackup starts copying the log later in xtrabackup_backup_func(), so it will not write MLOG_FILE_CREATE to xtrabackup_logfile

When the incremental backup is started:

- if the corresponding page updates in the tablespace have not been flushed yet, we generate an empty delta for it
- and copy the corresponding updates to the incremental log file

When the full backup is prepared:

- we ignore all possible log records corresponding to the tablespace, because it doesn't exist (and there's no MLOG_FILE_CREATE in the log, so it is not created on prepare)

When the incremental backup is applied:

- xb_delta_open_matching_space() creates a new tablespace assuming the table was created between the full and incremental backups
- xtrabackup then starts to apply log records to uninitialized pages

Stealing this as the fix is related to bug #1187071 and will be fixed in the same commit.

I'm not sure if my problem is the same as described here, but I experience similar things with latest Percona Xtrabackup 2.2 series.

Here's how backup was created:
innobackupex --compact --compress --compress-threads=6 --parallel=6 --slave-info --stream=xbstream /var/tmp/mysql

Further things that were done:
1) xbstream -x
2) innobackupex --decompress
3a) innobackupex --apply-log
3b) innobackupex --apply-log --rebuild-indexes --use-memory=20G

(first time I was only doing apply-log and thought the problem is not rebuild-indexes, but it seems it doesn't change anything)

So the output is:
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

141128 08:23:39 innobackupex: Starting the apply-log operation

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

141128 08:23:39 innobackupex: Starting ibbackup with command: xtrabackup --defaults-file="/home/mysql/backup-my.cnf" --defaults-group="mysqld" --prepare --target-dir=/home/mysql --use-memory=
20G --rebuild-indexes

xtrabackup version 2.2.6 based on MySQL server 5.6.21 Linux (x86_64) (revision id: )
xtrabackup: cd to /home/mysql
xtrabackup: This target seems to be not prepared yet.
2014-11-28 08:23:39 7f123becb780 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=36615536640, start_lsn=(163422478633685)
xtrabackup: using the following InnoDB configuration for recovery:
xtrabackup: innodb_data_home_dir = ./
xtrabackup: innodb_data_file_path = ibdata1:100M:autoextend
xtrabackup: innodb_log_group_home_dir = ./
xtrabackup: innodb_log_files_in_group = 1
xtrabackup: innodb_log_file_size = 36615536640
xtrabackup: using the following InnoDB configuration for recovery:
xtrabackup: innodb_data_home_dir = ./
xtrabackup: innodb_data_file_path = ibdata1:100M:autoextend
xtrabackup: innodb_log_group_home_dir = ./
xtrabackup: innodb_log_files_in_group = 1
xtrabackup: innodb_log_file_size = 36615536640
xtrabackup: Starting InnoDB instance for recovery.
xtrabackup: Using 21474836480 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 = 20.0G
InnoDB: Completed initialization of buffer pool
InnoDB: Highest supported file format is Barracuda.
InnoDB: Log scan progressed past the checkpoint lsn 163422478633685
InnoDB: Databa...

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