MySQL crashing since moving all tables to innodb

I’m having some weird problems on some of our servers since I converted most of our tables to innodb, the logs look like this:

2014-08-30 12:48:59 7fe93329f700 InnoDB: Warning: problems renaming 'ddcdb/drug_usage_denorm' to 'ddcdb/#sql-ib11087', 9000 iterations
2014-08-30 12:49:19 7fe93329f700 InnoDB: Warning: problems renaming 'ddcdb/drug_usage_denorm' to 'ddcdb/#sql-ib11087', 10000 iterations
2014-08-30 12:49:39 7fe93329f700 InnoDB: Warning: problems renaming 'ddcdb/drug_usage_denorm' to 'ddcdb/#sql-ib11087', 11000 iterations
InnoDB: Warning: a long semaphore wait:
--Thread 140639525598976 has waited at row0purge.cc line 720 for 241.00 seconds the semaphore:
S-lock on RW-latch at 0x136af60 created in file dict0dict.cc line 973
a writer (thread id 140639562495744) has reserved it in mode exclusive
number of readers 0, waiters flag 1, lock_word: 0
Last time read locked in file row0purge.cc line 720
Last time write locked in file /export/home/pb2/build/sb_0-12734909-1406113284.51/rpm/BUILD/mysql-5.6.20/mysql-5.6.20/storage/innobase/handler/handler0alter.cc line 5424
InnoDB: Warning: a long semaphore wait:
--Thread 140638545659648 has waited at dict0dict.cc line 1027 for 241.00 seconds the semaphore:
Mutex at 0x4b52da8 created file dict0dict.cc line 964, lock var 1
waiters flag 1
InnoDB: Warning: a long semaphore wait:
--Thread 140628694234880 has waited at dict0dict.cc line 1027 for 241.00 seconds the semaphore:
Mutex at 0x4b52da8 created file dict0dict.cc line 964, lock var 1
waiters flag 1
InnoDB: ###### Starts InnoDB Monitor for 30 secs to print diagnostic info:
InnoDB: Pending preads 0, pwrites 0
2014-08-30 12:49:59 7fe93329f700 InnoDB: Warning: problems renaming 'ddcdb/drug_usage_denorm' to 'ddcdb/#sql-ib11087', 12000 iterations

Innodb monitor output follows this, which includes:


