[MDEV-6424] MariaDB server crashes with assertion failure in file ha_innodb.c line 11652 Created: 2014-07-07  Updated: 2018-09-04  Resolved: 2014-07-08

Status: Closed
Project: MariaDB Server
Component/s: None
Affects Version/s: 10.0.11
Fix Version/s: 10.0.13

Type: Bug Priority: Major
Reporter: Kirill Komlev Assignee: Jan Lindström (Inactive)
Resolution: Fixed Votes: 0
Labels: assertion, ha_innodb
Environment:

Linux, kernel-3.10.25-gentoo, 10.0.11-MariaDB


Issue Links:
Relates
relates to MDEV-6443 Server crashed with assertaion failur... Closed
relates to MDEV-6642 Server crashed with assertion failure... Open
relates to MDEV-10011 Failing assertion crash Closed
relates to MDEV-17102 Server crash with failing assertion: ... Closed

 Description   

Hi, guys.

Sometimes in random situation I have got error with that message:

2014-07-06 07:22:12 7f3788e48700  InnoDB: MySQL and InnoDB data dictionaries are out of sync.
InnoDB: Unable to find the AUTOINC column vid in the InnoDB table .
InnoDB: We set the next AUTOINC column value to 0,
InnoDB: in effect disabling the AUTOINC next value generation.
InnoDB: You can either set the next AUTOINC value explicitly using ALTER TABLE
InnoDB: or fix the data dictionary by recreating the table.
2014-07-06 07:22:12 7f3788e48700  InnoDB: Assertion failure in thread 139876496606976 in file ha_innodb.cc line 11652
InnoDB: Failing assertion: index->table->stat_initialized
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.
140706  7:22:12 [ERROR] 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.
 
To report this bug, see http://kb.askmonty.org/en/reporting-bugs
 
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.
 
Server version: 10.0.11-MariaDB-log
key_buffer_size=16777216
read_buffer_size=262144
max_used_connections=259
max_threads=502
thread_count=158
It is possible that mysqld could use up to 
key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 412284 K  bytes of memory
Hope that's ok; if not, decrease some variables in the equation.
 
Thread pointer: 0x0x16753968
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 = 0x7f3788e47e48 thread_stack 0x48000
(my_addr_resolve failure: fork)
/usr/sbin/mysqld(my_print_stacktrace+0x26) [0xb0d036]
/usr/sbin/mysqld(handle_fatal_signal+0x398) [0x6ef3d8]
/lib64/libpthread.so.0(+0x10c20) [0x7f3a5d7d1c20]
/lib64/libc.so.6(gsignal+0x35) [0x7f3a5c3ed265]
/lib64/libc.so.6(abort+0x17b) [0x7f3a5c3ee6db]
/usr/sbin/mysqld() [0x964ba7]
/usr/sbin/mysqld() [0x96b396]
/usr/sbin/mysqld(handler::ha_open(TABLE*, char const*, int, unsigned int)+0x3f) [0x6f2fff]
/usr/sbin/mysqld() [0xaebedd]
/usr/sbin/mysqld(handler::ha_open(TABLE*, char const*, int, unsigned int)+0x3f) [0x6f2fff]
/usr/sbin/mysqld(open_table_from_share(THD*, TABLE_SHARE*, char const*, unsigned int, unsigned int, unsigned int, TABLE*, bool)+0x86c) [0x64d20c]
/usr/sbin/mysqld(open_table(THD*, TABLE_LIST*, st_mem_root*, Open_table_context*)+0x786) [0x5891f6]
/usr/sbin/mysqld(open_tables(THD*, TABLE_LIST**, unsigned int*, unsigned int, Prelocking_strategy*)+0xd36) [0x58a326]
/usr/sbin/mysqld(open_and_lock_tables(THD*, TABLE_LIST*, bool, unsigned int, Prelocking_strategy*)+0x49) [0x58a509]
/usr/sbin/mysqld() [0x5b95cd]
/usr/sbin/mysqld(mysql_execute_command(THD*)+0x5088) [0x5c42b8]
/usr/sbin/mysqld(mysql_parse(THD*, char*, unsigned int, Parser_state*)+0x1fc) [0x5c6b5c]
/usr/sbin/mysqld(dispatch_command(enum_server_command, THD*, char*, unsigned int)+0x1530) [0x5c80e0]
/usr/sbin/mysqld(do_handle_one_connection(THD*)+0x19d) [0x66fa4d]
/usr/sbin/mysqld(handle_one_connection+0x40) [0x66fb10]
/usr/sbin/mysqld() [0x89bc04]
/lib64/libpthread.so.0(+0x8eb7) [0x7f3a5d7c9eb7]
/lib64/libc.so.6(clone+0x6d) [0x7f3a5c4a4a7d]
 
