|
could you please provide your configuration files from 10.4.13/10.4.17
|
|
Same configuration was used. Attached. my.cnf
|
|
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.
|
|
Closing as duplicate of MDEV-24275
|
my.cnf