MySQL Bugs: #50366: InnoDB Assertion failure when converting from MyISAM to InnoDB

Bug #50366	InnoDB Assertion failure when converting from MyISAM to InnoDB
Submitted:	15 Jan 2010 14:09	Modified:	2 Oct 2013 17:30
Reporter:	Edward Dore	Email Updates:
Status:	Closed	Impact on me:	None
Category:	MySQL Server: InnoDB storage engine	Severity:	S1 (Critical)
Version:	5.0.90, 5.1.43	OS:	Any (CentOS 5.4 x86-64, XP)
Assigned to:	Assigned Account	CPU Architecture:	Any

Description:
When changing the engine type for a table from MyISAM to InnoDB for a user's table, the MySQL server crashes with the following messages in /var/log/mysqld.log:

100115 13:40:41InnoDB: Assertion failure in thread 1171859776 in file log0log.c line 202
InnoDB: Failing assertion: len < log->buf_size / 2
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.0/en/forcing-recovery.html
InnoDB: about forcing recovery.
100115 13:40:41 - mysqld got signal 11 ;
This could be because you hit a bug. It is also possible that this binary
or one of the libraries it was linked against is corrupt, improperly built,
or misconfigured. 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.

key_buffer_size=8384512
read_buffer_size=131072
max_used_connections=2
max_connections=100
threads_connected=1
It is possible that mysqld could use up to
key_buffer_size + (read_buffer_size + sort_buffer_size)*max_connections = 225787 K
bytes of memory
Hope that's ok; if not, decrease some variables in the equation.

thd=0x2aaaac85f9d0
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...
Cannot determine thread, fp=0x45d91fb0, backtrace may not be correct.
Bogus stack limit or frame pointer, fp=0x45d91fb0, stack_bottom=0x45d90000, thread_stack=262144, aborting backtrace.
Trying to get some variables.
Some pointers may be invalid and cause the dump to abort...
thd->query at 0x2aaaac8a0b30  is invalid pointer
thd->thread_id=139
The manual page at http://dev.mysql.com/doc/mysql/en/crashing.html contains
information that should help you find out what is causing the crash.

Number of processes running now: 0
100115 13:40:41  mysqld restarted
InnoDB: Log scan progressed past the checkpoint lsn 0 598869666
100115 13:40:41  InnoDB: Database was not shut down normally!
InnoDB: Starting crash recovery.
InnoDB: Reading tablespace information from the .ibd files...
InnoDB: Restoring possible half-written data pages from the doublewrite
InnoDB: buffer...
100115 13:40:41  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 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: Doing recovery: scanned up to log sequence number 0 604112384
InnoDB: Doing recovery: scanned up to log sequence number 0 604287591
InnoDB: 1 transaction(s) which must be rolled back or cleaned up
InnoDB: in total 239 row operations to undo
InnoDB: Trx id counter is 0 2304
100115 13:40:42  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 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
100115 13:40:43  InnoDB: Started; log sequence number 0 604287591
InnoDB: Starting in background the rollback of uncommitted transactions
100115 13:40:43  InnoDB: Rolling back trx with id 0 1874, 239 rows to undo
100115 13:40:43 [Note] /usr/libexec/mysqld: ready for connections.
Version: '5.0.77'  socket: '/var/lib/mysql/mysql.sock'  port: 3306  Source distribution

InnoDB: Rolling back of trx id 0 1874 completed
100115 13:40:44  InnoDB: Rollback of non-prepared transactions completed

====

I am running CentOS 5.4 x86-64 on a Dell R610 using the CentOS provided mysql-server RPM and /etc/my.cnf file.
I've updated to the latest version of CentOS and mysql-server via yum and still experience the same problem.

[root@sql lib]# rpm -q mysql
mysql-5.0.77-4.el5_4.1
[root@sql lib]# rpm -q mysql-server
mysql-server-5.0.77-4.el5_4.1
[root@sql lib]# cat /etc/redhat-release
CentOS release 5.4 (Final)

[root@sql lib]# cat /etc/my.cnf
[mysqld]
datadir=/var/lib/mysql
socket=/var/lib/mysql/mysql.sock
user=mysql
# Default to using old password format for compatibility with mysql 3.x
# clients (those using the mysqlclient10 compatibility package).
old_passwords=1

[mysqld_safe]
log-error=/var/log/mysqld.log
pid-file=/var/run/mysqld/mysqld.pid

How to repeat:
Run "ALTER TABLE `users` ENGINE=InnoDB" on the schema (attached as a private comment) or mysqldump the table, edit the ENGINE= line in the resulting .sql file and then try and run it.
Both result in a crash with the same messages in the MySQL error log.

Please, check if this is repeatable with a newer version, 5.0.89. If it is, please, send your my.cnf file content.

Apologies for the delay in replying. I have now tested this with the MySQL 5.0.90 community edition RPM in our lab and am encountering exactly the same behavior when trying to convert the storage engine this table from MyISAM to InnoDB.

