Bug #93530 ALTER TABLE DROP INDEX is very slow
Submitted: 8 Dec 2018 20:23 Modified: 3 Dec 2020 17:46
Reporter: monty solomon Email Updates:
Status: Duplicate Impact on me:
None 
Category:MySQL Server: InnoDB storage engine Severity:S3 (Non-critical)
Version:5.7.23, 5.7.24 OS:Any
Assigned to: CPU Architecture:Any

[8 Dec 2018 20:23] monty solomon
Description:
In Table 14.11 Online DDL Support for Index Operations the documentation states that dropping an index only modifies metadata.
https://dev.mysql.com/doc/refman/5.7/en/innodb-online-ddl-operations.html

When I drop an index it is taking a very long time and performance_schema.events_stages_current shows that it is in "stage/innodb/alter table (read PK and internal sort)"

How to repeat:
Execute the following commands on a slave.

SET sql_log_bin=0;
SET GLOBAL innodb_online_alter_log_max_size = 21474836480;
UPDATE performance_schema.setup_instruments SET ENABLED = 'YES' WHERE NAME LIKE 'stage/innodb/alter%';
UPDATE performance_schema.setup_consumers SET ENABLED = 'YES' WHERE NAME LIKE '%stages%';
UPDATE performance_schema.setup_instruments SET ENABLED = 'YES' WHERE NAME LIKE '%alter%';
ALTER TABLE notifications DROP INDEX idempotency_id_created_at;

Open a new connection and execute the following command while the ALTER TABLE is running.

mysql> SELECT EVENT_NAME, WORK_COMPLETED, WORK_ESTIMATED FROM performance_schema.events_stages_current\G
*************************** 1. row ***************************
    EVENT_NAME: stage/innodb/alter table (read PK and internal sort)
WORK_COMPLETED: 1005804
WORK_ESTIMATED: 229978455
1 row in set (0.00 sec)
[8 Dec 2018 20:23] monty solomon
I tested on 5.7.21 and the index was dropped immediately.
[8 Dec 2018 20:39] monty solomon
I tested on 5.7.22 and the index was dropped immediately.
[9 Dec 2018 5:48] monty solomon
The event changed to "stage/innodb/alter table (insert)"

mysql> SELECT EVENT_NAME, WORK_COMPLETED, WORK_ESTIMATED FROM performance_schema.events_stages_current\G
*************************** 1. row ***************************
    EVENT_NAME: stage/innodb/alter table (insert)
WORK_COMPLETED: 820850745
WORK_ESTIMATED: 1510366934
1 row in set (0.00 sec)
[11 Dec 2018 15:11] MySQL Verification Team
Hi,

Please, confirm that in the  5.7.22, online DROP INDEX works fast, while in 5.7.23 and 5.7.24 it works quite slow.

Also, send us the output from SHOW CREATE TABLE command. This looks like a consequence of fixing one serious bug.
[12 Dec 2018 0:21] monty solomon
DROP INDEX is fast on versions 5.7.21 and 5.7.22.

DROP INDEX is slow on versions 5.7.23 and 5.7.24.

For example, using 5.7.22

mysql> SELECT EVENT_NAME, WORK_COMPLETED, WORK_ESTIMATED FROM performance_schema.events_stages_current\G
*************************** 1. row ***************************
    EVENT_NAME: stage/sql/committing alter table to storage engine
WORK_COMPLETED: NULL
WORK_ESTIMATED: NULL
1 row in set (0.00 sec)
[12 Dec 2018 13:27] MySQL Verification Team
Hi,

Thank you for your feedback.

Can you just let us know, very approximately, how much the same DROP INDEX takes time on 5.7.23. Very approximately .....

This is because we are currently searching for the change in code that could have caused that.
[13 Dec 2018 5:55] monty solomon
It took four seconds to drop the index on 5.7.22.
[13 Dec 2018 5:56] monty solomon
It took over 24 hours to drop the index on 5.7.23 or 5.7.24.

After one hour on 5.7.24

     EVENT_NAME: stage/innodb/alter table (read PK and internal sort)
WORK_COMPLETED: 6684496
WORK_ESTIMATED: 221990727

After ten minutes on 5.7.23

    EVENT_NAME: stage/innodb/alter table (read PK and internal sort)
WORK_COMPLETED: 1548128
WORK_ESTIMATED: 221990727
[13 Dec 2018 13:57] MySQL Verification Team
Hi,

We are still looking for the confirmation, but this seems to be a consequence of the fix of the bug #26696448 (from the internal bugs database).

This is a bug that leads to the crash, so for that situation, on-line DDL had to be suspended. The bug occurs when the last insert log record to be applied was split across two pages.

Hence, disabling on-line operation is better then a crash.

However, we are still waiting for the confirmation of this hypothesis.
[13 Dec 2018 21:59] monty solomon
The documentation will need to be updated if that is the case.
[13 Dec 2018 22:04] monty solomon
I experienced a crash during the ALTER TABLE dropping the index.

Is that related to the internal bug you mentioned?

I added the details to bug 82940.
[14 Dec 2018 13:33] MySQL Verification Team
Yes, it might be related.

We shall look at that bug too .....
[14 Dec 2018 13:36] MySQL Verification Team
I have to correct myself.

That assert is not related to this bug.

And it is not a crash, but controlled assert. Those asserts are fully described in our Reference Manual.
[25 Jan 2019 5:28] monty solomon
Any update?  You wrote ...

We are still looking for the confirmation, but this seems to be a consequence of the fix of the bug #26696448 (from the internal bugs database).

This is a bug that leads to the crash, so for that situation, on-line DDL had to be suspended. The bug occurs when the last insert log record to be applied was split across two pages.

Hence, disabling on-line operation is better then a crash.

However, we are still waiting for the confirmation of this hypothesis.
[25 Jan 2019 14:12] MySQL Verification Team
Hi,

We have a confirmation that this assert that you are experiencing is not a consequence of the patch for an internal bug.

Hence, we need a fully repeatable test case, that would lead to the assert in the latest 5.7.
[29 Jan 2019 6:13] monty solomon
The confirmation you were waiting for was independent of the assert I experienced.

You thought the slowness I was seeing was a consequence of the fix for bug #26696448 that suspends the online DDL.

Do you have any update on that?

Thanks.
[29 Jan 2019 14:17] MySQL Verification Team
Hi,

We can inform you that the internal bug that you are mentioning is fixed so that the assert is avoided. It does not and could not influence the speed of the execution. I have analysed a patch myself.
[29 Jan 2019 14:25] MySQL Verification Team
Also, as far as I could see, you do not have a full text index in that table. Do respond only if you have added one.

Next, you do not have any table which has a  foreign key to this table. If that is a case, no need to reply.

You could also check, during that DDL, that no lock waits have been encountered. There are many patches related to this issue in 5.7.23, that might explain the behaviour.

Other then those cases, there are no other changes in 5.7.23 that could cause the slowdown ...
[10 Apr 2019 0:28] Marcelo Goncalves
I had this same issue, and it seems that this impacts FKs and Indexes.
The documentation says it is only a metadata change, but MySQL had a single transaction running for several hours, with history length going way over 600k, a high overhead for inserts in the table (higher than expected in my point of view) and some blocks for several minutes without allowing inserts into the table.

For 3 occasions during a 7+ hour alter drop index that I ran in 5.7.25 I witnessed over 400 sessions trying to insert into the table and waiting over 1 minute in updating event.

This is a really non online way of doing online DDL.
[10 Apr 2019 12:39] MySQL Verification Team
Hi,

First of all, not all DDL can be done online. Check our Reference Manual for the information on the subject.

Second, waiting longer is a much better solution then the assert, which leads to the (intentional) server crash.

Last, but not least, many of similar issues have been resolved in 8.0, which has a much better infrastructure.
[25 Sep 2019 8:28] v v
5.7.23 drop nonclustered index is very slowly.
mysqldump and restore to another mysql server,drop index quickly,may be recreate table don't go to the row_merge_build_indexes?

