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

shutdown_server 10 times out, causing server kill at shutdown

Details

    Description

      Occasionally, during a test that is restarting the server, a SIGABRT will be sent to the server even though there is no hang. I think that I have seen this happen on buildbot, but I do not know how to efficiently search for this in the cross-reference. The most recent occurrence was in a different CI environment:

      mariadb-10.3.24 with some changes

      		 
      binlog_encryption.encryption_combo 'mix' w8 [ fail ]  Found warnings/errors in server log file!
      		 
              Test ended at 2020-08-18 13:32:30
      		 
      line
      		 
      Attempting backtrace. You can use the following information to find out
      		 
      ^ Found warnings in /var/tmp/mtr/8/log/mysqld.1.err

      According to the server error log file, the signal is triggered during the second shutdown that the test is initiating (by executing the statement shutdown_server 10):

      Version: '10.3.24-8-MariaDB-enterprise-log'  socket: '/var/tmp/mtr/tmp/8/mysqld.1.sock'  port: 16120  MariaDB Enterprise Server
      		 
      2020-08-18 13:32:11 0 [Note] /home/jenkins/workspace/10.3e-DEV-NORMAL/BuildType/RelWithDebInfo/label/ubuntu-1804/bin/mysqld (initiated by: root[root] @ localhost [127.0.0.1]): Normal shutdown
      		 
      2020-08-18 13:32:11 0 [Note] Event Scheduler: Purging the queue. 0 events
      		 
      2020-08-18 13:32:11 0 [Note] InnoDB: FTS optimize thread exiting.
      		 
      2020-08-18 13:32:11 0 [Note] InnoDB: Starting shutdown...
      		 
      2020-08-18 13:32:11 0 [Note] InnoDB: Dumping buffer pool(s) to /var/tmp/mtr/8/mysqld.1/data/ib_buffer_pool
      		 
      2020-08-18 13:32:11 0 [Note] InnoDB: Instance 0, restricted to 127 pages due to innodb_buf_pool_dump_pct=25
      		 
      2020-08-18 13:32:11 0 [Note] InnoDB: Buffer pool(s) dump completed at 200818 13:32:11
      		 
      2020-08-18 13:32:21 0 [Note] InnoDB: Shutdown completed; log sequence number 1629902; transaction id 28
      		 
      200818 13:32:21 [ERROR] mysqld got signal 6 ;
      		 
      This could be because you hit a bug. It is also possible that this binary
      		 
      or one of the libraries it was linked against is corrupt, improperly built,
      		 
      or misconfigured. This error can also be caused by malfunctioning hardware.
      		 
       
      		 
      To report this bug, see https://mariadb.com/kb/en/reporting-bugs
      		 
       
      		 
      We will try our best to scrape up some info that will hopefully help
      		 
      diagnose the problem, but since we have already crashed, 
      something is definitely wrong and this may fail.
      		 
       
      		 
      Server version: 10.3.24-8-MariaDB-enterprise-log
      		 
      key_buffer_size=1048576
      		 
      read_buffer_size=131072
      		 
      max_used_connections=1
      		 
      max_threads=153
      		 
      thread_count=0
      		 
      It is possible that mysqld could use up to 
      key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 63225 K  bytes of memory
      		 
      Hope that's ok; if not, decrease some variables in the equation.
      		 
       
      		 
      Thread pointer: 0x0
      		 
      Attempting backtrace. You can use the following information to find out
      		 
      where mysqld died. If you see no messages after this, something went
      		 
      terribly wrong...
      		 
      stack_bottom = 0x0 thread_stack 0x49000
      		 
      2020-08-18 13:32:22 0 [Note] InnoDB: Removed temporary tablespace data file: "ibtmp1"
      		 
      /home/jenkins/workspace/10.3e-DEV-NORMAL/BuildType/RelWithDebInfo/label/ubuntu-1804/bin/mysqld(my_print_stacktrace+0x2e)[0x55ec00bcaa7e]
      		 
      mysys/stacktrace.c:271(my_print_stacktrace)[0x55ec00656775]
      		 
      /lib/x86_64-linux-gnu/libpthread.so.0(+0x12890)[0x7fa061392890]
      		 
      linux/futex-internal.h:88(futex_wait_cancelable)[0x7fa06138d9f3]
      		 
      2020-08-18 13:32:22 0 [Note] /home/jenkins/workspace/10.3e-DEV-NORMAL/BuildType/RelWithDebInfo/label/ubuntu-1804/bin/mysqld: Shutdown complete
      		 
       
      		 
      psi/mysql_thread.h:1177(inline_mysql_cond_wait)[0x55ec003bc6b1]
      		 
      /lib/x86_64-linux-gnu/libc.so.6(__libc_start_main+0xe7)[0x7fa060889b97]
      		 
      /home/jenkins/workspace/10.3e-DEV-NORMAL/BuildType/RelWithDebInfo/label/ubuntu-1804/bin/mysqld(_start+0x2a)[0x55ec003ae5fa]
      		 
      The manual page at https://mariadb.com/kb/en/how-to-produce-a-full-stack-trace-for-mysqld/ contains
      		 
      information that should help you find out what is causing the crash.
      		 
      Writing a core file...

      In the above output, we can see that the InnoDB shutdown almost completed within those 10 seconds. The last messages are interleaved with the stack trace output.

      In the core dump, only two threads exist: the signal handler, and the main thread. The SIGABRT is delivered to the signal_hand() thread that is executing a syscall inside the following:

      while ((error=my_sigwait(&set,&sig)) == EINTR) ;

      The mysqld_main() is waiting for that thread to terminate:

        mysql_mutex_lock(&LOCK_thread_count);
      		 
        while (!ready_to_exit)
      		 
          mysql_cond_wait(&COND_thread_count, &LOCK_thread_count);
      		 
        mysql_mutex_unlock(&LOCK_thread_count);

      I think that the 10-second timeout is unreasonably short for some CI environments. Many tests are using a 30-second timeout (which is on the border of being questionably short for debug builds), and the default timeout value is 60 seconds.

      Since this change in MariaDB 10.3.1, shutdown timeouts will result in prominent failures, due to a SIGABRT being sent before a final SIGKILL.

      Please fix all tests to use a more reasonable timeout than 10 seconds, and also consider replacing the 30-second timeouts with 60-second ones.

      git grep -w shutdown_server

      to find what to change.

      Attachments

        Activity

          Ascending order - Click to sort in descending order
          Elkin Andrei Elkin added a comment -

          Marko, could you please check out the commit. Thanks. Andrei.

          Elkin Andrei Elkin added a comment - Marko, could you please check out the commit. Thanks. Andrei.
          Elkin Andrei Elkin added a comment -

          Review is done by Marko on slack.

          At merging 10.2->10.3 pick 'ours' for two conflicts (incl a deleted file on 10.3).

          Elkin Andrei Elkin added a comment - Review is done by Marko on slack. At merging 10.2->10.3 pick 'ours' for two conflicts (incl a deleted file on 10.3).
          marko Marko Mäkelä added a comment -

          Thanks, it looks good. In 10.3, there were a few more non-zero arguments to shutdown_server, which I removed on the merge.

          marko Marko Mäkelä added a comment - Thanks, it looks good. In 10.3, there were a few more non-zero arguments to shutdown_server , which I removed on the merge.

          People

            marko Marko Mäkelä
            marko Marko Mäkelä
            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.