Trying to get some variables.
Some pointers may be invalid and cause the dump to abort.
Query (0x7f3776e82a60): is an invalid pointer
Connection ID (thread ID): 356991
Status: NOT_KILLED
 
Optimizer switch: index_merge=on,index_merge_union=on,index_merge_sort_union=on,index_merge_intersection=on,index_merge_sort_intersection=off,engine_condition_pushdown=off,index_condition_pushdown=on,derived_merge=on,derived_with_keys=on,firstmatch=on,loosescan=on,materialization=on,in_to_exists=on,semijoin=on,partial_match_rowid_merge=on,partial_match_table_scan=on,subquery_cache=on,mrr=off,mrr_cost_based=off,mrr_sort_keys=off,outer_join_with_cache=on,semijoin_with_cache=on,join_cache_incremental=on,join_cache_hashed=on,join_cache_bka=on,optimize_join_buffer_size=off,table_elimination=on,extended_keys=on,exists_to_in=off
 
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.
140706 11:51:40 [Note] CONNECT: Version 1.02.0002 March 16, 2014
2014-07-06 11:51:40 7f040bfdf740 InnoDB: Warning: Using innodb_additional_mem_pool_size is DEPRECATED. This option may be removed in future releases, together with the option innodb_use_sys_malloc and with the InnoDB's internal memory allocator.
140706 11:51:40 [Note] InnoDB: Using mutexes to ref count buffer pool pages
140706 11:51:40 [Note] InnoDB: The InnoDB memory heap is disabled
140706 11:51:40 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
140706 11:51:40 [Note] InnoDB: Compressed tables use zlib 1.2.8
140706 11:51:40 [Note] InnoDB: Using Linux native AIO
140706 11:51:40 [Note] InnoDB: Using CPU crc32 instructions
140706 11:51:40 [Note] InnoDB: Initializing buffer pool, size = 10.0G
140706 11:51:42 [Note] InnoDB: Completed initialization of buffer pool
140706 11:51:42 [Note] InnoDB: Highest supported file format is Barracuda.
140706 11:51:42 [Note] InnoDB: Log scan progressed past the checkpoint lsn 740281760840
140706 11:51:42 [Note] InnoDB: Database was not shutdown normally!
140706 11:51:42 [Note] InnoDB: Starting crash recovery.
140706 11:51:42 [Note] InnoDB: Reading tablespace information from the .ibd files...
140706 11:51:50 [Note] InnoDB: Restoring possible half-written data pages 
140706 11:51:50 [Note] InnoDB: from the doublewrite buffer...
...
some stuff is omitted
...
140706 11:52:10 [Note] InnoDB: Starting an apply batch of log records to the database...
InnoDB: Progress in percent: 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: Last MySQL binlog file position 0 651862295, file name ./emsow-bin.000013
140706 11:52:19 [Note] InnoDB: 128 rollback segment(s) are active.
140706 11:56:21 [Note] CONNECT: Version 1.02.0002 March 16, 2014
140706 11:56:21 [ERROR] mysqld: Can't lock aria control file '/var/lib/mysql/aria_log_control' for exclusive use, error: 11. Will retry for 30 seconds
2014-07-06 11:56:49 7f9daf3ad740 InnoDB: Warning: Using innodb_additional_mem_pool_size is DEPRECATED. This option may be removed in future releases, together with the option innodb_use_sys_malloc and with the InnoDB's internal memory allocator.
140706 11:56:49 [Note] InnoDB: Using mutexes to ref count buffer pool pages
140706 11:56:49 [Note] InnoDB: The InnoDB memory heap is disabled
140706 11:56:49 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
140706 11:56:49 [Note] InnoDB: Compressed tables use zlib 1.2.8
140706 11:56:49 [Note] InnoDB: Using Linux native AIO
140706 11:56:49 [Note] InnoDB: Using CPU crc32 instructions
140706 11:56:49 [Note] InnoDB: Initializing buffer pool, size = 10.0G
140706 11:56:50 [Note] InnoDB: Completed initialization of buffer pool
140706 11:56:50 [Note] InnoDB: Highest supported file format is Barracuda.
140706 11:56:50 [Note] InnoDB: Log scan progressed past the checkpoint lsn 740281760840
140706 11:56:50 [Note] InnoDB: Database was not shutdown normally!
140706 11:56:50 [Note] InnoDB: Starting crash recovery.
140706 11:56:50 [Note] InnoDB: Reading tablespace information from the .ibd files...
140706 11:56:51 [Note] InnoDB: Restoring possible half-written data pages 
140706 11:56:51 [Note] InnoDB: from the doublewrite buffer...
...
some stuff is omitted
...
140706 11:57:00 [Note] CONNECT: Version 1.02.0002 March 16, 2014
2014-07-06 11:57:00 7f81987da740 InnoDB: Warning: Using innodb_additional_mem_pool_size is DEPRECATED. This option may be removed in future releases, together with the option innodb_use_sys_malloc and with the InnoDB's internal memory allocator.
140706 11:57:00 [Note] InnoDB: Using mutexes to ref count buffer pool pages
140706 11:57:00 [Note] InnoDB: The InnoDB memory heap is disabled
140706 11:57:00 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
140706 11:57:00 [Note] InnoDB: Compressed tables use zlib 1.2.8
140706 11:57:00 [Note] InnoDB: Using Linux native AIO
140706 11:57:00 [Note] InnoDB: Using CPU crc32 instructions
140706 11:57:00 [Note] InnoDB: Initializing buffer pool, size = 10.0G
140706 11:57:01 [Note] InnoDB: Completed initialization of buffer pool
140706 11:57:01 [Note] InnoDB: Highest supported file format is Barracuda.
140706 11:57:01 [Note] InnoDB: Log scan progressed past the checkpoint lsn 740281760840
140706 11:57:01 [Note] InnoDB: Database was not shutdown normally!
140706 11:57:01 [Note] InnoDB: Starting crash recovery.
140706 11:57:01 [Note] InnoDB: Reading tablespace information from the .ibd files...
140706 11:57:02 [Note] InnoDB: Restoring possible half-written data pages 
140706 11:57:02 [Note] InnoDB: from the doublewrite buffer...
...
some stuff is omitted
...
140706 11:57:22 [Note] InnoDB: Starting an apply batch of log records to the database...
InnoDB: Progress in percent: 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: Last MySQL binlog file position 0 651862295, file name ./emsow-bin.000013
140706 11:57:30 [Note] InnoDB: 128 rollback segment(s) are active.
140706 12:00:46 [Note] InnoDB: Waiting for purge to start
140706 12:00:46 [Note] InnoDB:  Percona XtraDB (http://www.percona.com) 5.6.17-65.0 started; log sequence number 740978429198
140706 12:00:46 [Note] Recovering after a crash using emsow-bin
140706 12:00:57 [Note] Starting crash recovery...
140706 12:00:57 [Note] Crash recovery finished.
140706 12:00:57 [Note] Server socket created on IP: '0.0.0.0'.
140706 12:00:57 [Note] Event Scheduler: Loaded 0 events
140706 12:00:57 [Note] /usr/sbin/mysqld: ready for connections.
Version: '10.0.11-MariaDB-log'  socket: '/var/run/mysqld/mysqld.sock'  port: 3306  Source distribution

My server:

# uname -a 
Linux db 3.10.25-gentoo #1 SMP PREEMPT Wed Jan 29 19:50:21 EST 2014 x86_64 Intel(R) Xeon(R) CPU E5504 @ 2.00GHz GenuineIntel GNU/Linux
# mysql -V 
mysql -V
mysql  Ver 15.1 Distrib 10.0.11-MariaDB, for Linux (x86_64) using readline 6.2

I don't know how to repeat this bug.



 Comments   
Comment by Jan Lindström (Inactive) [ 2014-07-08 ]

revno: 4281
committer: Jan Lindström <jplindst@mariadb.org>
branch nick: 10.0-innodb
timestamp: Tue 2014-07-08 21:05:18 +0300
message:
MDEV-6424: Mariadb server crashes with assertion failure in file ha_innodb.cc

Analysis: For some reason table stats for a table pointed from a index
is not initialized. Added additional warning output on this situation
and table stats initialization. This is better than asserting.

If after migrate to version containing this fix you start seeing warnings like :

"InnoDB: Warning: Index %s points to table %s"									       
" and ib_table %s statistics is initialized %d "
" but index table %s initialized %d "
" mysql table is %s. Have you mixed "
"up .frm files from different "
"installations? "
"See " REFMAN
"innodb-troubleshooting.html\n",

please send error log.

R: Jan

Comment by Vaclav Rozsypalek [ 2015-06-09 ]

IS this really fixed ?

I have similar issue now with warning fix.

I don't know how to reproduce it, since it happens randomly on production server.

CentOS Linux release 7.1.1503
Linux 3.10.0-229.1.2.el7.x86_64 x86_64 x86_64
MariaDB-server-10.0.17-1.el7.centos.x86_64 

MariaDB is from yum repository, I don't use anything compiled from source. Everything is from RPM.

InnoDB: Duplicate FTS_DOC_ID value on table X1P40179/flox_products
Cannot find index FTS_DOC_ID_INDEX in InnoDB index translation table.
150605 15:06:26 [Warning] Find index FTS_DOC_ID_INDEX in InnoDB index list but not its MySQL index number It could be an InnoDB internal index.
2015-06-08 15:46:03 7ffd1bbf6700 InnoDB: FTS Optimize Removing table X5P48715/flox_blocks_faq
2015-06-08 15:47:20 7ffd1bbf6700 InnoDB: FTS Optimize Removing table X5P48715/flox_products
InnoDB: Warning: Index PRIMARY points to table X5P31514/flox_languages and ib_table X5P31514/flox_languages statistics is initialized 1  but index table X5P31514/flox_languages initialized 0  mysql table is flox_languages. Have you mixed up .frm files from different installations? See http://dev.mysql.com/doc/refman/5.6/en/innodb-troubleshooting.html
InnoDB: Warning: Index currency_id points to table X5P31514/flox_languages and ib_table X5P31514/flox_languages statistics is initialized 1  but index table X5P31514/flox_languages initialized 1  mysql table is flox_languages. Have you mixed up .frm files from different installations? See http://dev.mysql.com/doc/refman/5.6/en/innodb-troubleshooting.html
InnoDB: Warning: Index currency_id points to table X5P31514/flox_languages and ib_table X5P31514/flox_languages statistics is initialized 1  but index table X5P31514/flox_languages initialized 1  mysql table is flox_languages. Have you mixed up .frm files from different installations? See http://dev.mysql.com/doc/refman/5.6/en/innodb-troubleshooting.html
 
InnoDB: Warning: Index company_data_id points to table X5P31514/flox_languages and ib_table X5P31514/flox_languages statistics is initialized 1  but index table X5P31514/flox_languages initialized 1  mysql table is flox_languages. Have you mixed up .frm files from different installations? See http://dev.mysql.com/doc/refman/5.6/en/innodb-troubleshooting.html
2015-06-08 22:33:14 7ffd0de4d700  InnoDB: Assertion failure in thread 140724836554496 in file ha_innodb.cc line 6980
InnoDB: Failing assertion: templ->clust_rec_field_no != ULINT_UNDEFINED
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.
150608 22:33:15 [ERROR] 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.
 
To report this bug, see http://kb.askmonty.org/en/reporting-bugs
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.
 
Server version: 10.0.17-MariaDB
key_buffer_size=134217728
read_buffer_size=1048576
max_used_connections=288
max_threads=602
thread_count=7
It is possible that mysqld could use up to
key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 1376410 K  bytes of memory
Hope that's ok; if not, decrease some variables in the equation.
 
Thread pointer: 0x0x7ffd25700008
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 = 0x7ffd0de4cd90 thread_stack 0x48000
/usr/sbin/mysqld(my_print_stacktrace+0x2e)[0xbc4e2e]
/usr/sbin/mysqld(handle_fatal_signal+0x390)[0x7338d0]
/lib64/libpthread.so.0(+0xf130)[0x7ffd76090130]
/lib64/libc.so.6(gsignal+0x37)[0x7ffd748455d7]
/lib64/libc.so.6(abort+0x148)[0x7ffd74846cc8]
/usr/sbin/mysqld[0x8a7fcc]
/usr/sbin/mysqld[0x8b4608]
/usr/sbin/mysqld[0x8b7183]
/usr/sbin/mysqld[0x8b73b3]
/usr/sbin/mysqld(_ZN7handler22ha_rnd_init_with_errorEb+0x17)[0x739317]
/usr/sbin/mysqld(_Z16init_read_recordP11READ_RECORDP3THDP5TABLEP10SQL_SELECTibb+0x4d3)[0x845823]
/usr/sbin/mysqld(_Z21join_init_read_recordP13st_join_table+0x80)[0x607720]
/usr/sbin/mysqld(_Z10sub_selectP4JOINP13st_join_tableb+0x161)[0x6078c1]
/usr/sbin/mysqld[0x612d6d]
/usr/sbin/mysqld(_ZN4JOIN10exec_innerEv+0xa21)[0x624011]
/usr/sbin/mysqld(_ZN4JOIN4execEv+0x11)[0x625e41]
/usr/sbin/mysqld(_Z12mysql_selectP3THDPPP4ItemP10TABLE_LISTjR4ListIS1_ES2_jP8st_orderSB_S2_SB_yP13select_resultP18st_select_lex_unitP13st_select_lex+0xc7)[0x622807]
/usr/sbin/mysqld(_Z13handle_selectP3THDP3LEXP13select_resultm+0x27d)[0x62332d]
/usr/sbin/mysqld[0x5c4a5e]
/usr/sbin/mysqld(_Z21mysql_execute_commandP3THD+0x525f)[0x5d34ef]
/usr/sbin/mysqld(_Z11mysql_parseP3THDPcjP12Parser_state+0x1f9)[0x5d6169]
/usr/sbin/mysqld(_Z16dispatch_command19enum_server_commandP3THDPcj+0x1755)[0x5d7e35]
/usr/sbin/mysqld(_Z24do_handle_one_connectionP3THD+0x1e3)[0x69c813]
/usr/sbin/mysqld(handle_one_connection+0x39)[0x69c8f9]
/lib64/libpthread.so.0(+0x7df5)[0x7ffd76088df5]
/lib64/libc.so.6(clone+0x6d)[0x7ffd749061ad]
Trying to get some variables.
Some pointers may be invalid and cause the dump to abort.
Query (0x7ffd11bb8020): is an invalid pointer
Connection ID (thread ID): 174277856
Status: NOT_KILLED
 
Optimizer switch: index_merge=on,index_merge_union=on,index_merge_sort_union=on,index_merge_intersection=on,index_merge_sort_intersection=off,engine_condition_pushdown=off,index_condition_pushdown=on,derived_merge=on,derived_with_keys=on,firstmatch=on,loosescan=on,materialization=on,in_to_exists=on,semijoin=on,partial_match_rowid_merge=on,partial_match_table_scan=on,subquery_cache=on,mrr=off,mrr_cost_based=off,mrr_sort_keys=off,outer_join_with_cache=on,semijoin_with_cache=on,join_cache_incremental=on,join_cache_hashed=on,join_cache_bka=on,optimize_join_buffer_size=off,table_elimination=on,extended_keys=on,exists_to_in=on
 
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.
150608 22:33:15 mysqld_safe Number of processes running now: 0
150608 22:33:15 mysqld_safe mysqld restarted

Comment by Jan Lindström (Inactive) [ 2015-06-12 ]

Clearly not fully, do you have some information how to repeat the problem ?

Comment by Vaclav Rozsypalek [ 2015-06-17 ]

I am afraid, I do not have such information. The error happened on production server so I have no idea what started it.
I do not have more crashes so far.

Comment by Elena Stepanova [ 2016-06-17 ]

See also MDEV-10011. More occasions have been reported, but so far I haven't been able to reproduce the problem.

Comment by David Zhao [ 2018-04-27 ]

Is this bug really fixed? We also got this bug and I found the github commit of this bug here https://github.com/MariaDB/server/commit/03ddc19ab21d585f4aac16ad91e5cba39687cd31
The commit message says it's not fixed:

This is not a fix, this is instrumentation to find out is MySQL frm dictionary
and InnoDB data dictionary really out-of-sync when this assertion is fired,
or is there some other reason (bug).

And from the changes I can see it's really doing some logging only. Or is the bug later fixed in another commit? if so could you please put the github commit link here?

Comment by Sergei Golubchik [ 2018-04-30 ]

jplindst might give a better answer, but I believe it was closed after https://github.com/mariadb/server/commit/e0057340 which adds an additional dict_stats_init().

Generated at Thu Feb 08 07:11:47 UTC 2024 using Jira 8.20.16#820016-sha1:9d11dbea5f4be3d4cc21f03a88dd11d8c8687422.