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

MariaDB start is slow

Details

    Description

      It takes about 10 mins to start, had seen the same issue earlier in 10.1.18 which was fixed but has reoccurred in 10.1.22

      2017-04-27 15:48:10 139983869696032 [Warning] option 'general_log': boolean value 'xxxxx.log' wasn't recognized. Set to OFF.
      		 
      2017-04-27 15:48:10 139983869696032 [Warning] 'THREAD_CONCURRENCY' is deprecated and will be removed in a future release.
      		 
      2017-04-27 15:48:10 139983869696032 [Note] /usr/libexec/mysqld (mysqld 10.1.22-MariaDB) starting as process 19851 ...
      		 
      2017-04-27 15:48:12 7f5088d3d820 InnoDB: Warning: Using innodb_additional_mem_pool_size is DEPRECATED. This option may be removed in future releases, together with the option innodb_use_sys_malloc and with the InnoDB's internal memory allocator.
      		 
      2017-04-27 15:48:12 139983869696032 [Note] InnoDB: Using mutexes to ref count buffer pool pages
      		 
      2017-04-27 15:48:12 139983869696032 [Note] InnoDB: The InnoDB memory heap is disabled
      		 
      2017-04-27 15:48:12 139983869696032 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
      		 
      2017-04-27 15:48:12 139983869696032 [Note] InnoDB: GCC builtin __sync_synchronize() is used for memory barrier
      		 
      2017-04-27 15:48:12 139983869696032 [Note] InnoDB: Compressed tables use zlib 1.2.3
      		 
      2017-04-27 15:48:12 139983869696032 [Note] InnoDB: Using Linux native AIO
      		 
      2017-04-27 15:48:12 139983869696032 [Note] InnoDB: Using SSE crc32 instructions
      		 
      2017-04-27 15:48:12 139983869696032 [Note] InnoDB: Initializing buffer pool, size = 2.0G
      		 
      2017-04-27 15:48:12 139983869696032 [Note] InnoDB: Completed initialization of buffer pool
      		 
      2017-04-27 15:48:13 139983869696032 [Note] InnoDB: Highest supported file format is Barracuda.
      		 
      2017-04-27 15:58:24 139983869696032 [Note] InnoDB: 128 rollback segment(s) are active.
      		 
      2017-04-27 15:58:24 139983869696032 [Note] InnoDB: Waiting for purge to start
      		 
      2017-04-27 15:58:24 139983869696032 [Note] InnoDB:  Percona XtraDB (http://www.percona.com) 5.6.35-80.0 started; log sequence number 657936019547
      		 
      2017-04-27 15:58:25 139980747806464 [Note] InnoDB: Dumping buffer pool(s) not yet started
      		 
      2017-04-27 15:58:25 139983869696032 [Note] Plugin 'FEEDBACK' is disabled.
      		 
      2017-04-27 15:58:25 139983869696032 [Note] Server socket created on IP: '::'.
      		 
      2017-04-27 15:58:25 139983869696032 [Note] /usr/libexec/mysqld: ready for connections.
      		 
      Version: '10.1.22-MariaDB'  socket: 'xxxxx.sock'  port: 3306  MariaDB Server

      Attachments

        Issue Links

          is caused by

          Bug - A problem which impairs or prevents the functions of the product. MDEV-12623 InnoDB: Failing assertion: kv == 0 || kv >= crypt_data->min_key_version, encryption.innodb_encryption_tables failed in buildbot

          • Major - Major loss of function.
          • Closed
          is duplicated by

          Bug - A problem which impairs or prevents the functions of the product. MDEV-15333 MariaDB (still) slow start

          • Major - Major loss of function.
          • Closed
          relates to

          Bug - A problem which impairs or prevents the functions of the product. MDEV-9931 InnoDB reads first page of every .ibd file at startup

          • Major - Major loss of function.
          • Closed

          Bug - A problem which impairs or prevents the functions of the product. MDEV-21715 Allow loading buffer pool dumps for encrypted tablespaces

          • Major - Major loss of function.
          • Open

          Bug - A problem which impairs or prevents the functions of the product. MDEV-10198 MariaDB restart is too slow

          • Major - Major loss of function.
          • Closed

          Activity

            Ascending order - Click to sort in descending order
            View 12 older comments
            danblack Daniel Black added a comment -

            Logs and configuration would help verify this.

            danblack Daniel Black added a comment - Logs and configuration would help verify this.
            lu_nate Nathan Landis added a comment -

            Apologies! Log and config below from the latest version I tried (10.2.7). I'm using MySQL Sandbox for intermediate upgrade testing. I know I'm several releases behind on that, upgrading and retrying (or trying an instance without sandbox) is on my todo list.

            180126 16:26:03 mysqld_safe Starting mysqld daemon with databases from /redacted/dir
            2018-01-26 16:26:03 139690100025120 [Note] /redacted/10.2.7/bin/mysqld (mysqld 10.2.7-MariaDB) starting as process 20851 ...
            2018-01-26 16:26:04 139690100025120 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
            2018-01-26 16:26:04 139690100025120 [Note] InnoDB: Uses event mutexes
            2018-01-26 16:26:04 139690100025120 [Note] InnoDB: Compressed tables use zlib 1.2.3
            2018-01-26 16:26:04 139690100025120 [Note] InnoDB: Using Linux native AIO
            2018-01-26 16:26:04 139690100025120 [Note] InnoDB: Number of pools: 1
            2018-01-26 16:26:04 139690100025120 [Note] InnoDB: Using SSE2 crc32 instructions
            2018-01-26 16:26:04 139690100025120 [Note] InnoDB: Initializing buffer pool, total size = 128M, instances = 1, chunk size = 128M
            2018-01-26 16:26:04 139690100025120 [Note] InnoDB: Completed initialization of buffer pool
            2018-01-26 16:26:04 139689372313344 [Note] InnoDB: If the mysqld execution user is authorized, page cleaner thread priority can be changed. See the man page of setpriority().
            2018-01-26 16:26:04 139690100025120 [Note] InnoDB: Highest supported file format is Barracuda.
            2018-01-26 16:37:23 139690100025120 [Note] InnoDB: 128 out of 128 rollback segments are active.
            2018-01-26 16:37:23 139690100025120 [Note] InnoDB: Creating shared tablespace for temporary tables
            2018-01-26 16:37:23 139690100025120 [Note] InnoDB: Setting file './ibtmp1' size to 12 MB. Physically writing the file full; Please wait ...
            2018-01-26 16:37:23 139690100025120 [Note] InnoDB: File './ibtmp1' size is now 12 MB.
            2018-01-26 16:37:23 139690100025120 [Note] InnoDB: Waiting for purge to start
            2018-01-26 16:37:23 139690100025120 [Note] InnoDB: 5.7.18 started; log sequence number 243661604721
            2018-01-26 16:37:23 139690100025120 [Note] Plugin 'FEEDBACK' is disabled.
            2018-01-26 16:37:23 139690100025120 [Note] Server socket created on IP: '127.0.0.1'.
            2018-01-26 16:37:24 139690100025120 [Note] Reading of all Master_info entries succeded
            2018-01-26 16:37:24 139690100025120 [Note] Added new Master_info '' to hash table
            2018-01-26 16:37:24 139690100025120 [Note] /redacted/10.2.7/bin/mysqld: ready for connections.
            Version: '10.2.7-MariaDB' socket: '/tmp/mysql_sandbox10207.sock' port: 10207 MariaDB Server

            ---config:

            [mysql]
            prompt='mysql [\h]

            {\u}

            (\d) > '
            #

            [client]
            user = redacted
            password = redacted
            port = 10207
            socket = /tmp/mysql_sandbox10207.sock

            [mysqld]
            user = mysql
            port = 10207
            socket = /tmp/mysql_sandbox10207.sock
            basedir = /redacted/10.2.7
            datadir = /redacted/sandbox/shared-data #msb_10_2_7/data
            tmpdir = /redacted/sandbox/msb_10_2_7/tmp
            lower_case_table_names = 0
            pid-file = /redacted/sandbox/msb_10_2_7/data/mysql_sandbox10207.pid
            bind-address = 127.0.0.1

            1. log-slow-queries = /redacted/sandbox/msb_10_2_7/data/msandbox-slow.log
            2. log = /redacted/sandbox/msb_10_2_7/data/msandbox-general.log
              #
            3. additional options passed through 'my_clause'
              #
              log-error=/redacted/sandbox/msb_10_2_7/msandbox.err
              innodb_buffer_pool_load_at_startup = OFF
            lu_nate Nathan Landis added a comment - Apologies! Log and config below from the latest version I tried (10.2.7). I'm using MySQL Sandbox for intermediate upgrade testing. I know I'm several releases behind on that, upgrading and retrying (or trying an instance without sandbox) is on my todo list. 180126 16:26:03 mysqld_safe Starting mysqld daemon with databases from /redacted/dir 2018-01-26 16:26:03 139690100025120 [Note] /redacted/10.2.7/bin/mysqld (mysqld 10.2.7-MariaDB) starting as process 20851 ... 2018-01-26 16:26:04 139690100025120 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins 2018-01-26 16:26:04 139690100025120 [Note] InnoDB: Uses event mutexes 2018-01-26 16:26:04 139690100025120 [Note] InnoDB: Compressed tables use zlib 1.2.3 2018-01-26 16:26:04 139690100025120 [Note] InnoDB: Using Linux native AIO 2018-01-26 16:26:04 139690100025120 [Note] InnoDB: Number of pools: 1 2018-01-26 16:26:04 139690100025120 [Note] InnoDB: Using SSE2 crc32 instructions 2018-01-26 16:26:04 139690100025120 [Note] InnoDB: Initializing buffer pool, total size = 128M, instances = 1, chunk size = 128M 2018-01-26 16:26:04 139690100025120 [Note] InnoDB: Completed initialization of buffer pool 2018-01-26 16:26:04 139689372313344 [Note] InnoDB: If the mysqld execution user is authorized, page cleaner thread priority can be changed. See the man page of setpriority(). 2018-01-26 16:26:04 139690100025120 [Note] InnoDB: Highest supported file format is Barracuda. 2018-01-26 16:37:23 139690100025120 [Note] InnoDB: 128 out of 128 rollback segments are active. 2018-01-26 16:37:23 139690100025120 [Note] InnoDB: Creating shared tablespace for temporary tables 2018-01-26 16:37:23 139690100025120 [Note] InnoDB: Setting file './ibtmp1' size to 12 MB. Physically writing the file full; Please wait ... 2018-01-26 16:37:23 139690100025120 [Note] InnoDB: File './ibtmp1' size is now 12 MB. 2018-01-26 16:37:23 139690100025120 [Note] InnoDB: Waiting for purge to start 2018-01-26 16:37:23 139690100025120 [Note] InnoDB: 5.7.18 started; log sequence number 243661604721 2018-01-26 16:37:23 139690100025120 [Note] Plugin 'FEEDBACK' is disabled. 2018-01-26 16:37:23 139690100025120 [Note] Server socket created on IP: '127.0.0.1'. 2018-01-26 16:37:24 139690100025120 [Note] Reading of all Master_info entries succeded 2018-01-26 16:37:24 139690100025120 [Note] Added new Master_info '' to hash table 2018-01-26 16:37:24 139690100025120 [Note] /redacted/10.2.7/bin/mysqld: ready for connections. Version: '10.2.7-MariaDB' socket: '/tmp/mysql_sandbox10207.sock' port: 10207 MariaDB Server ---config: [mysql] prompt='mysql [\h] {\u} (\d) > ' # [client] user = redacted password = redacted port = 10207 socket = /tmp/mysql_sandbox10207.sock [mysqld] user = mysql port = 10207 socket = /tmp/mysql_sandbox10207.sock basedir = /redacted/10.2.7 datadir = /redacted/sandbox/shared-data #msb_10_2_7/data tmpdir = /redacted/sandbox/msb_10_2_7/tmp lower_case_table_names = 0 pid-file = /redacted/sandbox/msb_10_2_7/data/mysql_sandbox10207.pid bind-address = 127.0.0.1 log-slow-queries = /redacted/sandbox/msb_10_2_7/data/msandbox-slow.log log = /redacted/sandbox/msb_10_2_7/data/msandbox-general.log # additional options passed through 'my_clause' # log-error=/redacted/sandbox/msb_10_2_7/msandbox.err innodb_buffer_pool_load_at_startup = OFF
            marko Marko Mäkelä added a comment -

            lu_nate, MDEV-13869 was introduced in MariaDB 10.2.2 and has not been fixed yet.

            marko Marko Mäkelä added a comment - lu_nate , MDEV-13869 was introduced in MariaDB 10.2.2 and has not been fixed yet.
            lu_nate Nathan Landis added a comment -

            Ah, that is very helpful Marko, I missed seeing that issue. I will stop banging my head against in now . Thanks for taking the time to reply!

            lu_nate Nathan Landis added a comment - Ah, that is very helpful Marko, I missed seeing that issue. I will stop banging my head against in now . Thanks for taking the time to reply!
            marko Marko Mäkelä added a comment -

            As noted in MDEV-15333, I failed to merge this fix fully to MariaDB 10.2.7. I will try to fix it by 10.2.14, and will write a test to cover this with some instrumentation.

            marko Marko Mäkelä added a comment - As noted in MDEV-15333 , I failed to merge this fix fully to MariaDB 10.2.7. I will try to fix it by 10.2.14, and will write a test to cover this with some instrumentation.

            People

              jplindst Jan Lindström (Inactive)
              dgavhane Darshit Gavhane
              Votes:
              2 Vote for this issue
              Watchers:
              10 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.