[MDEV-6439] Server crashes in Explain_union::print_explain with explain in slow log, tis620 charset Created: 2014-07-12  Updated: 2020-08-26  Resolved: 2018-08-15

Status: Closed
Project: MariaDB Server
Component/s: Optimizer
Affects Version/s: 10.0.12, 10.1.0
Fix Version/s: 10.0.37, 10.1.36, 10.2.18

Type: Bug Priority: Major
Reporter: Elena Stepanova Assignee: Sergei Petrunia
Resolution: Fixed Votes: 2
Labels: crash

Issue Links:
Relates
relates to MDEV-16829 Odd code in Item_subselect::is_expensive Closed

 Description    

#2  0x0000000000864189 in handle_fatal_signal (sig=11) at 10.0/sql/signal_handler.cc:262
 
#3  <signal handler called>
 
#4  0x00000000007c4f24 in Explain_union::print_explain (this=0x7fee28b77b68, query=0x7fee28b77aa8, output=0x7fee325b4d10, explain_flags=0 '\000') at 10.0/sql/sql_explain.cc:228
 
#5  0x00000000007c53cc in Explain_node::print_explain_for_children (this=0x7fee28b78ff0, query=0x7fee28b77aa8, output=0x7fee325b4d10, explain_flags=0 '\000') at 10.0/sql/sql_explain.cc:327
 
#6  0x00000000007c57a7 in Explain_select::print_explain (this=0x7fee28b78ff0, query=0x7fee28b77aa8, output=0x7fee325b4d10, explain_flags=0 '\000') at 10.0/sql/sql_explain.cc:390
 
#7  0x00000000007c4c9c in Explain_query::print_explain (this=0x7fee28b77aa8, output=0x7fee325b4d10, explain_flags=0 '\000') at 10.0/sql/sql_explain.cc:175
 
#8  0x00000000007c4d63 in Explain_query::print_explain_str (this=0x7fee28b77aa8, thd=0x7fee2b32f070, out_str=0x7fee325b4e70) at 10.0/sql/sql_explain.cc:197
 
#9  0x00000000007c4cd0 in print_explain_query (lex=0x7fee2b332cc0, thd=0x7fee2b32f070, str=0x7fee325b4e70) at 10.0/sql/sql_explain.cc:182
 
#10 0x000000000093552b in MYSQL_QUERY_LOG::write (this=0x7fee2c3d6150, thd=0x7fee2b32f070, current_time=1405123297, user_host=0x7fee325b52a0 "root[root] @ localhost []", user_host_len=25, query_utime=1563, lock_utime=733, is_command=false, sql_text=0x7fee28819088 "SELECT * FROM t1 WHERE a >= ANY ( SELECT 'foo' UNION SELECT 'bar' )", sql_text_len=67) at 10.0/sql/log.cc:2926
 
#11 0x000000000093088b in Log_to_file_event_handler::log_slow (this=0x7fee2c3d5c00, thd=0x7fee2b32f070, current_time=..., user_host=0x7fee325b52a0 "root[root] @ localhost []", user_host_len=25, query_utime=1563, lock_utime=733, is_command=false, sql_text=0x7fee28819088 "SELECT * FROM t1 WHERE a >= ANY ( SELECT 'foo' UNION SELECT 'bar' )", sql_text_len=67) at 10.0/sql/log.cc:1018
 
#12 0x000000000093129e in LOGGER::slow_log_print (this=0x18a1600, thd=0x7fee2b32f070, query=0x7fee28819088 "SELECT * FROM t1 WHERE a >= ANY ( SELECT 'foo' UNION SELECT 'bar' )", query_length=67, current_utime=52081142100) at 10.0/sql/log.cc:1309
 
#13 0x000000000093d254 in slow_log_print (thd=0x7fee2b32f070, query=0x7fee28819088 "SELECT * FROM t1 WHERE a >= ANY ( SELECT 'foo' UNION SELECT 'bar' )", query_length=67, current_utime=52081142100) at 10.0/sql/log.cc:6020
 
