Bug #101900 Add partition is slow
Submitted: 8 Dec 2020 3:21 Modified: 8 Dec 2020 17:21
Reporter: peng gao Email Updates:
Status: Verified Impact on me:
None 
Category:MySQL Server: InnoDB storage engine Severity:S2 (Serious)
Version:8.0.21 OS:Linux (7.6)
Assigned to: CPU Architecture:Any

[8 Dec 2020 3:21] peng gao
Description:
Hi all:
at some time,we add a partition .this operation is so slow! any select is hang!
like this:

mysql> show processlist;
+----+-----------------+-----------+------+---------+------+------------------------------------------+----------------------------------------------------------------------------+
| Id | User            | Host      | db   | Command | Time | State                                    | Info                                                                       |
+----+-----------------+-----------+------+---------+------+------------------------------------------+----------------------------------------------------------------------------+
|  5 | event_scheduler | localhost | NULL | Daemon  |  165 | Waiting on empty queue                   | NULL                                                                       |
|  8 | root            | localhost | test | Query   |    4 | Waiting for table metadata lock          | select * from sales                                                        |
| 10 | root            | localhost | test | Query   |   25 | committing alter table to storage engine | alter table sales add partition (partition p_2035 values less than (2035)) |
| 11 | root            | localhost | NULL | Query   |    0 | starting                                 | show processlist                                                           |
+----+-----------------+-----------+------+---------+------+------------------------------------------+----------------------------------------------------------------------------+
4 rows in set (0.00 sec)

mysql> show processlist;
+----+-----------------+-----------+------+---------+------+------------------------------------------+----------------------------------------------------------------------------+
| Id | User            | Host      | db   | Command | Time | State                                    | Info                                                                       |
+----+-----------------+-----------+------+---------+------+------------------------------------------+----------------------------------------------------------------------------+
|  5 | event_scheduler | localhost | NULL | Daemon  |  185 | Waiting on empty queue                   | NULL                                                                       |
|  8 | root            | localhost | test | Query   |    3 | Waiting for table metadata lock          | select * from sales partition(p_2019)                                      |
| 10 | root            | localhost | test | Query   |   45 | committing alter table to storage engine | alter table sales add partition (partition p_2035 values less than (2035)) |
| 11 | root            | localhost | NULL | Query   |    0 | starting                                 | show processlist                                                           |
+----+-----------------+-----------+------+---------+------+------------------------------------------+----------------------------------------------------------------------------+

The stack like :

(gdb) bt
#0  0x0000000004fa1e73 in rec_offs_n_fields (offsets=0xb479910) at /opt/mysql/mysql-8.0.21/storage/innobase/rem/rec.h:449
#1  0x0000000004fa3d82 in rec_offs_data_size (offsets=0xb479910) at /opt/mysql/mysql-8.0.21/storage/innobase/include/rem0rec.ic:935
#2  0x0000000004fa7ad1 in rec_validate (rec=0x7fff450e7516 "", offsets=0xb479910) at /opt/mysql/mysql-8.0.21/storage/innobase/rem/rem0rec.cc:1337
#3  0x000000000519eeea in rec_fold (rec=0x7fff450e7516 "", offsets=0xb479910, n_fields=0, n_bytes=1, fold=108872348850564, index=0xb46d900)
    at /opt/mysql/mysql-8.0.21/storage/innobase/include/rem0rec.ic:1122
#4  0x00000000051a32e1 in btr_search_drop_page_hash_index (block=0x7fff4352f158) at /opt/mysql/mysql-8.0.21/storage/innobase/btr/btr0sea.cc:1177
#5  0x00000000051a38c3 in btr_search_drop_page_hash_when_freed (page_id=..., page_size=...) at /opt/mysql/mysql-8.0.21/storage/innobase/btr/btr0sea.cc:1275
#6  0x00000000051a3d23 in btr_drop_ahi_for_table (table=0xb46bc10) at /opt/mysql/mysql-8.0.21/storage/innobase/btr/btr0sea.cc:1354
#7  0x0000000004e61295 in alter_part_normal::try_commit (this=0xbaadc30, table=0x0, altered_table=0xbb75500, old_part=0xb474738, new_part=0xbb293c8)
    at /opt/mysql/mysql-8.0.21/storage/innobase/handler/handler0alter.cc:8550
#8  0x0000000004e4cdd5 in alter_parts::prepare_or_commit_for_new (this=0xb97f240, old_dd_tab=..., new_dd_tab=..., altered_table=0xbb75500, prepare=false)
    at /opt/mysql/mysql-8.0.21/storage/innobase/handler/handler0alter.cc:9657
#9  0x0000000004e4c6fe in alter_parts::try_commit (this=0xb97f240, old_dd_tab=..., new_dd_tab=..., table=0xaaef7b0, altered_table=0xbb75500)
    at /opt/mysql/mysql-8.0.21/storage/innobase/handler/handler0alter.cc:9584
