MySQL Bugs: #71515: MEB: Failing assertion: slot with compressed tables

Bug #71515	MEB: Failing assertion: slot with compressed tables
Submitted:	29 Jan 2014 20:34	Modified:	22 Aug 2014 17:28
Reporter:	Shane Bester (Platinum Quality Contributor)	Email Updates:
Status:	Won't fix	Impact on me:	None
Category:	MySQL Enterprise Backup	Severity:	S2 (Serious)
Version:	3.9.0, 3.10.0	OS:	Windows
Assigned to:		CPU Architecture:	Any

Description:
backup-and-apply-log in mysqlbackup 3.0.9 sometimes crashes when backing up 5.5.37 with compressed innodb tables.

mysqlbackup: INFO: InnoDB: Starting an apply batch of log records to the database...
InnoDB: Progress in percent: 0 <cut>  71 72 
InnoDB: Assertion failure in file ..\mysql\storage\innobase\page\page0zip.cc line 4199
InnoDB: Failing assertion: slot
InnoDB: We intentionally generate a memory trap.
InnoDB: Submit a detailed bug report to http://bugs.mysql.com.

Also seen the assertion here:
..\mysql\storage\innobase\page\page0zip.cc line 3597

How to repeat:
I can upload a datadir for you that causes the problem consistently.

Otherwise, a simple generic multi-threaded DML workload against 
some compressed innodb tables while you do a backup is enough.

(10 threads, 5 tables, insert/delete/update)

meb option file used

Attachment: go.ini (application/octet-stream, text), 242 bytes.

sample DML generator to run while you backup-and-apply-log

Attachment: bug71515.c (text/plain), 12.74 KiB.

meb 3.10.0 still cannot backup compressed innodb tables without crashing:

-------------------------------------------------------------
   Parameters Summary
-------------------------------------------------------------
   Start LSN                  : 180103680
   End LSN                    : 198933676
-------------------------------------------------------------

 mysqlbackup: INFO: Creating 16 buffers each of size 65536.
140219 05:45:42 mysqlbackup: INFO: Apply-log operation starts with following threads
                1 read-threads    1 process-threads
 mysqlbackup: INFO: Using up to 2000 MB of memory.
140219 05:45:42 mysqlbackup: INFO: ibbackup_logfile's creation parameters:
          start lsn 180103680, end lsn 198933676,
          start checkpoint 180103984.
 mysqlbackup: INFO: InnoDB: Starting an apply batch of log records to the database...
InnoDB: Progress in percent: 0 2014-02-19 05:45:43 2060  InnoDB: Assertion failure in file ..\mysql\storage\innobase\page\page0zip.cc line 3614
InnoDB: Failing assertion: slot
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.6/en/forcing-innodb-recovery.html
InnoDB: about forcing recovery.

This application has requested the Runtime to terminate it in an unusual way.
Please contact the application's support team for more information.

3.10.0 is actually failing much more than 3.9.0 did, and with multiple different errors.

 mysqlbackup: INFO: InnoDB: Starting an apply batch of log records to the database...
InnoDB: Progress in percent: 0 1 2 3 4 5 2014-02-19 05:49:43 2a48  InnoDB: Assertion failure in file ..\mysql\storage\innobase\rem\rem0rec.cc line 577
InnoDB: We intentionally generate a memory trap.

.......

Another location:

 mysqlbackup: INFO: InnoDB: Starting an apply batch of log records to the database...
InnoDB: Progress in percent: 2014-02-19 05:57:13 544  InnoDB: Assertion failure in file ..\mysql\storage\innobase\page\page0zip.cc line 4216
InnoDB: Failing assertion: slot

On linux meb 3.10.0 we have stack trace:
InnoDB: Progress in percent: 2014-02-16 08:30:12 7fffdddf5700  InnoDB: Assertion failure in file /pb2/build_bi/sb_7-11537209-1392698599.62/mysql/storage/innobase/page/page0zip.cc line 4356
InnoDB: Failing assertion: slot_rec
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.6/en/forcing-innodb-recovery.html
InnoDB: about forcing recovery.

Program received signal SIGABRT, Aborted.
[Switching to Thread 0x7fffdddf5700 (LWP 15543)]
0x0000003537235935 in raise () from /lib64/libc.so.6
(gdb) bt
#0  0x0000003537235935 in raise () from /lib64/libc.so.6
#1  0x00000035372370e8 in abort () from /lib64/libc.so.6
#2  0x00000000006b123e in page_zip_dir_delete(page_zip_des_t*, unsigned char*, dict_index_t const*, unsigned long const*, unsigned char const*) ()
#3  0x00000000006aa6eb in page_cur_delete_rec(page_cur_t*, dict_index_t const*, unsigned long const*, mtr_t*) ()
#4  0x00000000006aaac4 in page_cur_parse_delete_rec(unsigned char*, unsigned char*, buf_block_t*, dict_index_t*, mtr_t*) ()
#5  0x00000000006a313e in recv_parse_or_apply_log_rec_body(unsigned char, unsigned char*, unsigned char*, buf_block_t*, mtr_t*, unsigned long) ()
#6  0x00000000006a3c07 in recv_recover_page_func(buf_block_t*) ()
#7  0x00000000006a3fef in recv_apply_log_recs_for_backup() ()
#8  0x000000000045984f in meb::Back_apply_log::complete() ()
#9  0x000000000054d728 in meb::Processor::run() ()
#10 0x000000000055f0ee in meb::Thread::startThread(void*) ()
#11 0x0000003537607d14 in start_thread () from /lib64/libpthread.so.0
#12 0x00000035372f168d in clone () from /lib64/libc.so.6

