[MDEV-6888] Query spends a long time in best_extension_by_limited_search with mrr enabled - Jira

Details

Type: Bug
Status: Closed (View Workflow)
Priority: Major
Resolution: Fixed
Affects Version/s: 10.0.12
Fix Version/s: 10.0.15
Component/s: Optimizer
Labels:
- hash-join
- optimizer

Description

In order to improve test coverage, I applied the following patch to a test build and ran all tests:

--- a/sql/sql_priv.h         2014-07-10 23:01:30.000000000 -0700

+++ b/sql/sql_priv.h         2014-10-17 11:52:40.000000000 -0700

@@ -265,6 +265,8 @@ template <class T> bool valid_buffer_ran

                                     OPTIMIZER_SWITCH_EXTENDED_KEYS | \

                                     OPTIMIZER_SWITCH_IN_TO_EXISTS | \

                                     OPTIMIZER_SWITCH_MATERIALIZATION | \

+                                    OPTIMIZER_SWITCH_MRR | \

+                                    OPTIMIZER_SWITCH_MRR_SORT_KEYS | \

                                     OPTIMIZER_SWITCH_PARTIAL_MATCH_ROWID_MERGE|\

                                     OPTIMIZER_SWITCH_PARTIAL_MATCH_TABLE_SCAN|\

                                     OPTIMIZER_SWITCH_OUTER_JOIN_WITH_CACHE | \

--- a/sql/sys_vars.cc        2014-10-10 09:26:00.000000000 -0700

+++ b/sql/sys_vars.cc        2014-10-17 11:52:53.000000000 -0700

@@ -5488,7 +5488,7 @@ static Sys_var_ulong Sys_join_cache_leve

        "numbers are used for plain join buffers while even numbers are used "

        "for linked buffers",

        SESSION_VAR(join_cache_level), CMD_LINE(REQUIRED_ARG),

-       VALID_RANGE(0, 8), DEFAULT(2), BLOCK_SIZE(1));

