Details
-
Bug
-
Status: Closed (View Workflow)
-
Blocker
-
Resolution: Fixed
-
5.5.59, 10.0.33, 10.1.29, 10.0.33-galera, 10.2.10, 10.3.3
Description
It seems a regression happened after 10.0.31 with InnoDB handling of deleted secondary index records. The basic test case is the following:
drop table if exists test;
|
create table test(
|
id int unsigned auto_increment primary key,
|
serial int unsigned not null,
|
acked boolean default false,
|
index serial_acked (serial, acked)
|
);
|
|
insert into test (serial) values (12345);
|
insert into test (serial) select serial from test;
|
insert into test (serial) select serial from test;
|
insert into test (serial) select serial from test;
|
insert into test (serial) select serial from test;
|
insert into test (serial) select serial from test;
|
insert into test (serial) select serial from test;
|
insert into test (serial) select serial from test;
|
insert into test (serial) select serial from test;
|
insert into test (serial) select serial from test;
|
insert into test (serial) select serial from test;
|
insert into test (serial) select serial from test;
|
insert into test (serial) select serial from test;
|
insert into test (serial) select serial from test;
|
insert into test (serial) select serial from test;
|
insert into test (serial) select serial from test;
|
insert into test (serial) select serial from test;
|
insert into test (serial) select serial from test;
|
insert into test (serial) select serial from test;
|
insert into test (serial) select serial from test;
|
insert into test (serial) select serial from test;
|
|
explain select * from test where serial = 12345 and acked = true;
|
explain select * from test where serial = 12345 and acked = false;
|
|
update test set acked = true;
|
|
explain select * from test where serial = 12345 and acked = true;
|
explain select * from test where serial = 12345 and acked = false;
|
|
analyze table test;
|
|
explain select * from test where serial = 12345 and acked = true;
|
explain select * from test where serial = 12345 and acked = false;
|
We get the following after populating the table:
MariaDB [indextest]> select count(*) from test where serial = 12345 and acked = true;
|
+----------+
|
| count(*) |
|
+----------+
|
| 0 |
|
+----------+
|
1 row in set (0.03 sec)
|
|
MariaDB [indextest]> select count(*) from test where serial = 12345 and acked = false;
|
+----------+
|
| count(*) |
|
+----------+
|
| 1048576 |
|
+----------+
|
1 row in set (0.52 sec)
|
|
MariaDB [indextest]> explain select * from test where serial = 12345 and acked = true;
|
+------+-------------+-------+------+---------------+--------------+---------+-------------+------+-------------+
|
| id | select_type | table | type | possible_keys | key | key_len | ref | rows | Extra |
|
+------+-------------+-------+------+---------------+--------------+---------+-------------+------+-------------+
|
| 1 | SIMPLE | test | ref | serial_acked | serial_acked | 6 | const,const | 1 | Using index |
|
+------+-------------+-------+------+---------------+--------------+---------+-------------+------+-------------+
|
1 row in set (0.00 sec)
|
|
MariaDB [indextest]> explain select * from test where serial = 12345 and acked = false;
|
+------+-------------+-------+------+---------------+--------------+---------+-------------+--------+-------------+
|
| id | select_type | table | type | possible_keys | key | key_len | ref | rows | Extra |
|
+------+-------------+-------+------+---------------+--------------+---------+-------------+--------+-------------+
|
| 1 | SIMPLE | test | ref | serial_acked | serial_acked | 6 | const,const | 523672 | Using index |
|
+------+-------------+-------+------+---------------+--------------+---------+-------------+--------+-------------+
|
1 row in set (0.00 sec)
|
|
MariaDB [indextest]> show table status like 'test'\G
|
*************************** 1. row ***************************
|
Name: test
|
Engine: InnoDB
|
Version: 10
|
Row_format: Compact
|
Rows: 1047345
|
Avg_row_length: 31
|
Data_length: 33095680
|
Max_data_length: 0
|
Index_length: 17350656
|
Data_free: 4194304
|
Auto_increment: 1376221
|
Create_time: 2017-12-29 12:58:19
|
Update_time: NULL
|
Check_time: NULL
|
Collation: latin1_swedish_ci
|
Checksum: NULL
|
Create_options:
|
Comment:
|
1 row in set (0.00 sec)
|
Now, if we run UPDATE on 10.0.31 (all default settings besides port and socket), we get:
MariaDB [indextest]> update test set acked = true;
|
Query OK, 1048576 rows affected (23.26 sec)
|
Rows matched: 1048576 Changed: 1048576 Warnings: 0
|
|
MariaDB [indextest]> explain select * from test where serial = 12345 and acked = true;
|
+------+-------------+-------+------+---------------+--------------+---------+-------------+--------+-------------+
|
| id | select_type | table | type | possible_keys | key | key_len | ref | rows | Extra |
|
+------+-------------+-------+------+---------------+--------------+---------+-------------+--------+-------------+
|
| 1 | SIMPLE | test | ref | serial_acked | serial_acked | 6 | const,const | 523672 | Using index |
|
+------+-------------+-------+------+---------------+--------------+---------+-------------+--------+-------------+
|
1 row in set (0.00 sec)
|
|
MariaDB [indextest]> explain select * from test where serial = 12345 and acked = false;
|
+------+-------------+-------+------+---------------+--------------+---------+-------------+--------+-------------+
|
| id | select_type | table | type | possible_keys | key | key_len | ref | rows | Extra |
|
+------+-------------+-------+------+---------------+--------------+---------+-------------+--------+-------------+
|
| 1 | SIMPLE | test | ref | serial_acked | serial_acked | 6 | const,const | 465874 | Using index |
|
+------+-------------+-------+------+---------------+--------------+---------+-------------+--------+-------------+
|
1 row in set (0.01 sec)
|
|
MariaDB [indextest]> analyze table test;
|
+----------------+---------+----------+----------+
|
| Table | Op | Msg_type | Msg_text |
|
+----------------+---------+----------+----------+
|
| indextest.test | analyze | status | OK |
|
+----------------+---------+----------+----------+
|
1 row in set (0.10 sec)
|
|
MariaDB [indextest]> explain select * from test where serial = 12345 and acked = true;
|
+------+-------------+-------+------+---------------+--------------+---------+-------------+--------+-------------+
|
| id | select_type | table | type | possible_keys | key | key_len | ref | rows | Extra |
|
+------+-------------+-------+------+---------------+--------------+---------+-------------+--------+-------------+
|
| 1 | SIMPLE | test | ref | serial_acked | serial_acked | 6 | const,const | 523672 | Using index |
|
+------+-------------+-------+------+---------------+--------------+---------+-------------+--------+-------------+
|
1 row in set (0.00 sec)
|
|
MariaDB [indextest]> explain select * from test where serial = 12345 and acked = false;
|
+------+-------------+-------+------+---------------+--------------+---------+-------------+------+-------------+
|
| id | select_type | table | type | possible_keys | key | key_len | ref | rows | Extra |
|
+------+-------------+-------+------+---------------+--------------+---------+-------------+------+-------------+
|
| 1 | SIMPLE | test | ref | serial_acked | serial_acked | 6 | const,const | 1 | Using index |
|
+------+-------------+-------+------+---------------+--------------+---------+-------------+------+-------------+
|
1 row in set (0.00 sec)
|
|
MariaDB [indextest]> select count(*) from test where serial = 12345 and acked = true;
|
+----------+
|
| count(*) |
|
+----------+
|
| 1048576 |
|
+----------+
|
1 row in set (0.58 sec)
|
|
MariaDB [indextest]> select count(*) from test where serial = 12345 and acked = false;
|
+----------+
|
| count(*) |
|
+----------+
|
| 0 |
|
+----------+
|
1 row in set (0.00 sec)
|
That is, immediately after UPDATE the estimated number of rows in EXPLAIN for "false" case may be wrong, but as soon as we run ANALYZE we get expected estimation, and query that tries to get these rows (to find nothing) run fast.
Now, if we do the same on versions 10.0.33 or 10.2.11 (again all default settings besides port and socket), we get:
...
|
MariaDB [test]> select count(*) from test where serial = 12345 and acked = true;
|
+----------+
|
| count(*) |
|
+----------+
|
| 1048576 |
|
+----------+
|
1 row in set (0.52 sec)
|
|
MariaDB [test]> select count(*) from test where serial = 12345 and acked = false;
|
+----------+
|
| count(*) |
|
+----------+
|
| 0 |
|
+----------+
|
1 row in set (0.13 sec)
|
|
MariaDB [test]> analyze table test;
|
+-----------+---------+----------+----------+
|
| Table | Op | Msg_type | Msg_text |
|
+-----------+---------+----------+----------+
|
| test.test | analyze | status | OK |
|
+-----------+---------+----------+----------+
|
1 row in set (0.17 sec)
|
|
MariaDB [test]> explain select * from test where serial = 12345 and acked = true;
|
+------+-------------+-------+------+---------------+--------------+---------+-------------+--------+-------------+
|
| id | select_type | table | type | possible_keys | key | key_len | ref | rows | Extra |
|
+------+-------------+-------+------+---------------+--------------+---------+-------------+--------+-------------+
|
| 1 | SIMPLE | test | ref | serial_acked | serial_acked | 6 | const,const | 523672 | Using index |
|
+------+-------------+-------+------+---------------+--------------+---------+-------------+--------+-------------+
|
1 row in set (0.00 sec)
|
|
MariaDB [test]> explain select * from test where serial = 12345 and acked = false;
|
+------+-------------+-------+------+---------------+--------------+---------+-------------+--------+-------------+
|
| id | select_type | table | type | possible_keys | key | key_len | ref | rows | Extra |
|
+------+-------------+-------+------+---------------+--------------+---------+-------------+--------+-------------+
|
| 1 | SIMPLE | test | ref | serial_acked | serial_acked | 6 | const,const | 523672 | Using index |
|
+------+-------------+-------+------+---------------+--------------+---------+-------------+--------+-------------+
|
1 row in set (0.00 sec)
|
Note that ANALYZE does NOT help to get more correct estimation for rows for the "false" case, moreover, attempt to read these rows (to find nothing) takes notable time. Moreover, in the table status we see:
MariaDB [test]> show table status like 'test'\G
|
*************************** 1. row ***************************
|
Name: test
|
Engine: InnoDB
|
Version: 10
|
Row_format: Dynamic
|
Rows: 1047345
|
Avg_row_length: 31
|
Data_length: 33095680
|
Max_data_length: 0
|
Index_length: 33095680
|
Data_free: 5242880
|
Auto_increment: 1376221
|
Create_time: 2017-12-29 13:07:55
|
Update_time: 2017-12-29 13:10:14
|
Check_time: NULL
|
Collation: latin1_swedish_ci
|
Checksum: NULL
|
Create_options:
|
Comment:
|
1 row in set (0.10 sec)
|
that secondary index size is estimated as too big, to it seems delete-marked records are taken into account. Further attempts to run ANALYZE with any settings do not help:
MariaDB [test]> set global innodb_stats_persistent_sample_pages = 20000;
|
Query OK, 0 rows affected (0.03 sec)
|
|
MariaDB [test]> analyze table test;
|
+-----------+---------+----------+----------+
|
| Table | Op | Msg_type | Msg_text |
|
+-----------+---------+----------+----------+
|
| test.test | analyze | status | OK |
|
+-----------+---------+----------+----------+
|
1 row in set (0.41 sec)
|
|
MariaDB [test]> explain select * from test where serial = 12345 and acked = true;
|
+------+-------------+-------+------+---------------+--------------+---------+-------------+--------+-------------+
|
| id | select_type | table | type | possible_keys | key | key_len | ref | rows | Extra |
|
+------+-------------+-------+------+---------------+--------------+---------+-------------+--------+-------------+
|
| 1 | SIMPLE | test | ref | serial_acked | serial_acked | 6 | const,const | 524288 | Using index |
|
+------+-------------+-------+------+---------------+--------------+---------+-------------+--------+-------------+
|
1 row in set (0.00 sec)
|
|
MariaDB [test]> explain select * from test where serial = 12345 and acked = false;
|
+------+-------------+-------+------+---------------+--------------+---------+-------------+--------+-------------+
|
| id | select_type | table | type | possible_keys | key | key_len | ref | rows | Extra |
|
+------+-------------+-------+------+---------------+--------------+---------+-------------+--------+-------------+
|
| 1 | SIMPLE | test | ref | serial_acked | serial_acked | 6 | const,const | 524288 | Using index |
|
+------+-------------+-------+------+---------------+--------------+---------+-------------+--------+-------------+
|
1 row in set (0.00 sec)
|
|
MariaDB [test]> show table status like 'test'\G
|
*************************** 1. row ***************************
|
Name: test
|
Engine: InnoDB
|
Version: 10
|
Row_format: Dynamic
|
Rows: 1048576
|
Avg_row_length: 31
|
Data_length: 33095680
|
Max_data_length: 0
|
Index_length: 33095680
|
Data_free: 5242880
|
Auto_increment: 1376221
|
Create_time: 2017-12-29 13:07:55
|
Update_time: 2017-12-29 13:10:14
|
Check_time: NULL
|
Collation: latin1_swedish_ci
|
Checksum: NULL
|
Create_options:
|
Comment:
|
1 row in set (0.00 sec)
|
What does help is table rebuild/OPTIMIZE:
MariaDB [test]> optimize table test;
|
+-----------+----------+----------+-------------------------------------------------------------------+
|
| Table | Op | Msg_type | Msg_text |
|
+-----------+----------+----------+-------------------------------------------------------------------+
|
| test.test | optimize | note | Table does not support optimize, doing recreate + analyze instead |
|
| test.test | optimize | status | OK |
|
+-----------+----------+----------+-------------------------------------------------------------------+
|
2 rows in set (16.62 sec)
|
|
MariaDB [test]> show table status like 'test'\G *************************** 1. row ***************************
|
Name: test
|
Engine: InnoDB
|
Version: 10
|
Row_format: Dynamic
|
Rows: 1048576
|
Avg_row_length: 35
|
Data_length: 37273600
|
Max_data_length: 0
|
Index_length: 19447808
|
Data_free: 2097152
|
Auto_increment: 1376221
|
Create_time: 2017-12-29 13:13:51
|
Update_time: NULL
|
Check_time: NULL
|
Collation: latin1_swedish_ci
|
Checksum: NULL
|
Create_options:
|
Comment:
|
1 row in set (0.00 sec)
|
|
MariaDB [test]> explain select * from test where serial = 12345 and acked = true;
|
+------+-------------+-------+------+---------------+--------------+---------+-------------+--------+-------------+
|
| id | select_type | table | type | possible_keys | key | key_len | ref | rows | Extra |
|
+------+-------------+-------+------+---------------+--------------+---------+-------------+--------+-------------+
|
| 1 | SIMPLE | test | ref | serial_acked | serial_acked | 6 | const,const | 524288 | Using index |
|
+------+-------------+-------+------+---------------+--------------+---------+-------------+--------+-------------+
|
1 row in set (0.00 sec)
|
|
MariaDB [test]> explain select * from test where serial = 12345 and acked = false;
|
+------+-------------+-------+------+---------------+--------------+---------+-------------+------+-------------+
|
| id | select_type | table | type | possible_keys | key | key_len | ref | rows | Extra |
|
+------+-------------+-------+------+---------------+--------------+---------+-------------+------+-------------+
|
| 1 | SIMPLE | test | ref | serial_acked | serial_acked | 6 | const,const | 1 | Using index |
|
+------+-------------+-------+------+---------------+--------------+---------+-------------+------+-------------+
|
1 row in set (0.00 sec)
|
|
MariaDB [test]> select count(*) from test where serial = 12345 and acked = false;
|
+----------+
|
| count(*) |
|
+----------+
|
| 0 |
|
+----------+
|
1 row in set (0.00 sec)
|
I consider the wrong estimated number of records a symptom, as even if we get with exactly the same access plan, SELECT itself seems to spend time checking deleted rows as well, somehow. In real life cases, many selects that get wrong rows estimations becomes slow for this and similar cases involving changes of many records in secondary indexes after upgrade from 10.0.31, so there is a regression somewhere.
This may have something to do with https://bugs.mysql.com/bug.php?id=75231
I think this may have something to do
Attachments
Issue Links
- is duplicated by
-
MDEV-16003 too large INDEX_LENGTH
-
- Closed
-
- relates to
-
MDEV-29666 InnoDB fails to purge secondary index records when indexed virtual columns exist
-
- Closed
-
-
MDEV-14051 'Undo log record is too big.' error occurring in very narrow range of string lengths
-
- Closed
-
The change came with this patch in 5.5:
commit 439a7c994a6f01de1a3980c0405fb9e24ae3bd1a
Author: Marko Mäkelä <marko.makela@mariadb.com>
Date: Tue Oct 24 15:20:54 2017 +0300
MDEV-14051 'Undo log record is too big.' error occurring in very narrow range of string lengths
InnoDB was writing unnecessary information to the
update undo log records. Most notably, if an indexed column is updated,
the old value of the column would be logged twice: first as part of
the update vector, and then another time because it is an indexed column.
Because the InnoDB undo log record must fit in a single page,
this would cause unnecessary failure of certain updates.
Even after this fix, InnoDB still seems to be unnecessarily logging
indexed column values for non-updated columns. It seems that non-updated
secondary index columns only need to be logged when a PRIMARY KEY
column is updated. To reduce risk, we are not fixing this remaining flaw
in GA versions.
trx_undo_page_report_modify(): Log updated indexed columns only once.
Please note that the test case, if it's executed automatically or copy-pasted, might cause false positives even on "good" versions, it needs some time between ANALYZE and EXPLAIN to get the proper numbers.