[MDEV-22633] Assertion `user_table->get_ref_count() == 1 || ctx->online' failed in prepare_inplace_alter_table_dict Created: 2020-05-19  Updated: 2020-05-22  Resolved: 2020-05-20

Status: Closed
Project: MariaDB Server
Component/s: Storage Engine - InnoDB
Affects Version/s: 10.2.33
Fix Version/s: 10.5.4, 10.2.33, 10.3.24, 10.4.14

Type: Bug Priority: Major
Reporter: Matthias Leich Assignee: Thirunarayanan Balathandayuthapani
Resolution: Fixed Votes: 0
Labels: None

Attachments: File mdev-22633.patch    

 Description   

commit 4c0f3b3be76343c155b00feff3309d91e1e11441 origin/bb-10.2-marko
containing a fix for MDEV-19114 but IIRC I have seen that assert some months ago
 
Version: '10.2.33-MariaDB-debug-log'  socket: ...
mysqld: storage/innobase/handler/handler0alter.cc:5119: bool prepare_inplace_alter_table_dict(Alter_inplace_info*, const TABLE*, const TABLE*, const char*, ulint, ulint, ulint, bool, bool): Assertion `user_table->get_ref_count() == 1 || ctx->online' failed.
...
/home/mleich/Server_bin/bb-10.2-marko_2_debug/bin/mysqld(_ZN7handler30ha_prepare_inplace_alter_tableEP5TABLEP18Alter_inplace_info+0x81)[0x5609f836dc13]
handler/handler0alter.cc:5121(prepare_inplace_alter_table_dict(Alter_inplace_info*, TABLE const*, TABLE const*, char const*, unsigned long, unsigned long, unsigned long, bool, bool))[0x5609f81bd45b]
handler/handler0alter.cc:6041(ha_innobase::prepare_inplace_alter_table(TABLE*, Alter_inplace_info*))[0x5609f81c334c]
sql/handler.cc:4346(handler::ha_prepare_inplace_alter_table(TABLE*, Alter_inplace_info*))[0x5609f823f791]
sql/sql_table.cc:7401(mysql_inplace_alter_table(THD*, TABLE_LIST*, TABLE*, TABLE*, Alter_inplace_info*, enum_alter_inplace_result, MDL_request*, Alter_table_ctx*))[0x5609f80f3880]
sql/sql_table.cc:9594(mysql_alter_table(THD*, char*, char*, HA_CREATE_INFO*, TABLE_LIST*, Alter_info*, unsigned int, st_order*, bool))[0x5609f80f87f1]
sql/sql_alter.cc:333(Sql_cmd_alter_table::execute(THD*))[0x5609f80e6b24]
sql/sql_parse.cc:5972(mysql_execute_command(THD*))[0x5609f80e55a1]
sql/sql_parse.cc:7740(mysql_parse(THD*, char*, unsigned int, Parser_state*, bool, bool))[0x5609f823a317]
sql/sql_connect.cc:1336(do_handle_one_connection(CONNECT*))[0x5609f823a082]
 
Query (0x7f1818010720): ALTER TABLE t3 ADD FULLTEXT KEY IF NOT EXISTS `ftidx2` ( col_text ), ADD FULLTEXT INDEX IF NOT EXISTS `ftidx1` ( col_text )
 
RQG branch:
git clone https://github.com/mleich1/rqg --branch experimental RQG_mleich
 
perl rqg.pl \                        
--mysqld=--loose-innodb_lock_schedule_algorithm=fcfs \
--grammar=conf/mariadb/table_stress_innodb.yy \
--gendata=conf/mariadb/table_stress.zz \
--gendata_sql=conf/mariadb/table_stress.sql \
--engine=Innodb \
--reporters=Deadlock1,ErrorLog,Backtrace \
--mysqld=--connect_timeout=60 \
--mysqld=--net_read_timeout=30 \
--mysqld=--net_write_timeout=60 \
--mysqld=--loose-idle_readonly_transaction_timeout=0 \
--mysqld=--loose-idle_transaction_timeout=0 \
--mysqld=--loose-idle_write_transaction_timeout=0 \
--mysqld=--interactive_timeout=28800 \
--mysqld=--lock_wait_timeout=86400 \
--mysqld=--innodb-lock-wait-timeout=50 \
--mysqld=--loose-table_lock_wait_timeout=50 \
--mysqld=--wait_timeout=28800 \
--mysqld=--slave_net_timeout=60 \
--mysqld=--loose-max-statement-time=30 \
--mysqld=--loose-debug_assert_on_not_freed_memory=0 \
--mysqld=--log-output=none \
--duration=300 \
--seed=random \
--sqltrace=MarkErrors \
--threads=9 \
--mysqld=--innodb_adaptive_hash_index=ON \
--mysqld=--innodb_page_size=16K \
--mysqld=--innodb-buffer-pool-size=8M \
--no_mask \
--workdir=<local settings> \
--vardir=<local settings> \
--mtr-build-thread=<local settings> \
--basedir1=<local settings> \
--basedir2=<local settings> \
--script_debug=_nix_ \
--rr=Server



 Comments   
Comment by Thirunarayanan Balathandayuthapani [ 2020-05-19 ]

Analysis:
stats thread processing table and prepare phase fails before doing dict_stats_wait_bg_to_stop_using_table().
During error handling, InnoDB assumes that stats thread doesn't process dict_table_t*.

Fix:

diff --git a/storage/innobase/handler/handler0alter.cc b/storage/innobase/handler/handler0alter.cc
index 9b1d99d3730..75051f01207 100644
--- a/storage/innobase/handler/handler0alter.cc
+++ b/storage/innobase/handler/handler0alter.cc
@@ -4316,6 +4316,7 @@ prepare_inplace_alter_table_dict(
        ulint                   num_fts_index;
        dict_add_v_col_t*       add_v = NULL;
        ha_innobase_inplace_ctx*ctx;
+       bool                    stats_wait = false;
 
        DBUG_ENTER("prepare_inplace_alter_table_dict");
 
@@ -4481,6 +4482,7 @@ prepare_inplace_alter_table_dict(
        XXX what may happen if bg stats opens the table after we
        have unlocked data dictionary below? */
        dict_stats_wait_bg_to_stop_using_table(user_table, ctx->trx);
+       stats_wait = true;
 
        online_retry_drop_indexes_low(ctx->new_table, ctx->trx);
 
@@ -5120,7 +5122,8 @@ prepare_inplace_alter_table_dict(
                /* n_ref_count must be 1, because purge cannot
                be executing on this very table as we are
                holding dict_operation_lock X-latch. */
-               DBUG_ASSERT(user_table->get_ref_count() == 1 || ctx->online);
+               DBUG_ASSERT(user_table->get_ref_count() == 1
+                           || ctx->online || !stats_wait);
 
                online_retry_drop_indexes_with_trx(user_table, ctx->trx);
        } else {

Comment by Thirunarayanan Balathandayuthapani [ 2020-05-19 ]

mdev-22633.patch

Comment by Marko Mäkelä [ 2020-05-20 ]

I applied the patch, changing the DBUG_ASSERT() to ut_ad() because with special build options, ut_d() and ut_ad() could expand to empty while DBUG_ASSERT could expand to something else.
This was a bogus debug assertion. No effect on normal release builds.

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