Debian Wheezy/Jessie, 64bit.

Do you have any information that you can share about the table structure, data, or circumstances of the crash?
Did it happen only once, or has it been happening repeatedly?

We've had a similar complaint before, see the comment by calvix to MDEV-6424, but unfortunately there was nothing that would allow to analyze the problem.

Here is table structure:

CREATE TABLE `stranka_moduly` (
`id` int(11) NOT NULL AUTO_INCREMENT,
`id_firma` int(11) NOT NULL,
`link` varchar(64) NOT NULL,
`modul` varchar(64) NOT NULL,
`always_on` int(11) NOT NULL,
PRIMARY KEY (`id`)
) ENGINE=InnoDB AUTO_INCREMENT=31 DEFAULT CHARSET=cp1250

It contains only 21 simple lines (numbers and short strings without unicode characters).

As far as i rememeber, this was the first (and last so far) time this happend.

Could you please also attach your cnf file(s)?
Thanks.

Done.

I just got the "same" problem twice in two weeks.
Long standing databases.
my.cnf.d/*, table descriptions and indexes, and full error logs attached. my.cnf.d.tar blocked_ips entity_translation_revision mysql.2 mysql.3

jeffvoskamp, thank you.
In your cnf files, you have encryption enabled, but there is no sign of an encryption plugin or its configuration. Are you using an encryption plugin of your own?

We are not using encryption, I should probably disable it.
Most of this is "out of the box" for CentOS/RHEL 6 (MariaDB-server-10.1.13-1.el7.centos.x86_64 and family).

Sorry, you are right, nevermind. I didn't notice it was a preset file, not a cnf file. You don't have encryption enabled.

jeffvoskamp,

The error logs that you provided start from the warning. Could you please attach a whole log from the server startup till (and including) the failure?
Do you have any idea if there is anything special that happens at the time of the failures, maybe some maintenance activities?

It just happened again on the same server - different database. It's been nearly a month since the last time this happened, so full logs for the server is problematic.
I've attached today's bit from /var/log/messages and the files related to the table in question. If there's something specific that you'd like me to check for let me know.

Jeff Voskamp

messages metatag.frm metatag.ibd

Table structure from the provided frm:

CREATE TABLE `mdev10011`.`metatag` (

  `entity_type` varchar(32) NOT NULL DEFAULT '' COMMENT 'The entity type this data is attached to.',

  `entity_id` int(10) unsigned NOT NULL DEFAULT '0' COMMENT 'The entity id this data is attached to.',

  `revision_id` int(10) unsigned NOT NULL DEFAULT '0' COMMENT 'The revision_id for the entity object this data is attached to.',

  `language` varchar(32) NOT NULL DEFAULT '' COMMENT 'The language of the tag.',

  `data` longblob NOT NULL,

  PRIMARY KEY (`entity_type`,`entity_id`,`revision_id`,`language`),

  KEY `type_revision` (`entity_type`,`revision_id`)

) ENGINE=InnoDB DEFAULT CHARSET=utf8

I've run tests for days, still haven't been able to reproduce the problem. Putting it aside for a while, will get back to it later.

Hi,

Same problem here.
All tables was imported by mysqldump from a 5.5.39+maria-1~wheezy server to a Mariadb 10.1.14 server.
My "my.cnf" can be found in the previous bug that I've opened for another problem

I attached the log related to the crash that occured.
I've altered the name of the database / table and the name of the indexes (for confidentiality purpose) , shortened the "Processed xxxxxx .ibd/.isl files" and "scanned up to log sequence number xxxxxxx"

Don't pay intention to the "Normal Shutdown" it is related to the bug that I've previously opened.

Best regards, bug_mariadb

Hi all,

Just encountered a very similar problem here is the error from our crash logs (please let me know if we can provide additional detail):

InnoDB: Warning: Index period_time_index points to table deck_DATA_5/001EC60502D2_1_shark_prepared_1 and ib_table deck_DATA_5/001EC60502D2_1_shark_prepared_1 statistics is initialized 1 but index table deck_DATA_5/001EC60502D2_1_shark_prepared_1 initialized 1 mysql table is 001EC60502D2_1_shark_prepared_1.
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 period_time_index points to table deck_DATA_5/001EC60502D2_1_shark_prepared_1 and ib_table deck_DATA_5/001EC60502D2_1_shark_prepared_1 statistics is initialized 1 but index table deck_DATA_5/001EC60502D2_1_shark_prepared_1 initialized 1 mysql table is 001EC60502D2_1_shark_prepared_1.
Have you mixed up .frm files from different installations? See http://dev.mysql.com/doc/refman/5.6/en/innodb-troubleshooting.html
2016-10-07 02:37:33 7f47a80aeb00 InnoDB: Assertion failure in thread 139945738693376 in file ha_innodb.cc line 7813
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.
161007 2:37:33 [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.1.11-MariaDB-log
key_buffer_size=33554432
read_buffer_size=131072
max_used_connections=2001
max_threads=1202
thread_count=256
It is possible that mysqld could use up to
key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 2689262 K bytes of memory
Hope that's ok; if not, decrease some variables in the equation.

Thread pointer: 0x0x7f472bfc1008
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 = 0x7f47a80ae140 thread_stack 0x48400
(my_addr_resolve failure: fork)
/usr/sbin/mysqld(my_print_stacktrace+0x2b) [0x7f5dbc3cb43b]
/usr/sbin/mysqld(handle_fatal_signal+0x475) [0x7f5dbbf2cda5]
/lib64/libpthread.so.0(+0x3c5940f710) [0x7f5dbb534710]
/lib64/libc.so.6(gsignal+0x35) [0x7f5db995c625]
/lib64/libc.so.6(abort+0x175) [0x7f5db995de05]
/usr/sbin/mysqld(+0x7151e0) [0x7f5dbc0791e0]
/usr/sbin/mysqld(+0x722df0) [0x7f5dbc086df0]
/usr/sbin/mysqld(+0x724d39) [0x7f5dbc088d39]
/usr/sbin/mysqld(QUICK_RANGE_SELECT::reset()+0x1e9) [0x7f5dbc006249]
/usr/sbin/mysqld(join_init_read_record(st_join_table*)+0x25) [0x7f5dbbdf2615]
/usr/sbin/mysqld(sub_select(JOIN*, st_join_table*, bool)+0x169) [0x7f5dbbdf28d9]
/usr/sbin/mysqld(+0x49b37d) [0x7f5dbbdff37d]
/usr/sbin/mysqld(JOIN::exec_inner()+0xb50) [0x7f5dbbe0ff00]
/usr/sbin/mysqld(JOIN::exec()+0x5d) [0x7f5dbbe11e7d]
/usr/sbin/mysqld(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_lex_unit*, st_select_lex*)+0x12a) [0x7f5dbbe0e83a]
/usr/sbin/mysqld(handle_select(THD*, LEX*, select_result*, unsigned long)+0x25d) [0x7f5dbbe1215d]
/usr/sbin/mysqld(+0x4509b2) [0x7f5dbbdb49b2]
/usr/sbin/mysqld(mysql_execute_command(THD*)+0x5de3) [0x7f5dbbdc0c43]
/usr/sbin/mysqld(mysql_parse(THD*, char*, unsigned int, Parser_state*)+0x22d) [0x7f5dbbdc3fed]
/usr/sbin/mysqld(dispatch_command(enum_server_command, THD*, char*, unsigned int)+0x2293) [0x7f5dbbdc6aa3]
/usr/sbin/mysqld(do_command(THD*)+0x16b) [0x7f5dbbdc703b]
/usr/sbin/mysqld(do_handle_one_connection(THD*)+0x17f) [0x7f5dbbe8294f]
/usr/sbin/mysqld(handle_one_connection+0x47) [0x7f5dbbe82aa7]
/lib64/libpthread.so.0(+0x3c594079d1) [0x7f5dbb52c9d1]
/lib64/libc.so.6(clone+0x6d) [0x7f5db9a128fd]

We encountered the issue running version 10.1.11 on a CentOS 64bit system in a clustered environment how do i add this version number to "Affects Version" section for this bug ?

thank you

We see this regularly on nodes in a 3-node Galera cluster running 10.0.23 (Debian Jessie). There's no output in the log prior to the initialisation warnings and so far we've not been able to determine any reliable similarities between the tables involved. I've added a log file fwiw.

We can confirm this also affects 10.0.0.28

Can any of you who has database where this happens share the database for analysis?

commit 03ddc19ab21d585f4aac16ad91e5cba39687cd31
Author: Jan Lindström <jan.lindstrom@mariadb.com>
Date: Thu Nov 17 15:15:20 2016 +0200

MDEV-6424: MariaDB server crashes with assertion failure in file ha_innodb.c line 11652

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).

It also affects MariaDB 10.0.27 (debian jessie repo). I upgraded to 10.0.29 and will let you know if it happens.

We are still having problems on 10.0.29.

Uploaded log file (mariadb.log) as it seems to have more info than others.

I would need full datadir where this repeats for analysis.

How can i send it privately?

Based on error log MySQL and InnoDB do not agree the structure of the table. You can use MariaDB ftp server see https://mariadb.com/kb/en/meta/ftp/

I uploaded two files:
MDEV-10011-dump.sql.gz
MDEV-10011-raw.tar.gz

Is it ok?

Thanks, but I also need ibdata1.ibd file because InnoDB data dictionary is there.

Upload done, file MDEV-10011-ibdata1.gz

Thanks, however I could not repeat the assertion, the select in error logs did not crash in my environment. Could you try to recreate the problematic table.

This also just happened for us. Very recently switched to MariaDB 10.1.21 from MySQL 5.5 (via mysqldump). These are the logs:

Feb 28 23:24:52 underae18 mysqld[190405]: InnoDB: Warning: Index PRIMARY points to table cpoms_ourladyrosary/settings and ib_table cpoms_ourladyrosary/settings statistics is initialized 1  but index table cpoms_ourladyrosary/settings initialized 0  mysql table is settings. Have you mixed up .frm files from different installations? See http://dev.mysql.com/doc/refman/5.6/en/innodb-troubleshooting.html

Feb 28 23:24:52 underae18 mysqld[190405]: InnoDB: Warning: Index index_settings_on_id points to table cpoms_ourladyrosary/settings and ib_table cpoms_ourladyrosary/settings statistics is initialized 1  but index table cpoms_ourladyrosary/settings initialized 1  mysql table is settings. Have you mixed up .frm files from different installations? See http://dev.mysql.com/doc/refman/5.6/en/innodb-troubleshooting.html

Feb 28 23:24:52 underae18 mysqld[190405]: InnoDB: Warning: Index index_settings_on_name points to table cpoms_ourladyrosary/settings and ib_table cpoms_ourladyrosary/settings statistics is initialized 1  but index table cpoms_ourladyrosary/settings initialized 1  mysql table is settings. Have you mixed up .frm files from different installations? See http://dev.mysql.com/doc/refman/5.6/en/innodb-troubleshooting.html

Feb 28 23:24:52 underae18 mysqld[190405]: InnoDB: Warning: Index index_settings_on_name points to table cpoms_ourladyrosary/settings and ib_table cpoms_ourladyrosary/settings statistics is initialized 1  but index table cpoms_ourladyrosary/settings initialized 1  mysql table is settings. Have you mixed up .frm files from different installations? See http://dev.mysql.com/doc/refman/5.6/en/innodb-troubleshooting.html

Feb 28 23:24:52 underae18 mysqld[190405]: 2017-02-28 23:24:52 140385130568448 [Note] InnoDB: Looking for field 0 name id from table cpoms_ourladyrosary/settings

Feb 28 23:24:52 underae18 mysqld[190405]: 2017-02-28 23:24:52 140385130568448 [Note] InnoDB: InnoDB Table cpoms_ourladyrosary/settings field 0 name id

Feb 28 23:24:52 underae18 mysqld[190405]: 2017-02-28 23:24:52 140385130568448 [Note] InnoDB: MySQL table settings field 0 name id

Feb 28 23:24:52 underae18 mysqld[190405]: 2017-02-28 23:24:52 140385130568448 [Note] InnoDB: MySQL table settings field 1 name name

Feb 28 23:24:52 underae18 mysqld[190405]: 2017-02-28 23:24:52 140385130568448 [Note] InnoDB: MySQL table settings field 2 name nice_name

Feb 28 23:24:52 underae18 mysqld[190405]: 2017-02-28 23:24:52 140385130568448 [Note] InnoDB: MySQL table settings field 3 name value

Feb 28 23:24:52 underae18 mysqld[190405]: 2017-02-28 23:24:52 140385130568448 [Note] InnoDB: MySQL table settings field 4 name created_at

Feb 28 23:24:52 underae18 mysqld[190405]: 2017-02-28 23:24:52 140385130568448 [Note] InnoDB: MySQL table settings field 5 name updated_at

Feb 28 23:24:52 underae18 mysqld[190405]: 2017-02-28 23:24:52 140385130568448 [Note] InnoDB: MySQL table settings field 6 name adminable

Feb 28 23:24:52 underae18 mysqld[190405]: 2017-02-28 23:24:52 140385130568448 [ERROR] InnoDB: Clustered record field for column 0 not found table n_user_defined 1 index n_user_defined 7 InnoDB table cpoms_ourladyrosary/settings field name id MySQL table settings field name id n_fields 7 query SELECT  `settings`.* FROM `settings` WHERE `settings`.`name` = 'locale' LIMIT 1

Feb 28 23:24:52 underae18 mysqld[190405]: 2017-02-28 23:24:52 7fadf5d6db00  InnoDB: Assertion failure in thread 140385130568448 in file ha_innodb.cc line 8138

Feb 28 23:24:52 underae18 mysqld[190405]: InnoDB: Failing assertion: templ->clust_rec_field_no != ULINT_UNDEFINED

Feb 28 23:24:52 underae18 mysqld[190405]: InnoDB: We intentionally generate a memory trap.

Feb 28 23:24:52 underae18 mysqld[190405]: InnoDB: Submit a detailed bug report to http://bugs.mysql.com.

Feb 28 23:24:52 underae18 mysqld[190405]: InnoDB: If you get repeated assertion failures or crashes, even

Feb 28 23:24:52 underae18 mysqld[190405]: InnoDB: immediately after the mysqld startup, there may be

Feb 28 23:24:52 underae18 mysqld[190405]: InnoDB: corruption in the InnoDB tablespace. Please refer to

Feb 28 23:24:52 underae18 mysqld[190405]: InnoDB: http://dev.mysql.com/doc/refman/5.6/en/forcing-innodb-recovery.html

Feb 28 23:24:52 underae18 mysqld[190405]: InnoDB: about forcing recovery.

Feb 28 23:24:52 underae18 mysqld[190405]: 170228 23:24:52 [ERROR] mysqld got signal 6 ;

Feb 28 23:24:52 underae18 mysqld[190405]: This could be because you hit a bug. It is also possible that this binary

Feb 28 23:24:52 underae18 mysqld[190405]: or one of the libraries it was linked against is corrupt, improperly built,

Feb 28 23:24:52 underae18 mysqld[190405]: or misconfigured. This error can also be caused by malfunctioning hardware.

Feb 28 23:24:52 underae18 mysqld[190405]: To report this bug, see https://mariadb.com/kb/en/reporting-bugs

Feb 28 23:24:52 underae18 mysqld[190405]: We will try our best to scrape up some info that will hopefully help

Feb 28 23:24:52 underae18 mysqld[190405]: diagnose the problem, but since we have already crashed,

Feb 28 23:24:52 underae18 mysqld[190405]: something is definitely wrong and this may fail.

Feb 28 23:24:52 underae18 mysqld[190405]: Server version: 10.1.21-MariaDB-1~xenial

Feb 28 23:24:52 underae18 mysqld[190405]: key_buffer_size=134217728

Feb 28 23:24:52 underae18 mysqld[190405]: read_buffer_size=2097152

Feb 28 23:24:52 underae18 mysqld[190405]: max_used_connections=173

Feb 28 23:24:52 underae18 mysqld[190405]: max_threads=502

Feb 28 23:24:52 underae18 mysqld[190405]: thread_count=126

Feb 28 23:24:52 underae18 mysqld[190405]: It is possible that mysqld could use up to

Feb 28 23:24:52 underae18 mysqld[190405]: key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 3225650 K  bytes of memory

Feb 28 23:24:52 underae18 mysqld[190405]: Hope that's ok; if not, decrease some variables in the equation.

Feb 28 23:24:52 underae18 mysqld[190405]: Thread pointer: 0x7f92cb10a008

Feb 28 23:24:52 underae18 mysqld[190405]: Attempting backtrace. You can use the following information to find out

Feb 28 23:24:52 underae18 mysqld[190405]: where mysqld died. If you see no messages after this, something went

Feb 28 23:24:52 underae18 mysqld[190405]: terribly wrong...

Feb 28 23:24:52 underae18 mysqld[190405]: stack_bottom = 0x7fadf5d6d0b8 thread_stack 0x48400

Feb 28 23:24:53 underae18 mysqld[190405]: /usr/sbin/mysqld(my_print_stacktrace+0x2e)[0x5646683d904e]

Feb 28 23:24:53 underae18 mysqld[190405]: /usr/sbin/mysqld(handle_fatal_signal+0x2f5)[0x564667f27005]

Feb 28 23:24:53 underae18 mysqld[190405]: /lib/x86_64-linux-gnu/libpthread.so.0(+0x11390)[0x7fadf89a8390]

Feb 28 23:24:53 underae18 mysqld[190405]: /lib/x86_64-linux-gnu/libc.so.6(gsignal+0x38)[0x7fadf7f78428]

Feb 28 23:24:53 underae18 mysqld[190405]: /lib/x86_64-linux-gnu/libc.so.6(abort+0x16a)[0x7fadf7f7a02a]

Feb 28 23:24:53 underae18 mysqld[190405]: /usr/sbin/mysqld(+0x81b54a)[0x5646681ac54a]

Feb 28 23:24:53 underae18 mysqld[190405]: /usr/sbin/mysqld(+0x81bb5e)[0x5646681acb5e]

Feb 28 23:24:53 underae18 mysqld[190405]: /usr/sbin/mysqld(+0x81c040)[0x5646681ad040]

Feb 28 23:24:53 underae18 mysqld[190405]: /usr/sbin/mysqld(+0x450d8f)[0x564667de1d8f]

Feb 28 23:24:53 underae18 mysqld[190405]: /usr/sbin/mysqld(_Z10sub_selectP4JOINP13st_join_tableb+0x164)[0x564667dd0424]

Feb 28 23:24:53 underae18 mysqld[190405]: /usr/sbin/mysqld(+0x45003d)[0x564667de103d]

Feb 28 23:24:53 underae18 mysqld[190405]: /usr/sbin/mysqld(_ZN4JOIN10exec_innerEv+0xc66)[0x564667df44e6]

Feb 28 23:24:53 underae18 mysqld[190405]: /usr/sbin/mysqld(_ZN4JOIN4execEv+0x54)[0x564667df61b4]

Feb 28 23:24:53 underae18 mysqld[190405]: /usr/sbin/mysqld(_Z12mysql_selectP3THDPPP4ItemP10TABLE_LISTjR4ListIS1_ES2_jP8st_orderSB_S2_SB_yP13select_resultP18st_select_lex_unitP13st_select_lex+0xe7)[0x564667df2aa7]

Feb 28 23:24:53 underae18 mysqld[190405]: /usr/sbin/mysqld(_Z13handle_selectP3THDP3LEXP13select_resultm+0x139)[0x564667df3479]

Feb 28 23:24:53 underae18 mysqld[190405]: /usr/sbin/mysqld(+0x3ff631)[0x564667d90631]

Feb 28 23:24:53 underae18 mysqld[190405]: /usr/sbin/mysqld(_Z21mysql_execute_commandP3THD+0x63d3)[0x564667d9d443]

Feb 28 23:24:53 underae18 mysqld[190405]: /usr/sbin/mysqld(_Z11mysql_parseP3THDPcjP12Parser_state+0x311)[0x564667da01f1]

Feb 28 23:24:53 underae18 mysqld[190405]: /usr/sbin/mysqld(_Z16dispatch_command19enum_server_commandP3THDPcj+0x2303)[0x564667da3433]

Feb 28 23:24:53 underae18 mysqld[190405]: /usr/sbin/mysqld(_Z10do_commandP3THD+0x146)[0x564667da3b76]

Feb 28 23:24:53 underae18 mysqld[190405]: /usr/sbin/mysqld(_Z24do_handle_one_connectionP3THD+0x182)[0x564667e6dad2]

Feb 28 23:24:53 underae18 mysqld[190405]: /usr/sbin/mysqld(handle_one_connection+0x40)[0x564667e6dc70]

Feb 28 23:24:53 underae18 mysqld[190405]: /lib/x86_64-linux-gnu/libpthread.so.0(+0x76ba)[0x7fadf899e6ba]

Feb 28 23:24:53 underae18 mysqld[190405]: /lib/x86_64-linux-gnu/libc.so.6(clone+0x6d)[0x7fadf804982d]

Feb 28 23:24:53 underae18 mysqld[190405]: Trying to get some variables.

Feb 28 23:24:54 underae18 mysqld[190405]: Some pointers may be invalid and cause the dump to abort.

Feb 28 23:24:54 underae18 mysqld[190405]: Query (0x7f92cfc21020): SELECT  `settings`.* FROM `settings` WHERE `settings`.`name` = 'locale' LIMIT 1

Feb 28 23:24:54 underae18 mysqld[190405]: Connection ID (thread ID): 20

Feb 28 23:24:54 underae18 mysqld[190405]: Status: NOT_KILLED

Feb 28 23:24:54 underae18 mysqld[190405]: 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,orderby_uses_equalities=off

Feb 28 23:24:54 underae18 mysqld[190405]: The manual page at http://dev.mysql.com/doc/mysql/en/crashing.html contains

Feb 28 23:24:54 underae18 mysqld[190405]: information that should help you find out what is causing the crash.

Feb 28 23:25:04 underae18 mysqld[69669]: 2017-02-28 23:25:04 139722285930752 [Note] /usr/sbin/mysqld (mysqld 10.1.21-MariaDB-1~xenial) starting as process 69669 ...

Let me know if I can provide more information and I'll see what I can do.

The warning message was added in MDEV-6424 in this commit.

To me, it looks like initializing the statistics in ha_innobase::info_low() is prone to race conditions. The statistics should really have been initialized in ha_innobase::open() already. The only way how you can have !table->stats_initialized is when InnoDB internally opened the table (for example, due to purge of old transaction history) before ha_innobase::open() was executed to access the table from SQL.

So, I would suggest reverting the MDEV-6424 patch and fixing that issue correctly.

However, it is unclear if the MDEV-6424 change is a contributing factor to the assertion failure. Maybe the ha_innobase::info_low() was simply executed as part of the very first ha_innobase::open() for this table? That warning was issued 1 second before the assertion failure.

The assertion fails in build_template_field(), which is part of creating a query template for InnoDB. All columns are expected to exist in the InnoDB clustered index, but one is apparently missing. I would like to see some analysis of a core dump. Here is the relevant code (from 10.0.24 XtraDB):

static

mysql_row_templ_t*

build_template_field(

/*=================*/

        row_prebuilt_t* prebuilt,       /*!< in/out: template */

        dict_index_t*   clust_index,    /*!< in: InnoDB clustered index */

        dict_index_t*   index,          /*!< in: InnoDB index to use */

        TABLE*          table,          /*!< in: MySQL table object */

        const Field*    field,          /*!< in: field in MySQL table */

        ulint           i)              /*!< in: field index in InnoDB table */

