[MDEV-29277] On error, fts_sync_table() fails to release a table handle - Jira

Details

Type: Bug
Status: Closed (View Workflow)
Priority: Critical
Resolution: Fixed
Affects Version/s: 10.6, 10.7(EOL), 10.8(EOL), 10.9(EOL), 10.10(EOL), 10.11
Fix Version/s: 10.6.11, 10.7.7, 10.8.6, 10.9.4, 10.10.2
Component/s: Full-text Search, Storage Engine - InnoDB
Labels:

Description

It looks like there are still several issues around the table->get_ref_count() == 0 assert (ref ~~MDEV-26636~~, ~~MDEV-29250~~). Here is a list of UniqueID's/stacks that I have seen in connection with this:

table->get_ref_count() == 0|SIGABRT|ut_dbg_assertion_failed|dict_sys_t::remove|dict_sys_t::close|innodb_shutdown

table->get_ref_count() == 0|SIGABRT|ut_dbg_assertion_failed|dict_sys_t::remove|trx_t::commit|ha_innobase::delete_table

table->get_ref_count() == 0|SIGABRT|ut_dbg_assertion_failed|dict_sys_t::remove|trx_t::commit|ha_innobase::create

table->get_ref_count() > 0|SIGABRT|ut_dbg_assertion_failed|dict_table_close|row_prebuilt_free|ha_innobase::close

table->get_ref_count() == 0|SIGABRT|ut_dbg_assertion_failed|dict_sys_t::remove|row_drop_table_for_mysql|ha_innobase::delete_table

Issues seem to be highly sporadic, and so far I have several testcases just under 100 lines, some around 150 lines and some 400-900 lines. I will attempt to reduce further to ~10 lines or less.
Here is a selection of versions I have seen this bug on (list does not correlate to list above). Note the numbers after MD are DDMMYY.

MD140222-mariadb-10.9.0-linux-x86_64-dbg @ b5852ffbeebc3000982988383daeefb0549e058a

MD030322-mariadb-10.9.0-linux-x86_64-dbg 177345dadc9250387343164be0053b1952fc59c1

MD160322-mariadb-10.5.16-linux-x86_64-opt @ 73fee39ea62037780c59161507e89dd76c10b7a3

MD160322-mariadb-10.8.3-linux-x86_64-dbg @ 9f5a3e568913e0810109554608c56c93f3ec24f8

online-alter_MD080622-mariadb-10.10.0-linux-x86_64-dbg @ d7a7d16713070c7c2902c3df4b4f6d024cd0320f

MDEV-28883_MD280622-mariadb-10.10.0-linux-x86_64-dbg @ 2db18fdb3d68d906fbd188ec570a64502ba55849

MD120722-mariadb-10.10.0-linux-x86_64-dbg @ 88b22356e623fd63aa87273a895521a6e6667bc7

Likely other versions (and especially 10.6, 10.7 given there is 10.5 and 10.8) are affected.

Attachments

Issue Links

relates to

MDEV-26636 Race conditions due to attempted updates of InnoDB defragmentation statistics for temporary tables

Closed

MDEV-29053 safe_mutex: Trying to destroy a mutex cache->lock that was locked at innobase/fts/fts0fts.cc on shutdown

Closed

MDEV-29250 InnoDB: Failing assertion: table->get_ref_count() == 0

Closed

Activity

Ascending order - Click to sort in descending order

Roel Van de Paar added a comment - 2022-09-13 10:42 - edited

One example reduced testcase

CREATE TABLE t2 (c INT);

DROP TABLE t,t2;

CREATE TABLE t2 (s CHAR(255),FULLTEXT (s)) DEFAULT CHARSET=utf8;

INSERT INTO t2 VALUES (10009);

SET GLOBAL innodb_trx_rseg_n_slots_debug=1,@@SESSION.pseudo_slave_mode=ON;

SHUTDOWN;

Leads to:

10.11.0 bc563f1a4b0b38de3b41fd0f0d3d8b7f1aacbd8b (Debug)
InnoDB: Failing assertion: table->get_ref_count() == 0