stack:
#0  0x000000000115d185 in dict_col_copy_type (type=0x7f5c94cfad38, col=0x7f5ddaec1f54) at /home/op1/congyu/rpm/BUILD/mysql-5.7.23/mysql-5.7.23/storage/innobase/include/dict0dict.ic:89
#1  dict_table_copy_types (tuple=tuple@entry=0x7f5c94cfab50, table=table@entry=0x7f5dda9fc088) at /home/op1/congyu/rpm/BUILD/mysql-5.7.23/mysql-5.7.23/storage/innobase/dict/dict0dict.cc:3201
#2  0x00000000010418a1 in row_build_low (type=type@entry=2, index=index@entry=0x7f5ddae29488, rec=rec@entry=0x7f643c8f8cda "\200", offsets=<optimized out>, offsets@entry=0x7f5c94cfaa88, col_table=col_table@entry=0x7f5dda9fc088, add_cols=add_cols@entry=0x0, add_v=0x0, col_map=0x0, ext=0x7f5d5d377cb0, heap=0x7f5c94cfaa18) at /home/op1/congyu/rpm/BUILD/mysql-5.7.23/mysql-5.7.23/storage/innobase/row/row0row.cc:476
#3  0x000000000104239a in row_build_w_add_vcol (type=type@entry=2, index=index@entry=0x7f5ddae29488, rec=rec@entry=0x7f643c8f8cda "\200", offsets=offsets@entry=0x7f5c94cfaa88, col_table=col_table@entry=0x7f5dda9fc088, add_cols=add_cols@entry=0x0, add_v=add_v@entry=0x0, col_map=col_map@entry=0x0, ext=ext@entry=0x7f5d5d377cb0, heap=0x7f5c94cfaa18) at /home/op1/congyu/rpm/BUILD/mysql-5.7.23/mysql-5.7.23/storage/innobase/row/row0row.cc:648
#4  0x000000000101ea24 in row_merge_read_clustered_index (trx=trx@entry=0x7f671710a6d0, table=table@entry=0x7f5d7b957a20, old_table=old_table@entry=0x7f5dda9fc088, new_table=new_table@entry=0x7f5dda9fc088, online=online@entry=true, index=index@entry=0x7f5d2f8d64c0, fts_sort_idx=fts_sort_idx@entry=0x0, psort_info=0x0, files=files@entry=0x7f5d7f45b018, key_numbers=key_numbers@entry=0x7f5d2f8d64c8, n_index=n_index@entry=1, add_cols=add_cols@entry=0x0, add_v=add_v@entry=0x0, col_map=col_map@entry=0x0, add_autoinc=add_autoinc@entry=18446744073709551615, sequence=..., block=block@entry=0x7f5b65afc000 "\002\b00000421\200", skip_pk_sort=skip_pk_sort@entry=false, tmpfd=tmpfd@entry=0x7f5d5d379270, stage=stage@entry=0x7f5d7b9f91d8, eval_table=eval_table@entry=0x7f5d7b957a20) at /home/op1/congyu/rpm/BUILD/mysql-5.7.23/mysql-5.7.23/storage/innobase/row/row0merge.cc:2060
#5  0x0000000001021f6d in row_merge_build_indexes (trx=0x7f671710a6d0, old_table=0x7f5dda9fc088, new_table=0x7f5dda9fc088, online=true, indexes=0x7f5d2f8d64c0, key_numbers=0x7f5d2f8d64c8, n_indexes=1, table=table@entry=0x7f5d7b957a20, add_cols=0x0, col_map=0x0, add_autoinc=18446744073709551615, sequence=..., skip_pk_sort=false, stage=0x7f5d7b9f91d8, add_v=add_v@entry=0x0, eval_table=0x7f5d7b957a20) at /home/op1/congyu/rpm/BUILD/mysql-5.7.23/mysql-5.7.23/storage/innobase/row/row0merge.cc:4431
#6  0x0000000000f61782 in ha_innobase::inplace_alter_table (this=0x7f5c6b3c4830, altered_table=0x7f5d7b957a20, ha_alter_info=0x7f5d5d37d2b0) at /home/op1/congyu/rpm/BUILD/mysql-5.7.23/mysql-5.7.23/storage/innobase/handler/handler0alter.cc:6338
#7  0x0000000000d38126 in ha_inplace_alter_table (ha_alter_info=0x7f5d5d37d2b0, altered_table=0x7f5d7b957a20, this=<optimized out>) at /home/op1/congyu/rpm/BUILD/mysql-5.7.23/mysql-5.7.23/sql/handler.h:3430
#8  mysql_inplace_alter_table (target_mdl_request=0x7f5d5d37d0f0, alter_ctx=0x7f5d5d37da80, inplace_supported=HA_ALTER_INPLACE_NO_LOCK_AFTER_PREPARE, ha_alter_info=0x7f5d5d37d2b0, altered_table=0x7f5d7b957a20, table=0x7f5dd7dee220, table_list=0x7f5d7b9f1a80, thd=0x7f5d7b9bc000) at /home/op1/congyu/rpm/BUILD/mysql-5.7.23/mysql-5.7.23/sql/sql_table.cc:7626
#9  mysql_alter_table (thd=thd@entry=0x7f5d7b9bc000, new_db=<optimized out>, new_name=<optimized out>, create_info=create_info@entry=0x7f5d5d37ef00, table_list=table_list@entry=0x7f5d7b9f1a80, alter_info=alter_info@entry=0x7f5d5d37ee50) at /home/op1/congyu/rpm/BUILD/mysql-5.7.23/mysql-5.7.23/sql/sql_table.cc:9845
#10 0x0000000000cca552 in mysql_execute_command (thd=thd@entry=0x7f5d7b9bc000, first_level=first_level@entry=true) at /home/op1/congyu/rpm/BUILD/mysql-5.7.23/mysql-5.7.23/sql/sql_parse.cc:3329
#11 0x0000000000cce9dd in mysql_parse (thd=thd@entry=0x7f5d7b9bc000, parser_state=parser_state@entry=0x7f5d5d37fd00) at /home/op1/congyu/rpm/BUILD/mysql-5.7.23/mysql-5.7.23/sql/sql_parse.cc:5554
#12 0x0000000000ccf55d in dispatch_command (thd=thd@entry=0x7f5d7b9bc000, com_data=com_data@entry=0x7f5d5d3805a0, command=COM_QUERY) at /home/op1/congyu/rpm/BUILD/mysql-5.7.23/mysql-5.7.23/sql/sql_parse.cc:1484
#13 0x0000000000cd0f7f in do_command (thd=thd@entry=0x7f5d7b9bc000) at /home/op1/congyu/rpm/BUILD/mysql-5.7.23/mysql-5.7.23/sql/sql_parse.cc:1025
#14 0x0000000000d93030 in handle_connection (arg=arg@entry=0x7f5ddd79cdc0) at /home/op1/congyu/rpm/BUILD/mysql-5.7.23/mysql-5.7.23/sql/conn_handler/connection_handler_per_thread.cc:308
#15 0x000000000127a504 in pfs_spawn_thread (arg=0x7f5dddaf9a20) at /home/op1/congyu/rpm/BUILD/mysql-5.7.23/mysql-5.7.23/storage/perfschema/pfs.cc:2444
#16 0x00007f672413ee25 in start_thread () from /lib64/libpthread.so.0
#17 0x00007f6722bfb34d in clone () from /lib64/libc.so.6
[25 Sep 2019 12:11] MySQL Verification Team
Mr. v,

