Details
-
Bug
-
Status: Closed (View Workflow)
-
Major
-
Resolution: Fixed
-
10.2(EOL)
-
None
Description
perl ./mtr --mysqld=--loose-innodb-sync-debug
|
Over a hundred tests fail with several different assertion failures. Here is the list of the tests that failed on my machine (excluding those that failed on different reasons):
binlog_encryption.rpl_parallel
|
binlog_encryption.rpl_mixed_binlog_max_cache_size
|
federated.federated_transactions
|
multi_source.gtid_ignore_duplicates
|
rpl.rpl_ddl
|
rpl.rpl_innodb_mixed_dml
|
rpl.rpl_mixed_binlog_max_cache_size
|
rpl.rpl_drop_db_fail
|
rpl.rpl_gtid_crash
|
rpl.rpl_gtid_mdev4484
|
rpl.rpl_gtid_until
|
rpl.rpl_multi_engine
|
rpl.rpl_parallel
|
rpl.rpl_parallel_optimistic
|
rpl.rpl_read_only
|
rpl.rpl_truncate_3innodb
|
rpl.rpl_row_create_table
|
rpl.rpl_row_tabledefs_3innodb
|
rpl.rpl_old_master
|
rpl.rpl_gtid_strict
|
rpl.rpl_stm_binlog_max_cache_size
|
rpl.rpl_stm_stop_middle_group
|
binlog.flashback
|
binlog.binlog_row_mix_innodb_myisam
|
binlog.binlog_mysqlbinlog_row_trans
|
main-test_sql_discovery.mdl_sync
|
binlog.binlog_stm_mix_innodb_myisam
|
main.mdl_sync
|
main.partition_innodb_semi_consistent
|
innodb.innodb-16k
|
encryption.innodb_encrypt_log_corruption
|
encryption.innodb-bad-key-change
|
encryption.innodb_onlinealter_encryption
|
innodb.101_compatibility
|
innodb_zip.restart
|
innodb.truncate_purge_debug
|
main.commit_1innodb
|
main.sp_trans
|
parts.partition_debug_sync_innodb
|
innodb_fts.innodb-fts-stopword
|
innodb_fts.create
|
parts.partition_mgm_lc1_innodb
|
tokudb.truncate_txn_rollback_innodb
|
mroonga/wrapper.truncate
|
main.statistics_index_crash-7362
|
gcol.gcol_update
|
gcol.innodb_virtual_blob
|
gcol.innodb_virtual_index
|
handler.innodb
|
innodb.autoinc_persist
|
innodb.ibuf_not_empty
|
innodb.innodb-get-fk
|
gcol.innodb_virtual_basic
|
mariabackup.xb_fulltext_encrypted
|
main.innodb_mysql_sync
|
main.partition_explicit_prune
|
main.truncate-stale-6500
|
parts.partition_auto_increment_innodb
|
parts.partition_engine_innodb
|
innodb.innodb-truncate
|
innodb.innodb_blob_truncate
|
parts.partition_mgm_lc0_innodb
|
innodb.innodb_bug34300
|
innodb.innodb_bug38231
|
innodb.innodb_force_recovery
|
innodb.innodb_stats
|
innodb.log_corruption
|
innodb.read_only_recovery
|
innodb_fts.fulltext_multi
|
innodb_fts.fulltext_order_by
|
innodb_fts.fulltext_update
|
innodb_fts.fulltext_var
|
main.alter_table
|
innodb_fts.innodb-fts-basic
|
main.alter_table_trans
|
innodb_fts.innodb-fts-ddl
|
innodb_fts.innodb_fts_large_records
|
innodb_fts.innodb_fts_misc_1
|
innodb_fts.innodb_fts_multiple_index
|
innodb_fts.innodb_fts_plugin
|
innodb_fts.innodb-fts-fic
|
innodb_fts.innodb_fts_proximity
|
innodb_fts.innodb_fts_misc
|
innodb_fts.innodb_fts_stopword_charset
|
innodb_fts.innodb_fts_result_cache_limit
|
innodb_fts.innodb_fts_transaction
|
innodb_fts.misc_debug
|
main.commit
|
main.auto_increment_ranges_innodb
|
sys_vars.foreign_key_checks_func
|
innodb.row_format_redundant
|
vcol.vcol_ins_upd_innodb
|
innodb.temporary_table
|
innodb.tmpdir
|
innodb.truncate_debug
|
main.loaddata_autocom_innodb
|
innodb_fts.crash_recovery
|
innodb_fts.fulltext
|
innodb_fts.fulltext2
|
innodb_fts.fulltext_cache
|
innodb_fts.fulltext_distinct
|
innodb_fts.fulltext_left_join
|
innodb_fts.fulltext_misc
|
perfschema.innodb_table_io
|
I will put the assertion failures in the comment, to make them searchable for future, it might be helpful.
Apart from straightforward test failures, there are lots of reports
Errors/warnings were found in logfiles during server shutdown after running the
|
following sequence(s) of tests:
|
Mostly they're related to tests already mentioned among failures, so its side-effects, but possibly not all of them. The set needs to be re-run for catching those after the failures themselves have been fixed.
Attachments
Issue Links
- relates to
-
MDEV-11634 Improve the InnoDB change buffer
-
- Closed
-
-
-
- Closed
-
-
-
- Closed
-
-
-
- Closed
-
-
-
- Closed
-
-
-
- Closed
-
-
-
- Closed
-
-
-
- Closed
-
-
-
- Closed
-
(4 relates to)
Activity
bb-10.2-marko 6e2fb69a7940
|
innodb_zip.wl5522_zip,4k,innodb innodb_zip.wl5522_zip,8k,innodb |
2017-08-23 21:28:01 0x7fd8885f6700 InnoDB: Assertion failure in file /home/elenst/git/bb-10.2-marko/storage/innobase/sync/sync0debug.cc line 235
|
InnoDB: Failing assertion: latches->empty() || level == SYNC_LEVEL_VARYING || level == SYNC_NO_ORDER_CHECK || latches->back().get_level() == SYNC_NO_ORDER_CHECK || latches->back().m_latch->get_level() == SYNC_LEVEL_VARYING || latches->back().get_level() >= level
|
|
|
#5 0x00007fd89cb4702a in abort () from /lib/x86_64-linux-gnu/libc.so.6
|
#6 0x000055a44d753846 in ut_dbg_assertion_failed (expr=0x55a44dcdd598 "latches->empty() || level == SYNC_LEVEL_VARYING || level == SYNC_NO_ORDER_CHECK || latches->back().get_level() == SYNC_NO_ORDER_CHECK || latches->back().m_latch->get_level() == SYNC_LEVEL_VARYING || l"..., file=0x55a44dcdd538 "/home/elenst/git/bb-10.2-marko/storage/innobase/sync/sync0debug.cc", line=235) at /home/elenst/git/bb-10.2-marko/storage/innobase/ut/ut0dbg.cc:60
|
#7 0x000055a44d709d08 in LatchDebug::lock_validate (this=0x55a4502b4360, latch=0x7fd8885efe60, level=SYNC_IBUF_PESS_INSERT_MUTEX) at /home/elenst/git/bb-10.2-marko/storage/innobase/sync/sync0debug.cc:228
|
#8 0x000055a44d706147 in sync_check_lock_validate (latch=0x7fd8885efe60) at /home/elenst/git/bb-10.2-marko/storage/innobase/sync/sync0debug.cc:1144
|
#9 0x000055a44d55f558 in MutexDebug<TTASEventMutex<GenericPolicy> >::enter (this=0x55a44e61f570 <ibuf_pessimistic_insert_mutex+16>, mutex=0x55a44e61f560 <ibuf_pessimistic_insert_mutex>, name=0x55a44dc580d8 "/home/elenst/git/bb-10.2-marko/storage/innobase/ibuf/ibuf0ibuf.cc", line=2119) at /home/elenst/git/bb-10.2-marko/storage/innobase/include/sync0policy.ic:72
|
#10 0x000055a44d55e2d6 in GenericPolicy<TTASEventMutex<GenericPolicy> >::enter (this=0x55a44e61f570 <ibuf_pessimistic_insert_mutex+16>, mutex=..., filename=0x55a44dc580d8 "/home/elenst/git/bb-10.2-marko/storage/innobase/ibuf/ibuf0ibuf.cc", line=2119) at /home/elenst/git/bb-10.2-marko/storage/innobase/include/sync0policy.h:348
|
#11 0x000055a44d55c967 in PolicyMutex<TTASEventMutex<GenericPolicy> >::enter (this=0x55a44e61f560 <ibuf_pessimistic_insert_mutex>, n_spins=30, n_delay=6, name=0x55a44dc580d8 "/home/elenst/git/bb-10.2-marko/storage/innobase/ibuf/ibuf0ibuf.cc", line=2119) at /home/elenst/git/bb-10.2-marko/storage/innobase/include/ib0mutex.h:633
|
#12 0x000055a44d59f480 in ibuf_remove_free_page () at /home/elenst/git/bb-10.2-marko/storage/innobase/ibuf/ibuf0ibuf.cc:2119
|
#13 0x000055a44d59f929 in ibuf_free_excess_pages () at /home/elenst/git/bb-10.2-marko/storage/innobase/ibuf/ibuf0ibuf.cc:2245
|
#14 0x000055a44d85fbc2 in fseg_create_general (space_id=0, page=0, byte_offset=84, has_done_reservation=0, mtr=0x7fd8885f0d20) at /home/elenst/git/bb-10.2-marko/storage/innobase/fsp/fsp0fsp.cc:2113
|
#15 0x000055a44d860031 in fseg_create (space=0, page=0, byte_offset=84, mtr=0x7fd8885f0d20) at /home/elenst/git/bb-10.2-marko/storage/innobase/fsp/fsp0fsp.cc:2212
|
#16 0x000055a44d76071c in btr_create (type=3, space=0, page_size=..., index_id=62, index=0x7fd83c080978, btr_redo_create_info=0x0, mtr=0x7fd8885f0d20) at /home/elenst/git/bb-10.2-marko/storage/innobase/btr/btr0btr.cc:1185
|
#17 0x000055a44d7f2b3c in dict_create_index_tree_step (node=0x7fd83c075478) at /home/elenst/git/bb-10.2-marko/storage/innobase/dict/dict0crea.cc:910
|
#18 0x000055a44d7f4492 in dict_create_index_step (thr=0x7fd83c07f6d0) at /home/elenst/git/bb-10.2-marko/storage/innobase/dict/dict0crea.cc:1527
|
#19 0x000055a44d62c0f5 in que_thr_step (thr=0x7fd83c07f6d0) at /home/elenst/git/bb-10.2-marko/storage/innobase/que/que0que.cc:1063
|
#20 0x000055a44d62c270 in que_run_threads_low (thr=0x7fd83c07f6d0) at /home/elenst/git/bb-10.2-marko/storage/innobase/que/que0que.cc:1115
|
#21 0x000055a44d62c419 in que_run_threads (thr=0x7fd83c07f6d0) at /home/elenst/git/bb-10.2-marko/storage/innobase/que/que0que.cc:1155
|
#22 0x000055a44d67fb6c in row_create_index_for_mysql (index=0x7fd83c075158, trx=0x7fd892a72cc0, field_lengths=0x7fd83c05e5a0) at /home/elenst/git/bb-10.2-marko/storage/innobase/row/row0mysql.cc:2626
|
#23 0x000055a44d55bd22 in create_index (trx=0x7fd892a72cc0, form=0x7fd8885f1ae0, flags=33, table_name=0x7fd8885f1610 "test/t1", key_num=0) at /home/elenst/git/bb-10.2-marko/storage/innobase/handler/ha_innodb.cc:12013
|
#24 0x000055a44d5451dd in create_table_info_t::create_table (this=0x7fd8885f15c0) at /home/elenst/git/bb-10.2-marko/storage/innobase/handler/ha_innodb.cc:13155
|
#25 0x000055a44d545c3a in ha_innobase::create (this=0x7fd83c075c48, name=0x7fd8885f4320 "./test/t1", form=0x7fd8885f1ae0, create_info=0x7fd8885f4920) at /home/elenst/git/bb-10.2-marko/storage/innobase/handler/ha_innodb.cc:13452
|
#26 0x000055a44d32fe8e in handler::ha_create (this=0x7fd83c075c48, name=0x7fd8885f4320 "./test/t1", form=0x7fd8885f1ae0, info_arg=0x7fd8885f4920) at /home/elenst/git/bb-10.2-marko/sql/handler.cc:4339
|
#27 0x000055a44d330dba in ha_create_table (thd=0x7fd83c000b00, path=0x7fd8885f4320 "./test/t1", db=0x7fd83c012c30 "test", table_name=0x7fd83c0125e8 "t1", create_info=0x7fd8885f4920, frm=0x7fd8885f4310) at /home/elenst/git/bb-10.2-marko/sql/handler.cc:4710
|
#28 0x000055a44d1d07fd in rea_create_table (thd=0x7fd83c000b00, frm=0x7fd8885f4310, path=0x7fd8885f4320 "./test/t1", db=0x7fd83c012c30 "test", table_name=0x7fd83c0125e8 "t1", create_info=0x7fd8885f4920, file=0x7fd83c013310, no_ha_create_table=false) at /home/elenst/git/bb-10.2-marko/sql/unireg.cc:419
|
#29 0x000055a44d17fa08 in create_table_impl (thd=0x7fd83c000b00, orig_db=0x7fd83c012c30 "test", orig_table_name=0x7fd83c0125e8 "t1", db=0x7fd83c012c30 "test", table_name=0x7fd83c0125e8 "t1", path=0x7fd8885f4320 "./test/t1", options=..., create_info=0x7fd8885f4920, alter_info=0x7fd8885f4870, create_table_mode=0, is_trans=0x7fd8885f457e, key_info=0x7fd8885f4300, key_count=0x7fd8885f42f4, frm=0x7fd8885f4310) at /home/elenst/git/bb-10.2-marko/sql/sql_table.cc:4887
|
#30 0x000055a44d18000c in mysql_create_table_no_lock (thd=0x7fd83c000b00, db=0x7fd83c012c30 "test", table_name=0x7fd83c0125e8 "t1", create_info=0x7fd8885f4920, alter_info=0x7fd8885f4870, is_trans=0x7fd8885f457e, create_table_mode=0) at /home/elenst/git/bb-10.2-marko/sql/sql_table.cc:4999
|
#31 0x000055a44d180280 in mysql_create_table (thd=0x7fd83c000b00, create_table=0x7fd83c012620, create_info=0x7fd8885f4920, alter_info=0x7fd8885f4870) at /home/elenst/git/bb-10.2-marko/sql/sql_table.cc:5061
|
#32 0x000055a44d0b93b5 in mysql_execute_command (thd=0x7fd83c000b00) at /home/elenst/git/bb-10.2-marko/sql/sql_parse.cc:3964
|
#33 0x000055a44d0c5ba3 in mysql_parse (thd=0x7fd83c000b00, rawbuf=0x7fd83c0124c8 "CREATE TABLE t1(\nc1 INT NOT NULL AUTO_INCREMENT PRIMARY KEY,\nc2 INT) ENGINE=InnoDB", length=82, parser_state=0x7fd8885f5200, is_com_multi=false, is_next_command=false) at /home/elenst/git/bb-10.2-marko/sql/sql_parse.cc:7886
|
#34 0x000055a44d0b38c7 in dispatch_command (command=COM_QUERY, thd=0x7fd83c000b00, packet=0x7fd83c008881 "CREATE TABLE t1(\nc1 INT NOT NULL AUTO_INCREMENT PRIMARY KEY,\nc2 INT) ENGINE=InnoDB", packet_length=82, is_com_multi=false, is_next_command=false) at /home/elenst/git/bb-10.2-marko/sql/sql_parse.cc:1812
|
#35 0x000055a44d0b223a in do_command (thd=0x7fd83c000b00) at /home/elenst/git/bb-10.2-marko/sql/sql_parse.cc:1360
|
#36 0x000055a44d1fe7cc in do_handle_one_connection (connect=0x55a450321010) at /home/elenst/git/bb-10.2-marko/sql/sql_connect.cc:1354
|
#37 0x000055a44d1fe54c in handle_one_connection (arg=0x55a450321010) at /home/elenst/git/bb-10.2-marko/sql/sql_connect.cc:1260
|
#38 0x000055a44da3ff60 in pfs_spawn_thread (arg=0x55a450303e60) at /home/elenst/git/bb-10.2-marko/storage/perfschema/pfs.cc:1862
|
#39 0x00007fd89d7816ba in start_thread () from /lib/x86_64-linux-gnu/libpthread.so.0
|
#40 0x00007fd89cc1682d in clone () from /lib/x86_64-linux-gnu/libc.so.6
|
Seems to be reliably reproducible by running
perl ./mtr --mysqld=--loose-innodb-sync-debug --mem --noreorder innodb_zip.innodb-zip,4k,innodb innodb_zip.wl5522_debug_zip,4k,innodb innodb_zip.wl5522_zip,4k,innodb
|
The failure is caused by lazy eviction from the change buffer, which we should fix in MDEV-11634.
When an index or table is dropped, buffered changes may be left behind for those pages. The changes will not be discarded until the same page is being allocated for something else.
In this case, the stack trace directly implies this:
print *latches
|
$1 = std::vector of length 4, capacity 32 = {{m_latch = 0x55bb13b5aaa0,
|
m_level = SYNC_DICT_OPERATION}, {m_latch = 0x55bb13b5ab90,
|
m_level = SYNC_DICT}, {m_latch = 0x55bb13b0c1d8, m_level = SYNC_FSP}, {
|
m_latch = 0x55bb13b0c1d8, m_level = SYNC_FSP}}
|
This scenario should be more likely in the system tablespace, because DROP TABLE for an .ibd file should actually remove all change buffer entries for that tablespace ID. For .ibd files, you could theoretically get this by executing DROP INDEX (so that some changes were buffered) followed by CREATE INDEX. In this case, we are discarding buffered changes for a freed-and-reused page in the system tablespace:
# Export/import on the same instance, with --innodb-file-per-table=0
|
# This should fail because it is not supported
|
SET GLOBAL innodb_file_per_table = 0;
|
|
|
CREATE TABLE t1(
|
c1 INT NOT NULL AUTO_INCREMENT PRIMARY KEY,
|
c2 INT) ENGINE=InnoDB;
|
I will have to think if this could lead to a genuine deadlock, or if the debug assertion is simply too strict and should be relaxed.
This code in fseg_create_general() looks suspicious:
if (rw_lock_get_x_lock_count(&space->latch) == 1) {
|
/* This thread did not own the latch before this call: free
|
excess pages from the insert buffer free list */
|
|
|
if (space_id == IBUF_SPACE_ID) {
|
ibuf_free_excess_pages();
|
}
|
}
|
I believe that it would be better to do this ‘housekeeping’ while not holding any latches. Basically, it should be done in create_table_info_t::create_table() or earlier, as soon as we have decided that the table will be created in the system tablespace.
bb-10.2-marko ac33db347cb0e14
Test run is considered successful.
5 failures total: two of the previously analyzed kind (presumably related to MDEV-5800), two sysvar wrong results (expected with non-default innodb-sync-debug), and one sporadic failure unrelated to the current task (MDEV-13259).
The remaining two rpl test failures seem related to
MDEV-5800. Perhaps setting --innodb-sync-debug is affecting the timing so much that it makes those failures easier to repeat.In one of the core dumps, no SQL was executing inside InnoDB (the only ha_innodb.cc function among the stack traces was thd_destructor_proxy). Maybe RESET MASTER is somehow invalidating the THD objects, causing trouble for the InnoDB purge threads?