10.11.0 bc563f1a4b0b38de3b41fd0f0d3d8b7f1aacbd8b (Debug)
Core was generated by `/test/MD190822-mariadb-10.11.0-linux-x86_64-dbg/bin/mysqld --no-defaults --core'.
Program terminated with signal SIGABRT, Aborted.
#0 __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:50
[Current thread is 1 (Thread 0x14eb78942940 (LWP 40379))]
(gdb) bt
#0 __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:50
#1 0x000014eb78b1b859 in __GI_abort () at abort.c:79
#2 0x00005623ed87cd33 in ut_dbg_assertion_failed (expr=expr@entry=0x5623edeb1db0 "table->get_ref_count() == 0", file=file@entry=0x5623edeb2318 "/test/10.11_dbg/storage/innobase/dict/dict0dict.cc", line=line@entry=1854) at /test/10.11_dbg/storage/innobase/ut/ut0dbg.cc:60
#3 0x00005623ed93f986 in dict_sys_t::remove (this=this@entry=0x5623ee530a00 <dict_sys>, table=0x14eaec07c6d0, lru=lru@entry=false, keep=keep@entry=false) at /test/10.11_dbg/storage/innobase/dict/dict0dict.cc:1854
#4 0x00005623ed940305 in dict_sys_t::close (this=0x5623ee530a00 <dict_sys>) at /test/10.11_dbg/storage/innobase/dict/dict0dict.cc:4563
#5 0x00005623ed831529 in innodb_shutdown () at /test/10.11_dbg/storage/innobase/srv/srv0start.cc:1765
#6 0x00005623ed62f622 in innobase_end () at /test/10.11_dbg/storage/innobase/handler/ha_innodb.cc:4308
#7 0x00005623ed32d9a7 in ha_finalize_handlerton (plugin=0x5623efd3cb30) at /test/10.11_dbg/sql/handler.cc:596
#8 0x00005623ed05ff76 in plugin_deinitialize (plugin=0x5623efd3cb30, ref_check=ref_check@entry=true) at /test/10.11_dbg/sql/sql_plugin.cc:1269
#9 0x00005623ed063e55 in reap_plugins () at /test/10.11_dbg/sql/sql_plugin.cc:1343
#10 0x00005623ed064938 in plugin_shutdown () at /test/10.11_dbg/sql/sql_plugin.cc:2051
#11 0x00005623ecf092c0 in clean_up (print_message=print_message@entry=true) at /test/10.11_dbg/sql/mysqld.cc:1988
#12 0x00005623ecf156c6 in mysqld_main (argc=<optimized out>, argv=<optimized out>) at /test/10.11_dbg/sql/mysqld.cc:5940
#13 0x00005623ecf08b76 in main (argc=<optimized out>, argv=<optimized out>) at /test/10.11_dbg/sql/main.cc:34

As well as:

10.11.0 bc563f1a4b0b38de3b41fd0f0d3d8b7f1aacbd8b (Debug)
InnoDB: Failing assertion: table->get_ref_count() == 0

10.11.0 bc563f1a4b0b38de3b41fd0f0d3d8b7f1aacbd8b (Debug)
Core was generated by `/test/MD190822-mariadb-10.11.0-linux-x86_64-dbg/bin/mysqld --no-defaults --core'.
Program terminated with signal SIGABRT, Aborted.
#0 0x0000149a4e70200b in ?? ()
[Current thread is 1 (LWP 3947348)]
(gdb) bt
#0 0x0000149a4e70200b in ?? ()
Backtrace stopped: Cannot access memory at address 0x7fffa4a84110

Bug confirmed present in:
MariaDB: 10.6.10 (dbg), 10.7.6 (dbg), 10.8.5 (dbg), 10.9.2 (dbg), 10.10.2 (dbg), 10.11.0 (dbg)

Bug (or feature/syntax) confirmed not present in:
MariaDB: 10.3.37 (dbg), 10.3.37 (opt), 10.4.27 (dbg), 10.4.27 (opt), 10.5.18 (dbg), 10.5.18 (opt), 10.6.10 (opt), 10.7.6 (opt), 10.8.5 (opt), 10.9.2 (opt), 10.10.2 (opt), 10.11.0 (opt)
MySQL: 5.5.62 (dbg), 5.5.62 (opt), 5.6.51 (dbg), 5.6.51 (opt), 5.7.38 (dbg), 5.7.38 (opt), 8.0.29 (dbg), 8.0.29 (opt)