Please, just read all the previous comments.
[25 Sep 2019 13:00] MySQL Verification Team
Perhaps a duplicate of this:

https://bugs.mysql.com/bug.php?id=94383
BUG 29375764 - SIMPLE ALTER CAUSE UNNECESSARY INNODB INDEX REBUILDS, 5.7.23 OR LATER 5.7 RLSES

Customers can read about it in MOS KM:
Unexpected Table Rebuilds In 5.7.23 To 5.7.26 For "Inplace" DDL (Doc ID 2524820.1)
[25 Sep 2019 13:59] MySQL Verification Team
Possibly a duplicate of:

https://bugs.mysql.com/bug.php?id=94383

Should be fixed in 5.7.28 ....
[29 Sep 2019 6:53] v v
hi Sinisa Milivojevic,
thank you for helping me solve this problem.
[30 Sep 2019 12:05] MySQL Verification Team
Hi Mr. v,

You are welcome.
[3 Dec 2020 16:38] Jean-François Gagné
I am surprised that this is closed as "Not a Bug".

IMHO, this should be marked as a duplicate of Bug#94383.
[4 Dec 2020 12:49] MySQL Verification Team
Set as a duplicate.
[6 Dec 2020 17:24] Jean-François Gagné
> Set as a duplicate.

Thanks.