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

Server crashes in functions related to stored procedures

Details

    Description

      Crashes were seen with the following stack traces:

      stack_bottom = 0x7f82ebf32dd8 thread_stack 0x48000
      mysys/stacktrace.c:247(my_print_stacktrace)[0xad47ae]
      sql/signal_handler.cc:153(handle_fatal_signal)[0x6d388b]
      /lib64/libpthread.so.0[0x3121c0f710]
      sql/sql_string.h:240(String::free())[0x714227]
      sql/item.h:1435(Item::delete_self())[0x5578e0]
      sql/sql_class.h:761(~Query_arena)[0x7e2cd0]
      sql/sp_head.cc:775(~sp_head)[0x7de9ad]
      sql/sp_head.cc:528(sp_head::operator delete(void*, unsigned long))[0x7de9e1]
      mysys/hash.c:115(my_hash_free_elements)[0xab898f]
      sql/sp_cache.cc:132(sp_cache_clear(sp_cache**))[0x524553]
      sql/sql_class.cc:1433(THD::cleanup())[0x55f197]
      psi/mysql_thread.h:610(inline_mysql_mutex_lock)[0x504673]
      sql/mysqld.cc:2607(one_thread_per_connection_end(THD*, bool))[0x5048f5]
      sql/sql_connect.cc:1277(do_handle_one_connection(THD*))[0x64c080]
      sql/sql_connect.cc:1183(handle_one_connection)[0x64c3ec]
      /lib64/libpthread.so.0[0x3121c079d1]
      /lib64/libc.so.6(clone+0x6d)[0x31214e886d]

      stack_bottom = 0x7fc14df77dd8 thread_stack 0x48000
      mysys/stacktrace.c:247(my_print_stacktrace)[0xad47ae]
      sql/signal_handler.cc:153(handle_fatal_signal)[0x6d388b]
      /lib64/libpthread.so.0[0x3b2000f710]
      sql/sql_string.h:240(String::free())[0x714227]
      sql/sql_parse.cc:667(cleanup_items(Item*))[0x581b11]
      sql/sp_head.cc:1442(sp_head::execute(THD*, bool))[0x7de32d]
      sql/sp_head.cc:2199(sp_head::execute_procedure(THD*, List<Item>*))[0x7df077]
      sql/sql_parse.cc:4124(mysql_execute_command(THD*))[0x58bbac]
      sql/sql_parse.cc:5799(mysql_parse(THD*, char*, unsigned int, Parser_state*))[0x58eb09]
      sql/sql_parse.cc:1081(dispatch_command(enum_server_command, THD*, char*, unsigned int))[0x59009c]
      sql/sql_connect.cc:1266(do_handle_one_connection(THD*))[0x64c34f]
      sql/sql_connect.cc:1183(handle_one_connection)[0x64c3ec]
      /lib64/libpthread.so.0[0x3b200079d1]
      /lib64/libc.so.6(clone+0x6d)[0x3b1f8e88fd]

      stack_bottom = 0x7f905e89ddd8 thread_stack 0x48000
      mysys/stacktrace.c:247(my_print_stacktrace)[0xad47ae]
      sql/signal_handler.cc:153(handle_fatal_signal)[0x6d388b]
      /lib64/libpthread.so.0[0x3b2000f710]
      sql/sql_string.h:240(String::free())[0x714227]
      sql/sql_parse.cc:667(cleanup_items(Item*))[0x581b11]
      sql/sp_head.cc:1442(sp_head::execute(THD*, bool))[0x7de32d]
      sql/sp_head.cc:2199(sp_head::execute_procedure(THD*, List<Item>*))[0x7df077]
      sql/sql_parse.cc:4124(mysql_execute_command(THD*))[0x58bbac]
      sql/sql_parse.cc:5799(mysql_parse(THD*, char*, unsigned int, Parser_state*))[0x58eb09]
      sql/sql_parse.cc:1081(dispatch_command(enum_server_command, THD*, char*, unsigned int))[0x59009c]
      sql/sql_connect.cc:1266(do_handle_one_connection(THD*))[0x64c34f]
      sql/sql_connect.cc:1183(handle_one_connection)[0x64c3ec]
      /lib64/libpthread.so.0[0x3b200079d1]
      /lib64/libc.so.6(clone+0x6d)[0x3b1f8e88fd]

      stack_bottom = 0x7f10f349bdd8 thread_stack 0x48000
      mysys/stacktrace.c:247(my_print_stacktrace)[0xad47ae]
      sql/signal_handler.cc:153(handle_fatal_signal)[0x6d388b]
      /lib64/libpthread.so.0[0x3b2000f710]
      /lib64/libc.so.6(gsignal+0x35)[0x3b1f832625]
      /lib64/libc.so.6(abort+0x175)[0x3b1f833e05]
      /usr/lib64/libtcmalloc.so(_ZN8tcmalloc3LogENS_7LogModeEPKciNS_7LogItemES3_S3_S3_+0x22d)[0x7f151991aecd]
      /usr/lib64/libtcmalloc.so(+0x16413)[0x7f151990e413]
      /usr/lib64/libtcmalloc.so(tc_free+0x1fe)[0x7f151992f76e]
      sql/sql_string.h:240(String::free())[0x714243]
      sql/sql_parse.cc:667(cleanup_items(Item*))[0x581b11]
      sql/sp_head.cc:1442(sp_head::execute(THD*, bool))[0x7de32d]
      sql/sp_head.cc:2199(sp_head::execute_procedure(THD*, List<Item>*))[0x7df077]
      sql/sql_parse.cc:4124(mysql_execute_command(THD*))[0x58bbac]
      sql/sql_parse.cc:5799(mysql_parse(THD*, char*, unsigned int, Parser_state*))[0x58eb09]
      sql/sql_parse.cc:1081(dispatch_command(enum_server_command, THD*, char*, unsigned int))[0x59009c]
      sql/sql_connect.cc:1266(do_handle_one_connection(THD*))[0x64c34f]
      sql/sql_connect.cc:1183(handle_one_connection)[0x64c3ec]
      /lib64/libpthread.so.0[0x3b200079d1]
      /lib64/libc.so.6(clone+0x6d)[0x3b1f8e88fd]

      stack_bottom = 0x7f9593671dd8 thread_stack 0x48000
      mysys/stacktrace.c:247(my_print_stacktrace)[0xad47ae]
      sql/signal_handler.cc:153(handle_fatal_signal)[0x6d388b]
      /lib64/libpthread.so.0[0x3b2000f710]
      sql/sql_string.h:240(String::free())[0x714227]
      sql/item.h:1435(Item::delete_self())[0x5578e0]
      sql/sql_class.h:761(~Query_arena)[0x7e2cd0]
      sql/sp_head.cc:775(~sp_head)[0x7de9ad]
      sql/sp_head.cc:528(sp_head::operator delete(void*, unsigned long))[0x7de9e1]
      mysys/hash.c:115(my_hash_free_elements)[0xab898f]
      sql/sp_cache.cc:132(sp_cache_clear(sp_cache**))[0x524553]
      sql/sql_class.cc:1433(THD::cleanup())[0x55f197]
      psi/mysql_thread.h:610(inline_mysql_mutex_lock)[0x504673]
      sql/mysqld.cc:2607(one_thread_per_connection_end(THD*, bool))[0x5048f5]
      sql/sql_connect.cc:1277(do_handle_one_connection(THD*))[0x64c080]
      sql/sql_connect.cc:1183(handle_one_connection)[0x64c3ec]
      /lib64/libpthread.so.0[0x3b200079d1]
      /lib64/libc.so.6(clone+0x6d)[0x3b1f8e88fd]

      Attachments

        Issue Links

          Activity

            One crash from which I saw the error log happened upon KILL_CONNECTION. Is it always the case?

            elenst Elena Stepanova added a comment - One crash from which I saw the error log happened upon KILL_CONNECTION. Is it always the case?

            It looks like it crashed upon KILL_CONNECTION two times, and it crashed while executing the stored procedure three times.

            GeoffMontee Geoff Montee (Inactive) added a comment - It looks like it crashed upon KILL_CONNECTION two times, and it crashed while executing the stored procedure three times.

            The crash seasm to happen while freeing memory used by the stored procedure.
            This means that either the memory is freed twice or we have a memory overrun.

            In both cases the bug is closely related to the stored procedure and to be able to find out the bug we would need:

            • A copy of the stored procedure
            • The definition of the tables that are used by the stored procedure.
              (.frm files are probably enough)

            Another option would be to that we would provide a debug binary, mysqld would be started with the --core option and when/if it crashes again we would get access to the core file to debug this.

            monty Michael Widenius added a comment - The crash seasm to happen while freeing memory used by the stored procedure. This means that either the memory is freed twice or we have a memory overrun. In both cases the bug is closely related to the stored procedure and to be able to find out the bug we would need: A copy of the stored procedure The definition of the tables that are used by the stored procedure. (.frm files are probably enough) Another option would be to that we would provide a debug binary, mysqld would be started with the --core option and when/if it crashes again we would get access to the core file to debug this.

            See MDEV-7601 and its subtasks for intermediate results of stress tests which were run in attempt to reproduce the problem. It's not certain yet whether any of those is related, it will be analyzed.

            elenst Elena Stepanova added a comment - See MDEV-7601 and its subtasks for intermediate results of stress tests which were run in attempt to reproduce the problem. It's not certain yet whether any of those is related, it will be analyzed.

            Got the following stack trace, the test case is in the comment to MDEV-7594

            #3  <signal handler called>
            #4  0x00007fa6cea35fa0 in ?? ()
            #5  0x000000000060310b in Item::delete_self (this=0x7fa6cea345a8) at 5.5/sql/item.h:1434
            #6  0x00000000005fd3cd in Query_arena::free_items (this=0x7fa6d694e078) at 5.5/sql/sql_class.cc:3160
            #7  0x00000000005f8d6c in THD::cleanup_after_query (this=0x7fa6d694e060) at 5.5/sql/sql_class.cc:1883
            #8  0x0000000000910920 in sp_head::execute (this=0x7fa6ce98e078, thd=0x7fa6d694e060, merge_da_on_success=true) at 5.5/sql/sp_head.cc:1449
            #9  0x0000000000912610 in sp_head::execute_procedure (this=0x7fa6ce98e078, thd=0x7fa6d694e060, args=0x7fa6d6952000) at 5.5/sql/sp_head.cc:2199
            #10 0x0000000000636c41 in mysql_execute_command (thd=0x7fa6d694e060) at 5.5/sql/sql_parse.cc:4123
            #11 0x000000000063b20e in mysql_parse (thd=0x7fa6d694e060, rawbuf=0x7fa6ce951078 "CALL sp", length=7, parser_state=0x7fa6dec75620) at 5.5/sql/sql_parse.cc:5909
            #12 0x000000000062ee51 in dispatch_command (command=COM_QUERY, thd=0x7fa6d694e060, packet=0x7fa6d6a74061 "", packet_length=7) at 5.5/sql/sql_parse.cc:1079
            #13 0x000000000062dfdd in do_command (thd=0x7fa6d694e060) at 5.5/sql/sql_parse.cc:793
            #14 0x000000000073072a in do_handle_one_connection (thd_arg=0x7fa6d694e060) at 5.5/sql/sql_connect.cc:1266
            #15 0x00000000007301e9 in handle_one_connection (arg=0x7fa6d694e060) at 5.5/sql/sql_connect.cc:1181
            #16 0x0000000000b66b61 in pfs_spawn_thread (arg=0x7fa6d69ca480) at 5.5/storage/perfschema/pfs.cc:1015
            #17 0x00007fa6de8adb50 in start_thread (arg=<optimized out>) at pthread_create.c:304
            #18 0x00007fa6dd1bb70d in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:112
            #19 0x0000000000000000 in ?? ()

            elenst Elena Stepanova added a comment - Got the following stack trace, the test case is in the comment to MDEV-7594 #3 <signal handler called> #4 0x00007fa6cea35fa0 in ?? () #5 0x000000000060310b in Item::delete_self (this=0x7fa6cea345a8) at 5.5/sql/item.h:1434 #6 0x00000000005fd3cd in Query_arena::free_items (this=0x7fa6d694e078) at 5.5/sql/sql_class.cc:3160 #7 0x00000000005f8d6c in THD::cleanup_after_query (this=0x7fa6d694e060) at 5.5/sql/sql_class.cc:1883 #8 0x0000000000910920 in sp_head::execute (this=0x7fa6ce98e078, thd=0x7fa6d694e060, merge_da_on_success=true) at 5.5/sql/sp_head.cc:1449 #9 0x0000000000912610 in sp_head::execute_procedure (this=0x7fa6ce98e078, thd=0x7fa6d694e060, args=0x7fa6d6952000) at 5.5/sql/sp_head.cc:2199 #10 0x0000000000636c41 in mysql_execute_command (thd=0x7fa6d694e060) at 5.5/sql/sql_parse.cc:4123 #11 0x000000000063b20e in mysql_parse (thd=0x7fa6d694e060, rawbuf=0x7fa6ce951078 "CALL sp", length=7, parser_state=0x7fa6dec75620) at 5.5/sql/sql_parse.cc:5909 #12 0x000000000062ee51 in dispatch_command (command=COM_QUERY, thd=0x7fa6d694e060, packet=0x7fa6d6a74061 "", packet_length=7) at 5.5/sql/sql_parse.cc:1079 #13 0x000000000062dfdd in do_command (thd=0x7fa6d694e060) at 5.5/sql/sql_parse.cc:793 #14 0x000000000073072a in do_handle_one_connection (thd_arg=0x7fa6d694e060) at 5.5/sql/sql_connect.cc:1266 #15 0x00000000007301e9 in handle_one_connection (arg=0x7fa6d694e060) at 5.5/sql/sql_connect.cc:1181 #16 0x0000000000b66b61 in pfs_spawn_thread (arg=0x7fa6d69ca480) at 5.5/storage/perfschema/pfs.cc:1015 #17 0x00007fa6de8adb50 in start_thread (arg=<optimized out>) at pthread_create.c:304 #18 0x00007fa6dd1bb70d in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:112 #19 0x0000000000000000 in ?? ()

            I suppose MDEV-7601 and its subtasks should be enough to consider this issue verified, at least for now. Assigning to Monty since he said he would look into the problem.

            elenst Elena Stepanova added a comment - I suppose MDEV-7601 and its subtasks should be enough to consider this issue verified, at least for now. Assigning to Monty since he said he would look into the problem.

            The problem was that select_lex->non_agg_fields was not properly reset for re-execution and this caused an overwrite of a random memory position.
            The fix was move non_agg_fields from select_lext to JOIN, which is properly reset.

            Fix pushed into the 5.5 tree.

            monty Michael Widenius added a comment - The problem was that select_lex->non_agg_fields was not properly reset for re-execution and this caused an overwrite of a random memory position. The fix was move non_agg_fields from select_lext to JOIN, which is properly reset. Fix pushed into the 5.5 tree.

            Thanks for fixing this!

            The JIRA issue currently says the fix should go into 5.5.40, but it will actually be going into 5.5.44, correct?

            GeoffMontee Geoff Montee (Inactive) added a comment - Thanks for fixing this! The JIRA issue currently says the fix should go into 5.5.40, but it will actually be going into 5.5.44, correct?

            People

              monty Michael Widenius
              GeoffMontee Geoff Montee (Inactive)
              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.