another stack from linux 3.10.0.

InnoDB: Progress in percent: 2014-02-16 08:34:48 7fffddff6700  InnoDB: Assertion failure in file /pb2/build_bi/sb_7-11537209-1392698599.62/mysql/storage/innobase/page/page0zip.cc line 4240
InnoDB: Failing assertion: slot
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.6/en/forcing-innodb-recovery.html
InnoDB: about forcing recovery.

Program received signal SIGABRT, Aborted.
[Switching to Thread 0x7fffddff6700 (LWP 15743)]
0x0000003537235935 in raise () from /lib64/libc.so.6
(gdb) bt
#0  0x0000003537235935 in raise () from /lib64/libc.so.6
#1  0x00000035372370e8 in abort () from /lib64/libc.so.6
#2  0x00000000006afb9f in page_zip_rec_set_owned(page_zip_des_t*, unsigned char const*, unsigned long) ()
#3  0x00000000006a9b55 in page_cur_insert_rec_zip(page_cur_t*, dict_index_t*, unsigned char const*, unsigned long*, mtr_t*) ()
#4  0x00000000006aaf8f in page_cur_parse_insert_rec(unsigned long, unsigned char*, unsigned char*, buf_block_t*, dict_index_t*, mtr_t*) ()
#5  0x00000000006a31ee in recv_parse_or_apply_log_rec_body(unsigned char, unsigned char*, unsigned char*, buf_block_t*, mtr_t*, unsigned long) ()
#6  0x00000000006a3c07 in recv_recover_page_func(buf_block_t*) ()
#7  0x00000000006a3fef in recv_apply_log_recs_for_backup() ()
#8  0x000000000045984f in meb::Back_apply_log::complete() ()
#9  0x000000000054d728 in meb::Processor::run() ()
#10 0x000000000055f0ee in meb::Thread::startThread(void*) ()
#11 0x0000003537607d14 in start_thread () from /lib64/libpthread.so.0
#12 0x00000035372f168d in clone () from /lib64/libc.so.6

The other stack from 3.10.0

 mysqlbackup: INFO: InnoDB: Starting an apply batch of log records to the database...
InnoDB: Progress in percent: 0 1 2 3 4 5 6 2014-02-16 09:45:39 7fffde7f7700  InnoDB: Assertion failure in file /pb2/build_bi/sb_7-11537209-1392698599.62/mysql/storage/innobase/rem/rem0rec.cc line 577
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.6/en/forcing-innodb-recovery.html
InnoDB: about forcing recovery.

Program received signal SIGABRT, Aborted.
[Switching to Thread 0x7fffde7f7700 (LWP 995)]
0x0000003537235935 in raise () from /lib64/libc.so.6
(gdb) bt
#0  0x0000003537235935 in raise () from /lib64/libc.so.6
#1  0x00000035372370e8 in abort () from /lib64/libc.so.6
#2  0x00000000006b6759 in rec_get_offsets_func(unsigned char const*, dict_index_t const*, unsigned long*, unsigned long, mem_block_info_t**, char const*, unsigned long) ()
#3  0x00000000006aade7 in page_cur_parse_insert_rec(unsigned long, unsigned char*, unsigned char*, buf_block_t*, dict_index_t*, mtr_t*) ()
#4  0x00000000006a31ee in recv_parse_or_apply_log_rec_body(unsigned char, unsigned char*, unsigned char*, buf_block_t*, mtr_t*, unsigned long) ()
#5  0x00000000006a3c07 in recv_recover_page_func(buf_block_t*) ()
#6  0x00000000006a3fef in recv_apply_log_recs_for_backup() ()
#7  0x000000000045984f in meb::Back_apply_log::complete() ()
#8  0x000000000054d728 in meb::Processor::run() ()
#9  0x000000000055f0ee in meb::Thread::startThread(void*) ()
#10 0x0000003537607d14 in start_thread () from /lib64/libpthread.so.0
#11 0x00000035372f168d in clone () from /lib64/libc.so.6

Bug #72851 describes a likely reason for this bug.

The problem is due to a bug with the InnoDB storage engine, and it cannot be fixed on the side of MySQL Enterprsie Backup. The following entry has been added to the Limitations section of the MySQL Enterprise Backup 3.9, 3.10 and 3.11 manuals:

"Compressed InnoDB tables from MySQL server 5.6.10 and earlier cannot be restored with MySQL Enterprise Backup 3.9.0 or later, due to a bug with the InnoDB storage engine (see Bug# 72851 on the MySQL Bug System)."