+       VALID_RANGE(0, 8), DEFAULT(8), BLOCK_SIZE(1));

 static Sys_var_ulong Sys_mrr_buffer_size(

        "mrr_buffer_size",

I got a timeout in existing test funcs_1.memory_views due to an infinite recursion in best_extension_by_limited_search:

#1  0x0000000002bf4175 in best_extension_by_limited_search (join=0x7fffe7d52c70, remaining_tables=14876672, idx=23, record_count=11920928955078124, read_time=3323366612638157.5, search_depth=39, prune_level=1, use_cond_selectivity=1) at sql/sql_select.cc:7630

#2  0x0000000002bf4846 in best_extension_by_limited_search (join=0x7fffe7d52c70, remaining_tables=15400960, idx=22, record_count=2384185791015625, read_time=661748557793711.75, search_depth=40, prune_level=1, use_cond_selectivity=1) at sql/sql_select.cc:7750

#3  0x0000000002bf4846 in best_extension_by_limited_search (join=0x7fffe7d52c70, remaining_tables=15663104, idx=21, record_count=476837158203125, read_time=131625014508403, search_depth=41, prune_level=1, use_cond_selectivity=1) at sql/sql_select.cc:7750

#4  0x0000000002bf4846 in best_extension_by_limited_search (join=0x7fffe7d52c70, remaining_tables=149880832, idx=20, record_count=95367431640625, read_time=26211850088810.25, search_depth=42, prune_level=1, use_cond_selectivity=1) at sql/sql_select.cc:7750

#5  0x0000000002bf4846 in best_extension_by_limited_search (join=0x7fffe7d52c70, remaining_tables=183435264, idx=19, record_count=19073486328125, read_time=5218711483537.75, search_depth=43, prune_level=1, use_cond_selectivity=1) at sql/sql_select.cc:7750

#6  0x0000000002bf4846 in best_extension_by_limited_search (join=0x7fffe7d52c70, remaining_tables=200212480, idx=18, record_count=3814697265625, read_time=1037684303952.5, search_depth=44, prune_level=1, use_cond_selectivity=1) at sql/sql_select.cc:7750

#7  0x0000000002bf4846 in best_extension_by_limited_search (join=0x7fffe7d52c70, remaining_tables=201261056, idx=17, record_count=762939453125, read_time=206371221932.25, search_depth=45, prune_level=1, use_cond_selectivity=1) at sql/sql_select.cc:7750

#8  0x0000000002bf4846 in best_extension_by_limited_search (join=0x7fffe7d52c70, remaining_tables=268369920, idx=16, record_count=152587890625, read_time=41087076301, search_depth=46, prune_level=1, use_cond_selectivity=1) at sql/sql_select.cc:7750

#9  0x0000000002bf4846 in best_extension_by_limited_search (join=0x7fffe7d52c70, remaining_tables=268402688, idx=15, record_count=30517578125, read_time=8171051506.75, search_depth=47, prune_level=1, use_cond_selectivity=1) at sql/sql_select.cc:7750

#10 0x0000000002bf4846 in best_extension_by_limited_search (join=0x7fffe7d52c70, remaining_tables=268419072, idx=14, record_count=6103515625, read_time=1626985377.5, search_depth=48, prune_level=1, use_cond_selectivity=1) at sql/sql_select.cc:7750

#11 0x0000000002bf4846 in best_extension_by_limited_search (join=0x7fffe7d52c70, remaining_tables=268427264, idx=13, record_count=1220703125, read_time=323899784, search_depth=49, prune_level=1, use_cond_selectivity=1) at sql/sql_select.cc:7750

#12 0x0000000002bf4846 in best_extension_by_limited_search (join=0x7fffe7d52c70, remaining_tables=268431360, idx=12, record_count=244140625, read_time=64409097.25, search_depth=50, prune_level=1, use_cond_selectivity=1) at sql/sql_select.cc:7750

#13 0x0000000002bf4846 in best_extension_by_limited_search (join=0x7fffe7d52c70, remaining_tables=268433408, idx=11, record_count=48828125, read_time=12824070.75, search_depth=51, prune_level=1, use_cond_selectivity=1) at sql/sql_select.cc:7750

#14 0x0000000002bf4846 in best_extension_by_limited_search (join=0x7fffe7d52c70, remaining_tables=268434432, idx=10, record_count=9765625, read_time=2552885, search_depth=52, prune_level=1, use_cond_selectivity=1) at sql/sql_select.cc:7750

#15 0x0000000002bf4846 in best_extension_by_limited_search (join=0x7fffe7d52c70, remaining_tables=268434944, idx=9, record_count=1953125, read_time=507653.5, search_depth=53, prune_level=1, use_cond_selectivity=1) at sql/sql_select.cc:7750

#16 0x0000000002bf4846 in best_extension_by_limited_search (join=0x7fffe7d52c70, remaining_tables=268435200, idx=8, record_count=390625, read_time=101110.25, search_depth=54, prune_level=1, use_cond_selectivity=1) at sql/sql_select.cc:7750

#17 0x0000000002bf4846 in best_extension_by_limited_search (join=0x7fffe7d52c70, remaining_tables=268435328, idx=7, record_count=78125, read_time=20166.5, search_depth=55, prune_level=1, use_cond_selectivity=1) at sql/sql_select.cc:7750

#18 0x0000000002bf4846 in best_extension_by_limited_search (join=0x7fffe7d52c70, remaining_tables=268435392, idx=6, record_count=15625, read_time=4049.5, search_depth=56, prune_level=1, use_cond_selectivity=1) at sql/sql_select.cc:7750

#19 0x0000000002bf4846 in best_extension_by_limited_search (join=0x7fffe7d52c70, remaining_tables=268435424, idx=5, record_count=3125, read_time=842.5, search_depth=57, prune_level=1, use_cond_selectivity=1) at sql/sql_select.cc:7750

#20 0x0000000002bf4846 in best_extension_by_limited_search (join=0x7fffe7d52c70, remaining_tables=268435440, idx=4, record_count=625, read_time=197, search_depth=58, prune_level=1, use_cond_selectivity=1) at sql/sql_select.cc:7750

#21 0x0000000002bf4846 in best_extension_by_limited_search (join=0x7fffe7d52c70, remaining_tables=268435448, idx=3, record_count=125, read_time=61.75, search_depth=59, prune_level=1, use_cond_selectivity=1) at sql/sql_select.cc:7750

#22 0x0000000002bf4846 in best_extension_by_limited_search (join=0x7fffe7d52c70, remaining_tables=268435452, idx=2, record_count=25, read_time=26.5, search_depth=60, prune_level=1, use_cond_selectivity=1) at sql/sql_select.cc:7750

#23 0x0000000002bf4846 in best_extension_by_limited_search (join=0x7fffe7d52c70, remaining_tables=268435454, idx=1, record_count=5, read_time=11.25, search_depth=61, prune_level=1, use_cond_selectivity=1) at sql/sql_select.cc:7750

#24 0x0000000002bf4846 in best_extension_by_limited_search (join=0x7fffe7d52c70, remaining_tables=268435455, idx=0, record_count=1, read_time=0, search_depth=62, prune_level=1, use_cond_selectivity=1) at sql/sql_select.cc:7750

#25 0x0000000002bd31a8 in greedy_search (join=0x7fffe7d52c70, remaining_tables=268435455, search_depth=62, prune_level=1, use_cond_selectivity=1) at sql/sql_select.cc:6926

#26 0x0000000002bd1c27 in choose_plan (join=0x7fffe7d52c70, join_tables=268435455) at sql/sql_select.cc:6503

#27 0x0000000002bba03c in make_join_statistics (join=0x7fffe7d52c70, tables_list=..., conds=0x7fffe8154a08, keyuse_array=0x7fffe7d52f78) at sql/sql_select.cc:4047

#28 0x0000000002bb461b in JOIN::optimize_inner (this=0x7fffe7d52c70) at sql/sql_select.cc:1367

#29 0x0000000002bb3504 in JOIN::optimize (this=0x7fffe7d52c70) at sql/sql_select.cc:1052

#30 0x0000000002bb09ec in mysql_select (thd=0x7ffff3a14090, rref_pointer_array=0x7ffff3a18318, tables=0x7fffefb6ee10, wild_num=0, fields=..., conds=0x0, og_num=0, order=0x0, group=0x0, having=0x0, proc_param=0x0, select_options=2147748612, result=0x7fffe7d525b0, unit=0x7ffff3a17968, select_lex=0x7ffff3a180a0) at sql/sql_select.cc:3318

#31 0x0000000002be4ec7 in mysql_explain_union (thd=0x7ffff3a14090, unit=0x7ffff3a17968, result=0x7fffe7d525b0) at sql/sql_select.cc:23897

#32 0x0000000002b69913 in execute_sqlcom_select (thd=0x7ffff3a14090, all_tables=0x7fffefb6ee10) at sql/sql_parse.cc:5442

#33 0x0000000002b60464 in mysql_execute_command (thd=0x7ffff3a14090) at sql/sql_parse.cc:2660

#34 0x0000000002b5e1ef in mysql_parse (thd=0x7ffff3a14090, rawbuf=0x7fffefb6e8a8 "EXPLAIN SELECT CAST(f1 AS SIGNED INTEGER) AS f1,\nCAST(f2 AS CHAR) AS f2 FROM test1.v27", length=86, parser_state=0x7ffff6e64158) at sql/sql_parse.cc:6696

#35 0x0000000002b5b373 in dispatch_command (command=COM_QUERY, thd=0x7ffff3a14090, packet=0x7ffff2f61091 "", packet_length=86) at sql/sql_parse.cc:1349

#36 0x0000000002b5d93a in do_command (thd=0x7ffff3a14090) at sql/sql_parse.cc:1034

#37 0x0000000002b1391e in do_handle_one_connection (thd_arg=0x7ffff3a14090) at sql/sql_connect.cc:1397

#38 0x0000000002b136e2 in handle_one_connection (arg=0x7ffff3a14090) at sql/sql_connect.cc:1311

#39 0x00007ffff728214e in start_thread () from /usr/grte/v3/lib64/libpthread.so.0

#40 0x00007ffff6ef869d in clone () from /usr/grte/v3/lib64/libc.so.6

#41 0x0000000000000000 in ?? ()

Attachments

- Sort By Name
- Sort By Date
- Ascending
- Descending
- Thumbnails
- List
- Download All

all-3.sql
95 kB
2014-10-21 23:50
mdev6888-data.sql
87 kB
2014-10-21 13:24

Activity

Ascending order - Click to sort in descending order

Jeremy Cole created issue - 2014-10-17 23:10

Elena Stepanova added a comment - 2014-10-17 23:27

Jeremy, thanks for the report.

It's probably join_cache_level to blame rather than mrr.

See also ~~MDEV-6830~~, MDEV-3946 – might be related (or not).

Elena Stepanova added a comment - 2014-10-17 23:27 Jeremy, thanks for the report. It's probably join_cache_level to blame rather than mrr. See also MDEV-6830 , MDEV-3946 – might be related (or not).

Elena Stepanova made changes - 2014-10-17 23:27

Field	Original Value	New Value
Fix Version/s		10.0 [ 16000 ]
Assignee		Sergei Petrunia [ psergey ]

Sergei Petrunia added a comment - 2014-10-21 13:24

Test dataset. It has HEAP tables so it must be re-loaded after every server restart.

Sergei Petrunia added a comment - 2014-10-21 13:24 Test dataset. It has HEAP tables so it must be re-loaded after every server restart.

Sergei Petrunia made changes - 2014-10-21 13:24

Attachment

mdev6888-data.sql [ 34905 ]

Sergei Petrunia added a comment - 2014-10-21 13:26

I was able to repeat as follows:

1. Start the server on a datadir from mysql-test/var/install.db
2. load the mdev6888-data.sql
3. run

EXPLAIN SELECT CAST(f1 AS SIGNED INTEGER) AS f1, CAST(f2 AS CHAR) AS f2 FROM test1.v27;

it will instantly produce some query plan

3. Run

EXPLAIN SELECT CAST(f1 AS SIGNED INTEGER) AS f1, CAST(f2 AS CHAR) AS f2 FROM test1.v27;

again.. Now, it will work forever.

Sergei Petrunia added a comment - 2014-10-21 13:26 I was able to repeat as follows: 1. Start the server on a datadir from mysql-test/var/install.db 2. load the mdev6888-data.sql 3. run EXPLAIN SELECT CAST(f1 AS SIGNED INTEGER) AS f1, CAST(f2 AS CHAR) AS f2 FROM test1.v27; it will instantly produce some query plan 3. Run EXPLAIN SELECT CAST(f1 AS SIGNED INTEGER) AS f1, CAST(f2 AS CHAR) AS f2 FROM test1.v27; again.. Now, it will work forever.

Sergei Petrunia added a comment - 2014-10-21 23:49

Modified the dataset so that all tables have different aliases.
Debugging...

The first execution (fast) proceeds as follows:
(the call with idx=27 is the first one with idx=27)

...

  best_access_path: idx=27, table=t1_for_v0, record_count=7.45058e+18

                                                              pos: records_read=5 read_time=1.054e+18

  best_access_path: idx=26, table=t1_for_v0, record_count=1.49012e+18

                                                              pos: records_read=5 read_time=2.01246e+17

  best_access_path: idx=25, table=tab1_v1, record_count=2.98023e+17

                                                              pos: records_read=5 read_time=3.88508e+16

  best_access_path: idx=25, table=t1_for_v0, record_count=2.98023e+17

                                                              pos: records_read=5 read_time=3.88508e+16

  best_access_path: idx=24, table=tab1_v2, record_count=5.96046e+16

                                                              pos: records_read=5 read_time=7.49515e+15

  best_access_path: idx=24, table=tab1_v1, record_count=5.96046e+16

                                                              pos: records_read=5 read_time=7.49515e+15

The second execution (very slow):

  best_access_path: idx=27, table=t1_for_v0, record_count=7.45058e+18

                                                              pos: records_read=5 read_time=1.054e+18

  best_access_path: idx=26, table=t1_for_v0, record_count=1.49012e+18

                                                              pos: records_read=5 read_time=2.01246e+17

## and now, the difference starts:

  best_access_path: idx=27, table=tab1_v1, record_count=7.45058e+18

                                                              pos: records_read=5 read_time=1.054e+18

  best_access_path: idx=25, table=tab1_v1, record_count=2.98023e+17

                                                              pos: records_read=5 read_time=3.88508e+16

  best_access_path: idx=26, table=tab1_v2, record_count=1.49012e+18

                                                              pos: records_read=5 read_time=2.03809e+17

  best_access_path: idx=27, table=t1_for_v0, record_count=7.45058e+18

                                                              pos: records_read=5 read_time=1.054e+18

  best_access_path: idx=26, table=t1_for_v0, record_count=1.49012e+18

                                                              pos: records_read=5 read_time=2.03809e+17

  best_access_path: idx=25, table=t1_for_v0, record_count=2.98023e+17

                                                              pos: records_read=5 read_time=3.88508e+16

  best_access_path: idx=26, table=tab1_v1, record_count=1.49012e+18

Sergei Petrunia added a comment - 2014-10-21 23:49 Modified the dataset so that all tables have different aliases. Debugging... The first execution (fast) proceeds as follows: (the call with idx=27 is the first one with idx=27) ... best_access_path: idx=27, table=t1_for_v0, record_count=7.45058e+18 pos: records_read=5 read_time=1.054e+18 best_access_path: idx=26, table=t1_for_v0, record_count=1.49012e+18 pos: records_read=5 read_time=2.01246e+17 best_access_path: idx=25, table=tab1_v1, record_count=2.98023e+17 pos: records_read=5 read_time=3.88508e+16 best_access_path: idx=25, table=t1_for_v0, record_count=2.98023e+17 pos: records_read=5 read_time=3.88508e+16 best_access_path: idx=24, table=tab1_v2, record_count=5.96046e+16 pos: records_read=5 read_time=7.49515e+15 best_access_path: idx=24, table=tab1_v1, record_count=5.96046e+16 pos: records_read=5 read_time=7.49515e+15 The second execution (very slow): best_access_path: idx=27, table=t1_for_v0, record_count=7.45058e+18 pos: records_read=5 read_time=1.054e+18 best_access_path: idx=26, table=t1_for_v0, record_count=1.49012e+18 pos: records_read=5 read_time=2.01246e+17 ## and now, the difference starts: best_access_path: idx=27, table=tab1_v1, record_count=7.45058e+18 pos: records_read=5 read_time=1.054e+18 best_access_path: idx=25, table=tab1_v1, record_count=2.98023e+17 pos: records_read=5 read_time=3.88508e+16 best_access_path: idx=26, table=tab1_v2, record_count=1.49012e+18 pos: records_read=5 read_time=2.03809e+17 best_access_path: idx=27, table=t1_for_v0, record_count=7.45058e+18 pos: records_read=5 read_time=1.054e+18 best_access_path: idx=26, table=t1_for_v0, record_count=1.49012e+18 pos: records_read=5 read_time=2.03809e+17 best_access_path: idx=25, table=t1_for_v0, record_count=2.98023e+17 pos: records_read=5 read_time=3.88508e+16 best_access_path: idx=26, table=tab1_v1, record_count=1.49012e+18

Sergei Petrunia added a comment - 2014-10-21 23:50

For some reason, pruning on the second execution doesn't work in the same way as in the first execution.

Sergei Petrunia added a comment - 2014-10-21 23:50 For some reason, pruning on the second execution doesn't work in the same way as in the first execution.

Sergei Petrunia added a comment - 2014-10-21 23:50

all-3.sql - modified dataset

Sergei Petrunia added a comment - 2014-10-21 23:50 all-3.sql - modified dataset

Sergei Petrunia made changes - 2014-10-21 23:50

Attachment

all-3.sql [ 34907 ]

Sergei Petrunia added a comment - 2014-10-22 00:03

The execution starts to differ here in best_extension_by_limited_search:

          if (best_record_count >= current_record_count &&

              best_read_time >= current_read_time &&

              /* TODO: What is the reasoning behind this condition? */

              (!(s->key_dependent & allowed_tables & remaining_tables) ||

               join->positions[idx].records_read < 2.0))

            best_record_count= current_record_count;

            best_read_time=    current_read_time;

Fast execution:

(gdb) p idx

  $58 = 26

(gdb) p s->table->alias.Ptr

  $59 = 0x7fffa477c340 "t1_for_v0"

(gdb) p/x s->key_dependent

  $60 = 0x0

while in the slow execution we have:

(gdb) p/x s->key_dependent

  $186 = 0x4000000

Sergei Petrunia added a comment - 2014-10-22 00:03 The execution starts to differ here in best_extension_by_limited_search: if (best_record_count >= current_record_count && best_read_time >= current_read_time && /* TODO: What is the reasoning behind this condition? */ (!(s->key_dependent & allowed_tables & remaining_tables) || join->positions[idx].records_read < 2.0)) { best_record_count= current_record_count; best_read_time= current_read_time; Fast execution: (gdb) p idx $58 = 26 (gdb) p s->table->alias.Ptr $59 = 0x7fffa477c340 "t1_for_v0" (gdb) p/x s->key_dependent $60 = 0x0 while in the slow execution we have: (gdb) p/x s->key_dependent $186 = 0x4000000

Sergei Petrunia added a comment - 2014-10-22 00:30

on the first execution, join->join_tab[0..27].key_dependent==0.
on the second, they have various non-zero values:

(gdb) p/x join->join_tab[0].key_dependent

  $189 = 0x0

(gdb) p/x join->join_tab[1].key_dependent

  $190 = 0x5

(gdb) p/x join->join_tab[2].key_dependent

  $191 = 0xa

(gdb) p/x join->join_tab[3].key_dependent

  $192 = 0x14

(gdb) p/x join->join_tab[4].key_dependent

  $193 = 0x28

(gdb) p/x join->join_tab[5].key_dependent

  $194 = 0x50

(gdb) p/x join->join_tab[6].key_dependent

  $195 = 0xa0

(gdb) p/x join->join_tab[7].key_dependent

  $196 = 0x140

(gdb) p/x join->join_tab[8].key_dependent

  $197 = 0x280

Sergei Petrunia added a comment - 2014-10-22 00:30 on the first execution, join->join_tab [0..27] .key_dependent==0. on the second, they have various non-zero values: (gdb) p/x join->join_tab[0].key_dependent $189 = 0x0 (gdb) p/x join->join_tab[1].key_dependent $190 = 0x5 (gdb) p/x join->join_tab[2].key_dependent $191 = 0xa (gdb) p/x join->join_tab[3].key_dependent $192 = 0x14 (gdb) p/x join->join_tab[4].key_dependent $193 = 0x28 (gdb) p/x join->join_tab[5].key_dependent $194 = 0x50 (gdb) p/x join->join_tab[6].key_dependent $195 = 0xa0 (gdb) p/x join->join_tab[7].key_dependent $196 = 0x140 (gdb) p/x join->join_tab[8].key_dependent $197 = 0x280

Sergei Petrunia added a comment - 2014-10-22 00:31

looking where key_dependent comes from

sql_select.cc|3584| s->key_dependent= s->dependent;

sql_select.cc|4399| stat[0].key_dependent|=used_tables;

s->dependent=0 for all join_tabs I've checked in both queries (this is correct, there are no outer joins).

Sergei Petrunia added a comment - 2014-10-22 00:31 looking where key_dependent comes from sql_select.cc|3584| s->key_dependent= s->dependent; sql_select.cc|4399| stat[0].key_dependent|=used_tables; s->dependent=0 for all join_tabs I've checked in both queries (this is correct, there are no outer joins).

Sergei Petrunia added a comment - 2014-10-22 00:33

As for key_dependent, the second execution has:

(gdb) p stat_vector[1].table->alias

  $289 = {Ptr = 0x7ffe98b2f0e0 "tab1_v26", str_length = 8, Alloced_length = 16, extra_alloc = 0, alloced = true, thread_specific = false, str_charset = 0x17d8900}

(gdb) p stat_vector[1].table->field[0]->field_name

  $294 = 0x7ffe98b2f421 "f1"

(gdb) p/x stat_vector[1].table->field[0]->flags

  $298 = 0x8004000

while the first one has:

(gdb) set $i=0

(gdb) p stat_vector[$i++].table->alias.Ptr

  $121 = 0x7fffa435caa0 "tab1_v27"

(gdb) p stat_vector[$i++].table->alias.Ptr

  $122 = 0x7fffa4b2df80 "tab1_v26"

(gdb)

(gdb) p stat_vector[1].table->field[0].field_name

  $123 = 0x7fffa4b2e2c1 "f1"

(gdb) p stat_vector[1].table->field[0].flags

  $124 = 134217728

(gdb) p/x stat_vector[1].table->field[0].flags

  $125 = 0x8000000

Apparently tab1_v26.f1 has PART_KEY_FLAG on the second execution, but not on the first one!

Sergei Petrunia added a comment - 2014-10-22 00:33 As for key_dependent, the second execution has: (gdb) p stat_vector[1].table->alias $289 = {Ptr = 0x7ffe98b2f0e0 "tab1_v26", str_length = 8, Alloced_length = 16, extra_alloc = 0, alloced = true, thread_specific = false, str_charset = 0x17d8900} (gdb) p stat_vector[1].table->field[0]->field_name $294 = 0x7ffe98b2f421 "f1" (gdb) p/x stat_vector[1].table->field[0]->flags $298 = 0x8004000 while the first one has: (gdb) set $i=0 (gdb) p stat_vector[$i++].table->alias.Ptr $121 = 0x7fffa435caa0 "tab1_v27" (gdb) p stat_vector[$i++].table->alias.Ptr $122 = 0x7fffa4b2df80 "tab1_v26" (gdb) (gdb) p stat_vector[1].table->field[0].field_name $123 = 0x7fffa4b2e2c1 "f1" (gdb) p stat_vector[1].table->field[0].flags $124 = 134217728 (gdb) p/x stat_vector[1].table->field[0].flags $125 = 0x8000000 Apparently tab1_v26.f1 has PART_KEY_FLAG on the second execution, but not on the first one!

Sergei Petrunia added a comment - 2014-10-22 00:35

And the change is made here:

  Hardware watchpoint 7: *$a

  Old value = 134217728

  New value = 134234112

  TABLE::create_key_part_by_field (this=0x7fffa4b4e920, keyinfo=0x7fffa4e281c0, key_part_info=0x7fffa4e28268, field=0x7fffa4b4f8c0, fieldnr=1) at /home/psergey/dev2/10.0-cp1/sql/table.cc:6075

(gdb) p *$a

  $126 = 134234112

(gdb) p/x *$a

  $127 = 0x8004000

(gdb) up

  #1  0x00000000006ae265 in create_hj_key_for_table (join=0x7fffa4da8260, join_tab=0x7fffa4e2cbd0, org_keyuse=0x7fffa4e39fa0, used_tables=4611686018427387907) at /home/psergey/dev2/10.0-cp1/sql/sql_select.cc:8627

(gdb) down

  #0  TABLE::create_key_part_by_field (this=0x7fffa4b4e920, keyinfo=0x7fffa4e281c0, key_part_info=0x7fffa4e28268, field=0x7fffa4b4f8c0, fieldnr=1) at /home/psergey/dev2/10.0-cp1/sql/table.cc:6075

(gdb) wher

  #0  TABLE::create_key_part_by_field (this=0x7fffa4b4e920, keyinfo=0x7fffa4e281c0, key_part_info=0x7fffa4e28268, field=0x7fffa4b4f8c0, fieldnr=1) at /home/psergey/dev2/10.0-cp1/sql/table.cc:6075

  #1  0x00000000006ae265 in create_hj_key_for_table (join=0x7fffa4da8260, join_tab=0x7fffa4e2cbd0, org_keyuse=0x7fffa4e39fa0, used_tables=4611686018427387907) at /home/psergey/dev2/10.0-cp1/sql/sql_select.cc:8627

  #2  0x00000000006ae45b in create_ref_for_key (join=0x7fffa4da8260, j=0x7fffa4e2cbd0, org_keyuse=0x7fffa4e39fa0, allow_full_scan=true, used_tables=4611686018427387907) at /home/psergey/dev2/10.0-cp1/sql/sql_select.cc:8691

  #3  0x00000000006adc0e in get_best_combination (join=0x7fffa4da8260) at /home/psergey/dev2/10.0-cp1/sql/sql_select.cc:8482

  #4  0x00000000006a3960 in make_join_statistics (join=0x7fffa4da8260, tables_list=..., conds=0x7fffa4e1cfe8, keyuse_array=0x7fffa4da8568) at /home/psergey/dev2/10.0-cp1/sql/sql_select.cc:4055

  #5  0x0000000000699ec3 in JOIN::optimize_inner (this=0x7fffa4da8260) at /home/psergey/dev2/10.0-cp1/sql/sql_select.cc:1339

  #6  0x0000000000698e04 in JOIN::optimize (this=0x7fffa4da8260) at /home/psergey/dev2/10.0-cp1/sql/sql_select.cc:1024

  #7  0x00000000006a0c6d in mysql_select (thd=0x30464a0, rref_pointer_array=0x304ab10, tables=0x7fffa4005700, wild_num=0, fields=..., conds=0x0, og_num=0, order=0x0, group=0x0, having=0x0, proc_param=0x0, select_options=2147748612, result=0x7fffa4da7ba0, unit=0x304a1b0, select_lex=0x304a898) at /home/psergey/dev2/10.0-cp1/sql/sql_select.cc:3294

  #8  0x00000000006d37a6 in mysql_explain_union (thd=0x30464a0, unit=0x304a1b0, result=0x7fffa4da7ba0) at /home/psergey/dev2/10.0-cp1/sql/sql_select.cc:23879

  #9  0x000000000066a745 in execute_sqlcom_select (thd=0x30464a0, all_tables=0x7fffa4005700) at /home/psergey/dev2/10.0-cp1/sql/sql_parse.cc:5223

  #10 0x00000000006628fe in mysql_execute_command (thd=0x30464a0) at /home/psergey/dev2/10.0-cp1/sql/sql_parse.cc:2544

  #11 0x000000000066d1e3 in mysql_parse (thd=0x30464a0, rawbuf=0x7fffa4005198 "EXPLAIN SELECT CAST(f1 AS SIGNED INTEGER) AS f1, CAST(f2 AS CHAR) AS f2 FROM test1.v27", length=86, parser_state=0x7ffff7f83540) at /home/psergey/dev2/10.0-cp1/sql/sql_parse.cc:6406

  #12 0x000000000065fab6 in dispatch_command (command=COM_QUERY, thd=0x30464a0, packet=0x7fffa4040751 "", packet_length=86) at /home/psergey/dev2/10.0-cp1/sql/sql_parse.cc:1299

  #13 0x000000000065ee07 in do_command (thd=0x30464a0) at /home/psergey/dev2/10.0-cp1/sql/sql_parse.cc:996

  #14 0x0000000000783ba7 in do_handle_one_connection (thd_arg=0x30464a0) at /home/psergey/dev2/10.0-cp1/sql/sql_connect.cc:1379

  #15 0x00000000007838fa in handle_one_connection (arg=0x30464a0) at /home/psergey/dev2/10.0-cp1/sql/sql_connect.cc:1293

  #16 0x00007ffff7166e9a in start_thread (arg=0x7ffff7f84700) at pthread_create.c:308

  #17 0x00007ffff66813fd in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:112

  #18 0x0000000000000000 in ?? ()

Sergei Petrunia added a comment - 2014-10-22 00:35 And the change is made here: Hardware watchpoint 7: *$a Old value = 134217728 New value = 134234112 TABLE::create_key_part_by_field (this=0x7fffa4b4e920, keyinfo=0x7fffa4e281c0, key_part_info=0x7fffa4e28268, field=0x7fffa4b4f8c0, fieldnr=1) at /home/psergey/dev2/10.0-cp1/sql/table.cc:6075 (gdb) p *$a $126 = 134234112 (gdb) p/x *$a $127 = 0x8004000 (gdb) up #1 0x00000000006ae265 in create_hj_key_for_table (join=0x7fffa4da8260, join_tab=0x7fffa4e2cbd0, org_keyuse=0x7fffa4e39fa0, used_tables=4611686018427387907) at /home/psergey/dev2/10.0-cp1/sql/sql_select.cc:8627 (gdb) down #0 TABLE::create_key_part_by_field (this=0x7fffa4b4e920, keyinfo=0x7fffa4e281c0, key_part_info=0x7fffa4e28268, field=0x7fffa4b4f8c0, fieldnr=1) at /home/psergey/dev2/10.0-cp1/sql/table.cc:6075 (gdb) wher #0 TABLE::create_key_part_by_field (this=0x7fffa4b4e920, keyinfo=0x7fffa4e281c0, key_part_info=0x7fffa4e28268, field=0x7fffa4b4f8c0, fieldnr=1) at /home/psergey/dev2/10.0-cp1/sql/table.cc:6075 #1 0x00000000006ae265 in create_hj_key_for_table (join=0x7fffa4da8260, join_tab=0x7fffa4e2cbd0, org_keyuse=0x7fffa4e39fa0, used_tables=4611686018427387907) at /home/psergey/dev2/10.0-cp1/sql/sql_select.cc:8627 #2 0x00000000006ae45b in create_ref_for_key (join=0x7fffa4da8260, j=0x7fffa4e2cbd0, org_keyuse=0x7fffa4e39fa0, allow_full_scan=true, used_tables=4611686018427387907) at /home/psergey/dev2/10.0-cp1/sql/sql_select.cc:8691 #3 0x00000000006adc0e in get_best_combination (join=0x7fffa4da8260) at /home/psergey/dev2/10.0-cp1/sql/sql_select.cc:8482 #4 0x00000000006a3960 in make_join_statistics (join=0x7fffa4da8260, tables_list=..., conds=0x7fffa4e1cfe8, keyuse_array=0x7fffa4da8568) at /home/psergey/dev2/10.0-cp1/sql/sql_select.cc:4055 #5 0x0000000000699ec3 in JOIN::optimize_inner (this=0x7fffa4da8260) at /home/psergey/dev2/10.0-cp1/sql/sql_select.cc:1339 #6 0x0000000000698e04 in JOIN::optimize (this=0x7fffa4da8260) at /home/psergey/dev2/10.0-cp1/sql/sql_select.cc:1024 #7 0x00000000006a0c6d in mysql_select (thd=0x30464a0, rref_pointer_array=0x304ab10, tables=0x7fffa4005700, wild_num=0, fields=..., conds=0x0, og_num=0, order=0x0, group=0x0, having=0x0, proc_param=0x0, select_options=2147748612, result=0x7fffa4da7ba0, unit=0x304a1b0, select_lex=0x304a898) at /home/psergey/dev2/10.0-cp1/sql/sql_select.cc:3294 #8 0x00000000006d37a6 in mysql_explain_union (thd=0x30464a0, unit=0x304a1b0, result=0x7fffa4da7ba0) at /home/psergey/dev2/10.0-cp1/sql/sql_select.cc:23879 #9 0x000000000066a745 in execute_sqlcom_select (thd=0x30464a0, all_tables=0x7fffa4005700) at /home/psergey/dev2/10.0-cp1/sql/sql_parse.cc:5223 #10 0x00000000006628fe in mysql_execute_command (thd=0x30464a0) at /home/psergey/dev2/10.0-cp1/sql/sql_parse.cc:2544 #11 0x000000000066d1e3 in mysql_parse (thd=0x30464a0, rawbuf=0x7fffa4005198 "EXPLAIN SELECT CAST(f1 AS SIGNED INTEGER) AS f1, CAST(f2 AS CHAR) AS f2 FROM test1.v27", length=86, parser_state=0x7ffff7f83540) at /home/psergey/dev2/10.0-cp1/sql/sql_parse.cc:6406 #12 0x000000000065fab6 in dispatch_command (command=COM_QUERY, thd=0x30464a0, packet=0x7fffa4040751 "", packet_length=86) at /home/psergey/dev2/10.0-cp1/sql/sql_parse.cc:1299 #13 0x000000000065ee07 in do_command (thd=0x30464a0) at /home/psergey/dev2/10.0-cp1/sql/sql_parse.cc:996 #14 0x0000000000783ba7 in do_handle_one_connection (thd_arg=0x30464a0) at /home/psergey/dev2/10.0-cp1/sql/sql_connect.cc:1379 #15 0x00000000007838fa in handle_one_connection (arg=0x30464a0) at /home/psergey/dev2/10.0-cp1/sql/sql_connect.cc:1293 #16 0x00007ffff7166e9a in start_thread (arg=0x7ffff7f84700) at pthread_create.c:308 #17 0x00007ffff66813fd in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:112 #18 0x0000000000000000 in ?? ()

Sergei Petrunia added a comment - 2014-10-22 00:36 - edited

This is hash join code. It creates a "fake" index, and modifies table->field[i]->flags. This is a huge gotcha.

The offending code:

void TABLE::create_key_part_by_field(KEY *keyinfo,

                                     KEY_PART_INFO *key_part_info,

                                     Field *field, uint fieldnr)

  field->flags|= PART_KEY_FLAG;

...

Sergei Petrunia added a comment - 2014-10-22 00:36 - edited This is hash join code. It creates a "fake" index, and modifies table->field [i] ->flags. This is a huge gotcha. The offending code: void TABLE::create_key_part_by_field(KEY *keyinfo, KEY_PART_INFO *key_part_info, Field *field, uint fieldnr) { field->flags|= PART_KEY_FLAG; ...

Sergei Petrunia made changes - 2014-10-22 00:48

Labels

hash-join optimizer

Sergei Petrunia added a comment - 2014-10-22 17:33

Discussed with igor.

Following his advice, commented out the problematic line:

  field->flags|= PART_KEY_FLAG;

and then ran "mysql-test-run --suite=main" (keeping Jeremy's patch applied).

The test run produced lots of failures, because Jeremy's patch enables MRR and Hash Join. I've gone through failures and found

changed EXPLAINs (lots)
changed query results for non-deterministic queries (mostly in count_distinct.test)

lots of rounding changes like this:

-KENYA  1997    57578.36259999999

-KENYA  1996    59195.90210000001

+KENYA  1997    57578.3626

+KENYA  1996    59195.9021

these look weird, but they don't look like an indication that hash join is unable to function without the "field->flags|= PART_KEY_FLAG" line.

Sergei Petrunia added a comment - 2014-10-22 17:33 Discussed with igor . Following his advice, commented out the problematic line: field->flags|= PART_KEY_FLAG; and then ran "mysql-test-run --suite=main" (keeping Jeremy's patch applied). The test run produced lots of failures, because Jeremy's patch enables MRR and Hash Join. I've gone through failures and found changed EXPLAINs (lots) changed query results for non-deterministic queries (mostly in count_distinct.test) lots of rounding changes like this: -KENYA 1997 57578.36259999999 -KENYA 1996 59195.90210000001 +KENYA 1997 57578.3626 +KENYA 1996 59195.9021 these look weird, but they don't look like an indication that hash join is unable to function without the "field->flags|= PART_KEY_FLAG" line.

Sergei Petrunia added a comment - 2014-10-22 18:52 - edited

<igor__> spetrunia, : you can't just comment out this line, you have to do it only when creating index for hash join.

* spetrunia looks if there are any other users of create_key_part_by_field(

<spetrunia> - create_hj_key_for_table

<spetrunia> - TABLE::add_tmp_key

<spetrunia>    - which is called from several places

<spetrunia> ok

Sergei Petrunia added a comment - 2014-10-22 18:52 - edited <igor__> spetrunia, : you can't just comment out this line, you have to do it only when creating index for hash join. * spetrunia looks if there are any other users of create_key_part_by_field( <spetrunia> - create_hj_key_for_table <spetrunia> - TABLE::add_tmp_key <spetrunia> - which is called from several places <spetrunia> ok

Sergei Petrunia made changes - 2014-10-24 15:19

Summary

Inifinite recursion in best_extension_by_limited_search with mrr enabled

Query spends a long time in best_extension_by_limited_search with mrr enabled

Sergei Petrunia added a comment - 2014-10-24 16:55

Committed a patch: http://lists.askmonty.org/pipermail/commits/2014-October/006852.html

Sergei Petrunia added a comment - 2014-10-24 16:55 Committed a patch: http://lists.askmonty.org/pipermail/commits/2014-October/006852.html

Sergei Petrunia added a comment - 2014-10-29 14:24

Pushed the fix.

Sergei Petrunia added a comment - 2014-10-29 14:24 Pushed the fix.

Sergei Petrunia made changes - 2014-10-29 14:24

Fix Version/s		10.0.15 [ 17300 ]
Fix Version/s	10.0 [ 16000 ]
Resolution		Fixed [ 1 ]
Status	Open [ 1 ]	Closed [ 6 ]

Rasmus Johansson (Inactive) made changes - 2015-05-18 17:51

Workflow

MariaDB v2 [ 55828 ]

MariaDB v3 [ 64946 ]

Sergei Golubchik made changes - 2021-12-06 21:40

Workflow

MariaDB v3 [ 64946 ]

MariaDB v4 [ 148318 ]

People

Assignee:: Sergei Petrunia

Reporter:: Jeremy Cole

Votes:: 0 Vote for this issue

Watchers:: 5 Start watching this issue

Dates

Created:: 2014-10-17 23:10

Updated:: 2014-10-29 14:24

Resolved:: 2014-10-29 14:24

Git Integration

Error rendering 'com.xiplink.jira.git.jira_git_plugin:git-issue-webpanel'. Please contact your Jira administrators.

MariaDB Server

Details

Description

Attachments

Attachments

Activity

People

Dates

Git Integration