Bug #66933 Mysql Crashes after InnoDB Assertion failure
Submitted: 23 Sep 2012 13:47 Modified: 30 Jan 2013 14:26
Reporter: Thomas Gareis Email Updates:
Status: Not a Bug Impact on me:
None 
Category:MySQL Server: InnoDB Plugin storage engine Severity:S1 (Critical)
Version:5.5.27-1 OS:Linux (Debian 6.0)
Assigned to: Matthew Lord CPU Architecture:Any
Tags: assertion failure, innodb

[23 Sep 2012 13:47] Thomas Gareis
Description:
Mysql Crashes several times due to Assertion failures.

First Failure was:

 120921 19:26:46  InnoDB: Assertion failure in thread 140046562469632 in file ha0ha.c line 229
 InnoDB: Failing assertion: struct3333
 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.5/en/forcing-innodb-recovery.html
 InnoDB: about forcing recovery.
 17:26:46 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=4294967296
 read_buffer_size=262144
 max_used_connections=102
 max_threads=151
 thread_count=17
 connection_count=14
 It is possible that mysqld could use up to
 key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 4853174 K  bytes of memory
 Hope that's ok; if not, decrease some variables in the equation.

 Thread pointer: 0x7f5f04112a80
 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 = 7f5f219b9e88 thread_stack 0x30000
 /usr/sbin/mysqld(my_print_stacktrace+0x2e)[0x7f646c1d693e]
 /usr/sbin/mysqld(handle_fatal_signal+0x493)[0x7f646c08f373]
 /lib/libpthread.so.0(+0xeff0)[0x7f646b855ff0]
 /lib/libc.so.6(gsignal+0x35)[0x7f6469b111b5]
 /lib/libc.so.6(abort+0x180)[0x7f6469b13fc0]
 /usr/sbin/mysqld(+0x6742d0)[0x7f646c2f72d0]
 /usr/sbin/mysqld(+0x674328)[0x7f646c2f7328]
 /usr/sbin/mysqld(+0x630141)[0x7f646c2b3141]
 /usr/sbin/mysqld(+0x643832)[0x7f646c2c6832]
 /usr/sbin/mysqld(+0x644572)[0x7f646c2c7572]
 /usr/sbin/mysqld(+0x644984)[0x7f646c2c7984]
 /usr/sbin/mysqld(+0x63b3ad)[0x7f646c2be3ad]
 /usr/sbin/mysqld(+0x644e35)[0x7f646c2c7e35]
 /usr/sbin/mysqld(+0x6453ca)[0x7f646c2c83ca]
 /usr/sbin/mysqld(+0x639c0d)[0x7f646c2bcc0d]
 /usr/sbin/mysqld(+0x624f3c)[0x7f646c2a7f3c]
 /usr/sbin/mysqld(+0x5e8ac4)[0x7f646c26bac4]
 /usr/sbin/mysqld(+0x5c6ea7)[0x7f646c249ea7]
 /usr/sbin/mysqld(+0x327760)[0x7f646bfaa760]
 /usr/sbin/mysqld(_Z10sub_selectP4JOINP13st_join_tableb+0x63)[0x7f646bfad6a3]
 /usr/sbin/mysqld(+0x32babd)[0x7f646bfaeabd]
 /usr/sbin/mysqld(_ZN4JOIN4execEv+0xbde)[0x7f646bfc49ce]
 /usr/sbin/mysqld(_Z12mysql_selectP3THDPPP4ItemP10TABLE_LISTjR4ListIS1_ES2_jP8st_orderSB_S2_SB_yP13select_resultP18st_
select_lex_unitP13st_select_lex+0x134)[0x7f646bfc0554]
 /usr/sbin/mysqld(_Z13handle_selectP3THDP3LEXP13select_resultm+0x174)[0x7f646bfc6034]
 /usr/sbin/mysqld(+0x2ff487)[0x7f646bf82487]
 /usr/sbin/mysqld(_Z21mysql_execute_commandP3THD+0x2fda)[0x7f646bf8868a]
 /usr/sbin/mysqld(_Z11mysql_parseP3THDPcjP12Parser_state+0x24e)[0x7f646bf89e0e]
 /usr/sbin/mysqld(_Z16dispatch_command19enum_server_commandP3THDPcj+0x13f6)[0x7f646bf8b2a6]
 /usr/sbin/mysqld(_Z24do_handle_one_connectionP3THD+0x10e)[0x7f646c02981e]
 /usr/sbin/mysqld(handle_one_connection+0x50)[0x7f646c029940]
 /lib/libpthread.so.0(+0x68ca)[0x7f646b84d8ca]
 /lib/libc.so.6(clone+0x6d)[0x7f6469bae86d]

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

 Number of processes running now: 0
 mysqld restarted

