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

SHOW EXPLAIN: Server crashes while trying to destroy a mutex LOCK_apc_queue that was locked or to lock unitialized mutex

    XMLWordPrintable

Details

    • Bug
    • Status: Closed (View Workflow)
    • Major
    • Resolution: Fixed
    • None
    • 10.0.0
    • None
    • None

    Description

      Apparently it's a race condition between SHOW EXPLAIN and disconnect in the target connection.
      The problem comes in two flavors.

      Variant 1:

      safe_mutex: Trying to destroy a mutex LOCK_apc_queue that was locked at sql/my_apc.cc, line 149 at sql/my_apc.cc, line 54

      Stack trace:

      Thread 6 (Thread 0x7f97dda63700 (LWP 22010)):
      #0  0x00007f97e910f0dd in read () at ../sysdeps/unix/syscall-template.S:82
      #1  0x0000000000cc7855 in my_addr_resolve (ptr=0xcb0f34, loc=0x7f97dda621b0) at mysys/my_addr_resolve.c:146
      #2  0x0000000000cb0e82 in print_with_addr_resolve (addrs=0x7f97dda62200, n=16) at mysys/stacktrace.c:232
      #3  0x0000000000cb0f6d in my_print_stacktrace (stack_bottom=0x7f97dda62df8 "04Q\002", thread_stack=294912) at mysys/stacktrace.c:250
      #4  0x00000000007bf089 in handle_fatal_signal (sig=6) at sql/signal_handler.cc:170
      #5  <signal handler called>
      #6  0x00007f97e83cd3a5 in __GI_raise (sig=6) at ../nptl/sysdeps/unix/sysv/linux/raise.c:64
      #7  0x00007f97e83d0b0b in __GI_abort () at abort.c:92
      #8  0x0000000000cb9230 in safe_mutex_destroy (mp=0x25156f8, file=0xd61120 "sql/my_apc.cc", line=54) at mysys/thr_mutex.c:604
      #9  0x000000000075917b in Apc_target::destroy (this=0x25156e8) at sql/my_apc.cc:54
      #10 0x00000000005d3012 in THD::cleanup (this=0x2513430) at sql/sql_class.cc:1365
      #11 0x000000000055eb97 in thd_cleanup (thd=0x2513430) at sql/mysqld.cc:2396
      #12 0x000000000055ec94 in unlink_thd (thd=0x2513430) at sql/mysqld.cc:2445
      #13 0x000000000055f01f in one_thread_per_connection_end (thd=0x2513430, put_in_cache=true) at sql/mysqld.cc:2559
      #14 0x000000000070a5b5 in do_handle_one_connection (thd_arg=0x2513430) at sql/sql_connect.cc:1264
      #15 0x0000000000709efa in handle_one_connection (arg=0x2513430) at sql/sql_connect.cc:1168
      #16 0x0000000000bfa00f in pfs_spawn_thread (arg=0x24c7d20) at storage/perfschema/pfs.cc:1015
      #17 0x00007f97e9107efc in start_thread (arg=0x7f97dda63700) at pthread_create.c:304
      #18 0x00007f97e847a59d in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:112
      #19 0x0000000000000000 in ?? ()
       
      Thread 5 (Thread 0x7f97ddaf3700 (LWP 21819)):
      #0  do_sigwait (set=<optimized out>, sig=0x7f97ddaf2e48) at ../nptl/sysdeps/unix/sysv/linux/../../../../../sysdeps/unix/sysv/linux/sigwait.c:65
      #1  0x00007f97e910fe29 in __sigwait (set=<optimized out>, sig=<optimized out>) at ../nptl/sysdeps/unix/sysv/linux/../../../../../sysdeps/unix/sysv/linux/sigwait.c:100
      #2  0x000000000055fbce in signal_hand (arg=0x0) at sql/mysqld.cc:3009
      #3  0x0000000000bfa00f in pfs_spawn_thread (arg=0x2407e80) at storage/perfschema/pfs.cc:1015
      #4  0x00007f97e9107efc in start_thread (arg=0x7f97ddaf3700) at pthread_create.c:304
      #5  0x00007f97e847a59d in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:112
      #6  0x0000000000000000 in ?? ()
       
      Thread 4 (Thread 0x7f97ddaab700 (LWP 21823)):
      #0  0x00007fffab9ff92c in clock_gettime ()
      #1  0x00007f97e932107b in __GI_clock_gettime (clock_id=1, tp=0x7f97ddaaa390) at ../sysdeps/unix/clock_gettime.c:100
      #2  0x0000000000ca731d in my_interval_timer () at mysys/my_getsystime.c:52
      #3  0x000000000061b633 in THD::current_utime (this=0x240fb90) at sql/sql_class.h:2508
      #4  0x000000000061b670 in THD::update_server_status (this=0x240fb90) at sql/sql_class.h:2519
      #5  0x000000000060b461 in dispatch_command (command=COM_QUERY, thd=0x240fb90, packet=0x2504841 "", packet_length=20) at sql/sql_parse.cc:1430
      #6  0x0000000000609407 in do_command (thd=0x240fb90) at sql/sql_parse.cc:795
      #7  0x000000000070a50f in do_handle_one_connection (thd_arg=0x240fb90) at sql/sql_connect.cc:1253
      #8  0x0000000000709efa in handle_one_connection (arg=0x240fb90) at sql/sql_connect.cc:1168
      #9  0x0000000000bfa00f in pfs_spawn_thread (arg=0x24adbe0) at storage/perfschema/pfs.cc:1015
      #10 0x00007f97e9107efc in start_thread (arg=0x7f97ddaab700) at pthread_create.c:304
      #11 0x00007f97e847a59d in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:112
      #12 0x0000000000000000 in ?? ()
       
      Thread 3 (Thread 0x7f97e8180700 (LWP 21818)):
      #0  pthread_cond_timedwait@@GLIBC_2.3.2 () at ../nptl/sysdeps/unix/sysv/linux/x86_64/pthread_cond_timedwait.S:216
      #1  0x0000000000cb8fc4 in safe_cond_timedwait (cond=0x1d11520, mp=0x1d11460, abstime=0x7f97e817fdb0, file=0xdfbc60 "include/mysql/psi/mysql_thread.h", line=1012) at mysys/thr_mutex.c:550
      #2  0x000000000098e931 in inline_mysql_cond_timedwait (that=0x1d11520, mutex=0x1d11460, abstime=0x7f97e817fdb0, src_file=0xdfbca0 "storage/maria/ma_servicethread.c", src_line=119) at include/mysql/psi/mysql_thread.h:1012
      #3  0x000000000098ee3b in my_service_thread_sleep (control=0x139faf0, sleep_time=29000000000) at storage/maria/ma_servicethread.c:118
      #4  0x0000000000982b03 in ma_checkpoint_background (arg=0x1e) at storage/maria/ma_checkpoint.c:705
      #5  0x0000000000bfa00f in pfs_spawn_thread (arg=0x23eeab0) at storage/perfschema/pfs.cc:1015
      #6  0x00007f97e9107efc in start_thread (arg=0x7f97e8180700) at pthread_create.c:304
      #7  0x00007f97e847a59d in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:112
      #8  0x0000000000000000 in ?? ()
       
      Thread 2 (Thread 0x7f97e972b740 (LWP 21816)):
      #0  0x00007f97e846e473 in __GI___poll (fds=<optimized out>, nfds=<optimized out>, timeout=<optimized out>) at ../sysdeps/unix/sysv/linux/poll.c:87
      #1  0x00000000005639c4 in handle_connections_sockets () at sql/mysqld.cc:5496
      #2  0x0000000000562cff in mysqld_main (argc=75, argv=0x22cf3c0) at sql/mysqld.cc:4949
      #3  0x000000000055b0e4 in main (argc=6, argv=0x7fffab89fdd8) at sql/main.cc:25
       
      Thread 1 (Thread 0x7f97dda1b700 (LWP 22012)):
      #0  0x00007f97e83cd3a5 in __GI_raise (sig=6) at ../nptl/sysdeps/unix/sysv/linux/raise.c:64
      #1  0x00007f97e83d0b0b in __GI_abort () at abort.c:92
      #2  0x0000000000cb9230 in safe_mutex_destroy (mp=0x2529628, file=0xd61120 "sql/my_apc.cc", line=54) at mysys/thr_mutex.c:604
      #3  0x000000000075917b in Apc_target::destroy (this=0x2529618) at sql/my_apc.cc:54
      #4  0x00000000005d3012 in THD::cleanup (this=0x2527360) at sql/sql_class.cc:1365
      #5  0x000000000055eb97 in thd_cleanup (thd=0x2527360) at sql/mysqld.cc:2396
      #6  0x000000000055ec94 in unlink_thd (thd=0x2527360) at sql/mysqld.cc:2445
      #7  0x000000000055f01f in one_thread_per_connection_end (thd=0x2527360, put_in_cache=true) at sql/mysqld.cc:2559
      #8  0x000000000070a5b5 in do_handle_one_connection (thd_arg=0x2527360) at sql/sql_connect.cc:1264
      #9  0x0000000000709efa in handle_one_connection (arg=0x2527360) at sql/sql_connect.cc:1168
      #10 0x0000000000bfa00f in pfs_spawn_thread (arg=0x24bd030) at storage/perfschema/pfs.cc:1015
      #11 0x00007f97e9107efc in start_thread (arg=0x7f97dda1b700) at pthread_create.c:304
      #12 0x00007f97e847a59d in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:112
      #13 0x0000000000000000 in ?? ()

      Variant 2:

      safe_mutex: Trying to lock unitialized mutex at sql/my_apc.cc, line 149

      Stack trace:

      Thread 5 (Thread 0x7fc230748740 (LWP 22055)):
      #0  0x00007fc22f48b473 in __GI___poll (fds=<optimized out>, nfds=<optimized out>, timeout=<optimized out>) at ../sysdeps/unix/sysv/linux/poll.c:87
      #1  0x00000000005639c4 in handle_connections_sockets () at sql/mysqld.cc:5496
      #2  0x0000000000562cff in mysqld_main (argc=75, argv=0x2d2c3c0) at sql/mysqld.cc:4949
      #3  0x000000000055b0e4 in main (argc=6, argv=0x7fffb5fd3428) at sql/main.cc:25
       
      Thread 4 (Thread 0x7fc224a80700 (LWP 22214)):
      #0  __lll_lock_wait () at ../nptl/sysdeps/unix/sysv/linux/x86_64/lowlevellock.S:136
      #1  0x00007fc23012721b in _L_lock_1031 () from /lib/x86_64-linux-gnu/libpthread.so.0
      #2  0x00007fc23012719c in __pthread_mutex_lock (mutex=0x2f7f868) at pthread_mutex_lock.c:101
      #3  0x0000000000cb84a0 in safe_mutex_lock (mp=0x2f7f840, my_flags=0, file=0xd25b50 "sql/sql_class.cc", line=1376) at mysys/thr_mutex.c:297
      #4  0x00000000005cf668 in inline_mysql_mutex_lock (that=0x2f7f840, src_file=0xd25b50 "sql/sql_class.cc", src_line=1376) at include/mysql/psi/mysql_thread.h:618
      #5  0x00000000005d30d9 in THD::~THD (this=0x2f7e250, __in_chrg=<optimized out>) at sql/sql_class.cc:1376
      #6  0x00000000005d3462 in THD::~THD (this=0x2f7e250, __in_chrg=<optimized out>) at sql/sql_class.cc:1421
      #7  0x000000000055ec32 in delete_thd (thd=0x2f7e250) at sql/mysqld.cc:2425
      #8  0x000000000055ecf0 in unlink_thd (thd=0x2f7e250) at sql/mysqld.cc:2454
      #9  0x000000000055f01f in one_thread_per_connection_end (thd=0x2f7e250, put_in_cache=true) at sql/mysqld.cc:2559
      #10 0x000000000070a5b5 in do_handle_one_connection (thd_arg=0x2f7e250) at sql/sql_connect.cc:1264
      #11 0x0000000000709efa in handle_one_connection (arg=0x2f7e250) at sql/sql_connect.cc:1168
      #12 0x0000000000bfa00f in pfs_spawn_thread (arg=0x2f24d20) at storage/perfschema/pfs.cc:1015
      #13 0x00007fc230124efc in start_thread (arg=0x7fc224a80700) at pthread_create.c:304
      #14 0x00007fc22f49759d in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:112
      #15 0x0000000000000000 in ?? ()
       
      Thread 3 (Thread 0x7fc22f19d700 (LWP 22057)):
      #0  pthread_cond_timedwait@@GLIBC_2.3.2 () at ../nptl/sysdeps/unix/sysv/linux/x86_64/pthread_cond_timedwait.S:216
      #1  0x0000000000cb8fc4 in safe_cond_timedwait (cond=0x1d11520, mp=0x1d11460, abstime=0x7fc22f19cdb0, file=0xdfbc60 "include/mysql/psi/mysql_thread.h", line=1012) at mysys/thr_mutex.c:550
      #2  0x000000000098e931 in inline_mysql_cond_timedwait (that=0x1d11520, mutex=0x1d11460, abstime=0x7fc22f19cdb0, src_file=0xdfbca0 "storage/maria/ma_servicethread.c", src_line=119) at include/mysql/psi/mysql_thread.h:1012
      #3  0x000000000098ee3b in my_service_thread_sleep (control=0x139faf0, sleep_time=29000000000) at storage/maria/ma_servicethread.c:118
      #4  0x0000000000982b03 in ma_checkpoint_background (arg=0x1e) at storage/maria/ma_checkpoint.c:705
      #5  0x0000000000bfa00f in pfs_spawn_thread (arg=0x2e4bab0) at storage/perfschema/pfs.cc:1015
      #6  0x00007fc230124efc in start_thread (arg=0x7fc22f19d700) at pthread_create.c:304
      #7  0x00007fc22f49759d in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:112
      #8  0x0000000000000000 in ?? ()
       
      Thread 2 (Thread 0x7fc224b10700 (LWP 22058)):
      #0  do_sigwait (set=<optimized out>, sig=0x7fc224b0fe48) at ../nptl/sysdeps/unix/sysv/linux/../../../../../sysdeps/unix/sysv/linux/sigwait.c:65
      #1  0x00007fc23012ce29 in __sigwait (set=<optimized out>, sig=<optimized out>) at ../nptl/sysdeps/unix/sysv/linux/../../../../../sysdeps/unix/sysv/linux/sigwait.c:100
      #2  0x000000000055fbce in signal_hand (arg=0x0) at sql/mysqld.cc:3009
      #3  0x0000000000bfa00f in pfs_spawn_thread (arg=0x2e64e80) at storage/perfschema/pfs.cc:1015
      #4  0x00007fc230124efc in start_thread (arg=0x7fc224b10700) at pthread_create.c:304
      #5  0x00007fc22f49759d in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:112
      #6  0x0000000000000000 in ?? ()
       
      Thread 1 (Thread 0x7fc224ac8700 (LWP 22062)):
      #0  __pthread_kill (threadid=<optimized out>, signo=6) at ../nptl/sysdeps/unix/sysv/linux/pthread_kill.c:63
      #1  0x0000000000cb1008 in my_write_core (sig=6) at mysys/stacktrace.c:457
      #2  0x00000000007bf398 in handle_fatal_signal (sig=6) at sql/signal_handler.cc:279
      #3  <signal handler called>
      #4  0x00007fc22f3ea3a5 in __GI_raise (sig=6) at ../nptl/sysdeps/unix/sysv/linux/raise.c:64
      #5  0x00007fc22f3edb0b in __GI_abort () at abort.c:92
      #6  0x0000000000cb83cb in safe_mutex_lock (mp=0x2f80518, my_flags=0, file=0xd61120 "sql/my_apc.cc", line=149) at mysys/thr_mutex.c:250
      #7  0x0000000000759403 in Apc_target::make_apc_call (this=0x2f80508, func=0x5d9086 <Show_explain_request::get_explain_data(void*)>, func_arg=0x7fc224ac6c60, timeout_sec=30, timed_out=0x7fc224ac6d1e) at sql/my_apc.cc:149
      #8  0x0000000000681dd5 in mysqld_show_explain (thd=0x2e6cb90, thread_id=153) at sql/sql_show.cc:2069
      #9  0x000000000060f5b7 in mysql_execute_command (thd=0x2e6cb90) at sql/sql_parse.cc:3154
      #10 0x0000000000616a35 in mysql_parse (thd=0x2e6cb90, rawbuf=0x2f6d328 "SHOW EXPLAIN FOR 153", length=20, parser_state=0x7fc224ac7500) at sql/sql_parse.cc:5758
      #11 0x000000000060a150 in dispatch_command (command=COM_QUERY, thd=0x2e6cb90, packet=0x2f61841 "", packet_length=20) at sql/sql_parse.cc:1056
      #12 0x0000000000609407 in do_command (thd=0x2e6cb90) at sql/sql_parse.cc:795
      #13 0x000000000070a50f in do_handle_one_connection (thd_arg=0x2e6cb90) at sql/sql_connect.cc:1253
      #14 0x0000000000709efa in handle_one_connection (arg=0x2e6cb90) at sql/sql_connect.cc:1168
      #15 0x0000000000bfa00f in pfs_spawn_thread (arg=0x2f0abe0) at storage/perfschema/pfs.cc:1015
      #16 0x00007fc230124efc in start_thread (arg=0x7fc224ac8700) at pthread_create.c:304
      #17 0x00007fc22f49759d in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:112
      #18 0x0000000000000000 in ?? ()

      bzr version-info

      revision-id: psergey@askmonty.org-20120524182239-gq6jtnnovydnthtl
      date: 2012-05-24 22:22:39 +0400
      revno: 3405

      I was able to reproduce it with the provided MTR test case on 3 different machines (Ubuntu 11.10, openSUSE 11.3, Windows Server 2008 R2), all of them 64-bit. Could not reproduce on 32-bit openSUSE.

      Test case:

      let $run = 1000;
       
      while ($run)
      {
        --connect (con1,localhost,root,,test)
        --let $con_id = `SELECT CONNECTION_ID()`
        --connection default
        --send
          eval SHOW EXPLAIN FOR $con_id;
        --disconnect con1
        --connection default
        --error 0,ER_NO_SUCH_THREAD,ER_ERROR_WHEN_EXECUTING_COMMAND
        --reap
        --dec $run
      }

      Attachments

        Issue Links

          Activity

            People

              psergei Sergei Petrunia
              elenst Elena Stepanova
              Votes:
              0 Vote for this issue
              Watchers:
              2 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.