[MDEV-20810] mysqld: storage/innobase/include/ut0rnd.ic:142: ulint ut_fold_string(const char*): Assertion `str' failed. Created: 2019-10-11  Updated: 2022-03-09  Resolved: 2022-03-09

Status: Closed
Project: MariaDB Server
Component/s: Storage Engine - InnoDB
Affects Version/s: 10.3.19
Fix Version/s: N/A

Type: Bug Priority: Major
Reporter: Matthias Leich Assignee: Matthias Leich
Resolution: Cannot Reproduce Votes: 0
Labels: None

Attachments: File simp_ut_fold_string.yy    
Issue Links:
Relates
relates to MDEV-24811 Assertion `find(table)' failed in dic... Closed

 Description    

Assert hit during RQG testing on
 
10.3 4cdb72f2372b27e1fbbc573812240c1e29128c8f 2019-10-10
 
innodb-evict-tables-on-commit-debug was set to 1.
 
The setting of innodb_adaptive_hash_index has no impact.
 
In case I do not set innodb-evict-tables-on-commit-debug to 1 than the assert will not show up.
 
 
 
Version: '10.3.19-MariaDB-debug-log'  socket: ... 
# 2019-10-11T01:20:48 [50100] | mysqld: /work/10.3/storage/innobase/include/ut0rnd.ic:142: ulint ut_fold_string(const char*): Assertion `str' failed.
 
 
 
# 2019-10-11T01:20:48 [50100] | Thread pointer: 0x7fdbf0000a98
 
# 2019-10-11T01:20:48 [50100] | Attempting backtrace. You can use the following information to find out
 
# 2019-10-11T01:20:48 [50100] | where mysqld died. If you see no messages after this, something went
 
# 2019-10-11T01:20:48 [50100] | terribly wrong...
 
# 2019-10-11T01:20:48 [50100] | stack_bottom = 0x7fdc903fbec0 thread_stack 0x49000
 
# 2019-10-11T01:20:48 [50100] | /work/10.3/bld_debug/sql/mysqld(my_print_stacktrace+0x40)[0x561b0139cf52]
 
# 2019-10-11T01:20:48 [50100] | mysys/stacktrace.c:269(my_print_stacktrace)[0x561b00ad23f5]
 
# 2019-10-11T01:20:48 [50100] | /lib/x86_64-linux-gnu/libpthread.so.0(+0x11670)[0x7fdc9463a670]
 
# 2019-10-11T01:20:48 [50100] | linux/raise.c:58(__GI_raise)[0x7fdc939ef77f]
 
# 2019-10-11T01:20:48 [50100] | stdlib/abort.c:91(__GI_abort)[0x7fdc939f137a]
 
# 2019-10-11T01:20:48 [50100] | assert/assert.c:92(__assert_fail_base)[0x7fdc939e7b47]
 
# 2019-10-11T01:20:48 [50100] | /lib/x86_64-linux-gnu/libc.so.6(+0x2dbf2)[0x7fdc939e7bf2]
 
# 2019-10-11T01:20:48 [50100] | /work/10.3/bld_debug/sql/mysqld(+0xf72862)[0x561b01058862]
 
# 2019-10-11T01:20:48 [50100] | include/ut0rnd.ic:144(ut_fold_string(char const*))[0x561b01064fa9]
 
# 2019-10-11T01:20:48 [50100] | dict/dict0dict.cc:1999(dict_table_remove_from_cache_low(dict_table_t*, unsigned long))[0x561b00f78db7]
 
# 2019-10-11T01:20:48 [50100] | trx/trx0trx.cc:1306(trx_update_mod_tables_timestamp(trx_t*))[0x561b00f7953d]
 
# 2019-10-11T01:20:48 [50100] | trx/trx0trx.cc:1389(trx_commit_in_memory(trx_t*, mtr_t const*))[0x561b00f7a9a3]
 
# 2019-10-11T01:20:48 [50100] | trx/trx0trx.cc:1586(trx_commit_low(trx_t*, mtr_t*))[0x561b00f7aa5b]
 
# 2019-10-11T01:20:48 [50100] | trx/trx0trx.cc:1596(trx_commit(trx_t*))[0x561b00f7af0a]
 
# 2019-10-11T01:20:48 [50100] | trx/trx0trx.cc:1747(trx_commit_for_mysql(trx_t*))[0x561b00cfb182]
 
# 2019-10-11T01:20:48 [50100] | handler/ha_innodb.cc:4408(innobase_commit_low(trx_t*))[0x561b00cfb57a]
 
# 2019-10-11T01:20:48 [50100] | handler/ha_innodb.cc:4522(innobase_commit_ordered_2(trx_t*, THD*))[0x561b00cfbbab]
 
# 2019-10-11T01:20:48 [50100] | handler/ha_innodb.cc:4646(innobase_commit(handlerton*, THD*, bool))[0x561b00ad6b0b]
 
# 2019-10-11T01:20:48 [50100] | sql/handler.cc:1641(commit_one_phase_2(THD*, bool, THD_TRANS*, bool))[0x561b00ad6a07]
 
# 2019-10-11T01:20:48 [50100] | sql/handler.cc:1621(ha_commit_one_phase(THD*, bool))[0x561b00ad60c4]
 
# 2019-10-11T01:20:48 [50100] | sql/handler.cc:1483(ha_commit_trans(THD*, bool))[0x561b009415a9]
 
# 2019-10-11T01:20:48 [50100] | sql/transaction.cc:292(trans_commit(THD*))[0x561b007c368a]
 
