MySQL Bugs: #53544: Server hangs during JOIN query in stored procedure called twice in a row

Bug #53544	Server hangs during JOIN query in stored procedure called twice in a row
Submitted:	10 May 2010 16:50	Modified:	22 Nov 2010 11:51
Reporter:	John Embretsen	Email Updates:
Status:	Closed	Impact on me:	None
Category:	MySQL Server: Optimizer	Severity:	S2 (Serious)
Version:	5.1.47, 5.6.99-m4 Dahlia, bzr_mysql-6.0-codebase-bugfixing	OS:	Any
Assigned to:	Alexey Kopytov	CPU Architecture:	Any
Tags:	regression

Description:
A few minutes into running the Random Query Generator's outer_join.yy grammar against mysql-6.0-codebase-bugfixing branch as of 2010-05-05, the server hangs with 99% CPU usage, while the RQG test output and server query log is at standstill.

Last two statements in the query log are:

CALL stored_proc_32748 /* TRANSFORM_OUTCOME_UNORDERED_MATCH */
CALL stored_proc_32748 /* TRANSFORM_OUTCOME_UNORDERED_MATCH */

which comes from the RQG's attempt to validate query results by executing the same query in a stored prcedure (i.e. the Transformer validator) twice. The stored procedure in this example is defined like this:

CREATE PROCEDURE stored_proc_32748 () LANGUAGE SQL   
  SELECT STRAIGHT_JOIN  table2 . `col_int_key` AS field1 
  FROM E AS table1 
  RIGHT JOIN C AS table2 ON table1 . `pk` =  table2 . `pk`   
  RIGHT  JOIN A AS table3 ON table2 . `col_int_key` =  table3 . `col_int_key`
  WHERE table3 . `col_int_key` != 8  
  GROUP BY field1 
  HAVING (((field1 <> 4 AND field1 <> 8) OR field1 != 9) AND field1 >= 6) 
  ORDER BY field1

The query is different from run to run, but the M.O. of the stored procedure seems to be the same.

Stacktrace from the thread that seems most interesting from doing "kill -11" on the hanged server:

Thread 5 (process 32751):
#0  0x0000000000ad8c46 in my_strcasecmp_utf8mb3 (cs=0x12566e0, s=0x2934ffa "col_int_key", t=0x2aeb4a0 "field1")
    at /data0/johnemb/optimizer-testing/code/bzr/mysql-6.0-codebase-bugfixing/strings/ctype-utf8.c:2646
#1  0x00000000005c390c in find_field_in_table (thd=0x28fc0c8, table=0x2935e38, name=0x2aeb4a0 "field1", length=6, allow_rowid=false, 
    cached_field_index_ptr=0x2aeb56c) at /data0/johnemb/optimizer-testing/code/bzr/mysql-6.0-codebase-bugfixing/sql/sql_base.cc:6038
#2  0x00000000005c432d in find_field_in_table_ref (thd=0x28fc0c8, table_list=0x292d430, name=0x2aeb4a0 "field1", length=6, 
    item_name=0x2aeb4a0 "field1", db_name=0x0, table_name=0x0, ref=0x7ffab1dfc288, check_privileges=true, allow_rowid=false, 
    cached_field_index_ptr=0x2aeb56c, register_tree_change=false, actual_table=0x7ffab1dfbeb8)
    at /data0/johnemb/optimizer-testing/code/bzr/mysql-6.0-codebase-bugfixing/sql/sql_base.cc:6168
#3  0x00000000005c4b28 in find_field_in_tables (thd=0x28fc0c8, item=0x2aeb4c0, first_table=0x292ce80, last_table=0x0, ref=0x7ffab1dfc288, 
    report_error=IGNORE_ERRORS, check_privileges=true, register_tree_change=false)
    at /data0/johnemb/optimizer-testing/code/bzr/mysql-6.0-codebase-bugfixing/sql/sql_base.cc:6432
#4  0x0000000000648ec4 in find_order_in_list (thd=0x28fc0c8, ref_pointer_array=0x2936dc0, tables=0x292ce80, order=0x2aeb5a8, fields=@0x2af4a70, 
    all_fields=@0x2b6b7d8, is_group_field=true) at /data0/johnemb/optimizer-testing/code/bzr/mysql-6.0-codebase-bugfixing/sql/sql_select.cc:20290
