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

safe_mutex: Trying to lock uninitialized mutex or Got error 22 when trying to lock mutex LOCK_event_queue at sql/event_queue.cc, line 716 upon DROP DATABASE / EVENT upon server shutdown

    XMLWordPrintable

Details

    • Bug
    • Status: Open (View Workflow)
    • Major
    • Resolution: Unresolved
    • 10.1, 10.2, 10.3, 10.4, 10.5
    • 10.4, 10.5
    • Events, Locking
    • None

    Description

      10.3 670c9a3a

      2019-12-05  4:45:32 0 [Note] /ten1/builds/10.3-670c9a3a-deb/bin/mysqld (initiated by: root[root] @ localhost [127.0.0.1]): Normal shutdown
      2019-12-05  4:45:32 0 [Note] Event Scheduler: Purging the queue. 8 events
      2019-12-05  4:45:32 0 [Note] InnoDB: FTS optimize thread exiting.
      safe_mutex: Trying to lock uninitialized mutex at /home/elenst/src/10.3/sql/event_queue.cc, line 716
      191205  4:45:32 [ERROR] mysqld got signal 6 ;
       
      #3  <signal handler called>
      #4  0x00007fe11c33f207 in raise () from /lib64/libc.so.6
      #5  0x00007fe11c3408f8 in abort () from /lib64/libc.so.6
      #6  0x0000559ff438d0ce in safe_mutex_lock (mp=0x559ff8639270, my_flags=0, file=0x559ff460b8c0 "/home/elenst/src/10.3/sql/event_queue.cc", line=716) at /home/elenst/src/10.3/mysys/thr_mutex.c:248
      #7  0x0000559ff3caec66 in inline_mysql_mutex_lock (that=0x559ff8639270, src_file=0x559ff460b8c0 "/home/elenst/src/10.3/sql/event_queue.cc", src_line=716) at /home/elenst/src/10.3/include/mysql/psi/mysql_thread.h:710
      #8  0x0000559ff3cb067f in Event_queue::lock_data (this=0x559ff8639270, func=0x559ff460c000 <Event_queue::drop_schema_events(THD*, st_mysql_const_lex_string const*)::__FUNCTION__> "drop_schema_events", line=389) at /home/elenst/src/10.3/sql/event_queue.cc:716
      #9  0x0000559ff3cafa44 in Event_queue::drop_schema_events (this=0x559ff8639270, thd=0x7fe0a0000b90, schema=0x7fe0ec176de0) at /home/elenst/src/10.3/sql/event_queue.cc:389
      #10 0x0000559ff38f4bbc in Events::drop_schema_events (thd=0x7fe0a0000b90, db=0x7fe0a0011568 "t") at /home/elenst/src/10.3/sql/events.cc:658
      #11 0x0000559ff375847e in mysql_rm_db_internal (thd=0x7fe0a0000b90, db=0x7fe0a0005640, if_exists=true, silent=false) at /home/elenst/src/10.3/sql/sql_db.cc:929
      #12 0x0000559ff3758af2 in mysql_rm_db (thd=0x7fe0a0000b90, db=0x7fe0a0005640, if_exists=true) at /home/elenst/src/10.3/sql/sql_db.cc:1055
      #13 0x0000559ff37af751 in mysql_execute_command (thd=0x7fe0a0000b90) at /home/elenst/src/10.3/sql/sql_parse.cc:4981
      #14 0x0000559ff37b8ccb in mysql_parse (thd=0x7fe0a0000b90, rawbuf=0x7fe0a0011488 "DROP DATABASE IF EXISTS t /* QNO 16092 CON_ID 13 */", length=51, parser_state=0x7fe0ec1785e0, is_com_multi=false, is_next_command=false) at /home/elenst/src/10.3/sql/sql_parse.cc:7818
      #15 0x0000559ff37a590d in dispatch_command (command=COM_QUERY, thd=0x7fe0a0000b90, packet=0x7fe0a0071b91 "DROP DATABASE IF EXISTS t /* QNO 16092 CON_ID 13 */ ", packet_length=52, is_com_multi=false, is_next_command=false) at /home/elenst/src/10.3/sql/sql_parse.cc:1856
      #16 0x0000559ff37a41a2 in do_command (thd=0x7fe0a0000b90) at /home/elenst/src/10.3/sql/sql_parse.cc:1402
      #17 0x0000559ff391d9c3 in do_handle_one_connection (connect=0x559ff86390c0) at /home/elenst/src/10.3/sql/sql_connect.cc:1403
      #18 0x0000559ff391d705 in handle_one_connection (arg=0x559ff86390c0) at /home/elenst/src/10.3/sql/sql_connect.cc:1308
      #19 0x0000559ff3d138ef in pfs_spawn_thread (arg=0x559ff8648b70) at /home/elenst/src/10.3/storage/perfschema/pfs.cc:1862
      #20 0x00007fe11d975dd5 in start_thread () from /lib64/libpthread.so.0
      #21 0x00007fe11c406ead in clone () from /lib64/libc.so.6
      

      10.3 61c0df94

      2020-04-26  4:30:36 0 [Note] /ten1/builds/10.3-61c0df94-deb/bin/mysqld (initiated by: root[root] @ localhost [127.0.0.1]): Normal shutdown
      2020-04-26  4:30:36 0 [Note] InnoDB: FTS optimize thread exiting.
      2020-04-26  4:30:36 0 [Note] Event Scheduler: Purging the queue. 11 events
      Got error 22 when trying to lock mutex LOCK_event_queue at /home/elenst/src/10.3/sql/event_queue.cc, line 716
      200426  4:30:36 [ERROR] mysqld got signal 6 ;
       
      #3  <signal handler called>
      #4  0x00007f19a280f207 in raise () from /lib64/libc.so.6
      #5  0x00007f19a28108f8 in abort () from /lib64/libc.so.6
      #6  0x000055f94ad6b303 in safe_mutex_lock (mp=0x55f94f0e3870, my_flags=0, file=0x55f94b002080 "/home/elenst/src/10.3/sql/event_queue.cc", line=716) at /home/elenst/src/10.3/mysys/thr_mutex.c:300
      #7  0x000055f94a68adf4 in inline_mysql_mutex_lock (that=0x55f94f0e3870, src_file=0x55f94b002080 "/home/elenst/src/10.3/sql/event_queue.cc", src_line=716) at /home/elenst/src/10.3/include/mysql/psi/mysql_thread.h:717
      #8  0x000055f94a68c80d in Event_queue::lock_data (this=0x55f94f0e3870, func=0x55f94b0027c0 <Event_queue::drop_schema_events(THD*, st_mysql_const_lex_string const*)::__FUNCTION__> "drop_schema_events", line=389) at /home/elenst/src/10.3/sql/event_queue.cc:716
      #9  0x000055f94a68bbd2 in Event_queue::drop_schema_events (this=0x55f94f0e3870, thd=0x7f1924000af0, schema=0x7f197c50de30) at /home/elenst/src/10.3/sql/event_queue.cc:389
      #10 0x000055f94a2cefc6 in Events::drop_schema_events (thd=0x7f1924000af0, db=0x7f19240115c8 "g") at /home/elenst/src/10.3/sql/events.cc:658
      #11 0x000055f94a132176 in mysql_rm_db_internal (thd=0x7f1924000af0, db=0x7f1924005598, if_exists=true, silent=false) at /home/elenst/src/10.3/sql/sql_db.cc:929
      #12 0x000055f94a1327ea in mysql_rm_db (thd=0x7f1924000af0, db=0x7f1924005598, if_exists=true) at /home/elenst/src/10.3/sql/sql_db.cc:1055
      #13 0x000055f94a1892e3 in mysql_execute_command (thd=0x7f1924000af0) at /home/elenst/src/10.3/sql/sql_parse.cc:4980
      #14 0x000055f94a192835 in mysql_parse (thd=0x7f1924000af0, rawbuf=0x7f19240114e8 "DROP /* QNO 13747 CON_ID 14 */ DATABASE IF EXISTS g", length=51, parser_state=0x7f197c50f630, is_com_multi=false, is_next_command=false) at /home/elenst/src/10.3/sql/sql_parse.cc:7817
      #15 0x000055f94a17f4b6 in dispatch_command (command=COM_QUERY, thd=0x7f1924000af0, packet=0x7f19241171c1 "DROP /* QNO 13747 CON_ID 14 */ DATABASE IF EXISTS g", packet_length=51, is_com_multi=false, is_next_command=false) at /home/elenst/src/10.3/sql/sql_parse.cc:1856
      #16 0x000055f94a17dd48 in do_command (thd=0x7f1924000af0) at /home/elenst/src/10.3/sql/sql_parse.cc:1402
      #17 0x000055f94a2f7df9 in do_handle_one_connection (connect=0x55f94f0adaa0) at /home/elenst/src/10.3/sql/sql_connect.cc:1403
      #18 0x000055f94a2f7b3b in handle_one_connection (arg=0x55f94f0adaa0) at /home/elenst/src/10.3/sql/sql_connect.cc:1308
      #19 0x00007f19a3e45dd5 in start_thread () from /lib64/libpthread.so.0
      #20 0x00007f19a28d6ead in clone () from /lib64/libc.so.6
      

      For the first failure, I have a test with a debug injection which makes it quite reproducible (although not 100%). Currently applicable to all of 10.1-10.5:

      Injection

      diff --git a/sql/event_queue.cc b/sql/event_queue.cc
      index 6b3f5777df3..671f2a96220 100644
      --- a/sql/event_queue.cc
      +++ b/sql/event_queue.cc
      @@ -713,6 +713,7 @@ Event_queue::lock_data(const char *func, uint line)
         mutex_last_attempted_lock_in_func= func;
         mutex_last_attempted_lock_at_line= line;
         mutex_queue_data_attempting_lock= TRUE;
      +  DBUG_EXECUTE_IF("sleep_event_queue",my_sleep(1000000););
         mysql_mutex_lock(&LOCK_event_queue);
         mutex_last_attempted_lock_in_func= "";
         mutex_last_attempted_lock_at_line= 0;
      

      Test

      CREATE DATABASE db;
      CREATE EVENT db.ev ON SCHEDULE EVERY 1 MINUTE DO SELECT 1;
      --connect (con1,localhost,root,,)
      SET DEBUG_DBUG='+d,sleep_event_queue';
      --send
        DROP DATABASE db;
       
      --connection default  
        shutdown;
      

      Or a variation with dropping only event, not the database (with a correspondingly different stack trace):

      CREATE EVENT ev ON SCHEDULE EVERY 1 MINUTE DO SELECT 1;
      --connect (con1,localhost,root,,)
      SET DEBUG_DBUG='+d,sleep_event_queue';
      --send
        DROP EVENT ev;
       
      --connection default  
        shutdown;
      

      The second failure, error 22, actually happens more often in the concurrent tests, but I don't have an injection for it. Both happen on server shutdown are otherwise very similar, I hope they will be solved together. All threads' stack trace for the second failure is attached as error22_all_threads.

      Attachments

        Issue Links

          Activity

            People

              sanja Oleksandr Byelkin
              elenst Elena Stepanova
              Votes:
              0 Vote for this issue
              Watchers:
              1 Start watching this issue

              Dates

                Created:
                Updated:

                Git Integration

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