Bug #93530 ALTER TABLE DROP INDEX is very slow
Submitted: 8 Dec 2018 20:23 Modified: 29 Jan 6:13
Reporter: monty solomon Email Updates:
Status: Not a Bug 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] Sinisa Milivojevic
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] Sinisa Milivojevic
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] Sinisa Milivojevic
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] Sinisa Milivojevic
Yes, it might be related.

We shall look at that bug too .....
[14 Dec 2018 13:36] Sinisa Milivojevic
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 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 14:12] Sinisa Milivojevic
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 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 14:17] Sinisa Milivojevic
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 14:25] Sinisa Milivojevic
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 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 12:39] Sinisa Milivojevic
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.