#10 0x0000000004e4f83e in ha_innopart::commit_inplace_alter_partition (this=0xb47a018, altered_table=0xbb75500, ha_alter_info=0x7fff602dc670, commit=true, old_dd_tab=0xaaf06e8, 
    new_dd_tab=0xb924368) at /opt/mysql/mysql-8.0.21/storage/innobase/handler/handler0alter.cc:10515
#11 0x0000000004e4e8ee in ha_innopart::commit_inplace_alter_table (this=0xb47a018, altered_table=0xbb75500, ha_alter_info=0x7fff602dc670, commit=true, old_table_def=0xaaf06e8, 
    new_table_def=0xb924368) at /opt/mysql/mysql-8.0.21/storage/innobase/handler/handler0alter.cc:10216
#12 0x0000000003ad89a3 in handler::ha_commit_inplace_alter_table (this=0xb47a018, altered_table=0xbb75500, ha_alter_info=0x7fff602dc670, commit=true, old_table_def=0xaaf06e8, 
    new_table_def=0xb924368) at /opt/mysql/mysql-8.0.21/sql/handler.cc:4885

I think this operation is AHI maintain, when AHI rows is large this operation is slow,But this operation is 
protect by mdl x at DDL commit stage,so select is hang!
How to  avoid this ? set AHI OFF? thanks!!

How to repeat:
1.
CREATE TABLE `sales` (
  `order_date` datetime NOT NULL,
  `id` int DEFAULT NULL
) ENGINE=InnoDB DEFAULT CHARSET=utf8mb4 COLLATE=utf8mb4_0900_ai_ci
/*!50100 PARTITION BY RANGE (year(`order_date`))
(PARTITION P_2017 VALUES LESS THAN (2017) ENGINE = InnoDB,
 PARTITION P_2018 VALUES LESS THAN (2018) ENGINE = InnoDB,
 PARTITION p_2019 VALUES LESS THAN (2019) ENGINE = InnoDB,
 PARTITION p_2020 VALUES LESS THAN (2020) ENGINE = InnoDB,
 PARTITION p_2021 VALUES LESS THAN (2021) ENGINE = InnoDB */;
2.
insert 500W data
3.
alter table sales add partition (partition p_2035 values less than (2035));
4.
when innodb_adaptive_hash_index set OFF,add partition is not slow!!

Suggested fix:
no Suggest
[8 Dec 2020 3:35] peng gao
In test environment  I add a sleep in btr_drop_ahi_for_table.
But in our product environment this add partition operation expand 120 seconds.
[8 Dec 2020 6:27] peng gao
In 8.0.19 also have this problem
[8 Dec 2020 16:22] MySQL Verification Team
Hi,

I'm having issues reproducing this on 8.0.22

mysql [localhost:8022] {msandbox} (test) > select count(*) from sales;
+----------+
| count(*) |
+----------+
| 33554432 |
+----------+
1 row in set (15.60 sec)

mysql [localhost:8022] {msandbox} (test) > select @@innodb_adaptive_hash_index ;
+------------------------------+
| @@innodb_adaptive_hash_index |
+------------------------------+
|                            1 |
+------------------------------+

mysql [localhost:8022] {msandbox} (test) > alter table sales add partition (partition p_2035 values less than (2035));
Query OK, 0 rows affected (0.78 sec)
Records: 0  Duplicates: 0  Warnings: 0

mysql [localhost:8022] {msandbox} (test) > select @@innodb_adaptive_hash_index ;
+------------------------------+
| @@innodb_adaptive_hash_index |
+------------------------------+
|                            0 |
+------------------------------+
1 row in set (0.00 sec)

mysql [localhost:8022] {msandbox} (test) > alter table sales1 add partition (partition p_2035 values less than (2035));
Query OK, 0 rows affected (0.17 sec)
Records: 0  Duplicates: 0  Warnings: 0

mysql [localhost:8022] {msandbox} (test) > select @@version;
+-----------+
| @@version |
+-----------+
| 8.0.22    |
+-----------+
1 row in set (0.00 sec)

time with and withouyt adaptive hash index to add the partition is 100% identical

all best
Bogdan
[8 Dec 2020 16:24] MySQL Verification Team
Hi,

Apologies I'm blind 0.17 vs 0.79, that's almost 5x slower!

I'll verify this.

Thanks for reporting the bug
Bogdan
[8 Dec 2020 17:21] peng gao
Thanks for Bogdan:
  In my test 1.6 vs 0.3 ,the same as your result at most 5x slower!
  I think the most slowest point is:

->btr_search_drop_page_hash_when_freed   
  ->btr_search_drop_page_hash_index
    ->rec_fold
      ->ut_fold_ulint_pair
           