----------
SEMAPHORES
----------
OS WAIT ARRAY INFO: reservation count 2056334
--Thread 140639525598976 has waited at row0purge.cc line 720 for 256.00 seconds the semaphore:
S-lock on RW-latch at 0x136af60 created in file dict0dict.cc line 973
a writer (thread id 140639562495744) has reserved it in mode exclusive
number of readers 0, waiters flag 1, lock_word: 0
Last time read locked in file row0purge.cc line 720
Last time write locked in file /export/home/pb2/build/sb_0-12734909-1406113284.51/rpm/BUILD/mysql-5.6.20/mysql-5.6.20/storage/innobase/handler/handler0alter.cc line 5424
--Thread 140639667926784 has waited at ibuf0ibuf.cc line 4632 for 255.00 seconds the semaphore:
X-lock (wait_ex) on RW-latch at 0x7fe970509e40 created in file buf0buf.cc line 1016
a writer (thread id 140639667926784) has reserved it in mode wait exclusive
number of readers 1, waiters flag 1, lock_word: ffffffffffffffff
Last time read locked in file buf0flu.cc line 1060
Last time write locked in file /export/home/pb2/build/sb_0-12734909-1406113284.51/rpm/BUILD/mysql-5.6.20/mysql-5.6.20/storage/innobase/ibuf/ibuf0ibuf.cc line 4632
--Thread 140639646947072 has waited at ibuf0ibuf.cc line 4632 for 255.00 seconds the semaphore:
X-lock on RW-latch at 0x7fe970509e40 created in file buf0buf.cc line 1016
a writer (thread id 140639667926784) has reserved it in mode wait exclusive
number of readers 1, waiters flag 1, lock_word: ffffffffffffffff
Last time read locked in file buf0flu.cc line 1060
Last time write locked in file /export/home/pb2/build/sb_0-12734909-1406113284.51/rpm/BUILD/mysql-5.6.20/mysql-5.6.20/storage/innobase/ibuf/ibuf0ibuf.cc line 4632
--Thread 140639657436928 has waited at ibuf0ibuf.cc line 4903 for 255.00 seconds the semaphore:
X-lock on RW-latch at 0x7fe970509e40 created in file buf0buf.cc line 1016
a writer (thread id 140639667926784) has reserved it in mode wait exclusive
number of readers 1, waiters flag 1, lock_word: ffffffffffffffff
Last time read locked in file buf0flu.cc line 1060
Last time write locked in file /export/home/pb2/build/sb_0-12734909-1406113284.51/rpm/BUILD/mysql-5.6.20/mysql-5.6.20/storage/innobase/ibuf/ibuf0ibuf.cc line 4632
--Thread 140639636457216 has waited at ibuf0ibuf.cc line 4632 for 255.00 seconds the semaphore:
X-lock on RW-latch at 0x7fe970509e40 created in file buf0buf.cc line 1016
a writer (thread id 140639667926784) has reserved it in mode wait exclusive
number of readers 1, waiters flag 1, lock_word: ffffffffffffffff
Last time read locked in file buf0flu.cc line 1060
Last time write locked in file /export/home/pb2/build/sb_0-12734909-1406113284.51/rpm/BUILD/mysql-5.6.20/mysql-5.6.20/storage/innobase/ibuf/ibuf0ibuf.cc line 4632
--Thread 140638545659648 has waited at dict0dict.cc line 1027 for 256.00 seconds the semaphore:
Mutex at 0x4b52da8 created file dict0dict.cc line 964, lock var 1
waiters flag 1
--Thread 140628694234880 has waited at dict0dict.cc line 1027 for 256.00 seconds the semaphore:
Mutex at 0x4b52da8 created file dict0dict.cc line 964, lock var 1
waiters flag 1

snip...


--Thread 140632815363840 has waited at buf0buf.cc line 2477 for 246.00 seconds the semaphore:
S-lock on RW-latch at 0x7fe93d177cc0 created in file buf0buf.cc line 1016
a writer (thread id 140632815363840) has reserved it in mode exclusive
number of readers 0, waiters flag 1, lock_word: 0
Last time read locked in file buf0flu.cc line 1060
Last time write locked in file /export/home/pb2/build/sb_0-12734909-1406113284.51/rpm/BUILD/mysql-5.6.20/mysql-5.6.20/storage/innobase/buf/buf0buf.cc line 3592
--Thread 140638507853568 has waited at dict0dict.cc line 1027 for 245.00 seconds the semaphore:
Mutex at 0x4b52da8 created file dict0dict.cc line 964, lock var 1
waiters flag 1
--Thread 140638508119808 has waited at buf0buf.cc line 2477 for 244.00 seconds the semaphore:
S-lock on RW-latch at 0x7fe97d35f640 created in file buf0buf.cc line 1016
a writer (thread id 140638508119808) has reserved it in mode exclusive
number of readers 0, waiters flag 1, lock_word: 0
Last time read locked in file buf0flu.cc line 1060
Last time write locked in file /export/home/pb2/build/sb_0-12734909-1406113284.51/rpm/BUILD/mysql-5.6.20/mysql-5.6.20/storage/innobase/buf/buf0buf.cc line 3592
--Thread 140638547257088 has waited at dict0dict.cc line 1027 for 243.00 seconds the semaphore:
Mutex at 0x4b52da8 created file dict0dict.cc line 964, lock var 1
waiters flag 1

etc

The server then crashes (after a ton of innodb monitor output/queries etc):