I installed CentOS 5.4 x86-64 on a Dell PowerEdge R200 server in our lab and then installed the MySQL-server-community-5.0.90-0.rhel5 RPM downloaded from one of the MySQL.com mirrors in the UK before loading an exact copy of the database from the live server taken as a backup via mysqldump on January 15th when we first experienced this problem (this is the same mysqldump as I tried to import with ENGINE=InnoDB; on the "users" table in question.

The only change to the default /etc/my.cnf was to specify the log-error location.

Once the "ALTER TABLE `users` ENGINE=InnoDB;" command is run from the CLI client, the conversion begins and then after a minute or two the server crashes.
Some of the conversion is evidently completed fine as the /var/lib/mysql/ibdata1 file grows to 243MB and the server doesn't crash straight away.

When the server crashes, it looks like it reboots and tries to recover the transaction only to then crash again and get itself into a reboot loop.
I've included the contents of the log-error file for the first couple of times round this loop.

[root@localhost ~]# rpm -q MySQL-server-community
MySQL-server-community-5.0.90-0.rhel5
[root@localhost ~]# cat /etc/redhat-release
CentOS release 5.4 (Final)
[root@localhost ~]# cat /etc/my.cnf
[mysqld]
#datadir=/var/lib/mysql
#socket=/var/lib/mysql/mysql.sock
#user=mysql
# Default to using old password format for compatibility with mysql 3.x
# clients (those using the mysqlclient10 compatibility package).
#old_passwords=1

[mysqld_safe]
log-error=/var/log/mysqld.log
#pid-file=/var/run/mysqld/mysqld.pid

Contents of the log-error files from InnoDB assertion failure. Clipped to the first couple of MySQL restarts/recovery attempts

Attachment: log-error crash.txt (text/plain), 11.44 KiB.

I can repeat this crash using alot of fake data in the supplied table.

Version: '5.0.90-community-nt'  socket: ''  port: 3306  MySQL Community Edition (GPL)
100201  0:09:33InnoDB: Assertion failure in thread 10960 in file .\log\log0log.c line 202
InnoDB: Failing assertion: len < log->buf_size / 2
InnoDB: We intentionally generate a memory trap.
<cut>
mysqld-nt.exe!log_reserve_and_open()[log0log.c:202]
mysqld-nt.exe!mtr_log_reserve_and_write()[mtr0mtr.c:147]
mysqld-nt.exe!mtr_commit()[mtr0mtr.c:190]
mysqld-nt.exe!row_ins_index_entry_low()[row0ins.c:2108]
mysqld-nt.exe!row_ins_index_entry()[row0ins.c:2177]
mysqld-nt.exe!row_ins_index_entry_step()[row0ins.c:2246]
mysqld-nt.exe!row_ins()[row0ins.c:2380]
mysqld-nt.exe!row_ins_step()[row0ins.c:2487]
mysqld-nt.exe!row_insert_for_mysql()[row0mysql.c:1157]
mysqld-nt.exe!ha_innobase::write_row()[ha_innodb.cc:3304]
mysqld-nt.exe!copy_data_between_tables()[sql_table.cc:4244]
mysqld-nt.exe!mysql_alter_table()[sql_table.cc:3840]
mysqld-nt.exe!mysql_execute_command()[sql_parse.cc:3571]
mysqld-nt.exe!mysql_parse()[sql_parse.cc:6449]
mysqld-nt.exe!dispatch_command()[sql_parse.cc:1961]
mysqld-nt.exe!handle_one_connection()[sql_parse.cc:1233]
mysqld-nt.exe!pthread_start()[my_winthread.c:85]
mysqld-nt.exe!_callthreadstart()[thread.c:295]
mysqld-nt.exe!_threadstart()[thread.c:275]
kernel32.dll!BaseThreadStart()

The table had 400000 rows in it before being converted.  I'll upload a private testcase soon.

The table I was using had 38509 rows in it, so you're in the same region :)

I've just managed to get it to convert by ramping up innodb_buffer_pool_size, although I haven't tested what size it needs to be - I just set it to 4GB as the test server has 8GB of RAM.

Crash is repeatable with recent test case from Shane uploaded in private, both with -debug and non-debug binaries.

Here is some background information that may be relevant for this bug.

All operations that are covered by the InnoDB redo log are grouped into mini-transactions (mtr). Usually, a mtr should latch only a few pages. For example, operations on off-page columns (BLOBs) will keep at most two BLOB pages latched at a time.

The biggest mini-transactions occur during a B-tree split. In the worst case, splitting a B-tree leaf node will be propagated all the way to the root node. Again, in the worst case, when index records are long, each b-tree node will contain few node pointers, and the page-splitting mini-transaction may end up latching up to half the pages in the index tree.

During crash recovery, all pages touched by the mini-transaction will have to be latched in the buffer pool at the same time. Thus, if InnoDB crashes due to running out of buffer pool in a mini-transaction, the redo log application during crash recovery will likely crash as well, unless the buffer pool size is enlarged.

Sorry, my previous comment is a little misleading. If InnoDB runs out of buffer pool during the execution of a mini-transaction, mtr_commit(mtr) will not be executed and no redo log will be written for the mtr. Thus, crash recovery would not see the oversized mtr. If there is something oversized that kills InnoDB at crash recovery, that should be in the rollback of incomplete transactions.

bug #42170 is a duplicate of this.

Noted in 5.5.35, 5.6.15, 5.7.3 changelogs:

"Converting a table with a large number of columns from "MyISAM" to "InnoDB"
would cause an assertion due to insufficient log buffer space. Instead of
asserting, "InnoDB" now attempts to increase log buffer size automatically
if the redo log size is too large."

Thank you for the bug report.

5.5$ bzr log -r 4489
------------------------------------------------------------
revno: 4489
committer: Yasufumi Kinoshita <yasufumi.kinoshita@oracle.com>
branch nick: mysql-5.5
timestamp: Mon 2013-09-30 13:41:48 +0900
message:
  Bug#11758196 : INNODB ASSERTION FAILURE WHEN CONVERTING FROM MYISAM TO INNODB
  
  Changed to try to extend log buffer instead of crash, when log size is too large for the size.
  
  Approved by Marko in rb#3229

5.5$ bzr log -r 4490
------------------------------------------------------------
revno: 4490
committer: Yasufumi Kinoshita <yasufumi.kinoshita@oracle.com>
branch nick: mysql-5.5
timestamp: Mon 2013-09-30 15:02:54 +0900
message:
  Adjustment for fix for Bug#11758196
  
  log_buffer_extend() should fill the new buffer with 0.