[MDEV-6985] MariaDB crashes on stored procedure call Created: 2014-10-30  Updated: 2014-12-17  Resolved: 2014-12-17

Status: Closed
Project: MariaDB Server
Component/s: Optimizer
Affects Version/s: 5.5.40, 10.0.14
Fix Version/s: 5.5.41, 10.0.16

Type: Bug Priority: Critical
Reporter: Laurent Mahieux Assignee: Oleksandr Byelkin
Resolution: Fixed Votes: 0
Labels: crash, optimizer, procedure
Environment:

Linux mariadblab 3.2.0-4-686-pae #1 SMP Debian 3.2.60-1+deb7u3 i686 GNU/Linux
Server is a Xen VM

Mirror used: deb http://nwps.ws/pub/mariadb/repo/10.0/debian wheezy main

Fresh debian install with those packages (plus nginx/phpmyadmin):

ii libmariadbclient18 10.0.14+maria-1~wheezy i386
ii libmysqlclient18 10.0.14+maria-1~wheezy i386
ii mariadb-client-10.0 10.0.14+maria-1~wheezy i386
ii mariadb-client-core-10.0 10.0.14+maria-1~wheezy i386
ii mariadb-common 10.0.14+maria-1~wheezy all
ii mariadb-server 10.0.14+maria-1~wheezy all
ii mariadb-server-10.0 10.0.14+maria-1~wheezy i386
ii mariadb-server-core-10.0 10.0.14+maria-1~wheezy i386
ii mysql-common 10.0.14+maria-1~wheezy all

Attachments: File bug-db-dump.sql     File debian.my.cnf     File sql-edi-my.cnf    

 Description   

We encoutered the crash with an unusually complicated stored procedure we restored from a mysql dump (works on mysql 5.5.40-0+wheezy1).

We trimmed it down to the attached test case:
On a clean install, as root, create database, use database, load dump, call procedure as:
"CALL SP1(1);"

The server will crash on the first to third call (usually first).
syslog content:

Oct 30 15:26:18 mariadblab mysqld: 141030 15:26:18 [ERROR] mysqld got signal 11 ;
 
Oct 30 15:26:18 mariadblab mysqld: This could be because you hit a bug. It is also possible that this binary
 
Oct 30 15:26:18 mariadblab mysqld: or one of the libraries it was linked against is corrupt, improperly built,
 
Oct 30 15:26:18 mariadblab mysqld: or misconfigured. This error can also be caused by malfunctioning hardware.
 
Oct 30 15:26:18 mariadblab mysqld: 
Oct 30 15:26:18 mariadblab mysqld: To report this bug, see http://kb.askmonty.org/en/reporting-bugs
 
Oct 30 15:26:18 mariadblab mysqld: 
Oct 30 15:26:18 mariadblab mysqld: We will try our best to scrape up some info that will hopefully help
 
Oct 30 15:26:18 mariadblab mysqld: diagnose the problem, but since we have already crashed, 
Oct 30 15:26:18 mariadblab mysqld: something is definitely wrong and this may fail.
 
Oct 30 15:26:18 mariadblab mysqld: 
Oct 30 15:26:18 mariadblab mysqld: Server version: 10.0.14-MariaDB-1~wheezy-log
 
Oct 30 15:26:18 mariadblab mysqld: key_buffer_size=134217728
 
Oct 30 15:26:18 mariadblab mysqld: read_buffer_size=2097152
 
Oct 30 15:26:18 mariadblab mysqld: max_used_connections=1
 
Oct 30 15:26:18 mariadblab mysqld: max_threads=102
 
Oct 30 15:26:18 mariadblab mysqld: thread_count=1
 
Oct 30 15:26:18 mariadblab mysqld: It is possible that mysqld could use up to 
Oct 30 15:26:18 mariadblab mysqld: key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 759123 K  bytes of memory
 
Oct 30 15:26:18 mariadblab mysqld: Hope that's ok; if not, decrease some variables in the equation.
 
Oct 30 15:26:18 mariadblab mysqld: 
Oct 30 15:26:18 mariadblab mysqld: Thread pointer: 0x0x824da008
 
Oct 30 15:26:18 mariadblab mysqld: Attempting backtrace. You can use the following information to find out
 
Oct 30 15:26:18 mariadblab mysqld: where mysqld died. If you see no messages after this, something went
 
Oct 30 15:26:18 mariadblab mysqld: terribly wrong...
 
Oct 30 15:26:18 mariadblab mysqld: stack_bottom = 0x83b6c30c thread_stack 0x48000
 
Oct 30 15:26:18 mariadblab kernel: [ 1503.693631] mysqld[8445]: segfault at b77ae674 ip b64de54f sp 83b68958 error 7 in libc-2.13.so[b646e000+15f000]
 
Oct 30 15:26:18 mariadblab mysqld_safe: Number of processes running now: 0
 
Oct 30 15:26:18 mariadblab mysqld_safe: mysqld restarted

Although this procedure as it is is badly written (and we fixed it and the server no longer crashes), it should not bring down the whole the server.

