Details
-
Bug
-
Status: Closed (View Workflow)
-
Major
-
Resolution: Duplicate
-
10.4.17
-
None
-
CentOS Linux release 7.9.2009
Description
We noticed one issue on MariaDB 10.4.17 , the primary key isn't used on range lookups (full table scan is done):
|
|
# show create table jos_email_message\G
|
|
|
Table: jos_email_message
|
Create Table: CREATE TABLE `jos_email_message` (
|
`id` int(11) NOT NULL,
|
`email_message` longtext NOT NULL,
|
PRIMARY KEY (`id`)
|
) ENGINE=InnoDB DEFAULT CHARSET=utf8 ROW_FORMAT=COMPRESSED KEY_BLOCK_SIZE=2
|
# explain format=json SELECT count(id) FROM jos_email_message WHERE `id` between 2114506 AND 2114624\G
|
|
|
EXPLAIN: {
|
"query_block": {
|
"select_id": 1,
|
"table": {
|
"table_name": "jos_email_message",
|
"access_type": "index",
|
"possible_keys": ["PRIMARY"],
|
"key": "PRIMARY",
|
"key_length": "4",
|
"used_key_parts": ["id"],
|
"rows": 20489158,
|
"filtered": 5.8e-4,
|
"attached_condition": "jos_email_message.`id` between 2114506 and 2114624",
|
"using_index": true
|
}
|
}
|
}
|
# explain SELECT count(`id`) FROM jos_email_message WHERE `id` between 2114506 AND 2114624;
|
+------+-------------+--------------------------+-------+---------------+---------+---------+------+----------+--------------------------+
|
| id | select_type | table | type | possible_keys | key | key_len | ref | rows | Extra |
|
+------+-------------+--------------------------+-------+---------------+---------+---------+------+----------+--------------------------+
|
| 1 | SIMPLE | jos_email_message | index | PRIMARY | PRIMARY | 4 | NULL | 20489158 | Using where; Using index |
|
+------+-------------+--------------------------+-------+---------------+---------+---------+------+----------+--------------------------+
|
1 row in set (0.001 sec)
|
|
|
# explain SELECT count(`id`) FROM jos_email_message WHERE `id` >= 2114506;
|
+------+-------------+--------------------------+-------+---------------+---------+---------+------+----------+--------------------------+
|
| id | select_type | table | type | possible_keys | key | key_len | ref | rows | Extra |
|
+------+-------------+--------------------------+-------+---------------+---------+---------+------+----------+--------------------------+
|
| 1 | SIMPLE | jos_email_message | index | PRIMARY | PRIMARY | 4 | NULL | 20489158 | Using where; Using index |
|
+------+-------------+--------------------------+-------+---------------+---------+---------+------+----------+--------------------------+
|
1 row in set (0.006 sec)
|
|
|
# explain SELECT count(`id`) FROM jos_email_message WHERE `id` <= 2114506;
|
+------+-------------+--------------------------+-------+---------------+---------+---------+------+----------+--------------------------+
|
| id | select_type | table | type | possible_keys | key | key_len | ref | rows | Extra |
|
+------+-------------+--------------------------+-------+---------------+---------+---------+------+----------+--------------------------+
|
| 1 | SIMPLE | jos_email_message | index | PRIMARY | PRIMARY | 4 | NULL | 20489158 | Using where; Using index |
|
+------+-------------+--------------------------+-------+---------------+---------+---------+------+----------+--------------------------+
|
1 row in set (0.004 sec)
|
|
|
# explain SELECT count(`id`) FROM jos_email_message WHERE `id` = 2114506;
|
+------+-------------+--------------------------+-------+---------------+---------+---------+-------+------+-------------+
|
| id | select_type | table | type | possible_keys | key | key_len | ref | rows | Extra |
|
+------+-------------+--------------------------+-------+---------------+---------+---------+-------+------+-------------+
|
| 1 | SIMPLE | jos_email_message | const | PRIMARY | PRIMARY | 4 | const | 1 | Using index |
|
+------+-------------+--------------------------+-------+---------------+---------+---------+-------+------+-------------+
|
1 row in set (0.001 sec)
|
|
We didn't have this problem on 10.4.13, prior to upgrading to 10.4.17, and we don't have this problem on 10.3.27 (master data)
# explain SELECT count(`id`) FROM jos_email_message WHERE `id` between 2114506 AND 2114624;
|
+------+-------------+--------------------------+-------+---------------+---------+---------+------+------+--------------------------+
|
| id | select_type | table | type | possible_keys | key | key_len | ref | rows | Extra |
|
+------+-------------+--------------------------+-------+---------------+---------+---------+------+------+--------------------------+
|
| 1 | SIMPLE | jos_email_message | range | PRIMARY | PRIMARY | 4 | NULL | 119 | Using where; Using index |
|
+------+-------------+--------------------------+-------+---------------+---------+---------+------+------+--------------------------+
|
|
We've tried re-creating the table, doing analyze and forcing the index, they didn't do any difference:
- ANALYZE TABLE jos_email_message;
- ALTER TABLE jos_email_message FORCE;
- SELECT count(`id`) FROM jos_email_message FORCE INDEX(`PRIMARY`) WHERE `id` between 2114506 AND 2114624;
I've done a copy of the table, but using a simple string on email_message field, instead of the HTML text we usually store there:
- CREATE TABLE test_tbl LIKE jos_email_message;
- INSERT INTO test_tbl SELECT id,'test' FROM jos_email_message;
and on the new table the index lookup works just fine:
# explain SELECT count(`id`) FROM `test_tbl` WHERE `id` between 2114506 AND 2114624;
|
+------+-------------+-------+-------+---------------+---------+---------+------+------+--------------------------+
|
| id | select_type | table | type | possible_keys | key | key_len | ref | rows | Extra |
|
+------+-------------+-------+-------+---------------+---------+---------+------+------+--------------------------+
|
| 1 | SIMPLE | test_tbl | range | PRIMARY | PRIMARY | 4 | NULL | 119 | Using where; Using index |
|
+------+-------------+-------+-------+---------------+---------+---------+------+------+--------------------------+
|
The only difference between those two would be the size, the original one is around 64Gb and the test one was only around 500Mb.
Again, we didn't face this problem on 10.4.13 and don't have this problem on 10.3.27 with the exact same data.
Seems to be a regression introduced recently in MariaDB 10.4 branch.
Just let me know if you need any other info.
Attachments
Issue Links
- duplicates
-
-
- Closed
-
- is duplicated by
-
-
- Closed
-
Activity
I tried to reproduce the issue and will describe what I observed.
the test case:
-- source include/have_innodb.inc
|
-- source include/have_sequence.inc
|
|
|
CREATE TABLE `t1` ( |
`id` int(11) NOT NULL, |
`email_message` longtext NOT NULL, |
PRIMARY KEY (`id`) |
) ENGINE=InnoDB;
|
|
|
insert into t1 select seq, concat(repeat('A',500),seq) from seq_1_to_10000; |
|
|
analyze table t1; |
|
|
analyze format=json SELECT count(`id`) FROM t1 WHERE `id` between 1 AND 1300; |
analyze format=json SELECT count(`id`) FROM t1 WHERE `id` between 1 AND 1400; |
both 10.4.13 and 10.4.17 behaved the same, starting from some value type "range" switched to "index" and query execution takes much longer time, but on 10.4.17 it started earlier.
|
10.4.13 |
MariaDB [test]> analyze format=json SELECT count(`id`) FROM t1 WHERE `id` between 1 AND 1258;
|
| ANALYZE
|
| {
|
"query_block": {
|
"select_id": 1,
|
"r_loops": 1,
|
"r_total_time_ms": 0.3921,
|
"table": {
|
"table_name": "t1",
|
"access_type": "range",
|
"possible_keys": ["PRIMARY"],
|
"key": "PRIMARY",
|
"key_length": "4",
|
"used_key_parts": ["id"],
|
"r_loops": 1,
|
"rows": 2436,
|
"r_rows": 1258,
|
"r_total_time_ms": 0.2576,
|
"filtered": 100,
|
"r_filtered": 100,
|
"attached_condition": "t1.`id` between 1 and 1258",
|
"using_index": true
|
}
|
}
|
} |
|
1 row in set (0.001 sec)
|
|
|
MariaDB [test]> analyze format=json SELECT count(`id`) FROM t1 WHERE `id` between 1 AND 1259;
|
|
|
| ANALYZE
|
| {
|
"query_block": {
|
"select_id": 1,
|
"r_loops": 1,
|
"r_total_time_ms": 2.4693,
|
"table": {
|
"table_name": "t1",
|
"access_type": "index",
|
"possible_keys": ["PRIMARY"],
|
"key": "PRIMARY",
|
"key_length": "4",
|
"used_key_parts": ["id"],
|
"r_loops": 1,
|
"rows": 9415,
|
"r_rows": 10000,
|
"r_total_time_ms": 2.0081,
|
"filtered": 25.98,
|
"r_filtered": 12.59,
|
"attached_condition": "t1.`id` between 1 and 1259",
|
"using_index": true
|
}
|
}
|
} |
|
1 row in set (0.003 sec)
|
MariaDB [test]> select version();
|
+-----------------+
|
| version() |
|
+-----------------+
|
| 10.4.13-MariaDB |
|
+-----------------+
|
1 row in set (0.000 sec)
|
|
10.4.17 |
MariaDB [test]> analyze format=json SELECT count(`id`) FROM t1 WHERE `id` between 1 AND 559;
|
| ANALYZE|
|
| {
|
"query_block": {
|
"select_id": 1,
|
"r_loops": 1,
|
"r_total_time_ms": 0.2101,
|
"table": {
|
"table_name": "t1",
|
"access_type": "range",
|
"possible_keys": ["PRIMARY"],
|
"key": "PRIMARY",
|
"key_length": "4",
|
"used_key_parts": ["id"],
|
"r_loops": 1,
|
"rows": 1056,
|
"r_rows": 559,
|
"r_total_time_ms": 0.1302,
|
"filtered": 100,
|
"r_filtered": 100,
|
"attached_condition": "t1.`id` between 1 and 559",
|
"using_index": true
|
}
|
}
|
} |
|
1 row in set (0.001 sec)
|
|
|
MariaDB [test]> analyze format=json SELECT count(`id`) FROM t1 WHERE `id` between 1 AND 560;
|
| ANALYZE |
|
| {
|
"query_block": {
|
"select_id": 1,
|
"r_loops": 1,
|
"r_total_time_ms": 2.6735,
|
"table": {
|
"table_name": "t1",
|
"access_type": "index",
|
"possible_keys": ["PRIMARY"],
|
"key": "PRIMARY",
|
"key_length": "4",
|
"used_key_parts": ["id"],
|
"r_loops": 1,
|
"rows": 10000,
|
"r_rows": 10000,
|
"r_total_time_ms": 2.2185,
|
"filtered": 10.6,
|
"r_filtered": 5.6,
|
"attached_condition": "t1.`id` between 1 and 560",
|
"using_index": true
|
}
|
}
|
} |
|
1 row in set (0.003 sec)
|
|
|
MariaDB [test]> select version();
|
+-----------------+
|
| version() |
|
+-----------------+
|
| 10.4.17-MariaDB |
|
+-----------------+
|
1 row in set (0.000 sec)
|
diff'ing the optimizer trace:
--- trace-10.4.13.txt
|
+++ trace-10.4.17.txt
|
@@ -56,8 +56,8 @@
|
"table": "t1",
|
"range_analysis": {
|
"table_scan": {
|
- "rows": 9666,
|
- "cost": 2352.3
|
+ "rows": 10000,
|
+ "cost": 2419.1
|
},
|
"potential_range_indexes": [
|
{
|
@@ -68,7 +68,7 @@
|
],
|
"best_covering_index_scan": {
|
"index": "PRIMARY",
|
- "cost": 504.19,
|
+ "cost": 521.95,
|
"chosen": true
|
},
|
"setup_range_conditions": [], |
Ok so far ...
@@ -85,25 +85,15 @@
|
"using_mrr": false,
|
"index_only": true,
|
"rows": 2436,
|
- "cost": 490.2,
|
- "chosen": true
|
+ "cost": 904.21,
|
+ "chosen": false,
|
+ "cause": "cost"
|
}
|
], |
This is where the big difference starts.
Note that {{ "rows": 2436}} is the same in both cases, while the cost is 2x different?
"analyzing_roworder_intersect": {
|
"cause": "too few roworder scans"
|
},
|
"analyzing_index_merge_union": []
|
- },
|
- "chosen_range_access_summary": {
|
- "range_access_plan": {
|
- "type": "range_scan",
|
- "index": "PRIMARY",
|
- "rows": 2436,
|
- "ranges": ["(1) <= (id) <= (1258)"]
|
- },
|
- "rows_for_plan": 2436,
|
- "cost_for_plan": 490.2,
|
- "chosen": true
|
}
|
}
|
},
|
@@ -111,11 +101,11 @@ |
Ok, debugging Alice's testcase. Note: the testcase does run ANALYZE TABLE, the table has 10K rows.
The execution is here:
#0 0x0000555556313bef in ha_innobase::read_time (this=0x7ffe6c02b4b8, index=0, ranges=1, rows=2436) at /home/psergey/dev-git/10.4.13/storage/innobase/handler/ha_innodb.cc:13924
|
#1 0x0000555555f39012 in handler::multi_range_read_info_const (this=0x7ffe6c02b4b8, keyno=0, seq=0x7fffdc186f60, seq_init_param=0x7fffdc186f90, n_ranges_arg=0, bufsz=0x7fffdc186e54, flags=0x7fffdc186e50, cost=0x7fffdc187610) at /home/psergey/dev-git/10.4.13/sql/multi_range_read.cc:162
|
#2 0x0000555555f3c8c2 in DsMrr_impl::dsmrr_info_const (this=0x7ffe6c02b948, keyno=0, seq=0x7fffdc186f60, seq_init_param=0x7fffdc186f90, n_ranges=0, bufsz=0x7fffdc187528, flags=0x7fffdc187524, cost=0x7fffdc187610) at /home/psergey/dev-git/10.4.13/sql/multi_range_read.cc:1546
|
#3 0x000055555631df92 in ha_innobase::multi_range_read_info_const (this=0x7ffe6c02b4b8, keyno=0, seq=0x7fffdc186f60, seq_init_param=0x7fffdc186f90, n_ranges=0, bufsz=0x7fffdc187528, flags=0x7fffdc187524, cost=0x7fffdc187610) at /home/psergey/dev-git/10.4.13/storage/innobase/handler/ha_innodb.cc:20395
|
#4 0x000055555624c022 in check_quick_select (param=0x7fffdc187880, idx=0, index_only=true, tree=0x7ffe6c0a34d0, update_tbl_stats=true, mrr_flags=0x7fffdc187524, bufsize=0x7fffdc187528, cost=0x7fffdc187610, is_ror_scan=0x7fffdc187522) at /home/psergey/dev-git/10.4.13/sql/opt_range.cc:11123
|
#5 0x00005555562427b2 in get_key_scans_params (param=0x7fffdc187880, tree=0x7ffe6c0a32f0, index_read_must_be_used=false, for_range_access=true, read_time=504.18777540433325) at /home/psergey/dev-git/10.4.13/sql/opt_range.cc:7410
|
#6 0x0000555556237489 in SQL_SELECT::test_quick_select (this=0x7ffe6c015690, thd=0x7ffe6c000d50, keys_to_use=..., prev_tables=0, limit=18446744073709551615, force_quick_range=false, ordered_output=false, remove_false_parts_of_where=true, only_single_index_range_scan=false) at /home/psergey/dev-git/10.4.13/sql/opt_range.cc:2919
|
#7 0x0000555555db59f4 in get_quick_record_count (thd=0x7ffe6c000d50, select=0x7ffe6c015690, table=0x7ffe6c02a1f0, keys=0x7ffe6c0145d8, limit=18446744073709551615) at /home/psergey/dev-git/10.4.13/sql/sql_select.cc:4717
|
#8 0x0000555555db81de in make_join_statistics (join=0x7ffe6c013c40, tables_list=..., keyuse_array=0x7ffe6c013f30) at /home/psergey/dev-git/10.4.13/sql/sql_select.cc:5439
|
#9 0x0000555555dac8c1 in JOIN::optimize_inner (this=0x7ffe6c013c40) at /home/psergey/dev-git/10.4.13/sql/sql_select.cc:2254
|
#10 0x0000555555daa206 in JOIN::optimize (this=0x7ffe6c013c40) at /home/psergey/dev-git/10.4.13/sql/sql_select.cc:1601
|
and we are in ha_innobase::estimate_rows_upper_bound() :
|
10.4.13 |
(gdb) print stat_n_leaf_pages
|
$14 = 358
|
|
|
(gdb) print local_data_file_length
|
$19 = 5865472
|
|
|
(gdb) print estimate
|
$20 = 510041
|
|
10.4.17 |
(gdb) print stat_n_leaf_pages
|
$16 = 1
|
|
|
(gdb) print local_data_file_length
|
$21 = 16384
|
|
|
(gdb) print estimate
|
$22 = 1424
|
The t1.ibd file is ~14M in both cases, so stat_n_leaf_pages=1 looks very incorrrect...
|
10.4.13 |
Run till exit from #0 ha_innobase::estimate_rows_upper_bound (this=0x7ffe6c02b4b8) at /home/psergey/dev-git/10.4.13/storage/innobase/handler/ha_innodb.cc:13849
|
|
|
0x0000555556313bef in ha_innobase::read_time (this=0x7ffe6c02b4b8, index=0, ranges=1, rows=2436) at /home/psergey/dev-git/10.4.13/storage/innobase/handler/ha_innodb.cc:13924
|
Value returned is $21 = 510041
|
|
10.4.17 |
Run till exit from #0 ha_innobase::estimate_rows_upper_bound (this=0x7fbddc020758) at /home/psergey/dev-git/10.4.17/storage/innobase/handler/ha_innodb.cc:13825
|
0x000055936593d7bf in ha_innobase::read_time (this=0x7fbddc020758, index=0, ranges=1, rows=2436) at /home/psergey/dev-git/10.4.17/storage/innobase/handler/ha_innodb.cc:13900
|
Value returned is $23 = 1424
|
So, estimate_rows_upper_bound() has returned 1424 where the table has 10K rows! This breaks the call contract and can cause issues in filesort.
Interesting, in current 10.4 (commit 04741dc736e803b0a91c76d19de464e25b4a1977), stat_n_leaf_pages is back to 358.
looking through the commits, 5fbfdae130950d0a5a07d4b909f3bf1ff0498d34..04741dc736e803b0a91c76d19de464e25b4a1977 , the only fix that looks related is:
commit 5991bd6215054f21ec5c36fc9345ffb50f1b2d04
|
Author: Eugene Kosov <claprix@yandex.ru>
|
Date: Wed Nov 25 16:01:38 2020 +0300
|
|
|
MDEV-24275 InnoDB persistent stats analyze forces full scan forcing lock crash
|
|
This is a fixup patch for MDEV-23991 afc9d00c66db946c8240fe1fa6b345a3a8b6fec1
|
|
We really should read result.n_leaf_pages, which was set previously.
|
|
Analysis and fix was provided by Jukka Santala. Thanks!
|
|
Reviewed by: Marko Mäkelä
|
|
Indeed, if I apply that patch, stat_n_leaf_pages goes back to normal.
could you please provide your configuration files from 10.4.13/10.4.17