# 2019-10-11T01:20:48 [50100] | sql/sql_parse.cc:5519(mysql_execute_command(THD*))[0x561b007caad1]
 
# 2019-10-11T01:20:48 [50100] | sql/sql_parse.cc:7829(mysql_parse(THD*, char*, unsigned int, Parser_state*, bool, bool))[0x561b007b770b]
 
# 2019-10-11T01:20:48 [50100] | sql/sql_parse.cc:1857(dispatch_command(enum_server_command, THD*, char*, unsigned int, bool, bool))[0x561b007b6053]
 
# 2019-10-11T01:20:48 [50100] | sql/sql_parse.cc:1400(do_command(THD*))[0x561b0092cd64]
 
# 2019-10-11T01:20:48 [50100] | sql/sql_connect.cc:1403(do_handle_one_connection(CONNECT*))[0x561b0092cac6]
 
# 2019-10-11T01:20:48 [50100] | nptl/pthread_create.c:456(start_thread)[0x7fdc946306da]
 
# 2019-10-11T01:20:48 [50100] | x86_64/clone.S:107(clone)[0x7fdc93ac2d7f]
 
 
 
# 2019-10-11T01:20:48 [50100] | Query (0x7fdbf0010890): COMMIT /* E_R Thread2 QNO 327 CON_ID 18 */
 
# 2019-10-11T01:20:48 [50100] | Connection ID (thread ID): 18
 
# 2019-10-11T01:20:48 [50100] | Status: NOT_KILLED
 
 
 
I will add more information and some simplified replay test soon.



 Comments   
Comment by Matthias Leich [ 2019-10-11 ] 

simp_ut_fold_string.yy is my simplified RQG grammar.
 
There are only 3 concurrent sessions required.

Comment by Marko Mäkelä [ 2019-10-17 ]

mleich, I think that this could be a sign of bigger trouble, even when that debug variable is not set.
Can you please try the following patch?

diff --git a/storage/innobase/trx/trx0trx.cc b/storage/innobase/trx/trx0trx.cc
 
index 2c672dd24fa..155ae9e9dd5 100644
 
--- a/storage/innobase/trx/trx0trx.cc
 
+++ b/storage/innobase/trx/trx0trx.cc
 
@@ -1285,6 +1285,7 @@ trx_update_mod_tables_timestamp(
 
 		protecting it with a latch here would be too performance
 
 		intrusive. */
 
 		dict_table_t* table = it->first;
 
+		ut_a(table->name.m_name);
 
 		table->update_time = now;
 
 #ifdef UNIV_DEBUG
 
 		if (preserve_tables || table->get_ref_count()) {

Does it fail when the debug parameter is not set? The patch should be valid for both release and debug builds.

Comment by Marko Mäkelä [ 2019-10-18 ]

It seems that a hack related to adding or dropping GENERATED columns (persistent or virtual) in ha_innobase::commit_inplace_alter_table() could conflict with DML transaction commit:

	/* MDEV-17468: Avoid this at least when ctx->is_instant().
 
	Currently dict_load_column_low() is the only place where
 
	num_base for virtual columns is assigned to nonzero. */
 
	if (ctx0->num_to_drop_vcol || ctx0->num_to_add_vcol) {
 
		DBUG_ASSERT(ctx0->old_table->get_ref_count() == 1);
 
 
 
		trx_commit_for_mysql(m_prebuilt->trx);
 
#ifdef BTR_CUR_HASH_ADAPT
 
		if (btr_search_enabled) {
 
			btr_search_disable(false);
 
			btr_search_enable();
 
		}
 
#endif /* BTR_CUR_HASH_ADAPT */
 
 
 
		char	tb_name[FN_REFLEN];
 
		ut_strcpy(tb_name, m_prebuilt->table->name.m_name);
 
 
 
		tb_name[strlen(m_prebuilt->table->name.m_name)] = 0;
 
 
 
		dict_table_close(m_prebuilt->table, true, false);
 
		if (ctx0->is_instant()) {
 
			for (unsigned i = ctx0->old_n_v_cols; i--; ) {
 
				ctx0->old_v_cols[i].~dict_v_col_t();
 
			}
 
			const_cast<unsigned&>(ctx0->old_n_v_cols) = 0;
 
		}
 
		dict_sys.remove(m_prebuilt->table);
 
		m_prebuilt->table = dict_table_open_on_name(
 
			tb_name, TRUE, TRUE, DICT_ERR_IGNORE_NONE);

I do not know the exact mechanism for the failure, but I would for now suggest to avoid setting innodb_evict_tables_on_commit_debug while executing DML transactions concurrently with ALTER TABLE that add or drop GENERATED columns.

Comment by Marko Mäkelä [ 2019-10-19 ]

It could be that the innodb_evict_tables_on_commit_debug=ON simply suffers from a race condition when another thread is evicting the table at the same time.

Comment by Marko Mäkelä [ 2021-03-03 ]

This should be fixed in MDEV-24811.

Comment by Matthias Leich [ 2022-03-09 ] 

No replay of that problem with
 
- ~ 4900 RQG tests with the RQG grammar simp_ut_fold_string.yy
 
- origin/10.3 86c1bf118a48dd0bab80346f6d65c112ab2e486d 2022-03-07T16:42:05+03:00
 
   10.3.35
 
Therefore I close the bug.

Generated at Thu Feb 08 09:02:20 UTC 2024 using Jira 8.20.16#820016-sha1:9d11dbea5f4be3d4cc21f03a88dd11d8c8687422.