{

        mysql_row_templ_t*      templ;

        const dict_col_t*       col;

        //ut_ad(field == table->field[i]);

        ut_ad(clust_index->table == index->table);

        col = dict_table_get_nth_col(index->table, i);

        templ = prebuilt->mysql_template + prebuilt->n_template++;

        UNIV_MEM_INVALID(templ, sizeof *templ);

        templ->col_no = i;

        templ->clust_rec_field_no = dict_col_get_clust_pos(col, clust_index);

        ut_a(templ->clust_rec_field_no != ULINT_UNDEFINED);

Hi,
we have experienced the same issue here. We are running Centos 7 a MariaDB 10.1.22. Mysql log is in attachement. mysqld.log . I would like to contribute to solve this issue.
[root@xxx bednar]# uname -r
3.10.0-514.10.2.el7.x86_64
[root@xxx bednar]# cat /etc/redhat-release
CentOS Linux release 7.3.1611 (Core)
Server version: 10.1.22-MariaDB MariaDB Server

Attaching new log file from 10.1.22. Because of MDEV-12327 , innodb status output was ON and data were printed few seconds before the crash - i kept the output in log, maybe it helps (file mariadb-10.1.22-new.log).

it could be a coincedence, but we haven't had any crashes like those that I posted above for a few weeks now since increasing `table_open_cache`. our database server is quite large, with more than 250,000 tables in all.

Michael, what's your new value for table_open_cache? On one of our servers, we have about 75 000 tables, table_open_cache is set to 50000 and server is crashing almost every day.

I had it set to the default 2000 and I doubled it to 4000 ... I'm pretty sure it's not high enough but I read lots of conflicting things about this setting so I didn't want to make any drastic change in the first instance.

I also had mysql replication configured and disabled that at around the same time so could also be related to that..

Probably no, we are not using replication at all.

I've gotten to the bottom of the exact part of application code that was causing the problem, by piecing together logs from our various systems, for multiple crashes. It turns out the statement that causes it, for us at least, is a `TRUNCATE`. we're truncating a large table. It obviously doesn't fail everytime we truncate, but when it does fail it's always on/after a truncate.

There's obviously another moving part(s), creating some perfect storm. We're doing some more investigations to try and get something reproducable.

We just had it again (nothing for months...)
May 18 13:03:47 wms-mdb10-2 mysqld: InnoDB: Warning: Index PRIMARY points to table li7_carenison/biblio_crossref and ib_table li7_carenison/biblio_crossref statistics is initialized 1 but ind
ex table li7_carenison/biblio_crossref initialized 0 mysql table is biblio_crossref. Have you mixed up .frm files from different installations? See http://dev.mysql.com/doc/refman/5.6/en/inno
db-troubleshooting.html
May 18 13:03:47 wms-mdb10-2 mysqld: 2017-05-18 13:03:47 139978120375040 [Note] InnoDB: Looking for field 0 name nid from table li7_carenison/biblio_crossref
May 18 13:03:47 wms-mdb10-2 mysqld: 2017-05-18 13:03:47 139978120375040 [Note] InnoDB: InnoDB Table li7_carenison/biblio_crossref field 0 name nid
May 18 13:03:47 wms-mdb10-2 mysqld: 2017-05-18 13:03:47 139978120375040 [Note] InnoDB: MySQL table biblio_crossref field 0 name nid
May 18 13:03:47 wms-mdb10-2 mysqld: 2017-05-18 13:03:47 139978120375040 [Note] InnoDB: MySQL table biblio_crossref field 1 name biblio_crossref_md5
May 18 13:03:47 wms-mdb10-2 mysqld: 2017-05-18 13:03:47 139978120375040 [Note] InnoDB: MySQL table biblio_crossref field 2 name biblio_crossref_id
May 18 13:03:47 wms-mdb10-2 mysqld: 2017-05-18 13:03:47 139978120375040 [ERROR] InnoDB: Clustered record field for column 0 not found table n_user_defined 1 index n_user_defined 3 InnoDB table
li7_carenison/biblio_crossref field name nid MySQL table biblio_crossref field name nid n_fields 3 query SELECT nid, biblio_crossref_id FROM biblio_crossref WHERE nid IN('680')
May 18 13:03:47 wms-mdb10-2 mysqld: 2017-05-18 13:03:47 7f4f32242b00 InnoDB: Assertion failure in thread 139978120375040 in file ha_innodb.cc line 8359

'use li7_carenison;show create table biblio_crossref;' shows the same on both masters.

Just hit again on the other master, about an hour and a half later (as first one was coming back up).

May 18 14:34:30 wms-mdb10-1 mysqld: InnoDB: Warning: Index PRIMARY points to table li7_camechanicalmechatronicsengineering/page_title and ib_table li7_camechanicalmechatronicsengineering/page_title statistics is initialized 1 but index table li7_camechanicalmechatronicsengineering/page_title initialized 0 mysql table is page_title. Have you mixed up .frm files from different installations? See http://dev.mysql.com/doc/refman/5.6/en/innodb-troubleshooting.html
May 18 14:34:30 wms-mdb10-1 mysqld: InnoDB: Warning: Index PRIMARY points to table li7_camechanicalmechatronicsengineering/page_title and ib_table li7_camechanicalmechatronicsengineering/page_title statistics is initialized 1 but index table li7_camechanicalmechatronicsengineering/page_title initialized 1 mysql table is page_title. Have you mixed up .frm files from different installations? See http://dev.mysql.com/doc/refman/5.6/en/innodb-troubleshooting.html
May 18 14:34:30 wms-mdb10-1 mysqld: 2017-05-18 14:34:30 139708697381632 [Note] InnoDB: Looking for field 0 name type from table li7_camechanicalmechatronicsengineering/page_title
May 18 14:34:30 wms-mdb10-1 mysqld: 2017-05-18 14:34:30 139708697381632 [Note] InnoDB: InnoDB Table li7_camechanicalmechatronicsengineering/page_title field 0 name type
May 18 14:34:30 wms-mdb10-1 mysqld: 2017-05-18 14:34:30 139708697381632 [Note] InnoDB: InnoDB Table li7_camechanicalmechatronicsengineering/page_title field 1 name id
May 18 14:34:30 wms-mdb10-1 mysqld: 2017-05-18 14:34:30 139708697381632 [Note] InnoDB: MySQL table page_title field 0 name type
May 18 14:34:30 wms-mdb10-1 mysqld: 2017-05-18 14:34:30 139708697381632 [Note] InnoDB: MySQL table page_title field 1 name id
May 18 14:34:30 wms-mdb10-1 mysqld: 2017-05-18 14:34:30 139708697381632 [Note] InnoDB: MySQL table page_title field 2 name page_title
May 18 14:34:30 wms-mdb10-1 mysqld: 2017-05-18 14:34:30 139708697381632 [ERROR] InnoDB: Clustered record field for column 0 not found table n_user_defined 2 index n_user_defined 3 InnoDB table li7_camechanicalmechatronicsengineering/page_title field name type MySQL table page_title field name type n_fields 3 query SELECT page_title, id FROM page_title WHERE type = 'node' AND id IN ('26', '51', '350', '409', '436', '442', '443', '461', '753', '881', '914', '915', '916', '917', '1000', '1032', '1099', '1105', '1115', '1116')
May 18 14:34:30 wms-mdb10-1 mysqld: 2017-05-18 14:34:30 7f1077478b00 InnoDB: Assertion failure in thread 139708697381632 in file ha_innodb.cc line 8359
May 18 14:34:30 wms-mdb10-1 mysqld: InnoDB: Failing assertion: templ->clust_rec_field_no != ULINT_UNDEFINED
May 18 14:34:30 wms-mdb10-1 mysqld: InnoDB: We intentionally generate a memory trap.
May 18 14:34:30 wms-mdb10-1 mysqld: InnoDB: Submit a detailed bug report to http://bugs.mysql.com.
May 18 14:34:30 wms-mdb10-1 mysqld: InnoDB: If you get repeated assertion failures or crashes, even
May 18 14:34:30 wms-mdb10-1 mysqld: InnoDB: immediately after the mysqld startup, there may be
May 18 14:34:30 wms-mdb10-1 mysqld: InnoDB: corruption in the InnoDB tablespace. Please refer to
May 18 14:34:30 wms-mdb10-1 mysqld: InnoDB: http://dev.mysql.com/doc/refman/5.6/en/forcing-innodb-recovery.html
May 18 14:34:30 wms-mdb10-1 mysqld: InnoDB: about forcing recovery.
May 18 14:34:30 wms-mdb10-1 mysqld: 170518 14:34:30 [ERROR] mysqld got signal 6 ;
May 18 14:34:30 wms-mdb10-1 mysqld: This could be because you hit a bug. It is also possible that this binary
May 18 14:34:30 wms-mdb10-1 mysqld: or one of the libraries it was linked against is corrupt, improperly built,
May 18 14:34:30 wms-mdb10-1 mysqld: or misconfigured. This error can also be caused by malfunctioning hardware.
May 18 14:34:30 wms-mdb10-1 mysqld: To report this bug, see https://mariadb.com/kb/en/reporting-bugs
May 18 14:34:30 wms-mdb10-1 mysqld: We will try our best to scrape up some info that will hopefully help
May 18 14:34:30 wms-mdb10-1 mysqld: diagnose the problem, but since we have already crashed,
May 18 14:34:30 wms-mdb10-1 mysqld: something is definitely wrong and this may fail.
May 18 14:34:30 wms-mdb10-1 mysqld: Server version: 10.1.20-MariaDB
May 18 14:34:30 wms-mdb10-1 mysqld: key_buffer_size=134217728
May 18 14:34:30 wms-mdb10-1 mysqld: read_buffer_size=131072
May 18 14:34:30 wms-mdb10-1 mysqld: max_used_connections=130
May 18 14:34:30 wms-mdb10-1 mysqld: max_threads=602
May 18 14:34:30 wms-mdb10-1 mysqld: thread_count=128
May 18 14:34:30 wms-mdb10-1 mysqld: It is possible that mysqld could use up to
May 18 14:34:30 wms-mdb10-1 mysqld: key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 1453367 K bytes of memory
May 18 14:34:30 wms-mdb10-1 mysqld: Hope that's ok; if not, decrease some variables in the equation.
May 18 14:34:30 wms-mdb10-1 mysqld: Thread pointer: 0x0x7eed7eeb5008
May 18 14:34:30 wms-mdb10-1 mysqld: Attempting backtrace. You can use the following information to find out
May 18 14:34:30 wms-mdb10-1 mysqld: where mysqld died. If you see no messages after this, something went
May 18 14:34:30 wms-mdb10-1 mysqld: terribly wrong...
May 18 14:34:30 wms-mdb10-1 mysqld: stack_bottom = 0x7f10774780b0 thread_stack 0x48400
May 18 14:34:30 wms-mdb10-1 mysqld: (my_addr_resolve failure: fork)
May 18 14:34:30 wms-mdb10-1 mysqld: /usr/sbin/mysqld(my_print_stacktrace+0x2e) [0x7f107dd116fe]
May 18 14:34:30 wms-mdb10-1 mysqld: /usr/sbin/mysqld(handle_fatal_signal+0x305) [0x7f107d833f75]
May 18 14:34:30 wms-mdb10-1 mysqld: /lib64/libpthread.so.0(+0xf370) [0x7f107ce4f370]
May 18 14:34:30 wms-mdb10-1 mysqld: /lib64/libc.so.6(gsignal+0x37) [0x7f107b1a51d7]
May 18 14:34:30 wms-mdb10-1 mysqld: /lib64/libc.so.6(abort+0x148) [0x7f107b1a68c8]
May 18 14:34:30 wms-mdb10-1 mysqld: /usr/sbin/mysqld(+0x7381c5) [0x7f107d9b61c5]
May 18 14:34:30 wms-mdb10-1 mysqld: /usr/sbin/mysqld(+0x7386d0) [0x7f107d9b66d0]
May 18 14:34:30 wms-mdb10-1 mysqld: /usr/sbin/mysqld(+0x738d19) [0x7f107d9b6d19]
May 18 14:34:30 wms-mdb10-1 mysqld: /usr/sbin/mysqld(+0x738fd3) [0x7f107d9b6fd3]
May 18 14:34:30 wms-mdb10-1 mysqld: /usr/sbin/mysqld(handler::ha_rnd_init_with_error(bool)+0x17) [0x7f107d839957]
May 18 14:34:30 wms-mdb10-1 mysqld: /usr/sbin/mysqld(init_read_record(READ_RECORD*, THD*, TABLE*, SQL_SELECT*, int, bool, bool)+0x3f6) [0x7f107d93d4c6]
May 18 14:34:30 wms-mdb10-1 mysqld: /usr/sbin/mysqld(join_init_read_record(st_join_table*)+0x80) [0x7f107d6e8480]
May 18 14:34:30 wms-mdb10-1 mysqld: /usr/sbin/mysqld(sub_select(JOIN*, st_join_table*, bool)+0x169) [0x7f107d6e86e9]
May 18 14:34:30 wms-mdb10-1 mysqld: /usr/sbin/mysqld(+0x4795fd) [0x7f107d6f75fd]
May 18 14:34:30 wms-mdb10-1 mysqld: /usr/sbin/mysqld(JOIN::exec_inner()+0xb4c) [0x7f107d70972c]
May 18 14:34:30 wms-mdb10-1 mysqld: /usr/sbin/mysqld(JOIN::exec()+0x54) [0x7f107d70b724]
May 18 14:34:30 wms-mdb10-1 mysqld: /usr/sbin/mysqld(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_lex_unit*, st_select_lex*)+0x112) [0x7f107d707dc2]
May 18 14:34:30 wms-mdb10-1 mysqld: /usr/sbin/mysqld(handle_select(THD*, LEX*, select_result*, unsigned long)+0x245) [0x7f107d7088a5]

