[MDEV-26708] Query with many joins spends a lot of time in Statistics phase with join_cache_level > 0 Created: 2021-09-28  Updated: 2023-04-27

Status: Open
Project: MariaDB Server
Component/s: Optimizer
Affects Version/s: 10.2, 10.3, 10.4, 10.5, 10.6
Fix Version/s: 10.4, 10.5, 10.6

Type: Bug Priority: Major
Reporter: Elena Stepanova Assignee: Sergei Petrunia
Resolution: Unresolved Votes: 0
Labels: None


 Description   

The query below joins 18 tables, with 2 rows each. On a release build running with all defaults, on my machine it takes ~2.5 minutes, almost all of which are spent in "Statistics" phase, according to the processlist. Adding yet another join bumps up execution time so that I've never waited long enough for it to finish.

With join_cache_level=0 it takes ~4 sec with 18 tables and ~8 sec with 19 tables.

Stack trace during this time is approximately this (it doesn't hang, so it changes somewhat all the time):

10.2 3690c549

Thread 31 (Thread 0x7f1cf8892700 (LWP 2163427)):
#0  0x0000556369e4b3a2 in best_access_path (join=join@entry=0x7f1c8c045060, s=s@entry=0x7f1c8c06aa90, remaining_tables=remaining_tables@entry=196611, join_positions=0x7f1c8c06f090, idx=idx@entry=14, disable_jbuf=disable_jbuf@entry=false, record_count=record_count@entry=8192, pos=0x7f1c8c06ff00, loose_scan_pos=0x7f1cf888d8b0) at /data/src/10.2/sql/sql_select.cc:6388
#1  0x0000556369e4dd27 in best_extension_by_limited_search (join=join@entry=0x7f1c8c045060, remaining_tables=196611, idx=idx@entry=14, record_count=8192, read_time=4524.2205078125007, search_depth=search_depth@entry=48, prune_level=prune_level@entry=1, use_cond_selectivity=use_cond_selectivity@entry=1) at /data/src/10.2/sql/sql_select.cc:8358
#2  0x0000556369e4e037 in best_extension_by_limited_search (join=join@entry=0x7f1c8c045060, remaining_tables=196675, idx=idx@entry=13, record_count=4096, read_time=2883.8170898437502, search_depth=search_depth@entry=49, prune_level=prune_level@entry=1, use_cond_selectivity=use_cond_selectivity@entry=1) at /data/src/10.2/sql/sql_select.cc:8430
#3  0x0000556369e4e037 in best_extension_by_limited_search (join=join@entry=0x7f1c8c045060, remaining_tables=196683, idx=idx@entry=12, record_count=2048, read_time=2062.6136718749999, search_depth=search_depth@entry=50, prune_level=prune_level@entry=1, use_cond_selectivity=use_cond_selectivity@entry=1) at /data/src/10.2/sql/sql_select.cc:8430
#4  0x0000556369e4e037 in best_extension_by_limited_search (join=join@entry=0x7f1c8c045060, remaining_tables=229451, idx=idx@entry=11, record_count=1024, read_time=1652.013671875, search_depth=search_depth@entry=51, prune_level=prune_level@entry=1, use_cond_selectivity=use_cond_selectivity@entry=1) at /data/src/10.2/sql/sql_select.cc:8430
#5  0x0000556369e4e037 in best_extension_by_limited_search (join=join@entry=0x7f1c8c045060, remaining_tables=229963, idx=idx@entry=10, record_count=1024, read_time=423.21367187500005, search_depth=search_depth@entry=52, prune_level=prune_level@entry=1, use_cond_selectivity=use_cond_selectivity@entry=1) at /data/src/10.2/sql/sql_select.cc:8430
#6  0x0000556369e4e037 in best_extension_by_limited_search (join=join@entry=0x7f1c8c045060, remaining_tables=229979, idx=idx@entry=9, record_count=512, read_time=216.41025390625001, search_depth=search_depth@entry=53, prune_level=prune_level@entry=1, use_cond_selectivity=use_cond_selectivity@entry=1) at /data/src/10.2/sql/sql_select.cc:8430
#7  0x0000556369e4e037 in best_extension_by_limited_search (join=join@entry=0x7f1c8c045060, remaining_tables=230107, idx=idx@entry=8, record_count=256, read_time=112.0068359375, search_depth=search_depth@entry=54, prune_level=prune_level@entry=1, use_cond_selectivity=use_cond_selectivity@entry=1) at /data/src/10.2/sql/sql_select.cc:8430
#8  0x0000556369e4e037 in best_extension_by_limited_search (join=join@entry=0x7f1c8c045060, remaining_tables=230363, idx=idx@entry=7, record_count=128, read_time=59.806835937500004, search_depth=search_depth@entry=55, prune_level=prune_level@entry=1, use_cond_selectivity=use_cond_selectivity@entry=1) at /data/src/10.2/sql/sql_select.cc:8430
#9  0x0000556369e4e037 in best_extension_by_limited_search (join=join@entry=0x7f1c8c045060, remaining_tables=246747, idx=idx@entry=6, record_count=64, read_time=33.206835937500003, search_depth=search_depth@entry=56, prune_level=prune_level@entry=1, use_cond_selectivity=use_cond_selectivity@entry=1) at /data/src/10.2/sql/sql_select.cc:8430
#10 0x0000556369e4e037 in best_extension_by_limited_search (join=join@entry=0x7f1c8c045060, remaining_tables=246779, idx=idx@entry=5, record_count=32, read_time=18.403417968749999, search_depth=search_depth@entry=57, prune_level=prune_level@entry=1, use_cond_selectivity=use_cond_selectivity@entry=1) at /data/src/10.2/sql/sql_select.cc:8430
#11 0x0000556369e4e037 in best_extension_by_limited_search (join=join@entry=0x7f1c8c045060, remaining_tables=254971, idx=idx@entry=4, record_count=16, read_time=11.00341796875, search_depth=search_depth@entry=58, prune_level=prune_level@entry=1, use_cond_selectivity=use_cond_selectivity@entry=1) at /data/src/10.2/sql/sql_select.cc:8430
#12 0x0000556369e4e037 in best_extension_by_limited_search (join=join@entry=0x7f1c8c045060, remaining_tables=259067, idx=idx@entry=3, record_count=8, read_time=6.8034179687500007, search_depth=search_depth@entry=59, prune_level=prune_level@entry=1, use_cond_selectivity=use_cond_selectivity@entry=1) at /data/src/10.2/sql/sql_select.cc:8430
#13 0x0000556369e4e037 in best_extension_by_limited_search (join=join@entry=0x7f1c8c045060, remaining_tables=259071, idx=idx@entry=2, record_count=4, read_time=3.2000000000000002, search_depth=search_depth@entry=60, prune_level=prune_level@entry=1, use_cond_selectivity=use_cond_selectivity@entry=1) at /data/src/10.2/sql/sql_select.cc:8430
#14 0x0000556369e4e037 in best_extension_by_limited_search (join=join@entry=0x7f1c8c045060, remaining_tables=261119, idx=idx@entry=1, record_count=2, read_time=1.3999999999999999, search_depth=search_depth@entry=61, prune_level=prune_level@entry=1, use_cond_selectivity=use_cond_selectivity@entry=1) at /data/src/10.2/sql/sql_select.cc:8430
#15 0x0000556369e4e037 in best_extension_by_limited_search (join=join@entry=0x7f1c8c045060, remaining_tables=remaining_tables@entry=262143, idx=idx@entry=0, record_count=record_count@entry=1, read_time=read_time@entry=0, search_depth=search_depth@entry=62, prune_level=prune_level@entry=1, use_cond_selectivity=use_cond_selectivity@entry=1) at /data/src/10.2/sql/sql_select.cc:8430
#16 0x0000556369e4e3f1 in greedy_search (join=join@entry=0x7f1c8c045060, remaining_tables=remaining_tables@entry=262143, search_depth=62, prune_level=prune_level@entry=1, use_cond_selectivity=use_cond_selectivity@entry=1) at /data/src/10.2/sql/sql_select.cc:7544
#17 0x0000556369e4e8a6 in choose_plan (join=join@entry=0x7f1c8c045060, join_tables=join_tables@entry=262143) at /data/src/10.2/sql/sql_select.cc:7120
#18 0x0000556369e6c101 in make_join_statistics (join=0x7f1c8c045060, tables_list=..., keyuse_array=0x7f1c8c045350) at /data/src/10.2/sql/sql_select.cc:4593
#19 0x0000556369e73990 in JOIN::optimize_inner (this=0x7f1c8c045060) at /data/src/10.2/sql/sql_select.cc:1597
#20 0x0000556369e76749 in JOIN::optimize (this=0x7f1c8c045060) at /data/src/10.2/sql/sql_select.cc:1127
#21 JOIN::optimize (this=0x7f1c8c045060) at /data/src/10.2/sql/sql_select.cc:1119
#22 0x0000556369e78891 in mysql_select (thd=0x7f1c8c000c48, tables=0x7f1c8c00f8c0, wild_num=0, fields=..., conds=0x0, og_num=0, order=0x0, group=0x0, having=0x0, proc_param=0x0, select_options=<optimized out>, result=0x7f1c8c043468, unit=0x7f1c8c004680, select_lex=0x7f1c8c004dd0) at /data/src/10.2/sql/sql_select.cc:3835
#23 0x0000556369e78b67 in handle_select (thd=thd@entry=0x7f1c8c000c48, lex=lex@entry=0x7f1c8c0045c0, result=result@entry=0x7f1c8c043468, setup_tables_done_option=setup_tables_done_option@entry=0) at /data/src/10.2/sql/sql_select.cc:361
#24 0x0000556369e0dec1 in execute_sqlcom_select (thd=0x7f1c8c000c48, all_tables=0x7f1c8c00f8c0) at /data/src/10.2/sql/sql_parse.cc:6271
#25 0x0000556369e1b6ea in mysql_execute_command (thd=<optimized out>) at /data/src/10.2/sql/sql_parse.cc:3582
#26 0x0000556369e1e3eb in mysql_parse (thd=thd@entry=0x7f1c8c000c48, rawbuf=<optimized out>, length=<optimized out>, parser_state=parser_state@entry=0x7f1cf8891550, is_com_multi=is_com_multi@entry=false, is_next_command=is_next_command@entry=false) at /data/src/10.2/sql/sql_parse.cc:7793
#27 0x0000556369e2140d in dispatch_command (command=COM_QUERY, thd=0x7f1c8c000c48, packet=<optimized out>, packet_length=<optimized out>, is_com_multi=<optimized out>, is_next_command=<optimized out>) at /data/src/10.2/sql/sql_class.h:1109
#28 0x0000556369e2282d in do_command (thd=0x7f1c8c000c48) at /data/src/10.2/sql/sql_parse.cc:1381
#29 0x0000556369efc216 in do_handle_one_connection (connect=connect@entry=0x55636d4a0db8) at /data/src/10.2/sql/sql_connect.cc:1336
#30 0x0000556369efc38f in handle_one_connection (arg=0x55636d4a0db8) at /data/src/10.2/sql/sql_connect.cc:1241
#31 0x00007f1cfb89e609 in start_thread (arg=<optimized out>) at pthread_create.c:477
#32 0x00007f1cfb492293 in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95

--source include/have_innodb.inc
 
CREATE TABLE t1 (a INT, KEY(a)) ENGINE=MyISAM;
INSERT INTO t1 VALUES (1),(2);
 
CREATE TABLE t2 (b INT, KEY(b)) ENGINE=InnoDB;
INSERT INTO t2 VALUES (1),(2);
 
SELECT COUNT(*) FROM
  t1 AS tbl01
  JOIN
  t1 AS tbl02
  ON tbl01.a = tbl02.a
  JOIN
  t1 AS tbl03
  JOIN
  t1 AS tbl04
  JOIN
  t1 AS tbl05
  JOIN
  t1 AS tbl06
  JOIN
  t1 AS tbl07
  JOIN
  t1 AS tbl08
  JOIN
  t2 AS tbl09
  JOIN
  t2 AS tbl10
  ON tbl09.b = tbl10.b
  JOIN
  t2 AS tbl11
  JOIN
  t2 AS tbl12
  JOIN
  t2 AS tbl13
  JOIN
  t2 AS tbl14
  JOIN
  t2 AS tbl15
  JOIN
  t2 AS tbl16
  JOIN
  t2 AS tbl17
  JOIN
  t2 AS tbl18
;
 
# Cleanup
DROP TABLE t1, t2;

Reproducible on 10.2-10.7. I didn't check earlier versions.


Generated at Thu Feb 08 09:47:20 UTC 2024 using Jira 8.20.16#820016-sha1:9d11dbea5f4be3d4cc21f03a88dd11d8c8687422.