---------------------------------------------------------------------

One Day later:
Mysql does Page dumps:

 120922 22:23:49  InnoDB: Page dump in ascii and hex (16384 bytes):
  len 16384; hex 99b41c5f000123fa000123f9000123fb0000008e3d20e31145bf0000000000...........

 InnoDB: End of page dump
 120922 22:23:49  InnoDB: Page checksum 2056152839, prior-to-4.0.14-form checksum 2549181439
 InnoDB: stored checksum 2578717791, prior-to-4.0.14-form stored checksum 2549181439
 InnoDB: Page lsn 142 1025565457, low 4 bytes of lsn at page end 1025565457
 InnoDB: Page number (if stored to page already) 74746,
 InnoDB: space id (if created with >= MySQL-4.1.1 and stored already) 17
 InnoDB: Page may be an index page where index id is 110
 InnoDB: (index "PRIMARY" of table "websitewiki"."domains")
 InnoDB: Error: page old data size 14323 new data size 14387
 InnoDB: Error: page old max ins size 1910 new max ins size 1846
 InnoDB: Submit a detailed bug report to http://bugs.mysql.com
 120922 22:23:49  InnoDB: Assertion failure in thread 140474685064960 in file btr0cur.c line 2126
 InnoDB: Failing assertion: rec
 InnoDB: We intentionally generate a memory trap.
...

 key_buffer_size=4294967296
 read_buffer_size=262144
 max_used_connections=98
 max_threads=151
 thread_count=25
 connection_count=22
 It is possible that mysqld could use up to
 key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 4853174 K  bytes of memory
 Hope that's ok; if not, decrease some variables in the equation.

 Thread pointer: 0x7fc2b402ad00
 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 = 7fc2cfb3fe88 thread_stack 0x30000
 *memory stack trace*
 /lib/libpthread.so.0(+0x68ca)[0x7fc8192c78ca]
 /lib/libc.so.6(clone+0x6d)[0x7fc81762886d]

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

 Number of processes running now: 0
 mysqld restarted

-------------------------------------------------------------

Then I upgraded 5.5.20 to 5.5.27 (yesterday)
Upgrade was fine, no problems.

And than the same today (2 times):

It starts with an InnoDB: Page dump

Then 1:

 120923 14:34:26  InnoDB: Page checksum 2056152839, prior-to-4.0.14-form checksum 2549181439
 ....

 Memory status:
 Non-mmapped space allocated from system: 474648576
 Number of free chunks:#011#011#011 3
 Number of fastbin blocks:#011#011 0
 Number of mmapped regions:#011#011 31
 Space in mmapped regions:#011#011 -1390362624
 Maximum total allocated space:#011#011 0
 Space available in freed fastbin blocks: 0
 Total allocated space:#011#011#011 474495680
 Total free space:#011#011#011 152896
 Top-most, releasable space:#011#011 152048
 Estimated memory (with thread stack):    -915124224

 Events status:
 LLA = Last Locked At  LUA = Last Unlocked At
 WOC = Waiting On Condition  DL = Data Locked

 Event scheduler status:
 State      : INITIALIZED
 Thread id  : 0
 LLA        : n/a:0
 LUA        : n/a:0
 WOC        : NO
 Workers    : 0
 Executed   : 0
 Data locked: NO

 Event queue status:
 Element count   : 0
 Data locked     : NO
 Attempting lock : NO
 LLA             : init_queue:139
 LUA             : init_queue:149
 WOC             : NO
 Next activation : never
 12:34:26 UTC - mysqld got signal 6 ;