We tend to get them in pairs.

This looks like a race condition in main-memory data structures and not a permanent corruption of data.

Interestingly, the original crash report in MDEV-6424 included something that looks like a real table schema mismatch (an AUTO_INCREMENT column is named 'vid' in the .frm file, but in InnoDB it is something else):

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

In this ticket, there is no mention of any AUTO_INCREMENT column name mismatch.
That the AUTO_INCREMENT was disabled in the original crash report should not have any impact on whether dict_table_t::stat_initialized will be set.
(Even more severe types of mismatch between .frm files and the InnoDB data dictionary can easily occur when the server is killed during a DDL operation.)

I think that the MDEV-6424 patch should be reverted and the race condition should be found and fixed.
As far as I can tell, this race condition should not have anything to do with .frm files being out of sync with InnoDB.

Not all access to dict_table_t::stat_initialized is delimited by dict_table_stats_lock() and dict_table_stats_unlock(). Also, the design assumption is that once a table has been opened for SQL execution, its statistics will be initialized by ha_innobase::open() and remain so until the table is evicted from the dict_sys cache, or dropped. To my knowledge, the call to ha_innobase::info_low() should always be preceded by a call to ha_innobase::open().

When can a table exist in the dict_sys cache so that dict_table_t::stat_initalized is 0? That should only be the case when the table definition is loaded by an InnoDB background operation, such as purge or the rollback of recovered incomplete transactions.