We also tried building the package from source (deb-src) to no avail.

We reproduced this on 3 different physical servers, with default my.cnf settings as well as innoDB optimized settings for lots of RAM, on a new install as well as on a fully loaded server.

For what it's worth, we noticed that the problem seems to be linked to the connection: if the server does not crash on the first call, quitting the client and connecting again seems to somehow delay the occurance of the crash.

Best regards,
Laurent

 Comments   
Comment by Elena Stepanova [ 2014-10-31 ]

Hi,

Could you please attach your cnf file(s) or the output of SHOW VARIABLES?

Thanks.

Comment by Laurent Mahieux [ 2014-10-31 ]

my.cnf when we first noticed the problem

Comment by Laurent Mahieux [ 2014-10-31 ]

Stock Debian default my.cnf which also produces the crash

Comment by Laurent Mahieux [ 2014-10-31 ]

I have attached both the initial config in which we encountered the bug, as well as the default debian package config that we tested before submitting the report.

Best regards,
Laurent

Comment by Laurent Mahieux [ 2014-11-13 ]

Hi,

any update on this problem? Has anyone been able to replicate the problem?

Knowing it is possible to crash the whole server with a poorly crafted stored procedure is a show stopper for us (we were a week away from production deployment).

We would be thankful for any indication of progress, even if negative, as we need to re-evaluate our options.

Best regards,
Laurent

Comment by Elena Stepanova [ 2014-11-13 ]

lmahieux,

Sorry, a notification about your previous feedback slipped through the cracks.
I will look into it today and will update you on the progress.

Comment by Elena Stepanova [ 2014-11-13 ]

I can reproduce it.
It happens on the 2nd execution of the SP, that's why reconnect helps.

MTR-like test case (the query is exactly the same as in the initial SP, no simplification). 

--source include/have_innodb.inc
 
 
 
CREATE TABLE `TABLE1` (
 
  `ID` int(11) NOT NULL,
 
  PRIMARY KEY (`ID`)
 
) ENGINE=InnoDB;
 
 
 
CREATE TABLE `TABLE2` (
 
  `ID` int(11) NOT NULL,
 
  `DATE` datetime DEFAULT NULL,
 
  PRIMARY KEY (`ID`)
 
) ENGINE=InnoDB;
 
 
 
--delimiter ;;
 
 
 
CREATE PROCEDURE `SP1`()
 
BEGIN
 
  DECLARE _mySelect CURSOR FOR 
	SELECT DISTINCT TABLE1.ID
 
	FROM TABLE1  
		LEFT JOIN TABLE2 AS T2 ON 
			T2.ID = TABLE1.ID
 
			AND T2.DATE = (
 
				SELECT MAX(T3.DATE) FROM TABLE2 AS T3 WHERE T3.ID = T2.ID AND T3.DATE<=NOW()
 
			)
 
	WHERE TABLE1.ID = 1;
 
  OPEN _mySelect;
 
  CLOSE _mySelect;
 
END ;;
 
--delimiter ;
 
 
 
CALL SP1();
 
CALL SP1();

Stack trace on 5.5 revno 4349

 
#2  0x00000000007e29ed in handle_fatal_signal (sig=11) at 5.5/sql/signal_handler.cc:262
 
#3  <signal handler called>
 
#4  0x000000000067e4d7 in compare_fields_by_table_order (field1=0x7f34b9a837a8, field2=0x7f34b9a838c8, table_join_idx=0x7f34b9a24078) at 5.5/sql/sql_select.cc:12249
 
#5  0x0000000000827c05 in bubble_sort<Item> (list_to_sort=0x7f34b99f1a30, sort_func=0x67e2e7 <compare_fields_by_table_order(Item*, Item*, void*)>, arg=0x7f34b9a24078) at 5.5/sql/sql_list.h:604
 
#6  0x00000000008244fc in Item_equal::sort (this=0x7f34b99f1970, compare=0x67e2e7 <compare_fields_by_table_order(Item*, Item*, void*)>, arg=0x7f34b9a24078) at 5.5/sql/item_cmpfunc.cc:5901
 
#7  0x000000000067f0fa in substitute_for_best_equal_field (context_tab=0x1, cond=0x7f34b9a27078, cond_equal=0x7f34b9a27160, table_join_idx=0x7f34b9a24078) at 5.5/sql/sql_select.cc:12634
 
#8  0x00000000006620cf in JOIN::optimize (this=0x7f34b9a27a20) at 5.5/sql/sql_select.cc:1317
 
#9  0x0000000000627530 in st_select_lex::optimize_unflattened_subqueries (this=0x7f34b99e4800, const_only=false) at 5.5/sql/sql_lex.cc:3506
 
#10 0x0000000000776ba0 in JOIN::optimize_unflattened_subqueries (this=0x7f34b9a274d0) at 5.5/sql/opt_subselect.cc:4939
 
#11 0x0000000000663c68 in JOIN::optimize (this=0x7f34b9a274d0) at 5.5/sql/sql_select.cc:1798
 