...

 key_buffer_size=6442450944
 read_buffer_size=262144
 max_used_connections=103
 max_threads=151
 thread_count=19
 connection_count=16
 It is possible that mysqld could use up to
 key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 6950329 K  bytes of memory
 Hope that's ok; if not, decrease some variables in the equation.
...

 Number of processes running now: 0
 mysqld restarted

And 2.

another Page dump in ascii and hex
and the same assertion failure

How to repeat:
Don't know.
Its a dedicated Database Server with:
Intel i7-2600 Quad-Core
32 GB DDR3 RAM
2 x 3 TB SATA 6 Gb/s HDD (Software Raid 1)

Disks and Raid is ok
[27 Sep 2012 11:44] Ivan Isaev
same there:

120927 18:20:01  InnoDB: Assertion failure in thread 140526767687424 in file ha0ha.c line 229
InnoDB: Failing assertion: struct3333
...

Server version: 5.5.25-MariaDB-log
key_buffer_size=1073741824
read_buffer_size=131072
max_used_connections=97
max_threads=514
thread_count=21
It is possible that mysqld could use up to
key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 2174173 K  bytes of memory
Hope that's ok; if not, decrease some variables in the equation.

Thread pointer: 0x0x7891f70
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 = 0x7fcef011be68 thread_stack 0x48000
mysys/lf_hash.c:279(hash_key)[0xa5b679]
sql/hash_filo.h:103(hash_filo::search(unsigned char*, unsigned long))[0x6b626a]
/lib64/libpthread.so.0(+0x10410)[0x7fd02bed8410]
/lib64/libc.so.6(gsignal+0x35)[0x7fd029f0faa5]
/lib64/libc.so.6(abort+0x185)[0x7fd029f10da5]
ibuf/ibuf0ibuf.c:3275(ibuf_get_entry_counter_low_func)[0x90d379]
ibuf/ibuf0ibuf.c:755(ibuf_bitmap_page_get_bits_low)[0x90d428]
include/sync0sync.ic:247(pfs_mutex_enter_func)[0x8b332e]
buf/buf0buf.c:1976(buf_page_get_zip)[0x8b369d]
include/buf0buf.ic:373(buf_page_get_mutex_enter)[0x8b4770]
include/page0page.ic:515(page_get_page_no)[0x8a5b7c]
include/sync0rw.ic:323(rw_lock_s_lock_low)[0x866711]
include/sync0sync.ic:243(pfs_mutex_enter_func)[0x845d7f]
mysys/md5.c:66(putu32)[0xa3c506]
sql/sql_select.cc:20410(JOIN::make_sum_func_list(List<Item>&, List<Item>&, bool, bool))[0x5c11ff]
sql/handler.h:1844(handler::ha_index_init(unsigned int, bool))[0x5b8226]
sql/sql_select.cc:714(JOIN::prepare(Item***, TABLE_LIST*, unsigned int, Item*, unsigned int, st_order*, st_order*, Item*, st_order*, st_select_lex*, st_select_lex_unit*))[0x5c046d]
sql/sql_string.h:267(String::realloc_with_extra(unsigned int))[0x5d5f5a]
sql/sql_list.h:397(base_list::after(void*, list_node*))[0x5d1944]
sql/sql_string.h:112(String::set_charset(charset_info_st const*))[0x5d80a4]
sql/sql_parse.cc:2264(mysql_execute_command(THD*))[0x588841]
sql/sql_plugin.cc:2608(update_func_long(THD*, st_mysql_sys_var*, void*, void const*))[0x58fb79]
sql/sql_plugin.cc:2152(mysql_install_plugin(THD*, st_mysql_lex_string const*, st_mysql_lex_string const*))[0x5952b8]
sql/sql_plugin.cc:3175(sys_var_pluginvar::do_value_ptr(THD*, enum_var_type, st_mysql_lex_string*))[0x596646]
sql/mdl.cc:1977(MDL_context::acquire_lock(MDL_request*, unsigned long))[0x63a454]
psi/mysql_thread.h:842(inline_mysql_prlock_wrlock)[0x63a4ea]
/lib64/libpthread.so.0(+0x7d96)[0x7fd02becfd96]
/lib64/libc.so.6(clone+0x6d)[0x7fd029fc4a8d]

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