The two UniqueID's for this testcase specifically:

table->get_ref_count() == 0|SIGABRT|Backtrace stopped: Cannot access memory at address

table->get_ref_count() == 0|SIGABRT|ut_dbg_assertion_failed|dict_sys_t::remove|dict_sys_t::close|innodb_shutdown

Roel Van de Paar added a comment - 2022-09-13 10:42 - edited One example reduced testcase CREATE TABLE t2 (c INT ); DROP TABLE t,t2; CREATE TABLE t2 (s CHAR (255),FULLTEXT (s)) DEFAULT CHARSET=utf8; INSERT INTO t2 VALUES (10009); SET GLOBAL innodb_trx_rseg_n_slots_debug=1,@@SESSION.pseudo_slave_mode= ON ; SHUTDOWN; Leads to: 10.11.0 bc563f1a4b0b38de3b41fd0f0d3d8b7f1aacbd8b (Debug) InnoDB: Failing assertion: table->get_ref_count() == 0 10.11.0 bc563f1a4b0b38de3b41fd0f0d3d8b7f1aacbd8b (Debug) Core was generated by `/test/MD190822-mariadb-10.11.0-linux-x86_64-dbg/bin/mysqld --no-defaults --core'. Program terminated with signal SIGABRT, Aborted. #0 __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:50 [Current thread is 1 (Thread 0x14eb78942940 (LWP 40379))] (gdb) bt #0 __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:50 #1 0x000014eb78b1b859 in __GI_abort () at abort.c:79 #2 0x00005623ed87cd33 in ut_dbg_assertion_failed (expr=expr@entry=0x5623edeb1db0 "table->get_ref_count() == 0", file=file@entry=0x5623edeb2318 "/test/10.11_dbg/storage/innobase/dict/dict0dict.cc", line=line@entry=1854) at /test/10.11_dbg/storage/innobase/ut/ut0dbg.cc:60 #3 0x00005623ed93f986 in dict_sys_t::remove (this=this@entry=0x5623ee530a00 <dict_sys>, table=0x14eaec07c6d0, lru=lru@entry=false, keep=keep@entry=false) at /test/10.11_dbg/storage/innobase/dict/dict0dict.cc:1854 #4 0x00005623ed940305 in dict_sys_t::close (this=0x5623ee530a00 <dict_sys>) at /test/10.11_dbg/storage/innobase/dict/dict0dict.cc:4563 #5 0x00005623ed831529 in innodb_shutdown () at /test/10.11_dbg/storage/innobase/srv/srv0start.cc:1765 #6 0x00005623ed62f622 in innobase_end () at /test/10.11_dbg/storage/innobase/handler/ha_innodb.cc:4308 #7 0x00005623ed32d9a7 in ha_finalize_handlerton (plugin=0x5623efd3cb30) at /test/10.11_dbg/sql/handler.cc:596 #8 0x00005623ed05ff76 in plugin_deinitialize (plugin=0x5623efd3cb30, ref_check=ref_check@entry=true) at /test/10.11_dbg/sql/sql_plugin.cc:1269 #9 0x00005623ed063e55 in reap_plugins () at /test/10.11_dbg/sql/sql_plugin.cc:1343 #10 0x00005623ed064938 in plugin_shutdown () at /test/10.11_dbg/sql/sql_plugin.cc:2051 #11 0x00005623ecf092c0 in clean_up (print_message=print_message@entry=true) at /test/10.11_dbg/sql/mysqld.cc:1988 #12 0x00005623ecf156c6 in mysqld_main (argc=<optimized out>, argv=<optimized out>) at /test/10.11_dbg/sql/mysqld.cc:5940 #13 0x00005623ecf08b76 in main (argc=<optimized out>, argv=<optimized out>) at /test/10.11_dbg/sql/main.cc:34 As well as: 10.11.0 bc563f1a4b0b38de3b41fd0f0d3d8b7f1aacbd8b (Debug) InnoDB: Failing assertion: table->get_ref_count() == 0 10.11.0 bc563f1a4b0b38de3b41fd0f0d3d8b7f1aacbd8b (Debug) Core was generated by `/test/MD190822-mariadb-10.11.0-linux-x86_64-dbg/bin/mysqld --no-defaults --core'. Program terminated with signal SIGABRT, Aborted. #0 0x0000149a4e70200b in ?? () [Current thread is 1 (LWP 3947348)] (gdb) bt #0 0x0000149a4e70200b in ?? () Backtrace stopped: Cannot access memory at address 0x7fffa4a84110 Bug confirmed present in: MariaDB: 10.6.10 (dbg), 10.7.6 (dbg), 10.8.5 (dbg), 10.9.2 (dbg), 10.10.2 (dbg), 10.11.0 (dbg) Bug (or feature/syntax) confirmed not present in: MariaDB: 10.3.37 (dbg), 10.3.37 (opt), 10.4.27 (dbg), 10.4.27 (opt), 10.5.18 (dbg), 10.5.18 (opt), 10.6.10 (opt), 10.7.6 (opt), 10.8.5 (opt), 10.9.2 (opt), 10.10.2 (opt), 10.11.0 (opt) MySQL: 5.5.62 (dbg), 5.5.62 (opt), 5.6.51 (dbg), 5.6.51 (opt), 5.7.38 (dbg), 5.7.38 (opt), 8.0.29 (dbg), 8.0.29 (opt) The two UniqueID's for this testcase specifically: table->get_ref_count() == 0|SIGABRT|Backtrace stopped: Cannot access memory at address table->get_ref_count() == 0|SIGABRT|ut_dbg_assertion_failed|dict_sys_t::remove|dict_sys_t::close|innodb_shutdown

