[MDEV-25850] CREATE FULLTEXT INDEX unnecessarily writes undo log Created: 2021-06-03  Updated: 2023-03-03

Status: Stalled
Project: MariaDB Server
Component/s: Data Definition - Alter Table, Full-text Search, Storage Engine - InnoDB
Affects Version/s: 10.0, 10.1, 10.2, 10.3, 10.4, 10.5, 10.6
Fix Version/s: 10.6

Type: Bug Priority: Major
Reporter: Marko Mäkelä Assignee: Thirunarayanan Balathandayuthapani
Resolution: Unresolved Votes: 0
Labels: performance, purge

Issue Links:
Relates
relates to MDEV-25506 Atomic DDL: .frm file is removed and ... Closed

 Description   

In the third part of MDEV-25506, any DDL operations that will delete .ibd files will be rewritten. The design is such that MDL_EXCLUSIVE is supposed to prevent background access to tables that are about to be deleted. For the InnoDB internal tables that implement FULLTEXT INDEX, we tried to jump through some hoops to acquire MDL on the main table name. This will work for the #sql-backup table, but not for the #sql-alter table. (And MDEV-11415 was not really fixed for the internal tables related to fulltext indexes).
I observed the following crash:

CURRENT_TEST: innodb_fts.fulltext
 
mysqltest: At line 729: query 'CREATE FULLTEXT INDEX idx1 ON t1 (title,body)' failed with wrong errno <Unknown> (2013): 'Lost connection to server during query', instead of ER_DUP_ENTRY (1062)...
 
…
 
2021-06-03 14:41:15 0x7fcc1923c700  InnoDB: Assertion failure in file /mariadb/10.6/storage/innobase/dict/dict0dict.cc line 1893
 
InnoDB: Failing assertion: table->get_ref_count() == 0

The holder of the reference is about to release the reference as well as MDL_SHARED on test.t1:

#6  0x00005580aaac4ff5 in dict_sys_t::mutex_lock (this=<optimized out>) at /mariadb/10.6/storage/innobase/dict/dict0dict.cc:1064
 
#7  0x00005580aaac4b0a in dict_table_close (table=0x7fca877d0bc8, dict_locked=false, try_drop=false, thd=0x7fcb04001158, mdl=0x7fcb040286b0) at /mariadb/10.6/storage/innobase/dict/dict0dict.cc:325
 
#8  0x00005580aa98cf1d in purge_node_t::close_table (this=this@entry=0x5580ae1e9668) at /mariadb/10.6/storage/innobase/include/row0purge.h:229
 
#9  0x00005580aa98d422 in purge_node_t::end (this=0x5580ae1e9668) at /mariadb/10.6/storage/innobase/include/row0purge.h:259
 
#10 0x00005580aa9856a7 in row_purge_step (thr=thr@entry=0x5580ae1e9478) at /mariadb/10.6/storage/innobase/row/row0purge.cc:1335

But, the crashing thread is not holding MDL_EXCLUSIVE because it is executing a rollback. Hence, concurrent access from the purge thread was not blocked:

#5  0x00005580aaa1ad94 in ut_dbg_assertion_failed (expr=0x5580aaed071e "table->get_ref_count() == 0", file=<optimized out>, line=<optimized out>, line@entry=1893) at /mariadb/10.6/storage/innobase/ut/ut0dbg.cc:60
 
#6  0x00005580aaac91d9 in dict_sys_t::remove (this=0x5580ab5455c0 <dict_sys>, table=0x7fca877d0bc8, lru=false, keep=false) at /mariadb/10.6/storage/innobase/dict/dict0dict.cc:1893
 
#7  0x00005580aaaff4db in trx_t::commit (this=0x7fcc1a4f0290, deleted=std::vector of length 6, capacity 8 = {{m_file = 56, m_psi = 0x7fcc1bde0400}, {m_file = 55, m_psi = 0x7fcc1bde0140}, {m_file = 54, m_psi = 0x7fcc1bddfe80}, {m_file = 53, m_psi = 0x7fcc1bddfbc0}, {m_file = 52, m_psi = 0x7fcc1bddf900}, {m_file = 51, m_psi = 0x7fcc1bddf640}}) at /mariadb/10.6/storage/innobase/dict/drop.cc:241
 
#8  0x00005580aa839e15 in commit_unlock_and_unlink (trx=0x7fcc1a4f0290) at /mariadb/10.6/storage/innobase/handler/handler0alter.cc:6106
 
#9  rollback_inplace_alter_table (ha_alter_info=<optimized out>, ha_alter_info@entry=0x7fcc19238f80, table=0x7fca84b6e828, prebuilt=0x7fca877c4b88) at /mariadb/10.6/storage/innobase/handler/handler0alter.cc:8742
 
#10 0x00005580aa82eb64 in ha_innobase::commit_inplace_alter_table (this=0x7fca84c31420, altered_table=0x7fcc19238610, ha_alter_info=0x7fcc19238f80, commit=false) at /mariadb/10.6/storage/innobase/handler/handler0alter.cc:10771
 