Maybe there is a race condition that the SQL layer is trying to open the table roughly at the same time as the table definition is being loaded due to a background operation?

In cases like this, my personal opinion is that it would be more useful to abort immediately and allow a useful core dump to be produced for forensic analysis. With luck, there could be some evidence of another thread causing the race condition in the core dump. The longer time we spend on dumping some variables to the error log, the less likely it is to get such useful core dumps. If this assertion failure templ->clust_rec_field_no != ULINT_UNDEFINED is always preceded by the mismatch output, this could also be a case of "garbage in, garbage out". That is, we already noticed that something is wrong in an irrecoverable way, but we kept going, allowing more corruption to occur, and making it harder to find the root cause.

You may remove MDEV-6424 patch and fix the race condition if that is suspect. When that patch was done my suspect was more like user copying .frm file from other installation or some DDL failure.

We saw it again. "better" logs (attached).
We're running MariaDB-server-10.1.20-1.el7.centos.x86_64 on RHEL 6
xxx

And as per usual, we flip and an hour or so later the second one crashes. Here's bits from /var/log/messages yy

Why this isn't a blocker when it's affecting so many people?

Revert MDEV-6424 patch.

http://lists.askmonty.org/pipermail/commits/2017-September/011481.html

azurit — we have a rule that a Blocker, basically, blocks a release. We cannot release if there're active blockers. But this issue, for some reason, had no "Fix Version/s" set, so it was a "blocker" that blocked nothing. I have now specified that this bug should be fixed in 10.0 and in 10.1, but as it wasn't really a blocker, I changed the priority to match what it really was — a high-priority bug, but not blocking a release.