Marko Mäkelä added a comment - 2022-09-14 13:21 - edited

I do not agree that this is a race condition or a sporadic failure. Many assertion failures on dict_table_t::n_ref_count are due to a race condition, but not this one.

I can deterministically reproduce this with the following:

--source include/have_innodb.inc

CREATE TABLE t1 (s CHAR(255),FULLTEXT (s)) ENGINE=InnoDB DEFAULT CHARSET=utf8;

INSERT INTO t1 VALUES (10009);

SET GLOBAL innodb_trx_rseg_n_slots_debug=1,@@SESSION.pseudo_slave_mode=ON;

--source include/restart_mysqld.inc

DROP TABLE t1;

Edit: if the 10009 above is changed to '10009', then this will not crash.

10.6 fd0bdd3180a7d5f4b9804d372d6a63b6a202818c
Thread 1 received signal SIGABRT, Aborted.
__pthread_kill_implementation (threadid=<optimized out>, signo=signo@entry=6, no_tid=no_tid@entry=0) at ./nptl/pthread_kill.c:44
44 ./nptl/pthread_kill.c: Tiedostoa tai hakemistoa ei ole.
(rr) up 4
#4 0x0000558e7f9b41c6 in ut_dbg_assertion_failed (
expr=expr@entry=0x558e7ea06d52 "table->get_ref_count() == 0",
file=file@entry=0x558e7eac44c0 "/mariadb/10.6/storage/innobase/dict/dict0dict.cc", line=line@entry=1860) at /mariadb/10.6/storage/innobase/ut/ut0dbg.cc:60
60 abort();
(rr) up
#5 0x0000558e7f7e0733 in dict_sys_t::remove (
this=this@entry=0x558e7fc43980 <dict_sys>, table=0x7f57b0226b08,
lru=lru@entry=false, keep=keep@entry=false)
at /mariadb/10.6/storage/innobase/dict/dict0dict.cc:1860
1860 ut_a(table->get_ref_count() == 0);
(rr) p table.name
$1 = {
m_name = 0x7f57b0057168 "test/FTS_", '0' <repeats 14 times>, "12_", '0' <repeats 14 times>, "1e_INDEX_1"}
(rr) watch -l table.n_ref_count
Hardware watchpoint 1: -location table.n_ref_count
(rr) reverse-continue
…
(rr) reverse-continue
…
(rr) continue
Thread 4 hit Hardware watchpoint 1: -location table.n_ref_count

