Uploaded image for project: 'MariaDB Server'
  1. MariaDB Server
  2. MDEV-6985

MariaDB crashes on stored procedure call

Details

    • Bug
    • Status: Closed (View Workflow)
    • Critical
    • Resolution: Fixed
    • 5.5.40, 10.0.14
    • 5.5.41, 10.0.16
    • Optimizer

    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

      Attachments

        1. bug-db-dump.sql
          4 kB
        2. debian.my.cnf
          5 kB
        3. sql-edi-my.cnf
          2 kB

        Activity

          Hi,

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

          Thanks.

          elenst Elena Stepanova added a comment - Hi, Could you please attach your cnf file(s) or the output of SHOW VARIABLES ? Thanks.

          my.cnf when we first noticed the problem

          lmahieux Laurent Mahieux added a comment - my.cnf when we first noticed the problem

          Stock Debian default my.cnf which also produces the crash

          lmahieux Laurent Mahieux added a comment - Stock Debian default my.cnf which also produces the crash

          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

          lmahieux Laurent Mahieux added a comment - 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

          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

          lmahieux Laurent Mahieux added a comment - 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

          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.

          elenst Elena Stepanova added a comment - 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.

          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 ?? ()

          elenst Elena Stepanova added a comment - 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 ?? ()

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

          sanja Oleksandr Byelkin added a comment - map2table second element is freed on second execution (why only second?)

          table_count somehow become 1

          sanja Oleksandr Byelkin added a comment - table_count somehow become 1

          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.

          sanja Oleksandr Byelkin added a comment - 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.

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

          sanja Oleksandr Byelkin added a comment - The field resolved from cache and does not marked as "outer".

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

          sanja Oleksandr Byelkin added a comment - Problem is that can_be_dependent is not set on the second execution (but set on the first)

          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

          sanja Oleksandr Byelkin added a comment - 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

          Could you review this please?

          sanja Oleksandr Byelkin added a comment - Could you review this please?

          People

            sanja Oleksandr Byelkin
            lmahieux Laurent Mahieux
            Votes:
            0 Vote for this issue
            Watchers:
            4 Start watching this issue

            Dates

              Created:
              Updated:
              Resolved:

              Git Integration

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