#5  0x000000000064922d in setup_group (thd=0x28fc0c8, ref_pointer_array=0x2936dc0, tables=0x292ce80, fields=@0x2af4a70, all_fields=@0x2b6b7d8, 
    order=0x2aeb5a8, hidden_group_fields=0x2b6b7b7)
    at /data0/johnemb/optimizer-testing/code/bzr/mysql-6.0-codebase-bugfixing/sql/sql_select.cc:20442
#6  0x000000000067b1cc in setup_without_group (thd=0x28fc0c8, ref_pointer_array=0x2936dc0, tables=0x292ce80, leaves=0x292ce80, fields=@0x2af4a70, 
    all_fields=@0x2b6b7d8, conds=0x2b6b8c0, order=0x2aec5f0, group=0x2aeb5a8, hidden_group_fields=0x2b6b7b7)
    at /data0/johnemb/optimizer-testing/code/bzr/mysql-6.0-codebase-bugfixing/sql/sql_select.cc:498
#7  0x000000000066eea2 in JOIN::prepare (this=0x2b65c20, rref_pointer_array=0x2af4b50, tables_init=0x292ce80, wild_num=0, conds_init=0x2aeb328, 
    og_num=2, order_init=0x2aec5f0, group_init=0x2aeb5a8, having_init=0x2a68340, proc_param_init=0x0, select_lex_arg=0x2af4968, unit_arg=0x2af42c8)
    at /data0/johnemb/optimizer-testing/code/bzr/mysql-6.0-codebase-bugfixing/sql/sql_select.cc:568
#8  0x00000000006705a1 in mysql_select (thd=0x28fc0c8, rref_pointer_array=0x2af4b50, tables=0x292ce80, wild_num=0, fields=@0x2af4a70, 
    conds=0x2aeb328, og_num=2, order=0x2aec5f0, group=0x2aeb5a8, having=0x2a68340, proc_param=0x0, select_options=2147749634, result=0x2a68710, 
    unit=0x2af42c8, select_lex=0x2af4968) at /data0/johnemb/optimizer-testing/code/bzr/mysql-6.0-codebase-bugfixing/sql/sql_select.cc:3252
#9  0x000000000067603e in handle_select (thd=0x28fc0c8, lex=0x2af4228, result=0x2a68710, setup_tables_done_option=0)
    at /data0/johnemb/optimizer-testing/code/bzr/mysql-6.0-codebase-bugfixing/sql/sql_select.cc:321
#10 0x000000000061370f in execute_sqlcom_select (thd=0x28fc0c8, all_tables=0x292ce80)
    at /data0/johnemb/optimizer-testing/code/bzr/mysql-6.0-codebase-bugfixing/sql/sql_parse.cc:5103
#11 0x000000000061557d in mysql_execute_command (thd=0x28fc0c8)
    at /data0/johnemb/optimizer-testing/code/bzr/mysql-6.0-codebase-bugfixing/sql/sql_parse.cc:2358
#12 0x00000000008a9ae7 in sp_instr_stmt::exec_core (this=0x2aec638, thd=0x28fc0c8, nextp=0x7ffab1dfe608)
    at /data0/johnemb/optimizer-testing/code/bzr/mysql-6.0-codebase-bugfixing/sql/sp_head.cc:2948
#13 0x00000000008a9ce8 in sp_lex_keeper::reset_lex_and_exec_core (this=0x2aec678, thd=0x28fc0c8, nextp=0x7ffab1dfe608, open_tables=false, 
    instr=0x2aec638) at /data0/johnemb/optimizer-testing/code/bzr/mysql-6.0-codebase-bugfixing/sql/sp_head.cc:2764
#14 0x00000000008b0130 in sp_instr_stmt::execute (this=0x2aec638, thd=0x28fc0c8, nextp=0x7ffab1dfe608)
    at /data0/johnemb/optimizer-testing/code/bzr/mysql-6.0-codebase-bugfixing/sql/sp_head.cc:2886
#15 0x00000000008ac12e in sp_head::execute (this=0x2af3850, thd=0x28fc0c8)
    at /data0/johnemb/optimizer-testing/code/bzr/mysql-6.0-codebase-bugfixing/sql/sp_head.cc:1262
#16 0x00000000008acfb5 in sp_head::execute_procedure (this=0x2af3850, thd=0x28fc0c8, args=0x28fe6d0)
    at /data0/johnemb/optimizer-testing/code/bzr/mysql-6.0-codebase-bugfixing/sql/sp_head.cc:2006
#17 0x000000000061bc57 in mysql_execute_command (thd=0x28fc0c8)
    at /data0/johnemb/optimizer-testing/code/bzr/mysql-6.0-codebase-bugfixing/sql/sql_parse.cc:4617
#18 0x000000000061d38e in mysql_parse (thd=0x28fc0c8, inBuf=0x29f2db0 "CALL stored_proc_32748 /* TRANSFORM_OUTCOME_UNORDERED_MATCH */", length=62, 
    found_semicolon=0x7ffab1e008b8) at /data0/johnemb/optimizer-testing/code/bzr/mysql-6.0-codebase-bugfixing/sql/sql_parse.cc:6131
#19 0x000000000061dee5 in dispatch_command (command=COM_QUERY, thd=0x28fc0c8, 
    packet=0x29eae99 "CALL stored_proc_32748 /* TRANSFORM_OUTCOME_UNORDERED_MATCH */", packet_length=62)
    at /data0/johnemb/optimizer-testing/code/bzr/mysql-6.0-codebase-bugfixing/sql/sql_parse.cc:1154
#20 0x000000000061f40f in do_command (thd=0x28fc0c8) at /data0/johnemb/optimizer-testing/code/bzr/mysql-6.0-codebase-bugfixing/sql/sql_parse.cc:838
#21 0x00000000006ff465 in do_handle_one_connection (thd_arg=0x28fc0c8)
    at /data0/johnemb/optimizer-testing/code/bzr/mysql-6.0-codebase-bugfixing/sql/sql_connect.cc:1187
#22 0x00000000006ff52a in handle_one_connection (arg=0x28fc0c8)
    at /data0/johnemb/optimizer-testing/code/bzr/mysql-6.0-codebase-bugfixing/sql/sql_connect.cc:1127
#23 0x00007ffabe64c3ba in start_thread () from /lib/libpthread.so.0
#24 0x00007ffabd5cafcd in clone () from /lib/libc.so.6
#25 0x0000000000000000 in ?? ()

How to repeat:
perl runall.pl \
--threads=1 \
--seed=1273496682 \
--mysqld=--init-file=/path/to/init-file.sql \
--engine=INNODB \
--grammar=conf/optimizer/outer_join.yy \
--gendata=conf/optimizer/outer_join.zz \
--queries=1M \
--duration=1200 \
--basedir=/path/to/mysql-6.0-codebase-bugfixing

where init-file.sql contains:

SET GLOBAL optimizer_join_cache_level=8;
SET GLOBAL optimizer_switch="engine_condition_pushdown=on,firstmatch=on,index_condition_pushdown=on,index_merge=on,index_merge_intersection=on,index_merge_sort_union=on,index_merge_union=on,loosescan=on,materialization=on,mrr=on,mrr_cost_based=off,semijoin=off";

I expect to be able to provide more details and a simplified reproducible test case later.

The following SQL exhibits this behavior with current mysql-6.0-codebase-bugfixing as well as mysql-next-mr-opt-backporting:

(it may be possible to simplify further)

-------------------------------------

--
-- Create and populate tables
--

DROP TABLE IF EXISTS `AA`;

CREATE TABLE `AA` (
  `col_int` int(11) DEFAULT NULL,
  `col_int_key` int(11) DEFAULT NULL,
  `pk` int(11) NOT NULL AUTO_INCREMENT,
  PRIMARY KEY (`pk`),
  KEY `col_int_key` (`col_int_key`)
) ENGINE=InnoDB AUTO_INCREMENT=3 DEFAULT CHARSET=latin1;

INSERT INTO `AA` VALUES (NULL,7,1),(8,3,2);

DROP TABLE IF EXISTS `FF`;

CREATE TABLE `FF` (
  `pk` int(11) NOT NULL AUTO_INCREMENT,
  `col_int` int(11) DEFAULT NULL,
  `col_int_key` int(11) DEFAULT NULL,
  PRIMARY KEY (`pk`),
  KEY `col_int_key` (`col_int_key`)
) ENGINE=InnoDB AUTO_INCREMENT=3 DEFAULT CHARSET=latin1;

INSERT INTO `FF` VALUES (1,9,6),(2,8,NULL);

DROP TABLE IF EXISTS `M`;

CREATE TABLE `M` (
  `pk` int(11) NOT NULL AUTO_INCREMENT,
  `col_int_key` int(11) DEFAULT NULL,
  `col_int` int(11) DEFAULT NULL,
  PRIMARY KEY (`pk`),
  KEY `col_int_key` (`col_int_key`)
) ENGINE=InnoDB AUTO_INCREMENT=3 DEFAULT CHARSET=latin1;

INSERT INTO `M` VALUES (1,9,8),(2,3,NULL);

-- 
-- Create the stored procedure with the query.
-- In this example the query itself returns no rows.
--

DROP PROCEDURE IF EXISTS stored_proc_1;

CREATE PROCEDURE stored_proc_1 ()
  LANGUAGE SQL
  SELECT table2.`col_int` AS field1
  FROM FF AS table1 LEFT JOIN M AS table2 
      ON table1.`pk` =  table2.`col_int` 
      RIGHT JOIN AA AS table3 
          ON table1.`col_int_key` =  table3.`col_int_key`
  WHERE ( table3.`col_int_key` BETWEEN 1 AND 4 ) 
  GROUP BY field1;

-- 
-- Run the stored procedure. Hang occurs on second run. 
--

CALL stored_proc_1;
CALL stored_proc_1;

Same hang also observed when using Prepared Statements instead of Stored Procedures.

This is a regression introduced in 5.0.74 and 5.1.31 by the fix for bug #33811.

Noted in 5.1.51, 5.5.6 changelogs.

Queries with nested joins could cause an infinite loop in the
server when used from stored procedures and prepared statements.

Pushed into mysql-5.1 5.1.52 (revid:sunanda.menon@sun.com-20100928083322-wangbv97uobu7g66) (version source revid:sunanda.menon@sun.com-20100928083322-wangbv97uobu7g66) (merge vers: 5.1.52) (pib:21)

Pushed into mysql-5.1-telco-7.0 5.1.51-ndb-7.0.20 (revid:martin.skold@mysql.com-20101014082627-jrmy9xbfbtrebw3c) (version source revid:martin.skold@mysql.com-20101014082627-jrmy9xbfbtrebw3c) (merge vers: 5.1.51-ndb-7.0.20) (pib:21)

Pushed into mysql-5.1-telco-6.3 5.1.51-ndb-6.3.39 (revid:martin.skold@mysql.com-20101014083757-5qo48b86d69zjvzj) (version source revid:martin.skold@mysql.com-20101014083757-5qo48b86d69zjvzj) (merge vers: 5.1.51-ndb-6.3.39) (pib:21)

Pushed into mysql-5.1-telco-6.2 5.1.51-ndb-6.2.19 (revid:martin.skold@mysql.com-20101014084420-y54ecj85j5we27oa) (version source revid:martin.skold@mysql.com-20101014084420-y54ecj85j5we27oa) (merge vers: 5.1.51-ndb-6.2.19) (pib:21)

Already documented in the 5.1.50 changelog; no new changelog entries required. setting back to Closed state.

CVE-2010-3839

CVE-2010-3839

Pushed into mysql-5.5 5.5.7-rc (revid:sunanda.menon@sun.com-20101109182959-otkxq8vo2dcd13la) (version source revid:marko.makela@oracle.com-20100824081003-v4ecy0tga99cpxw2) (merge vers: 5.1.50) (pib:21)

Pushed into mysql-trunk 5.6.99-m5 (revid:alexander.nozdrin@oracle.com-20101113155825-czmva9kg4n31anmu) (version source revid:marko.makela@oracle.com-20100824081003-v4ecy0tga99cpxw2) (merge vers: 5.1.50) (pib:21)

Pushed into mysql-next-mr (revid:alexander.nozdrin@oracle.com-20101113160336-atmtmfb3mzm4pz4i) (version source revid:marko.makela@oracle.com-20100824081003-v4ecy0tga99cpxw2) (pib:21)