#11 0x00005580aa307d8e in mysql_inplace_alter_table (thd=0x7fca84000d48, table_list=0x7fca84016a48, table=0x7fca84b6e828, altered_table=0x7fcc19238610, ha_alter_info=0x7fcc19238f80, target_mdl_request=<optimized out>, ddl_log_state=0x7fcc192385a0, trigger_param=0x7fcc19239c98, alter_ctx=0x7fcc19239040) at /mariadb/10.6/sql/sql_table.cc:7538

Purge was operating on the table FTS_0000000000000258_CONFIG, and it was holding MDL on test.t1 because table ID 0x258 belongs to that name.

Later, a different solution was implemented as part of that development: If a transaction would drop any FTS_ tables, using a new primitive purge_sys.stop_FTS() we will ensure that purge will not be running (on any table) until the transaction has been committed.

Could we fix fts_create_common_tables() so that it never invokes fts_drop_common_tables(), but simply empties the tables if they exist? That would remove the need to drop those common tables. (Note: this suggestion conflicts with the idea below.)

Even better would be to ensure that DDL operations will never write undo log to the FTS_ tables (extending what was implemented in MDEV-11415). We would still have to protect ALGORITHM=COPY and TRUNCATE TABLE operation by MDL (maybe by having ha_innobase::delete_table() and ha_innobase::truncate() acquire MDL on each to-be-dropped FTS_ table name), because purge may be processing undo log records that had been previously written for the old table.

 Comments   
Comment by Marko Mäkelä [ 2021-06-07 ]

We now have an execution trace of this:

ssh pluto
 
rr replay /data/Results/1622894097/TBR-1069/dev/shm/vardir/1622894097/66/1/rr/latest-trace


(rr) c
 
…
 
Thread 3 received signal SIGABRT, Aborted.
 
[Switching to Thread 2548458.2552602]
 
__GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:50
 
50	../sysdeps/unix/sysv/linux/raise.c: No such file or directory.
 
(rr) up 4
 
#4  0x00005560994a4fac in trx_t::commit (this=0x7ff55accdfe8, 
    deleted=std::vector of length 10, capacity 16 = {...})
 
    at /data/Server/bb-10.6-MDEV-25506_I/storage/innobase/dict/drop.cc:241
 
241	        dict_sys.remove(table);
 
(rr) p table.n_ref_count
 
$1 = {m_counter = {<std::__atomic_base<unsigned int>> = {
 
      static _S_alignment = 4, _M_i = 1}, <No data fields>}}
 
(rr) watch -l table.n_ref_count
 
Hardware watchpoint 1: -location table.n_ref_count
 
(rr) rc
 
Continuing.
 
…
 
Continuing.
 
[Switching to Thread 2548458.2561743]
 
 
 
Thread 25 hit Hardware watchpoint 1: -location table.n_ref_count
 
 
 
Old value = 
      {m_counter = {<std::__atomic_base<unsigned int>> = {static _S_alignment = 4, _M_i = 1}, <No data fields>}}
 
New value = 
      {m_counter = {<std::__atomic_base<unsigned int>> = {static _S_alignment = 4, _M_i = 0}, <No data fields>}}
 
0x0000556097aa32c8 in std::__atomic_base<unsigned int>::fetch_add (
 
    __m=std::memory_order_relaxed, __i=1, this=0x6180001b5750)
 
    at /usr/include/c++/9/bits/atomic_base.h:541
 
541	      { return __atomic_fetch_add(&_M_i, __i, int(__m)); }
 
(rr) bt
 
#0  0x0000556097aa32c8 in std::__atomic_base<unsigned int>::fetch_add (
 
    __m=std::memory_order_relaxed, __i=1, this=0x6180001b5750)
 
    at /usr/include/c++/9/bits/atomic_base.h:541
 
#1  Atomic_counter<unsigned int>::add (this=0x6180001b5750, i=1)
 
    at /data/Server/bb-10.6-MDEV-25506_I/include/my_counter.h:27
 
#2  0x0000556097aa16d6 in Atomic_counter<unsigned int>::operator++ (
 
    this=0x6180001b5750)
 
    at /data/Server/bb-10.6-MDEV-25506_I/include/my_counter.h:36
 
#3  0x0000556098e4a418 in dict_table_t::acquire (this=0x6180001b5508)
 
    at /data/Server/bb-10.6-MDEV-25506_I/storage/innobase/include/dict0dict.ic:1145
 
#4  0x00005560991bbb1a in row_purge_parse_undo_rec (node=0x61a00000abc8, 
    undo_rec=0x621000052eb0 "", thr=0x61a00000ab20, 
    updated_extern=0x7ff52fd9a820)
 
    at /data/Server/bb-10.6-MDEV-25506_I/storage/innobase/row/row0purge.cc:1101
 
…
 
(rr) f 3
 
#3  0x0000556098e4a418 in dict_table_t::acquire (this=0x6180001b5508)
 
    at /data/Server/bb-10.6-MDEV-25506_I/storage/innobase/include/dict0dict.ic:1145
 