before:
120927  6:20:02 [ERROR] mysqld got signal 11 ;
..

Thread pointer: 0x0x88eaa90
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 = 0x7f1136ae6e68 thread_stack 0x48000
mysys/stacktrace.c:247(my_print_stacktrace)[0xa5b679]
sql/signal_handler.cc:170(handle_fatal_signal)[0x6b626a]
/lib64/libpthread.so.0(+0x10410)[0x7f12da812410]
include/ut0byte.ic:113(ut_align_down)[0x90d40a]
btr/btr0sea.c:1221(btr_search_drop_page_hash_index)[0x8b332e]
include/mach0data.ic:84(mach_read_from_2)[0x8b369d]
include/mem0mem.ic:478(mem_heap_free_func)[0x8b4770]
include/btr0sea.ic:83(btr_search_info_update)[0x8a5b7c]
row/row0sel.c:2960(row_sel_get_clust_rec_for_mysql)[0x866711]
handler/ha_innodb.cc:6992(ha_innobase::general_fetch(unsigned char*, unsigned int, unsigned int))[0x845d7f]
sql/sql_class.h:4190(handler::ha_index_next(unsigned char*))[0xa3c506]
sql/sql_class.h:4190(handler::ha_index_next(unsigned char*))[0x5c11ff]
sql/sql_select.cc:16119(sub_select(JOIN*, st_join_table*, bool))[0x5b8226]
sql/sql_select.cc:15768(do_select)[0x5c046d]
sql/sql_select.cc:2388(JOIN::exec())[0x5d5f5a]
sql/sql_select.cc:3046(mysql_select(THD*, Item***, TABLE_LIST*, unsigned int, List<Item>&, Item*, unsigned int, st_order*, st_order*, Item*, st_order*, unsigned long long, select_result*, st_select_le
x_unit*, st_select_lex*))[0x5d1944]
sql/sql_select.cc:313(handle_select(THD*, LEX*, select_result*, unsigned long))[0x5d80a4]
sql/sql_parse.cc:4622(execute_sqlcom_select)[0x588841]
sql/sql_parse.cc:2189(mysql_execute_command(THD*))[0x58fb79]
sql/sql_parse.cc:5736(mysql_parse(THD*, char*, unsigned int, Parser_state*))[0x5952b8]
sql/sql_parse.cc:1057(dispatch_command(enum_server_command, THD*, char*, unsigned int))[0x596646]
sql/sql_connect.cc:1253(do_handle_one_connection(THD*))[0x63a454]
sql/sql_connect.cc:1170(handle_one_connection)[0x63a4ea]
/lib64/libpthread.so.0(+0x7d96)[0x7f12da809d96]
/lib64/libc.so.6(clone+0x6d)[0x7f12d88fea8d]

before:

120926  0:15:49 [ERROR] mysqld got signal 11 ;
...
Thread pointer: 0x0x86ef760
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 = 0x7fa22a00ee68 thread_stack 0x48000
mysys/stacktrace.c:247(my_print_stacktrace)[0xa5b679]
sql/signal_handler.cc:170(handle_fatal_signal)[0x6b626a]
/lib64/libpthread.so.0(+0x10410)[0x7fa22d6c1410]
sql/sql_cache.cc:3553(Query_cache::get_free_block(unsigned long, char, unsigned long))[0x55c58e]
sql/sql_cache.cc:3509(Query_cache::allocate_block(unsigned long, char, unsigned long))[0x55e81f]
sql/sql_cache.cc:2867(Query_cache::write_block_data(unsigned long, unsigned char*, unsigned long, Query_cache_block::block_type, unsigned int))[0x55e8e2]
sql/sql_cache.cc:1519(Query_cache::store_query(THD*, TABLE_LIST*))[0x5609e1]
sql/sql_parse.cc:4621(execute_sqlcom_select)[0x588831]
sql/sql_parse.cc:2189(mysql_execute_command(THD*))[0x58fb79]
sql/sql_parse.cc:5736(mysql_parse(THD*, char*, unsigned int, Parser_state*))[0x5952b8]
sql/sql_parse.cc:1057(dispatch_command(enum_server_command, THD*, char*, unsigned int))[0x596646]
sql/sql_connect.cc:1253(do_handle_one_connection(THD*))[0x63a454]
sql/sql_connect.cc:1170(handle_one_connection)[0x63a4ea]
/lib64/libpthread.so.0(+0x7d96)[0x7fa22d6b8d96]
/lib64/libc.so.6(clone+0x6d)[0x7fa22b7ada8d]

etc.

I would not blame OS. Now i have gentoo, had freebsd before. mysql 5.1.x through 5.5.x. This segmentation fault occure for several years now, mysql changed many versions.
[22 Dec 2012 13:16] MySQL Verification Team
Thomas, what you're seeing is probably some memory corruption.  Hence, all various kinds of crashes are shown.  You should start by turning of query cache and see if it helps reduce crash frequency.

[mysqld]
query_cache_type=0
query_cache_size=0
[22 Dec 2012 15:27] Thomas Gareis
Ok, I solved this issue for my needs.
I checked every table and found a corruption in a big (50 GB) Innodb table.
When a certain row was accessed mysql crashes. I checked access logs some seconds before the crash occurs and found the query which accesses the corrupted rows.
I have blacklisted the select query for that filter criteria and dumped and rebuild the whole table (took more than one week, disable keys was not an option, cause mysql freezes the whole server, when I tried to import the table and build keys afterwards).
To sum up: Corrupted data in innodb table causes Mysql to crash.. thats not a very nice behaviour of an DBMS. No idea why this little portion of data (maybe 4kb of 50GB) was corrupted.

Don't know if I should close this ticket. IMHO Mysql should not crash due to a corrupted row in a table. (Restart, fixing MyISAM tables, going through the whole transaction log for InnoDB Tables, building the whole InnoDB Buffer Pool (20 GB on my site, to gain full performance), took around 30 minutes to have Mysql responding as normal)

@Shane Bester: Sorry, your reply must be a kind of joke.. disabling query cache to avoid memory access?? Query Cache here on my dedicated server is 256 MB in RAM, What about KeyBuffer, SortBuffer, Inno Buffer Pool, ... all in memory, MySQL allocates 29GB here on my dedicated Database Server (32 GB RAM installed).. MySQL lives in memory for good performance, all disk data is only a kind of data backup for server power restarts..
[30 Jan 2013 14:26] Matthew Lord
We're sorry, but the bug system is not the appropriate forum for asking help on using MySQL products. Your problem is not clearly the result of a bug.

You appear to have some corruption within your InnoDB table, and some process that causes InnoDB to encounter this corruption around the same time every day. When InnoDB encounters the invalid data, the ASSERT fails and a forced shutdown occurs intentionally. The crux of the problem is the corruption which causes the ASSERT to fail.

There is no test-case even associated with the bug so there is nothing for me to try and verify here. If you come up with a test case, then I'll be happy to try and verify it.

Support on using our products is available both free in our forums at http://forums.mysql.com/ and for a reasonable fee direct from our skilled support engineers at http://www.mysql.com/support/

Thank you for your interest in MySQL.