Sergei thank you for clarification. Why do you not consider priority of this bug high enough to be a blocker? For example, we are unable to do a all databases backup without triggering a crash - in other words, our MariaDB servers are crashing DAILY because of this (multiple crashes per day are also common).

Hi, is there some certain steps that cause the assertion, can you enable e.g. general-log and provide the contents of that. Full database and steps how to repeat would also help.

Hi, is there some certain steps that cause the assertion, can you enable e.g. general-log and provide the contents of that. Full database and steps how to repeat would also help.

I don't know of any certain steps which can cause this and, unfortunately, i cannot provide you with anything you are asking, because this is happening only on big MariaDB servers (several thousands of databases and almost thousand qps - i don't think that general-log with 1000 qps will be usefull). It's NOT happening on small servers or it is very uncommon.

azurit, "critical" means that whenever Marko will be fixing 10.0 bugs, this bug will be the first to fix. So "critical" is usually good enough. As there is no clear understanding of the reason of this bug, and not even of a clear steps to repeat it — fixing it might take an unpredictable amount of time. We would rather not to delay the release for an unpredictable amount of time (which is what "Blocker" would mean) — it would be unfair for all users that are affected by bugs that we have already fixed. And it won't make this bug being fixed sooner anyway.

In last log there is number of following messages just before the crash:

Jun  5 12:19:46 wms-mdb10-2 mysqld: InnoDB: Warning: Index PRIMARY points to table li7_calibrary/scheduler and ib_table li7_calibrary/scheduler statistics is initialized 1  but index table li7_calibrary/scheduler initialized 0  mysql table is scheduler. Have you mixed up .frm files from different installations? See http://dev.mysql.com/doc/refman/5.6/en/innodb-troubleshooting.html

Jun  5 12:19:46 wms-mdb10-2 mysqld: InnoDB: Warning: Index scheduler_publish_on points to table li7_calibrary/scheduler and ib_table li7_calibrary/scheduler statistics is initialized 1  but index table li7_calibrary/scheduler initialized 1  mysql table is scheduler. Have you mixed up .frm files from different installations? See http://dev.mysql.com/doc/refman/5.6/en/innodb-troubleshooting.html

Jun  5 12:19:46 wms-mdb10-2 mysqld: InnoDB: Warning: Index scheduler_unpublish_on points to table li7_calibrary/scheduler and ib_table li7_calibrary/scheduler statistics is initialized 1  but index table li7_calibrary/scheduler initialized 1  mysql table is scheduler. Have you mixed up .frm files from different installations? See http://dev.mysql.com/doc/refman/5.6/en/innodb-troubleshooting.html