#12 0x0000000000668347 in mysql_select (thd=0x7f34c199f060, rref_pointer_array=0x7f34b99e4a70, tables=0x7f34b99eaf78, wild_num=0, fields=..., conds=0x7f34b9a84c30, og_num=0, order=0x0, group=0x0, having=0x0, proc_param=0x0, select_options=2147749633, result=0x7f34b9a27328, unit=0x7f34b99e4128, select_lex=0x7f34b99e4800) at 5.5/sql/sql_select.cc:3080
 
#13 0x000000000065eea9 in handle_select (thd=0x7f34c199f060, lex=0x7f34b99e4078, result=0x7f34b9a27328, setup_tables_done_option=0) at 5.5/sql/sql_select.cc:319
 
#14 0x000000000063845c in execute_sqlcom_select (thd=0x7f34c199f060, all_tables=0x7f34b99eaf78) at 5.5/sql/sql_parse.cc:4689
 
#15 0x000000000063163e in mysql_execute_command (thd=0x7f34c199f060) at 5.5/sql/sql_parse.cc:2234
 
#16 0x000000000092a174 in mysql_open_cursor (thd=0x7f34c199f060, result=0x7f34b99514a8, pcursor=0x7f34b99514d8) at 5.5/sql/sql_cursor.cc:120
 
#17 0x000000000091a012 in sp_cursor::open (this=0x7f34b99514a0, thd=0x7f34c199f060) at 5.5/sql/sp_rcontext.cc:535
 
#18 0x00000000009154a5 in sp_instr_copen::exec_core (this=0x7f34b9a84ef8, thd=0x7f34c199f060, nextp=0x7f34c9dfeb38) at 5.5/sql/sp_head.cc:3815
 
#19 0x00000000009138a1 in sp_lex_keeper::reset_lex_and_exec_core (this=0x7f34b9a84e98, thd=0x7f34c199f060, nextp=0x7f34c9dfeb38, open_tables=false, instr=0x7f34b9a84ef8) at 5.5/sql/sp_head.cc:3000
 
#20 0x000000000091540a in sp_instr_copen::execute (this=0x7f34b9a84ef8, thd=0x7f34c199f060, nextp=0x7f34c9dfeb38) at 5.5/sql/sp_head.cc:3800
 
#21 0x000000000090fc54 in sp_head::execute (this=0x7f34b99ea078, thd=0x7f34c199f060, merge_da_on_success=true) at 5.5/sql/sp_head.cc:1433
 
#22 0x00000000009119b0 in sp_head::execute_procedure (this=0x7f34b99ea078, thd=0x7f34c199f060, args=0x7f34c19a2ff8) at 5.5/sql/sp_head.cc:2199
 
#23 0x0000000000636975 in mysql_execute_command (thd=0x7f34c199f060) at 5.5/sql/sql_parse.cc:4123
 
#24 0x000000000063ab6a in mysql_parse (thd=0x7f34c199f060, rawbuf=0x7f34b9951078 "CALL SP1()", length=10, parser_state=0x7f34c9dff630) at 5.5/sql/sql_parse.cc:5800
 
#25 0x000000000062eb85 in dispatch_command (command=COM_QUERY, thd=0x7f34c199f060, packet=0x7f34c1a7c061 "CALL SP1()", packet_length=10) at 5.5/sql/sql_parse.cc:1079
 
#26 0x000000000062dd11 in do_command (thd=0x7f34c199f060) at 5.5/sql/sql_parse.cc:793
 
#27 0x000000000072ff22 in do_handle_one_connection (thd_arg=0x7f34c199f060) at 5.5/sql/sql_connect.cc:1266
 
#28 0x000000000072f9e1 in handle_one_connection (arg=0x7f34c199f060) at 5.5/sql/sql_connect.cc:1181
 
#29 0x0000000000b65851 in pfs_spawn_thread (arg=0x7f34c19a5480) at 5.5/storage/perfschema/pfs.cc:1015
 
#30 0x00007f34c9a38b50 in start_thread (arg=<optimized out>) at pthread_create.c:304
 
#31 0x00007f34c834720d in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:112
 
#32 0x0000000000000000 in ?? ()

Comment by Oleksandr Byelkin [ 2014-11-16 ]

map2table second element is freed on second execution (why only second?)

Comment by Oleksandr Byelkin [ 2014-11-16 ]

table_count somehow become 1

Comment by Oleksandr Byelkin [ 2014-11-16 ]

everything happened in subquery where is really only one table. So why in subquery it tries to find external table field that is the question.

Comment by Oleksandr Byelkin [ 2014-11-16 ]

The field resolved from cache and does not marked as "outer".

Comment by Oleksandr Byelkin [ 2014-11-17 ]

Problem is that can_be_dependent is not set on the second execution (but set on the first)

Comment by Oleksandr Byelkin [ 2014-11-17 ]

The problem is that Item_ident can't stand double cleanup:

first cleanup() set depended_from to NULL
second cleanup drop can_be_depended flag because depended_from was zeroed by first cleanup

Comment by Oleksandr Byelkin [ 2014-11-17 ]

Could you review this please?

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