#14 0x000000000067708c in log_slow_statement (thd=0x7fee2b32f070) at 10.0/sql/sql_parse.cc:1823
 
#15 0x0000000000676d62 in dispatch_command (command=COM_QUERY, thd=0x7fee2b32f070, packet=0x7fee2c3f6071 "", packet_length=67) at 10.0/sql/sql_parse.cc:1743
 
#16 0x0000000000674be2 in do_command (thd=0x7fee2b32f070) at 10.0/sql/sql_parse.cc:1006
 
#17 0x0000000000790ab5 in do_handle_one_connection (thd_arg=0x7fee2b32f070) at 10.0/sql/sql_connect.cc:1379
 
#18 0x0000000000790808 in handle_one_connection (arg=0x7fee2b32f070) at 10.0/sql/sql_connect.cc:1293
 
#19 0x0000000000cc22f6 in pfs_spawn_thread (arg=0x7fee2a6a0970) at 10.0/storage/perfschema/pfs.cc:1860
 
#20 0x00007fee321a0b50 in start_thread (arg=<optimized out>) at pthread_create.c:304
 
#21 0x00007fee30698a7d in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:112

Stack trace from:

revision-id: knielsen@knielsen-hq.org-20140711100647-nf3rdaf5ep26pgty
 
revno: 4290
 
branch-nick: 10.0

Test case:

SET NAMES tis620;
 
SET GLOBAL slow_query_log = 1;
 
SET long_query_time = 0.000001;
 
SET log_slow_verbosity = 'explain';
 
 
 
CREATE TABLE t1 (a VARCHAR(3)) ENGINE=MyISAM;
 
SELECT * FROM t1 WHERE a >= ANY ( SELECT 'foo' UNION SELECT 'bar' );



 Comments   
Comment by Sergei Petrunia [ 2014-08-08 ]

Debugging, I can see this:

  #0  JOIN::optimize_inner (this=0x7fffc8ce8850) at /home/psergey/dev2/10.0/sql/sql_select.cc:1071
 
  #1  0x0000000000693696 in JOIN::optimize (this=0x7fffc8ce8850) at /home/psergey/dev2/10.0/sql/sql_select.cc:1023
 
  #2  0x000000000072776e in st_select_lex_unit::optimize (this=0x7fffc8c47d40) at /home/psergey/dev2/10.0/sql/sql_union.cc:611
 
  #3  0x0000000000727973 in st_select_lex_unit::exec (this=0x7fffc8c47d40) at /home/psergey/dev2/10.0/sql/sql_union.cc:644
 
  #4  0x00000000008fd3ab in subselect_union_engine::exec (this=0x7fffc8c48e48) at /home/psergey/dev2/10.0/sql/item_subselect.cc:3711
 
  #5  0x00000000008f4259 in Item_subselect::exec (this=0x7fffc8cd65c0) at /home/psergey/dev2/10.0/sql/item_subselect.cc:667
 
  #6  0x00000000008f5af0 in Item_singlerow_subselect::val_str (this=0x7fffc8cd65c0, str=0x7ffff7f36990) at /home/psergey/dev2/10.0/sql/item_subselect.cc:1264
 
  #7  0x0000000000885c11 in Item_func_conv_charset::Item_func_conv_charset (this=0x7fffc8cd69b8, a=0x7fffc8cd65c0, cs=0x188b200, cache_if_const=true) at /home/psergey/dev2/10.0/sql/item_strfunc.h:932
 
  #8  0x0000000000869fb7 in Item::safe_charset_converter (this=0x7fffc8cd65c0, tocs=0x188b200) at /home/psergey/dev2/10.0/sql/item.cc:1169
 
  #9  0x000000000086cf1f in agg_item_set_converter (coll=..., fname=0x10e887d "<=", args=0x7fffc8cd67b0, nargs=2, flags=7, item_sep=1) at /home/psergey/dev2/10.0/sql/item.cc:2231
 
  #10 0x000000000086d164 in agg_item_charsets (coll=..., fname=0x10e887d "<=", args=0x7fffc8cd67b0, nargs=2, flags=7, item_sep=1) at /home/psergey/dev2/10.0/sql/item.cc:2312
 
  #11 0x000000000089cf3c in agg_item_charsets_for_comparison (c=..., name=0x10e887d "<=", items=0x7fffc8cd67b0, nitems=2, item_sep=1) at /home/psergey/dev2/10.0/sql/item.h:1949
 
  #12 0x000000000089d0d6 in Item_func::agg_arg_charsets_for_comparison (this=0x7fffc8cd6720, c=..., items=0x7fffc8cd67b0, nitems=2, item_sep=1) at /home/psergey/dev2/10.0/sql/item_func.h:225
 
  #13 0x000000000088a702 in Item_bool_func2::fix_length_and_dec (this=0x7fffc8cd6720) at /home/psergey/dev2/10.0/sql/item_cmpfunc.cc:554
 
  #14 0x00000000008b78aa in Item_func::fix_fields (this=0x7fffc8cd6720, thd=0x7fffd1ec2070, ref=0x7ffff7f36e28) at /home/psergey/dev2/10.0/sql/item_func.cc:229
 
  #15 0x00000000008f76e7 in Item_allany_subselect::transform_into_max_min (this=0x7fffc8c48c88, join=0x7fffc8ce8850) at /home/psergey/dev2/10.0/sql/item_subselect.cc:1933
 
  #16 0x00000000007c6c1a in JOIN::transform_max_min_subquery (this=0x7fffc8ce8850) at /home/psergey/dev2/10.0/sql/opt_subselect.cc:891
 
  #17 0x0000000000693a96 in JOIN::optimize_inner (this=0x7fffc8ce8850) at /home/psergey/dev2/10.0/sql/sql_select.cc:1113
 
  #18 0x0000000000693696 in JOIN::optimize (this=0x7fffc8ce8850) at /home/psergey/dev2/10.0/sql/sql_select.cc:1023
 
  #19 0x0000000000651f93 in st_select_lex::optimize_unflattened_subqueries (this=0x7fffd1ec6468, const_only=false) at /home/psergey/dev2/10.0/sql/sql_lex.cc:3489
 
  #20 0x00000000007cff68 in JOIN::optimize_unflattened_subqueries (this=0x7fffc8ce8088) at /home/psergey/dev2/10.0/sql/opt_subselect.cc:4952
 
  #21 0x000000000069680d in JOIN::optimize_inner (this=0x7fffc8ce8088) at /home/psergey/dev2/10.0/sql/sql_select.cc:1916
 
  #22 0x0000000000693696 in JOIN::optimize (this=0x7fffc8ce8088) at /home/psergey/dev2/10.0/sql/sql_select.cc:1023
 
  #23 0x000000000069b517 in mysql_select (thd=0x7fffd1ec2070, rref_pointer_array=0x7fffd1ec66e0, tables=0x7fffc8c472d0, wild_num=1, fields=..., conds=0x7fffc8c48e80, og_num=0, order=0x0, group=0x0, having=0x0, proc_param=0x0, select_options=2147748608, result=0x7fffc8c48ff0, unit=0x7fffd1ec5d80, select_lex=0x7fffd1ec6468) at /home/psergey/dev2/10.0/sql/sql_select.cc:3293
 
  #24 0x00000000006918a0 in handle_select (thd=0x7fffd1ec2070, lex=0x7fffd1ec5cb8, result=0x7fffc8c48ff0, setup_tables_done_option=0) at /home/psergey/dev2/10.0/sql/sql_select.cc:372
 
  #25 0x0000000000665204 in execute_sqlcom_select (thd=0x7fffd1ec2070, all_tables=0x7fffc8c472d0) at /home/psergey/dev2/10.0/sql/sql_parse.cc:5265
 
  #26 0x000000000065d238 in mysql_execute_command (thd=0x7fffd1ec2070) at /home/psergey/dev2/10.0/sql/sql_parse.cc:2552
 
  #27 0x0000000000667a75 in mysql_parse (thd=0x7fffd1ec2070, rawbuf=0x7fffc8c47088 "SELECT * FROM t1 WHERE a >= ANY ( SELECT 'foo' UNION SELECT 'bar' )", length=67, parser_state=0x7ffff7f384b0) at /home/psergey/dev2/10.0/sql/sql_parse.cc:6411

JOIN::optimize() is called for " select 'foo'" (select_number=2). Then, it calls Item_allany_subselect::transform_into_max_min, which calls agg_item_set_converter... which eventually sees the item as inexpensive and calls Item_singlerow_subselect::val_str, which tries to execute the UNION. That is, JOIN::optimize() indirectly calls itself for the same object.

Comment by Sergei Petrunia [ 2014-08-08 ]

The inner JOIN::optimize() call doesn't save the query plan. this branch

  if (was_optimized != optimized && !res && have_query_plan != QEP_DELETED)

is not taken, because was_optimized != optimized.

Then, the UNION is executed. It calls JOIN::exec() which calls JOIN::join_free()
which computes

  bool full= !(select_lex->uncacheable) &&  !(thd->lex->describe);

to be true, calls JOIN::cleanup(full=true) which deletes the query plan and
sets have_query_plan= QEP_DELETED. This will prevent the outer-most
JOIN::optimize from saving the query plan (it will be already deleted).

When we arrive at the phase where EXPLAIN should be printed, we will crash
because one part of UNION will not have the query plan.

Comment by Sergei Petrunia [ 2014-08-08 ]

Why not change the condition in JOIN::optimize() to be
1. We have the query plan ( we might not have it if optimization failed with an error), AND
2. "explain data structure has no query plan for this select yet".

This should cover all cases.. or it seems so at first glance.

Comment by Sergei Petrunia [ 2018-07-26 ]

When debugging this, discovered odd code in Item_subselect::is_expensive(). See details in MDEV-16829.

If a UNION subquery has one degenerate select, it is immediately considered "inexpensive".

In the testcase for this bug, the other part of the SELECT is degenerate/inexpensive as well, but it is not yet optimized at the point where the rewrite code attempts to evaluate it:

(gdb) wher
 
  #0  Item_subselect::is_expensive (this=0x7fffca8dc7d8) at /home/psergey/dev-git/10.0/sql/item_subselect.cc:577
 
  #1  0x0000000000895307 in Item_func_conv_charset::Item_func_conv_charset (this=0x7fffca8dcb98, a=0x7fffca8dc7d8, cs=0x174f000 <my_charset_latin1>, cache_if_const=true) at /home/psergey/dev-git/10.0/sql/item_strfunc.h:950
 
  #2  0x0000000000878e59 in Item::safe_charset_converter (this=0x7fffca8dc7d8, tocs=0x174f000 <my_charset_latin1>) at /home/psergey/dev-git/10.0/sql/item.cc:1180
 
  #3  0x000000000087ba2e in agg_item_set_converter (coll=..., fname=0xff5308 "<=", args=0x7fffca8dc998, nargs=2, flags=7, item_sep=1) at /home/psergey/dev-git/10.0/sql/item.cc:2202
 
  #4  0x000000000087bc89 in agg_item_charsets (coll=..., fname=0xff5308 "<=", args=0x7fffca8dc998, nargs=2, flags=7, item_sep=1) at /home/psergey/dev-git/10.0/sql/item.cc:2285
 
  #5  0x00000000008ad5bf in agg_item_charsets_for_comparison (c=..., name=0xff5308 "<=", items=0x7fffca8dc998, nitems=2, item_sep=1) at /home/psergey/dev-git/10.0/sql/item.h:2098
 
  #6  0x00000000008ad763 in Item_func::agg_arg_charsets_for_comparison (this=0x7fffca8dc900, c=..., items=0x7fffca8dc998, nitems=2, item_sep=1) at /home/psergey/dev-git/10.0/sql/item_func.h:233
 
  #7  0x0000000000899db6 in Item_bool_func2::fix_length_and_dec (this=0x7fffca8dc900) at /home/psergey/dev-git/10.0/sql/item_cmpfunc.cc:562
 
  #8  0x00000000008c82e8 in Item_func::fix_fields (this=0x7fffca8dc900, thd=0x7fffe32c5070, ref=0x7ffff7f21fc0) at /home/psergey/dev-git/10.0/sql/item_func.cc:230
 
  #9  0x000000000090af86 in Item_allany_subselect::transform_into_max_min (this=0x7fffca823cf8, join=0x7fffca8cd900) at /home/psergey/dev-git/10.0/sql/item_subselect.cc:1957
 
  #10 0x00000000007ceed3 in JOIN::transform_max_min_subquery (this=0x7fffca8cd900) at /home/psergey/dev-git/10.0/sql/opt_subselect.cc:901
 
  #11 0x000000000068ff2b in JOIN::optimize_inner (this=0x7fffca8cd900) at /home/psergey/dev-git/10.0/sql/sql_select.cc:1131
 
  #12 0x000000000068fb2e in JOIN::optimize (this=0x7fffca8cd900) at /home/psergey/dev-git/10.0/sql/sql_select.cc:1041
 
  #13 0x000000000064b0ec in st_select_lex::optimize_unflattened_subqueries (this=0x7fffe32c90f8, const_only=false) at /home/psergey/dev-git/10.0/sql/sql_lex.cc:3553
 
  #14 0x00000000007d9de6 in JOIN::optimize_unflattened_subqueries (this=0x7fffca8cd0b0) at /home/psergey/dev-git/10.0/sql/opt_subselect.cc:5234
 
  #15 0x0000000000692e56 in JOIN::optimize_inner (this=0x7fffca8cd0b0) at /home/psergey/dev-git/10.0/sql/sql_select.cc:1946
 
  #16 0x000000000068fb2e in JOIN::optimize (this=0x7fffca8cd0b0) at /home/psergey/dev-git/10.0/sql/sql_select.cc:1041
 
  #17 0x0000000000697f92 in mysql_select (thd=0x7fffe32c5070, rref_pointer_array=0x7fffe32c93a0, tables=0x7fffca8222d0, wild_num=1, fields=..., conds=0x7fffca823f00, og_num=0, order=0x0, group=0x0, having=0x0, proc_param=0x0, select_options=2147748608, result=0x7fffca8cd090, unit=0x7fffe32c8a08, select_lex=0x7fffe32c90f8) at /home/psergey/dev-git/10.0/sql/sql_select.cc:3340
 
  #18 0x000000000068da68 in handle_select (thd=0x7fffe32c5070, lex=0x7fffe32c8940, result=0x7fffca8cd090, setup_tables_done_option=0) at /home/psergey/dev-git/10.0/sql/sql_select.cc:377
 
  #19 0x000000000065e7fe in execute_sqlcom_select (thd=0x7fffe32c5070, all_tables=0x7fffca8222d0) at /home/psergey/dev-git/10.0/sql/sql_parse.cc:5298
 
  #20 0x0000000000656a1c in mysql_execute_command (thd=0x7fffe32c5070) at /home/psergey/dev-git/10.0/sql/sql_parse.cc:2554
 
  #21 0x00000000006619d3 in mysql_parse (thd=0x7fffe32c5070, rawbuf=0x7fffca822088 "SELECT * FROM t1 WHERE a >= ANY ( SELECT 'foo' UNION SELECT 'bar' )", length=67, parser_state=0x7ffff7f236c0) at /home/psergey/dev-git/10.0/sql/sql_parse.cc:6634

Comment by Sergei Petrunia [ 2018-07-26 ]

If I change is_expensive to return TRUE in this case, the query result changes. Instead of empty set, I now get an error:

SELECT * FROM t1 WHERE a >= ANY ( SELECT 'foo' UNION SELECT 'bar' );
 
ERROR HY000: Illegal mix of collations (tis620_thai_ci,COERCIBLE) and (latin1_swedish_ci,IMPLICIT) for operation '<='

Without the UNION:

SELECT * FROM t1 WHERE a >= ANY ( SELECT 'foo');
 
a

Comment by Sergei Petrunia [ 2018-07-26 ]

However if the subquery uses a table (and so bypasses the degenerate-query-rewrite), we would still get an error

create table t2 (b int);
 
insert into t2 values (1),(2),(3);
 
SELECT * FROM t1 WHERE a >= ANY ( SELECT 'foo' FROM t2);
 
ERROR HY000: Illegal mix of collations (tis620_thai_ci,COERCIBLE) and (latin1_swedish_ci,IMPLICIT) for operation '<='

Comment by Sergei Petrunia [ 2018-07-26 ]

Discussed the issue with bar. It is ok if we produce an error like in the testcase for the query.

Comment by Sergei Petrunia [ 2018-07-26 ]

Again, the failure scenario:

SELECT * FROM t1 WHERE a >= ANY ( SELECT 'foo' UNION SELECT 'bar' );

  • Query optimization starts
  • We enter JOIN::optimize() for the "SELECT 'foo'" (select_number=2)
  • JOIN::optimize discovers this is a degenerate select and sets tables_list=NULL.
  • Then it calls JOIN::transform_max_min_subquery
    • the subquery is a UNION, so MIN/MAX rewrite is not applicable
    • instead, the subquery is converted into Item_maxmin_subselect
    • the rewrite constructs a comparison, 'a < ALL (SELECT ...)'
    • Then it calls fix_fields() for the comparison
      • which sees that one part of the comparison is a constant and inexpensive,
        and tries to compute it.

TADA, we are trying to execute a JOIN that we are currently optimizing.

JOIN::exec() will be able to finish just fine in this example.

The problem is that we still have JOIN::have_query_plan==QEP_NOT_PRESENT_YET. and since the SELECT is not correlated, we will call JOIN::cleanup(full=true), which will destroy the query plan before we had a chance to save its EXPLAIN (this is done in two places: at the end of JOIN::optimize and the end of JOIN::exec() . When we reach either of them, we will already have JOIN::have_query_plan==QEP_DELETED).

Trying to execute a JOIN while we are still inside JOIN::optimize() for that join is not expected and can potentially cause all kinds of harm, so it's
better to disable it.

Note that the second part of the UNION is not yet optimized when we are at point.
So if we make Item_subselect::is_expensive() return TRUE for this case,we will prevent the problematic scenario from happening.

(One may ask won't we get into the same problem after we have optimized the second part of the UNION? No, we would not, because the subquery rewrite only happens when we are optimizing the first part of the UNION. Which is not a good place to do it but that's where it is done)

So, the fix is ugly but it works.

We would be better off if this rewrite wasn't so convoluted but fixing that is outside of scope of this bugfix and would be a too big change for 10.0.

Comment by Sergei Petrunia [ 2018-07-26 ]

sanja, please review

Comment by Sergei Petrunia [ 2018-08-15 ]

Somehow, the patch wasn't sent to the commits@. Now, sent it: http://lists.askmonty.org/pipermail/commits/2018-August/012797.html

Comment by Oleksandr Byelkin [ 2018-08-15 ]

OK to push after removing spaces at the end of line.

Generated at Thu Feb 08 07:11:55 UTC 2024 using Jira 8.20.16#820016-sha1:9d11dbea5f4be3d4cc21f03a88dd11d8c8687422.