Old value = {m_counter = std::atomic<unsigned int> = { 0 }}
New value = {m_counter = std::atomic<unsigned int> = { 1 }}
0x0000558e7f74494d in dict_table_t::acquire (this=0x7f57b0226b08) at /mariadb/10.6/storage/innobase/include/dict0dict.inl:1133
1133 }
(rr) backtrace
#0 0x0000558e7f74494d in dict_table_t::acquire (this=0x7f57b0226b08) at /mariadb/10.6/storage/innobase/include/dict0dict.inl:1133
#1 0x0000558e7f7ddf06 in dict_table_open_on_name (table_name=<optimized out>, dict_locked=dict_locked@entry=true, ignore_err=ignore_err@entry=DICT_ERR_IGNORE_NONE)
at /mariadb/10.6/storage/innobase/dict/dict0dict.cc:1111
#2 0x0000558e7f8ec436 in pars_retrieve_table_def (sym_node=sym_node@entry=0x7f57cc007138) at /mariadb/10.6/storage/innobase/pars/pars0pars.cc:768
#3 0x0000558e7f8ee021 in pars_insert_statement (table_sym=0x7f57cc007138, values_list=0x7f57cc007248, select=select@entry=0x0) at /mariadb/10.6/storage/innobase/pars/pars0pars.cc:1274
#4 0x0000558e7f8ef5d0 in yyparse () at /dev/shm/10.6/pars0grm.y:311
#5 0x0000558e7f8edaf0 in pars_sql (info=info@entry=0x7f57cc004838,
str=str@entry=0x7f57cc0065c8 "PROCEDURE P() IS\nBEGIN\nINSERT INTO $index_table_name VALUES (:token, :first_doc_id, :last_doc_id, :doc_count, :ilist);\nEND;\n")
at /mariadb/10.6/storage/innobase/pars/pars0pars.cc:1986
#6 0x0000558e7f82c969 in fts_parse_sql (fts_table=fts_table@entry=0x7f57d5053410, info=info@entry=0x7f57cc004838,
sql=sql@entry=0x558e7eb52ed0 "BEGIN\nINSERT INTO $index_table_name VALUES (:token, :first_doc_id, :last_doc_id, :doc_count, :ilist);") at /mariadb/10.6/storage/innobase/fts/fts0sql.cc:136
#7 0x0000558e7f7562f6 in fts_write_node (trx=trx@entry=0x7f57d6b60b80, graph=0x7f57b011a3d8, fts_table=fts_table@entry=0x7f57d5053410, word=word@entry=0x7f57b0088158, node=0x7f57b011a620)
at /mariadb/10.6/storage/innobase/fts/fts0fts.cc:3753
#8 0x0000558e7f75b402 in fts_sync_write_words (trx=trx@entry=0x7f57d6b60b80, index_cache=index_cache@entry=0x7f57b011a388) at /mariadb/10.6/storage/innobase/fts/fts0fts.cc:3877
#9 0x0000558e7f75b66e in fts_sync_index (sync=sync@entry=0x7f57b011a338, index_cache=index_cache@entry=0x7f57b011a388) at /mariadb/10.6/storage/innobase/fts/fts0fts.cc:3960
#10 0x0000558e7f75c38a in fts_sync (sync=0x7f57b011a338) at /mariadb/10.6/storage/innobase/fts/fts0fts.cc:4107
#11 0x0000558e7f75c51a in fts_sync_table (table=table@entry=0x7f57b01359f8) at /mariadb/10.6/storage/innobase/fts/fts0fts.cc:4152
#12 0x0000558e7f82967b in fts_optimize_sync_table (table=<optimized out>, process_message=process_message@entry=false) at /mariadb/10.6/storage/innobase/fts/fts0opt.cc:2768
#13 0x0000558e7f82c12a in fts_optimize_callback () at /mariadb/10.6/storage/innobase/fts/fts0opt.cc:2886
#14 0x0000558e7f9b9582 in tpool::task_group::execute (this=0x558e80566b00 <task_group>, t=t@entry=0x558e80566ae0 <task>) at /mariadb/10.6/tpool/task_group.cc:55
…
(rr) continue
Continuing.

Thread 4 hit Hardware watchpoint 1: -location table.n_ref_count

Old value = {m_counter = std::atomic<unsigned int> = { 1 }}
New value = {m_counter = std::atomic<unsigned int> = { 2 }}
0x0000558e7f74494d in dict_table_t::acquire (this=0x7f57b0226b08) at /mariadb/10.6/storage/innobase/include/dict0dict.inl:1133
1133 }
(rr) bt
…
#10 0x0000558e7f9a1358 in trx_t::rollback (this=this@entry=0x7f57d6b60b80, savept=savept@entry=0x0) at /mariadb/10.6/storage/innobase/trx/trx0roll.cc:176
#11 0x0000558e7f75bbb3 in fts_sync_commit (sync=sync@entry=0x7f57b011a338) at /mariadb/10.6/storage/innobase/fts/fts0fts.cc:4004
…
(rr) continue
Continuing.