What happened? Can you provide output for show create table li7_calibrary.scheduler, run check table for it and provide output. Did you run some alter table for this table before these warnings? Can you provide full unedited error log for this case ?

jplindst, do you have an updated patch to review that addresses my comments?

Hi,

We're also experiencing this problem since last summer. It was time to time (once a month) but this week it's each day one to three time. We installed a fresh server, injected SQL using dumps: same issue.

We're using MariaDB 10.1 and follow updates for Debian Jessie (currently 10.1.30-MariaDB-1~jessie).

Here is our last crash (on the new server):

Jan 12 11:36:01 sql-e1b mysqld[4384]: InnoDB: Warning: Index PRIMARY points to table xxxxxx/wp_wfBlocksAdv and ib_table xxxxxx/wp_wfBlocksAdv statistics is initialized 1  but index table xxxxxx/wp_wfBlocksAdv initialized 0  mysql table is wp_wfBlocksAdv. Have you mixed up .frm files from different installation

s? See http://dev.mysql.com/doc/refman/5.6/en/innodb-troubleshooting.html

Jan 12 11:36:01 sql-e1b mysqld[4384]: 2018-01-12 11:36:01 139826108274432 [Note] InnoDB: Looking for field 0 name id from table xxxxxx/wp_wfBlocksAdv

Jan 12 11:36:01 sql-e1b mysqld[4384]: 2018-01-12 11:36:01 139826108274432 [Note] InnoDB: InnoDB Table xxxxxx/wp_wfBlocksAdv field 0 name id

Jan 12 11:36:01 sql-e1b mysqld[4384]: 2018-01-12 11:36:01 139826108274432 [Note] InnoDB: MySQL table wp_wfBlocksAdv field 0 name id

Jan 12 11:36:01 sql-e1b mysqld[4384]: 2018-01-12 11:36:01 139826108274432 [Note] InnoDB: MySQL table wp_wfBlocksAdv field 1 name blockType

Jan 12 11:36:01 sql-e1b mysqld[4384]: 2018-01-12 11:36:01 139826108274432 [Note] InnoDB: MySQL table wp_wfBlocksAdv field 2 name blockString

Jan 12 11:36:01 sql-e1b mysqld[4384]: 2018-01-12 11:36:01 139826108274432 [Note] InnoDB: MySQL table wp_wfBlocksAdv field 3 name ctime

Jan 12 11:36:01 sql-e1b mysqld[4384]: 2018-01-12 11:36:01 139826108274432 [Note] InnoDB: MySQL table wp_wfBlocksAdv field 4 name reason

Jan 12 11:36:01 sql-e1b mysqld[4384]: 2018-01-12 11:36:01 139826108274432 [Note] InnoDB: MySQL table wp_wfBlocksAdv field 5 name totalBlocked

Jan 12 11:36:01 sql-e1b mysqld[4384]: 2018-01-12 11:36:01 139826108274432 [Note] InnoDB: MySQL table wp_wfBlocksAdv field 6 name lastBlocked

Jan 12 11:36:01 sql-e1b mysqld[4384]: 2018-01-12 11:36:01 139826108274432 [ERROR] InnoDB: Clustered record field for column 0 not found table n_user_defined 1 index n_user_defined 7 InnoDB table xxxxxx/wp_wfBlocksAdv field name id MySQL table wp_wfBlocksAdv field name id n_fields 7 query SELECT id, blockType, bloc

kString FROM wp_wfBlocksAdv

Jan 12 11:36:01 sql-e1b mysqld[4384]: 2018-01-12 11:36:01 7f2bcd839700  InnoDB: Assertion failure in thread 139826108274432 in file ha_innodb.cc line 8156

Jan 12 11:36:01 sql-e1b mysqld[4384]: InnoDB: Failing assertion: templ->clust_rec_field_no != ULINT_UNDEFINED

Database and table are not always the same. We can see, sometimes, the following message in log just before:

[ERROR] mysqld: Deadlock found when trying to get lock; try restarting transaction

Olivier

We upgraded MariaDB from 10.1.25+maria-1~jessie to 10.1.26+maria-1~jessie the 2017-08-16 and first crash was the 2017-09-05. MariaDB crashed 47 times (43 times on the previous server and 4 times this day on the newly installed server). Each time it was with a SELECT query on 23 different tables. All tables are very used and can easily have many write and read queries at the same time.

I think @Marko Makela is right:

Maybe there is a race condition that the SQL layer is trying to open the table roughly at the same time as the table definition is being loaded due to a background operation?

In our use case (I work with @Michael Campbell) we have found that it is mainly to do with a large TRUNCATE operation.
We hadn't had a crash in months after we eliminated most TRUNCATEs from our application but last week we had something running which was performing a TRUNCATE on a relatively large table and this caused a crash (TRUNCATE was the last operation to run).

TRUNCATE can't be involved in our crash but it could be some long running DELETE on some table. For other, it some sort of "read only" tables.

The problem occured yesterday. Each time, the crash comes when the server is "heavy" loaded. The server has a little more than 9000 tables. I changed table_open_cache to 9500 and no crash for 1 day and 3 hours.

Some status variables with "open" in name :

+--------------------------+---------+

| Variable_name            | Value   |

+--------------------------+---------+

| Open_files               | 952     |

| Open_table_definitions   | 4303    |

| Open_tables              | 7484    |

| Opened_files             | 2006284 |

| Opened_tables            | 0       |

| Opened_views             | 0       |

+--------------------------+---------+

Note that this day, the problem occured on another server.

I have the same problem.