2014-08-30 12:54:20 7fe93329f700 InnoDB: Warning: problems renaming 'ddcdb/drug_usage_denorm' to 'ddcdb/#sql-ib11087', 25000 iterations
2014-08-30 12:54:20 7fe93329f700 InnoDB: Assertion failure in thread 140639562495744 in file handler0alter.cc line 4954
InnoDB: Failing assertion: error == DB_SUCCESS
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.
16:54:20 UTC - mysqld got signal 6 ;
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=402653184
read_buffer_size=131072
max_used_connections=973
max_threads=1000
thread_count=975
connection_count=973
It is possible that mysqld could use up to
key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 790919 K bytes of memory
Hope that's ok; if not, decrease some variables in the equation.

Thread pointer: 0x7fe920000990
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 = 7fe93329e7e0 thread_stack 0x40000
/usr/sbin/mysqld(my_print_stacktrace+0x35)[0x8d9d85]
/usr/sbin/mysqld(handle_fatal_signal+0x494)[0x665344]
/lib64/libpthread.so.0[0x3f1ee0f710]
/lib64/libc.so.6(gsignal+0x35)[0x3f1ea32925]
/lib64/libc.so.6(abort+0x175)[0x3f1ea34105]
/usr/sbin/mysqld[0x958528]
/usr/sbin/mysqld[0x732895]
/usr/sbin/mysqld(_Z17mysql_alter_tableP3THDPcS1_P24st_ha_create_informationP10TABLE_LISTP10Alter_infojP8st_orderb+0x2f82)[0x735a32]
/usr/sbin/mysqld(_Z20mysql_recreate_tableP3THDP10TABLE_LISTb+0x118)[0x736478]
/usr/sbin/mysqld[0x81ba46]
/usr/sbin/mysqld(_ZN22Sql_cmd_optimize_table7executeEP3THD+0xcf)[0x81c10f]
/usr/sbin/mysqld(_Z21mysql_execute_commandP3THD+0x2089)[0x6e25e9]
/usr/sbin/mysqld(_Z11mysql_parseP3THDPcjP12Parser_state+0x3b8)[0x6e5658]
/usr/sbin/mysqld(_ZN15Query_log_event14do_apply_eventEPK14Relay_log_infoPKcj+0x754)[0x87bc24]
/usr/sbin/mysqld(_ZN9Log_event11apply_eventEP14Relay_log_info+0x74)[0x87e7d4]
/usr/sbin/mysqld(_Z26apply_event_and_update_posPP9Log_eventP3THDP14Relay_log_info+0x263)[0x8a9233]
/usr/sbin/mysqld[0x8af0f3]
/usr/sbin/mysqld(handle_slave_sql+0xb09)[0x8b0989]
/usr/sbin/mysqld(pfs_spawn_thread+0x12a)[0xafde1a]
/lib64/libpthread.so.0[0x3f1ee079d1]
/lib64/libc.so.6(clone+0x6d)[0x3f1eae8b5d]

Trying to get some variables.
Some pointers may be invalid and cause the dump to abort.
Query (7fe922a055da): is an invalid pointer
Connection ID (thread ID): 1
Status: NOT_KILLED

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.
140830 12:54:21 mysqld_safe Number of processes running now: 0
140830 12:54:21 mysqld_safe mysqld restarted

Can anyone pin point what’s going on here?

Hi, can you please provide the steps that how you have converted all tables from MyISAM (or other Storage engine) to InnoDB? Also have you changed the MySQL version with it? (means lower to higher version)

MySQL version hasn’t changed (using 5.6.20). I use ALTER TABLE to change to innodb, e.g.

ALTER TABLE `table_name` ENGINE = InnoDB;

It’s possible that the problem was occuring under MyISAM but it never crashed MySQL. After talking to my devs the script that is causing this problem is running for 7 hours, doing 2.7M inserts. We’re looking at a way to optimize this a bit further.

Okay, thanks for update. Let us know if we can help you in anyway further.