Thread 4 hit Hardware watchpoint 1: -location table.n_ref_count

Old value = {m_counter = std::atomic<unsigned int> = { 2 }}
New value = {m_counter = std::atomic<unsigned int> = { 1 }}
dict_table_t::release (this=0x7f57b0226b08) at /mariadb/10.6/storage/innobase/include/dict0dict.inl:1142
1142 ut_ad(n > 0);
(rr) bt
…
#10 0x0000558e7f9a1358 in trx_t::rollback (this=this@entry=0x7f57d6b60b80, savept=savept@entry=0x0) at /mariadb/10.6/storage/innobase/trx/trx0roll.cc:176
#11 0x0000558e7f75bbb3 in fts_sync_commit (sync=sync@entry=0x7f57b011a338) at /mariadb/10.6/storage/innobase/fts/fts0fts.cc:4004

The first table handle was never released. The rollback acquired and released a table handle just fine.

Marko Mäkelä added a comment - 2022-09-14 13:21 - edited I do not agree that this is a race condition or a sporadic failure. Many assertion failures on dict_table_t::n_ref_count are due to a race condition, but not this one. I can deterministically reproduce this with the following: --source include/have_innodb.inc CREATE TABLE t1 (s CHAR (255),FULLTEXT (s)) ENGINE=InnoDB DEFAULT CHARSET=utf8; INSERT INTO t1 VALUES (10009); SET GLOBAL innodb_trx_rseg_n_slots_debug=1,@@SESSION.pseudo_slave_mode= ON ; --source include/restart_mysqld.inc DROP TABLE t1; Edit: if the 10009 above is changed to '10009', then this will not crash. 10.6 fd0bdd3180a7d5f4b9804d372d6a63b6a202818c Thread 1 received signal SIGABRT, Aborted. __pthread_kill_implementation (threadid=<optimized out>, signo=signo@entry=6, no_tid=no_tid@entry=0) at ./nptl/pthread_kill.c:44 44 ./nptl/pthread_kill.c: Tiedostoa tai hakemistoa ei ole. (rr) up 4 #4 0x0000558e7f9b41c6 in ut_dbg_assertion_failed ( expr=expr@entry=0x558e7ea06d52 "table->get_ref_count() == 0", file=file@entry=0x558e7eac44c0 "/mariadb/10.6/storage/innobase/dict/dict0dict.cc", line=line@entry=1860) at /mariadb/10.6/storage/innobase/ut/ut0dbg.cc:60 60 abort(); (rr) up #5 0x0000558e7f7e0733 in dict_sys_t::remove ( this=this@entry=0x558e7fc43980 <dict_sys>, table=0x7f57b0226b08, lru=lru@entry=false, keep=keep@entry=false) at /mariadb/10.6/storage/innobase/dict/dict0dict.cc:1860 1860 ut_a(table->get_ref_count() == 0); (rr) p table.name $1 = { m_name = 0x7f57b0057168 "test/FTS_", '0' <repeats 14 times>, "12_", '0' <repeats 14 times>, "1e_INDEX_1"} (rr) watch -l table.n_ref_count Hardware watchpoint 1: -location table.n_ref_count (rr) reverse-continue … (rr) reverse-continue … (rr) continue Thread 4 hit Hardware watchpoint 1: -location table.n_ref_count Old value = {m_counter = std::atomic<unsigned int> = { 0 }} New value = {m_counter = std::atomic<unsigned int> = { 1 }} 0x0000558e7f74494d in dict_table_t::acquire (this=0x7f57b0226b08) at /mariadb/10.6/storage/innobase/include/dict0dict.inl:1133 1133 } (rr) backtrace #0 0x0000558e7f74494d in dict_table_t::acquire (this=0x7f57b0226b08) at /mariadb/10.6/storage/innobase/include/dict0dict.inl:1133 #1 0x0000558e7f7ddf06 in dict_table_open_on_name (table_name=<optimized out>, dict_locked=dict_locked@entry=true, ignore_err=ignore_err@entry=DICT_ERR_IGNORE_NONE) at /mariadb/10.6/storage/innobase/dict/dict0dict.cc:1111 #2 0x0000558e7f8ec436 in pars_retrieve_table_def (sym_node=sym_node@entry=0x7f57cc007138) at /mariadb/10.6/storage/innobase/pars/pars0pars.cc:768 #3 0x0000558e7f8ee021 in pars_insert_statement (table_sym=0x7f57cc007138, values_list=0x7f57cc007248, select=select@entry=0x0) at /mariadb/10.6/storage/innobase/pars/pars0pars.cc:1274 #4 0x0000558e7f8ef5d0 in yyparse () at /dev/shm/10.6/pars0grm.y:311 #5 0x0000558e7f8edaf0 in pars_sql (info=info@entry=0x7f57cc004838, str=str@entry=0x7f57cc0065c8 "PROCEDURE P() IS\nBEGIN\nINSERT INTO $index_table_name VALUES (:token, :first_doc_id, :last_doc_id, :doc_count, :ilist);\nEND;\n") at /mariadb/10.6/storage/innobase/pars/pars0pars.cc:1986 #6 0x0000558e7f82c969 in fts_parse_sql (fts_table=fts_table@entry=0x7f57d5053410, info=info@entry=0x7f57cc004838, sql=sql@entry=0x558e7eb52ed0 "BEGIN\nINSERT INTO $index_table_name VALUES (:token, :first_doc_id, :last_doc_id, :doc_count, :ilist);") at /mariadb/10.6/storage/innobase/fts/fts0sql.cc:136 #7 0x0000558e7f7562f6 in fts_write_node (trx=trx@entry=0x7f57d6b60b80, graph=0x7f57b011a3d8, fts_table=fts_table@entry=0x7f57d5053410, word=word@entry=0x7f57b0088158, node=0x7f57b011a620) at /mariadb/10.6/storage/innobase/fts/fts0fts.cc:3753 #8 0x0000558e7f75b402 in fts_sync_write_words (trx=trx@entry=0x7f57d6b60b80, index_cache=index_cache@entry=0x7f57b011a388) at /mariadb/10.6/storage/innobase/fts/fts0fts.cc:3877 #9 0x0000558e7f75b66e in fts_sync_index (sync=sync@entry=0x7f57b011a338, index_cache=index_cache@entry=0x7f57b011a388) at /mariadb/10.6/storage/innobase/fts/fts0fts.cc:3960 #10 0x0000558e7f75c38a in fts_sync (sync=0x7f57b011a338) at /mariadb/10.6/storage/innobase/fts/fts0fts.cc:4107 #11 0x0000558e7f75c51a in fts_sync_table (table=table@entry=0x7f57b01359f8) at /mariadb/10.6/storage/innobase/fts/fts0fts.cc:4152 #12 0x0000558e7f82967b in fts_optimize_sync_table (table=<optimized out>, process_message=process_message@entry=false) at /mariadb/10.6/storage/innobase/fts/fts0opt.cc:2768 #13 0x0000558e7f82c12a in fts_optimize_callback () at /mariadb/10.6/storage/innobase/fts/fts0opt.cc:2886 #14 0x0000558e7f9b9582 in tpool::task_group::execute (this=0x558e80566b00 <task_group>, t=t@entry=0x558e80566ae0 <task>) at /mariadb/10.6/tpool/task_group.cc:55 … (rr) continue Continuing. Thread 4 hit Hardware watchpoint 1: -location table.n_ref_count Old value = {m_counter = std::atomic<unsigned int> = { 1 }} New value = {m_counter = std::atomic<unsigned int> = { 2 }} 0x0000558e7f74494d in dict_table_t::acquire (this=0x7f57b0226b08) at /mariadb/10.6/storage/innobase/include/dict0dict.inl:1133 1133 } (rr) bt … #10 0x0000558e7f9a1358 in trx_t::rollback (this=this@entry=0x7f57d6b60b80, savept=savept@entry=0x0) at /mariadb/10.6/storage/innobase/trx/trx0roll.cc:176 #11 0x0000558e7f75bbb3 in fts_sync_commit (sync=sync@entry=0x7f57b011a338) at /mariadb/10.6/storage/innobase/fts/fts0fts.cc:4004 … (rr) continue Continuing. Thread 4 hit Hardware watchpoint 1: -location table.n_ref_count Old value = {m_counter = std::atomic<unsigned int> = { 2 }} New value = {m_counter = std::atomic<unsigned int> = { 1 }} dict_table_t::release (this=0x7f57b0226b08) at /mariadb/10.6/storage/innobase/include/dict0dict.inl:1142 1142 ut_ad(n > 0); (rr) bt … #10 0x0000558e7f9a1358 in trx_t::rollback (this=this@entry=0x7f57d6b60b80, savept=savept@entry=0x0) at /mariadb/10.6/storage/innobase/trx/trx0roll.cc:176 #11 0x0000558e7f75bbb3 in fts_sync_commit (sync=sync@entry=0x7f57b011a338) at /mariadb/10.6/storage/innobase/fts/fts0fts.cc:4004 The first table handle was never released. The rollback acquired and released a table handle just fine.