1145	  n_ref_count++;
 
(rr) p name
 
$2 = {
 
  m_name = 0x604000068250 "test/FTS_", '0' <repeats 13 times>, "199_CONFIG", 
  static part_suffix = "#P#"}
 
(rr) thr a 3 bt
 
…
 
#12 0x000055609978f36e in safe_cond_wait (cond=0x7ff535b1e680, mp=0x610000000240, file=0x55609a785840 "/data/Server/bb-10.6-MDEV-25506_I/storage/innobase/fts/fts0opt.cc", line=2601) at /data/Server/bb-10.6-MDEV-25506_I/mysys/thr_mutex.c:492
 
#13 0x000055609954e743 in fts_optimize_remove_table (table=0x618000113108) at /data/Server/bb-10.6-MDEV-25506_I/storage/innobase/fts/fts0opt.cc:2601
 
#14 0x0000556098e1f9a7 in ha_innobase::delete_table (this=0x62b000145718, name=0x61b000168748 "./test/#sql-alter-26e2ea-35") at /data/Server/bb-10.6-MDEV-25506_I/storage/innobase/handler/ha_innodb.cc:13293
 
#15 0x00005560984e5848 in hton_drop_table (hton=0x615000002118, path=0x61b000168748 "./test/#sql-alter-26e2ea-35") at /data/Server/bb-10.6-MDEV-25506_I/sql/handler.cc:576
 
#16 0x000055609833d45e in THD::rm_temporary_table (this=0x62b00013b218, base=0x615000002118, path=0x61b000168748 "./test/#sql-alter-26e2ea-35") at /data/Server/bb-10.6-MDEV-25506_I/sql/temporary_tables.cc:703
 
#17 0x0000556098340fa1 in THD::free_tmp_table_share (this=0x62b00013b218, share=0x61b000168198, delete_table=true) at /data/Server/bb-10.6-MDEV-25506_I/sql/temporary_tables.cc:1462
 
#18 0x000055609833d16c in THD::drop_temporary_table (this=0x62b00013b218, table=0x619000433598, is_trans=0x0, delete_table=true) at /data/Server/bb-10.6-MDEV-25506_I/sql/temporary_tables.cc:669
 
#19 0x0000556097fc8e28 in mysql_alter_table (thd=0x62b00013b218, new_db=0x62b00013fc28, new_name=0x62b000140040, create_info=0x7ff535b225d0, table_list=0x62b000142488, alter_info=0x7ff535b224a0, order_num=0, order=0x0, ignore=false, if_exists=false) at /data/Server/bb-10.6-MDEV-25506_I/sql/sql_table.cc:10739
 
#20 0x00005560981519f5 in Sql_cmd_alter_table::execute (this=0x62b000142e90, thd=0x62b00013b218) at /data/Server/bb-10.6-MDEV-25506_I/sql/sql_alter.cc:550
 
#21 0x0000556097d5a466 in mysql_execute_command (thd=0x62b00013b218) at /data/Server/bb-10.6-MDEV-25506_I/sql/sql_parse.cc:5983
 
#22 0x0000556097d66933 in mysql_parse (thd=0x62b00013b218, rawbuf=0x62b000142238 "ALTER TABLE t3 ADD KEY IF NOT EXISTS `Marvão_idx3` ( col1, col2 ), ADD UNIQUE KEY `MarvãO_uidx3` ( col_string(9) ), ALGORITHM = COPY, LOCK = SHARED  /* E_R Thread6 QNO 259 CON_ID 53 */", length=186, parser_state=0x7ff535b23b20) at /data/Server/bb-10.6-MDEV-25506_I/sql/sql_parse.cc:8016
 
…
 
(rr) thr 3
 
[Switching to thread 3 (Thread 2548458.2552602)]
 
#0  0x0000000070000002 in ?? ()
 
(rr) f 14
 
#14 0x0000556098e1f9a7 in ha_innobase::delete_table (this=0x62b000145718, 
    name=0x61b000168748 "./test/#sql-alter-26e2ea-35")
 
    at /data/Server/bb-10.6-MDEV-25506_I/storage/innobase/handler/ha_innodb.cc:13293
 
13293	    fts_optimize_remove_table(table);
 
(rr) p/x table.id
 
$3 = 0x199

Note: In purge, we cannot acquire MDL for the table name of table 0x199, because that main table name is test/#sql-alter-26e2ea-35. We could work this around by extending the SQL layer somehow.

A better fix is to not write undo log for any tables of that intermediate table, so that purge will have nothing to do there. In this ALGORITHM=COPY we are not dropping (and re-creating) the common tables, like in the originally reported ALGORITHM=INPLACE case, but the same problem remains: we are writing unnecessary undo log and hitting a race between purge and a DROP of an internal FTS_ table.

Comment by Marko Mäkelä [ 2021-06-16 ]

The reference count problem was worked around in MDEV-25506 part 3, and a race condition in the work-around was fixed in MDEV-25936.

There ought to be no correctness problem in the code. The unnecessary undo logging is merely a performance problem for now.

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