because every block、every row and every field will calculate fold.
[17 Mar 2022 2:44] shaoqing sun
mysql version is 8.0.23

Add partition is not only slow, when i kill the running this session, mysql server is down.

ASSERTION FAILURE: DICT0DICT.CC:1885:TABLE->GET_REF_COUNT == 0
[17 Mar 2022 2:44] shaoqing sun
mysql version is 8.0.23

Add partition is not only slow, when i kill the running this session, mysql server is down.

ASSERTION FAILURE: DICT0DICT.CC:1885:TABLE->GET_REF_COUNT == 0
[2 Dec 2022 10:05] Marek Kretkiewicz
Do you have any update for this ?
In our version 8.0.26 we had very similar problem today.

We have table with some transation informations, and we create partitions for each week.

 PARTITION p202242 VALUES LESS THAN ('2022-10-17') ENGINE = InnoDB,
 PARTITION p202243 VALUES LESS THAN ('2022-10-24') ENGINE = InnoDB,
 PARTITION p202244 VALUES LESS THAN ('2022-10-31') ENGINE = InnoDB,
 PARTITION p202245 VALUES LESS THAN ('2022-11-07') ENGINE = InnoDB,
 PARTITION p202246 VALUES LESS THAN ('2022-11-14') ENGINE = InnoDB,
 PARTITION p202247 VALUES LESS THAN ('2022-11-21') ENGINE = InnoDB,
 PARTITION p202248 VALUES LESS THAN ('2022-11-28') ENGINE = InnoDB,
 PARTITION p202249 VALUES LESS THAN ('2022-12-05') ENGINE = InnoDB,

a month ago we have increased innodb_log_file_size and innodb_buffer_pool_size, and after that alter table exection time has increased above 10s (usualy 12-14s), before it was 3s.
However what is interesting today it was running for ~90s, so decided to stop it, as a consequence mysql server was restarted.

2022-12-02T08:38:06.937369Z 2269171 [ERROR] [MY-013183] [InnoDB] Assertion failure: dict0dict.cc:1882:table->get_ref_count() == 0 thread 139909770733312
InnoDB: We intentionally generate a memory trap.
InnoDB: Submit a detailed bug report to http://bugs.mysql.com.
InnoDB: If you get repeated assertion failures or crashes, even
InnoDB: immediately after the mysqld startup, there may be
InnoDB: corruption in the InnoDB tablespace. Please refer to
InnoDB: http://dev.mysql.com/doc/refman/8.0/en/forcing-innodb-recovery.html
InnoDB: about forcing recovery.
08:38:06 UTC - mysqld got signal 6 ;
Most likely, you have hit a bug, but this error can also be caused by malfunctioning hardware.
Thread pointer: 0x7f393c0e96c0
Attempting backtrace. You can use the following information to find out
where mysqld died. If you see no messages after this, something went
terribly wrong...
stack_bottom = 7f3f482f5c70 thread_stack 0x30000
/usr/sbin/mysqld(my_print_stacktrace(unsigned char const*, unsigned long)+0x3d) [0x20e7edd]
/usr/sbin/mysqld(handle_fatal_signal+0x30b) [0xf387fb]
/lib64/libpthread.so.0(+0xf5d0) [0x7f3fba9ea5d0]
/lib64/libc.so.6(gsignal+0x37) [0x7f3fb8f37207]
/lib64/libc.so.6(abort+0x148) [0x7f3fb8f388f8]
/usr/sbin/mysqld() [0xc76ef0]
/usr/sbin/mysqld() [0x2437668]
/usr/sbin/mysqld(dict_partitioned_table_remove_from_cache(char const*)+0xf8) [0x2437858]
/usr/sbin/mysqld() [0x21cf2c2]
/usr/sbin/mysqld() [0xe8b881]
/usr/sbin/mysqld(mysql_alter_table(THD*, char const*, char const*, HA_CREATE_INFO*, TABLE_LIST*, Alter_info*)+0x7aab) [0xea05db]
/usr/sbin/mysqld(Sql_cmd_alter_table::execute(THD*)+0x4dc) [0x126715c]
/usr/sbin/mysqld(mysql_execute_command(THD*, bool)+0x9c8) [0xdf1ab8]
/usr/sbin/mysqld(dispatch_sql_command(THD*, Parser_state*)+0x40b) [0xdf50cb]
/usr/sbin/mysqld(dispatch_command(THD*, COM_DATA const*, enum_server_command)+0xdda) [0xdf638a]
/usr/sbin/mysqld(do_command(THD*)+0x194) [0xdf8184]
/usr/sbin/mysqld() [0xf29900]
/usr/sbin/mysqld() [0x259ac6e]
/lib64/libpthread.so.0(+0x7dd5) [0x7f3fba9e2dd5]
/lib64/libc.so.6(clone+0x6d) [0x7f3fb8ffeead]