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

Server shuts down in unclean fashion after failing to start with a wrong value of innodb_undo_tablespaces

Details

    Description

      Note: I'm not sure it's actually an InnoDB problem, please change the category and re-assign if needed.

      To reproduce,

      • create a datadir with the default innodb_undo_tablespaces=0,
      • start the server with another value, e.g. --innodb_undo_tablespaces=2.

      The error is expected in this case, but what happens after it appears to be wrong.

      On 10.2:

      2016-12-30 13:08:15 139840456656768 [Note] InnoDB: Created tablespace for space 4294967280 name innodb_redo_log key_id 0 encryption 0
      2016-12-30 13:08:15 139840456656768 [ERROR] InnoDB: Expected to open 2 undo tablespaces but was able to find only 0 undo tablespaces. Set the innodb_undo_tablespaces parameter to the correct value and retry. Suggested value is 0
      2016-12-30 13:08:15 139840456656768 [ERROR] InnoDB: Plugin initialization aborted at srv0start.cc[2112] with error Generic error
      2016-12-30 13:08:15 139840456656768 [ERROR] Plugin 'InnoDB' init function returned error.
      2016-12-30 13:08:15 139840456656768 [ERROR] Plugin 'InnoDB' registration as a STORAGE ENGINE failed.
      2016-12-30 13:08:15 139840456656768 [Note] Plugin 'FEEDBACK' is disabled.
      2016-12-30 13:08:15 139840456656768 [ERROR] Unknown/unsupported storage engine: InnoDB
      2016-12-30 13:08:15 139840456656768 [ERROR] Aborting
       
      2016-12-30 13:08:15 139840456656768 [ERROR] Plugin 'MyISAM' has ref_count=1 after shutdown.
      Error in my_thread_global_end(): 1 threads didn't exit
      mysqld: /data/src/10.2/sql/mysqld.cc:2154: void mysqld_exit(int): Assertion `global_status_var.global_memory_used == 0' failed.
      161230 13:08:21 [ERROR] mysqld got signal 6 ;
      ...
      

      On 10.1, there is no assertion failure or ref_count problem, but it seems that the process just disappears without proper shut down:

      2016-12-30 13:11:38 140051651819392 [Note] InnoDB: Created tablespace for space 0 name ./ibdata1 key_id 1 encryption 0.
      2016-12-30 13:11:38 140051651819392 [Note] InnoDB: Created tablespace for space 4294967280 name ./ib_logfile0 key_id 0 encryption 0.
      2016-12-30 13:11:38 140051651819392 [Note] InnoDB: Created tablespace for space 4294967281 name arch_log_space key_id 0 encryption 0.
      2016-12-30 13:11:38 7f6050f4f780 InnoDB: Expected to open 2 undo tablespaces but was able
      2016-12-30 13:11:38 7f6050f4f780 InnoDB: to find only 0 undo tablespaces.
      2016-12-30 13:11:38 7f6050f4f780 InnoDB: Set the innodb_undo_tablespaces parameter to the
      2016-12-30 13:11:38 7f6050f4f780 InnoDB: correct value and retry. Suggested value is 0
      2016-12-30 13:11:38 140051651819392 [ERROR] Plugin 'InnoDB' init function returned error.
      2016-12-30 13:11:38 140051651819392 [ERROR] Plugin 'InnoDB' registration as a STORAGE ENGINE failed.
      2016-12-30 13:11:38 140051651819392 [Note] Plugin 'FEEDBACK' is disabled.
      2016-12-30 13:11:38 140051651819392 [ERROR] Unknown/unsupported storage engine: InnoDB
      2016-12-30 13:11:38 140051651819392 [ERROR] Aborting
      

      MySQL 5.6, 5.7, MariaDB 5.5, 10.0 perform the shutdown, e.g. on 10.0:

      2016-12-30 13:11:02 7f9fc17a6780 InnoDB: Expected to open 2 undo tablespaces but was able
      2016-12-30 13:11:02 7f9fc17a6780 InnoDB: to find only 0 undo tablespaces.
      2016-12-30 13:11:02 7f9fc17a6780 InnoDB: Set the innodb_undo_tablespaces parameter to the
      2016-12-30 13:11:02 7f9fc17a6780 InnoDB: correct value and retry. Suggested value is 0
      161230 13:11:02 [ERROR] Plugin 'InnoDB' init function returned error.
      161230 13:11:02 [ERROR] Plugin 'InnoDB' registration as a STORAGE ENGINE failed.
      161230 13:11:02 [ERROR] Unknown/unsupported storage engine: InnoDB
      161230 13:11:02 [ERROR] Aborting
       
      161230 13:11:02 [Note] /data/bld/10.0/bin/mysqld: Shutdown complete
      

      Attachments

        Issue Links

          Activity

            I suspect that this does not affect 10.1 at all, but only 10.2. I will compile&test 10.1.

            marko Marko Mäkelä added a comment - I suspect that this does not affect 10.1 at all, but only 10.2. I will compile&test 10.1.

            I was unable to repeat this in 10.1 with the following test:

            --source include/have_innodb.inc
            let $restart_parameters= --innodb-undo-tablespaces=2;
            --source include/restart_mysqld.inc
            

            This resulted in an aborted InnoDB startup as follows:

            2017-01-03 13:38:04 7fca82302740 InnoDB: Expected to open 2 undo tablespaces but was able
            2017-01-03 13:38:04 7fca82302740 InnoDB: to find only 0 undo tablespaces.
            2017-01-03 13:38:04 7fca82302740 InnoDB: Set the innodb_undo_tablespaces parameter to the
            2017-01-03 13:38:04 7fca82302740 InnoDB: correct value and retry. Suggested value is 0
            2017-01-03 13:38:04 140507744315200 [ERROR] Plugin 'InnoDB' init function returned error.
            2017-01-03 13:38:04 140507744315200 [ERROR] Plugin 'InnoDB' registration as a STORAGE ENGINE failed.
            …
            2017-01-03 13:38:04 140507744315200 [Note] Server socket created on IP: '127.0.0.1'.
            2017-01-03 13:38:04 140507744315200 [Note] /dev/shm/t/sql/mysqld: ready for connections.
            Version: '10.1.21-MariaDB-debug'  socket: '/dev/shm/t/mysql-test/var/tmp/mysqld.1.sock'  port: 16000  Source distribution
            

            I reran the test under --manual-gdb (appending --innodb-undo-tablespaces=2 to the arguments when restarting mysqld), and I did not observe any problem in th 10.1.21 shutdown:

            2017-01-03 13:40:56 140737225456384 [Note] /dev/shm/t/sql/mysqld: Normal shutdown
             
            2017-01-03 13:40:56 140737225456384 [Note] Event Scheduler: Purging the queue. 0 events
            [Thread 0x7ffff0591b00 (LWP 18670) exited]
            [Thread 0x7fffebfff700 (LWP 18662) exited]
            [Thread 0x7ffff2248700 (LWP 18661) exited]
            2017-01-03 13:40:56 140737225456384 [Note] Debug sync points hit:                   167
            2017-01-03 13:40:56 140737225456384 [Note] Debug sync points executed:              0
            2017-01-03 13:40:56 140737225456384 [Note] Debug sync points max active per thread: 0
            2017-01-03 13:40:56 140737225456384 [Note] /dev/shm/t/sql/mysqld: Shutdown complete
            

            marko Marko Mäkelä added a comment - I was unable to repeat this in 10.1 with the following test: --source include/have_innodb.inc let $restart_parameters= --innodb-undo-tablespaces=2; --source include/restart_mysqld.inc This resulted in an aborted InnoDB startup as follows: 2017-01-03 13:38:04 7fca82302740 InnoDB: Expected to open 2 undo tablespaces but was able 2017-01-03 13:38:04 7fca82302740 InnoDB: to find only 0 undo tablespaces. 2017-01-03 13:38:04 7fca82302740 InnoDB: Set the innodb_undo_tablespaces parameter to the 2017-01-03 13:38:04 7fca82302740 InnoDB: correct value and retry. Suggested value is 0 2017-01-03 13:38:04 140507744315200 [ERROR] Plugin 'InnoDB' init function returned error. 2017-01-03 13:38:04 140507744315200 [ERROR] Plugin 'InnoDB' registration as a STORAGE ENGINE failed. … 2017-01-03 13:38:04 140507744315200 [Note] Server socket created on IP: '127.0.0.1'. 2017-01-03 13:38:04 140507744315200 [Note] /dev/shm/t/sql/mysqld: ready for connections. Version: '10.1.21-MariaDB-debug' socket: '/dev/shm/t/mysql-test/var/tmp/mysqld.1.sock' port: 16000 Source distribution I reran the test under --manual-gdb (appending --innodb-undo-tablespaces=2 to the arguments when restarting mysqld), and I did not observe any problem in th 10.1.21 shutdown: 2017-01-03 13:40:56 140737225456384 [Note] /dev/shm/t/sql/mysqld: Normal shutdown   2017-01-03 13:40:56 140737225456384 [Note] Event Scheduler: Purging the queue. 0 events [Thread 0x7ffff0591b00 (LWP 18670) exited] [Thread 0x7fffebfff700 (LWP 18662) exited] [Thread 0x7ffff2248700 (LWP 18661) exited] 2017-01-03 13:40:56 140737225456384 [Note] Debug sync points hit: 167 2017-01-03 13:40:56 140737225456384 [Note] Debug sync points executed: 0 2017-01-03 13:40:56 140737225456384 [Note] Debug sync points max active per thread: 0 2017-01-03 13:40:56 140737225456384 [Note] /dev/shm/t/sql/mysqld: Shutdown complete
            elenst Elena Stepanova added a comment - - edited

            To reproduce the missing "mysqld: Shutdown complete" on 10.1, one needs to have InnoDB as a default storage engine. MTR sets it to MyISAM, so you need to run the test with --mysqld=--default-storage-engine=InnoDB.

            elenst Elena Stepanova added a comment - - edited To reproduce the missing "mysqld: Shutdown complete" on 10.1, one needs to have InnoDB as a default storage engine. MTR sets it to MyISAM, so you need to run the test with --mysqld=--default-storage-engine=InnoDB .

            When this is fixed, the workarounds in the test innodb.log_file_size should be removed. (Add --core-file and remove all ,134 to repeat the problem.)
            That test does not repeat the problem in 10.0 or 10.1.

            marko Marko Mäkelä added a comment - When this is fixed, the workarounds in the test innodb.log_file_size should be removed. (Add --core-file and remove all ,134 to repeat the problem.) That test does not repeat the problem in 10.0 or 10.1.

            In 10.2, also the test innodb.log_file needed workarounds for this bug, so please uncomment the core_file and remove all ,134 when fixing this bug.
            Curiously, innodb.log_corruption (which is trying to start up InnoDB with various corrupted redo log files) appears to be unaffected by this problem.

            marko Marko Mäkelä added a comment - In 10.2, also the test innodb.log_file needed workarounds for this bug, so please uncomment the core_file and remove all ,134 when fixing this bug. Curiously, innodb.log_corruption (which is trying to start up InnoDB with various corrupted redo log files) appears to be unaffected by this problem.

            Fixed in 30ba3100579

            serg Sergei Golubchik added a comment - Fixed in 30ba3100579

            People

              serg Sergei Golubchik
              elenst Elena Stepanova
              Votes:
              0 Vote for this issue
              Watchers:
              3 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.