Roel Van de Paar added a comment - 2022-09-15 08:40 - edited

While the testcase given may be deterministic and yield a correct stack, I have also observed stack smashing (ref example above) and possibly sporadicity (cannot recall). There are also other asserts (ref initial description), so it is likely not all code paths/avenues are covered yet.

Roel Van de Paar added a comment - 2022-09-15 08:40 - edited While the testcase given may be deterministic and yield a correct stack, I have also observed stack smashing (ref example above) and possibly sporadicity (cannot recall). There are also other asserts (ref initial description), so it is likely not all code paths/avenues are covered yet.

Marko Mäkelä added a comment - 2022-09-16 11:29

Actually, it turns out that I was just lucky 2 days ago to get a failure straight away. Today, the same test would only crash after very many retries.

Marko Mäkelä added a comment - 2022-09-16 11:29 Actually, it turns out that I was just lucky 2 days ago to get a failure straight away. Today, the same test would only crash after very many retries.

Thirunarayanan Balathandayuthapani added a comment - 2022-09-20 06:34

Given test case fails only in 10.6+ versions.

Thirunarayanan Balathandayuthapani added a comment - 2022-09-20 06:34 Given test case fails only in 10.6+ versions.

Thirunarayanan Balathandayuthapani added a comment - 2022-09-20 06:42