2018-01-22 12:12:49 7faa4f75d700  InnoDB: Warning: difficult to find free blocks in
InnoDB: the buffer pool (338 search iterations)!
InnoDB: 0 failed attempts to flush a page! Consider
InnoDB: increasing the buffer pool size.
InnoDB: It is also possible that in your Unix version
InnoDB: fsync is very slow, or completely frozen inside
InnoDB: the OS kernel. Then upgrading to a newer version
InnoDB: of your operating system may help. Look at the
InnoDB: number of fsyncs in diagnostic info below.
InnoDB: Pending flushes (fsync) log: 0; buffer pool: 1
InnoDB: 733232238 OS file reads, 57552200 OS file writes, 9498695 OS fsyncs
InnoDB: Starting InnoDB Monitor to print further
InnoDB: diagnostics to the standard output.
InnoDB: Warning: Index PRIMARY points to table user/ss_currency_types and ib_table user/ss_currency_types statistics is initialized 1  but index table user/ss_currency_types initialized 0  mysql table is ss_currency_types. Have you mixed up .frm files from different installations? See http://dev.mysql.c
om/doc/refman/5.6/en/innodb-troubleshooting.html
InnoDB: Warning: Index PRIMARY points to table user/ss_currency_types and ib_table user/ss_currency_types statistics is initialized 1  but index table user/ss_currency_types initialized 0  mysql table is ss_currency_types. Have you mixed up .frm files from different installations? See http://dev.mysql.c
om/doc/refman/5.6/en/innodb-troubleshooting.html
InnoDB: Warning: Index PRIMARY points to table user/ss_currency_types and ib_table user/ss_currency_types statistics is initialized 1  but index table user/ss_currency_types initialized 0  mysql table is ss_currency_types. Have you mixed up .frm files from different installations? See http://dev.mysql.c
om/doc/refman/5.6/en/innodb-troubleshooting.html
2018-01-22 12:13:00 140370849056512 [Note] InnoDB: Looking for field 0 name CID from table user/ss_currency_types
2018-01-22 12:13:00 140370849056512 [Note] InnoDB: InnoDB Table user/ss_currency_types field 0 name CID
2018-01-22 12:13:00 140370849056512 [Note] InnoDB: MySQL table ss_currency_types field 0 name CID
2018-01-22 12:13:00 140370849056512 [Note] InnoDB: MySQL table ss_currency_types field 1 name Name
2018-01-22 12:13:00 140370849056512 [Note] InnoDB: MySQL table ss_currency_types field 2 name code
2018-01-22 12:13:00 140370849056512 [Note] InnoDB: MySQL table ss_currency_types field 3 name currency_value
2018-01-22 12:13:00 140370849056512 [Note] InnoDB: MySQL table ss_currency_types field 4 name where2show
2018-01-22 12:13:00 140370849056512 [Note] InnoDB: MySQL table ss_currency_types field 5 name sort_order
2018-01-22 12:13:00 140370849056512 [Note] InnoDB: MySQL table ss_currency_types field 6 name currency_iso_3
2018-01-22 12:13:00 140370849056512 [ERROR] InnoDB: Clustered record field for column 0 not found table n_user_defined 1 index n_user_defined 7 InnoDB table user/ss_currency_types field name CID MySQL table ss_currency_types field name CID n_fields 7 query select CID, Name, code, currency_value, where2show from
SS_currency_types order by sort_order
2018-01-22 12:13:00 7faaa2984700  InnoDB: Assertion failure in thread 140370849056512 in file ha_innodb.cc line 8156
InnoDB: Failing assertion: templ->clust_rec_field_no != ULINT_UNDEFINED
InnoDB: We intentionally generate a memory trap.
InnoDB: Submit a detailed bug report to https://jira.mariadb.org/
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.
180122 12:13:00 [ERROR] mysqld got signal 6 ;

innodb_open_files 60000
open_files_limit 300000
table_open_cache 120000

Open_files 18066
Open_table_definitions   | 13962  |
Open_tables              | 15974  |
Opened_files             | 147012 |
Opened_plugin_libraries  | 0      |
Opened_table_definitions | 0      |
Opened_tables            | 0      |
Opened_views             | 0      |

I think you should be more worry about this warning:

Warning: difficult to find free blocks in the buffer pool (338 search iterations)!

Having slow I/O can cause this warning and this bug. We don't have anymore this bug on our server for 1 week because we changed table_open_cache. But we also found and fixed an I/O performance issue.

I think you should be more worry about this warning:

Warning: difficult to find free blocks in the buffer pool (338 search iterations)!
Having slow I/O can cause this warning and this bug. We don't have anymore this bug on our server for 1 week because we changed table_open_cache. But we also found and fixed an I/O performance issue.

Nice remark, thanks! I didn't notice this at once.

Still a problem in 10.1.31.. This bug was opened 2 years ago, it is affecting A LOT of people and still no solution? Are you serious?

Not only no solution, despite continuous attempts we still did not manage to reproduce this bug...
Which is why it is not fixed yet, not because it is ignored.

azurit can you provide full error log about the assertion and give use some idea how to repeat this issue. Do you e.g. have general log ?

We have not general log activated as MariaDB servers, where this is happening, are quite big (thousands of databases and about 1000 qps).

Questions:

(1) Does it happen soon after restart or has machine being up a long time?
(2) Does it happen first access to that db or table ?
(3) Do you have full unedited error log and what query causes the crash ?
(3) Does it happen only with DML i.e. SELECT, INSERT, UPDATE, DELETEs or does it need DDL RENAME, ALTER ?
(4) Do you have general log and what are lets say 10-20 previous statements to same table ?

I'm not agree with the way azurit report the problem because it an Open Source product but I'm totally agree with what he tells you. I tried to debug this issue, to reproduce it, to give some info and noone answer to this ticket...

Jan Linström, did you read what I wrote?

yowik Yes, I did read what you wrote, but there seems to be different ways to get this assertion one of them seem to be mysqldump. It is not that we have not tried, I did try to repeat with one user database where it was reported to be repeatable, no luck. Could it be possible that we have some race condition between table/index statistics publishing new stats and query engine trying to read them and getting unfinished results (i.e. corrupted).

I have a hypothesis that this could be related to table eviction. InnoDB in MySQL 5.6 (and in MariaDB 10.x) implemented eviction of least recently used table definitions from the dict_sys cache.

I think that the problem should occur when a table definition has been first opened internally in InnoDB, and then from SQL. This either has to occur right after server startup, or some time after table definition eviction. Note that the FLUSH TABLES statement is not directly connected to the InnoDB table cache eviction.

I would like to get access to a core dump that demonstrates this problem. Possibly we might have to revert the MDEV-6424 change so that the crash occurs sooner after the inconsistency has been detected, and we would have better stack traces of the ‘conflicting threads’.

As discussed on Slack, I might try to use this injection to force table eviction:

        DBUG_EXECUTE_IF("innodb_evict_autoinc_table",

            mutex_enter(&dict_sys->mutex);

            dict_table_remove_from_cache_low(user_table, TRUE);

            mutex_exit(&dict_sys->mutex);

        );

In MariaDB 10.3.18 and 10.4.8, we introduced innodb_evict_tables_on_commit_debug, which could be set to trigger these bugs. But, I remember that mleich reported some bugs related to this instrumentation itself.

Can anyone reproduce this bug? We have not seen this in our internal testing. As far as I can tell, the MDEV-6424 changes were never reverted despite jplindst’s intention to do so.

Perhaps mleich should enable innodb_evict_tables_on_commit_debug in his tests, now that the bugs in its implementation were fixed in MDEV-15880.

I didn't see a crash similar to this for quite a long time.