[MDEV-22633] Assertion `user_table->get_ref_count() == 1 || ctx->online' failed in prepare_inplace_alter_table_dict - Jira

Details

Type: Bug
Status: Closed (View Workflow)
Priority: Major
Resolution: Fixed
Affects Version/s: 10.2.33
Fix Version/s: 10.5.4, 10.2.33, 10.3.24, 10.4.14
Component/s: Storage Engine - InnoDB
Labels:
None

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

Attachments

- Sort By Name
- Sort By Date
- Ascending
- Descending
- Thumbnails
- List
- Download All

mdev-22633.patch
1 kB
2020-05-19 14:31

Activity

Ascending order - Click to sort in descending order

Matthias Leich created issue - 2020-05-19 13:11

Matthias Leich made changes - 2020-05-19 13:18

Field	Original Value	New Value
Assignee	Matthias Leich [ mleich ]	Thirunarayanan Balathandayuthapani [ thiru ]
Description	{noformat} 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 {noformat}	{noformat} 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 {noformat}
Summary	Draft: Assertion `user_table->get_ref_count() == 1 \|\| ctx->online' failed in prepare_inplace_alter_table_dict	Assertion `user_table->get_ref_count() == 1 \|\| ctx->online' failed in prepare_inplace_alter_table_dict

Thirunarayanan Balathandayuthapani added a comment - 2020-05-19 14:02

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 {

Thirunarayanan Balathandayuthapani added a comment - 2020-05-19 14:02 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 {

Thirunarayanan Balathandayuthapani made changes - 2020-05-19 14:05

Status

Open [ 1 ]

In Progress [ 3 ]

Thirunarayanan Balathandayuthapani made changes - 2020-05-19 14:05

Assignee	Thirunarayanan Balathandayuthapani [ thiru ]	Marko Mäkelä [ marko ]
Status	In Progress [ 3 ]	In Review [ 10002 ]

Thirunarayanan Balathandayuthapani made changes - 2020-05-19 14:31

Attachment

mdev-22633.patch [ 51813 ]

Thirunarayanan Balathandayuthapani added a comment - 2020-05-19 14:31

mdev-22633.patch

Thirunarayanan Balathandayuthapani added a comment - 2020-05-19 14:31 mdev-22633.patch

Marko Mäkelä added a comment - 2020-05-20 08:27

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.

Marko Mäkelä added a comment - 2020-05-20 08:27 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.

Marko Mäkelä made changes - 2020-05-20 08:27

issue.field.resolutiondate

2020-05-20 08:27:14.0

2020-05-20 08:27:14.268

Marko Mäkelä made changes - 2020-05-20 08:27

Fix Version/s		10.2.33 [ 24307 ]
Fix Version/s		10.3.24 [ 24306 ]
Fix Version/s		10.4.14 [ 24305 ]
Fix Version/s		10.5.4 [ 24264 ]
Fix Version/s	10.2 [ 14601 ]
Assignee	Marko Mäkelä [ marko ]	Thirunarayanan Balathandayuthapani [ thiru ]
Resolution		Fixed [ 1 ]
Status	In Review [ 10002 ]	Closed [ 6 ]

Sergei Golubchik made changes - 2021-12-06 21:51

Workflow

MariaDB v3 [ 108907 ]

MariaDB v4 [ 157812 ]

People

Assignee:: Thirunarayanan Balathandayuthapani

Reporter:: Matthias Leich

Votes:: 0 Vote for this issue

Watchers:: 3 Start watching this issue

Dates

Created:: 2020-05-19 13:11

Updated:: 2020-05-22 18:18

Resolved:: 2020-05-20 08:27

Git Integration

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

MariaDB Server

Details

Description

Attachments

Attachments

Activity

People

Dates

Git Integration