Patch is in bb-10.6-MDEV-29277

Thirunarayanan Balathandayuthapani added a comment - 2022-09-20 06:42 Patch is in bb-10.6- MDEV-29277

Marko Mäkelä added a comment - 2022-09-21 09:08

The fix looks OK to me.

Marko Mäkelä added a comment - 2022-09-21 09:08 The fix looks OK to me.

Marko Mäkelä added a comment - 2022-09-21 09:44 - edited

This bug is likely not the only reason why the assertion would fail. The provided test case was never claimed to reproduce a crash on 10.5.

Marko Mäkelä added a comment - 2022-09-21 09:44 - edited This bug is likely not the only reason why the assertion would fail. The provided test case was never claimed to reproduce a crash on 10.5.

Marko Mäkelä added a comment - 2022-09-21 12:50

I removed the stack-smashing label because I do not see any evidence of any buffer overflow with the posted test case. Buffer overflows like ~~MDEV-23256~~ can corrupt InnoDB dict_table_t, including dict_table_t::n_ref_count, but no specific evidence of that has been posted in this ticket.

Marko Mäkelä added a comment - 2022-09-21 12:50 I removed the stack-smashing label because I do not see any evidence of any buffer overflow with the posted test case. Buffer overflows like MDEV-23256 can corrupt InnoDB dict_table_t , including dict_table_t::n_ref_count , but no specific evidence of that has been posted in this ticket.

People

Assignee:: Thirunarayanan Balathandayuthapani

Reporter:: Roel Van de Paar

Votes:: 0 Vote for this issue

Watchers:: 3 Start watching this issue

Dates

Created:: 2022-08-09 02:31

Updated:: 2023-04-24 05:36

Resolved:: 2022-09-23 07:46

Git Integration

Error rendering 'com.xiplink.jira.git.jira_git_plugin:git-issue-webpanel'. Please contact your Jira administrators.

MariaDB Server