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

MTR's internal check of the test case 'innodb.recovery_shutdown' failed due to extra #sql-ib*.ibd files

    Details

      Description

      The test innodb.recovery_shutdown often fails like this:

      10.3 82490a97dbbe1dfdf88ed6b9fee8974cf58c63e3

      innodb.recovery_shutdown 'innodb'        [ pass ]   5680
       
      MTR's internal check of the test case 'innodb.recovery_shutdown' failed.
      This means that the test case does not preserve the state that existed
      before the test case was executed.  Most likely the test case did not
      do a proper clean-up. It could also be caused by the previous test run
      by this thread, if the server wasn't restarted.
      This is the diff of the states of the servers before and after the
      test case was executed:
      mysqltest: Logging to '/dev/shm/10.3/mysql-test/var/tmp/check-mysqld_1.log'.
      mysqltest: Results saved in '/dev/shm/10.3/mysql-test/var/tmp/check-mysqld_1.result'.
      mysqltest: Connecting to server localhost:16000 (socket /dev/shm/10.3/mysql-test/var/tmp/mysqld.1.sock) as 'root', connection 'default', attempt 0 ...
      mysqltest: ... Connected.
      mysqltest: Start processing test commands from './include/check-testcase.test' ...
      mysqltest: ... Done processing test commands.
      --- /dev/shm/10.3/mysql-test/var/tmp/check-mysqld_1.result	2019-01-14 09:00:35.439659687 +0200
      +++ /dev/shm/10.3/mysql-test/var/tmp/check-mysqld_1.reject	2019-01-14 09:00:41.279817227 +0200
      @@ -1059,3 +1059,4 @@
       partition	1.0	DISABLED	STORAGE ENGINE	100313.0	NULL	NULL	Mikael Ronstrom, MySQL AB	Partition Storage Engine Helper	GPL	OFF	Stable	1.0
       VARIABLE_NAME	VARIABLE_VALUE
       DEBUG_SYNC	ON - current signal: ''
      +#sql-ib28.ibd
      

      The reason would be visible in the server error log:

      Version: '10.3.13-MariaDB-debug-log'  socket: '/dev/shm/10.3/mysql-test/var/tmp/mysqld.1.sock'  port: 16000  Source distribution
      2019-01-14  9:00:40 0 [Note] InnoDB: Rolled back recovered transaction 49
      2019-01-14  9:00:41 8 [Note] InnoDB: Deferring DROP TABLE `test`.`t1`; renaming to test/#sql-ib28
      2019-01-14  9:00:41 0 [Note] /dev/shm/10.3/sql/mysqld (initiated by: root[root] @ localhost [127.0.0.1]): Normal shutdown
      

      It is a mystery why this only started failing recently. Nothing has changed since this fix of MDEV-14705: Do not rollback on InnoDB shutdown
      and there has been no relevant change to mysql-test/include/check-testcase.test since this adjustment.
      That is, only a shutdown with innodb_fast_shutdown=0 would wait for the rollback of recovered transactions to complete.
      With this simple fix, the test will stop failing, because no locks would be held by recovered not-yet-rolled-back transactions when the DROP TABLE is executing:

      diff --git a/mysql-test/suite/innodb/t/recovery_shutdown.test b/mysql-test/suite/innodb/t/recovery_shutdown.test
      index d796189c724..9b4a5f337d4 100644
      --- a/mysql-test/suite/innodb/t/recovery_shutdown.test
      +++ b/mysql-test/suite/innodb/t/recovery_shutdown.test
      @@ -51,6 +51,10 @@ FLUSH TABLES;
       --let $shutdown_timeout=60
       --source include/restart_mysqld.inc
       
      +--disable_query_log
      +SET GLOBAL innodb_fast_shutdown=0;
      +--source include/restart_mysqld.inc
      +
       --disable_query_log
       let $c = $trx;
       while ($c)
      

        Attachments

          Issue Links

            Activity

              People

              • Assignee:
                marko Marko Mäkelä
                Reporter:
                marko Marko Mäkelä
              • Votes:
                0 Vote for this issue
                Watchers:
                1 Start watching this issue

                Dates

                • Created:
                  Updated:
                  Resolved: