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

Assertion oldest_lsn >= log_sys.last_checkpoint_lsn failed in log_checkpoint()

Details

    Description

      Every now and then, especially in IMPORT TABLESPACE tests, we encounter an assertion failure in log_checkpoint():

      10.5

      #7  0x000055cadaf300cb in log_checkpoint ()
          at /mariadb/10.5-MDEV-12353/storage/innobase/log/log0log.cc:1367
      1367		ut_ad(oldest_lsn >= log_sys.last_checkpoint_lsn);
      (gdb) i lo
      oldest_lsn = 93891
      flush_lsn = <optimized out>
      end_lsn = <optimized out>
      do_write = <optimized out>
      

      (gdb) p log_sys.last_checkpoint_lsn
      $1 = 93906
      (gdb) p log_sys.next_checkpoint_lsn
      $2 = 93906
      (gdb) p log_sys.last_checkpoint_lsn-oldest_lsn
      $3 = 15
      (gdb) p log_sys.lsn
      $4 = {<std::__atomic_base<unsigned long>> = {_M_i = 121116}, <No data fields>}

       

      The difference is more than the size of FILE_CHECKPOINT record, which is 12 bytes.

      If I understand it correctly, the the assertion is reporting that the previous checkpoint was too long ago, and we were not actually crash-safe. This is an indication that a log_free_check() call is missing. I do not see any call to in row0import.cc. The function row_import_for_mysql() is writing a small amount of redo log in trx_undo_assign().

      I have the feeling that this is related to either MDEV-12353 changing the redo log format, or MDEV-21534 improving the log write speed.

      One affected test is encryption.innodb-checksum-algorithm, but there probably are others.

      Attachments

        Issue Links

          Activity

            I had no luck reproducing this so far, even with the full list of tests from the above logs, invoked in a loop that would terminate on test failure:

            while ./mtr --no-reorder innodb.autoinc_persist innodb.blob-update-debug innodb.blob_unique2pk innodb.count_distinct innodb.create-index innodb.deadlock_detect innodb.default_row_format_alter innodb.default_row_format_compatibility innodb.drop_table_background
            do :
            done
            

            I tried both a plain debug build and an ASAN-instrumented debug build.

            marko Marko Mäkelä added a comment - I had no luck reproducing this so far, even with the full list of tests from the above logs, invoked in a loop that would terminate on test failure: while ./mtr --no-reorder innodb.autoinc_persist innodb.blob-update-debug innodb.blob_unique2pk innodb.count_distinct innodb.create-index innodb.deadlock_detect innodb.default_row_format_alter innodb.default_row_format_compatibility innodb.drop_table_background do : done I tried both a plain debug build and an ASAN-instrumented debug build.
            danblack Daniel Black added a comment -

            encryption.innodb-checksum-algorithm-16k,ctr,innodb test on Power9.

            10.5-0781c91d288e528477e4ab446f91522a8802e5ec-Debug + 8399af81be0a87d1c0ea09164c05a9ac8eb715e2 revert

            encryption.innodb-checksum-algorithm '16k,ctr,innodb' w4 [ fail ]
                    Test ended at 2020-05-06 19:36:19
             
            CURRENT_TEST: encryption.innodb-checksum-algorithm
            mysqltest: At line 111: query 'ALTER TABLE tce_$checksum IMPORT TABLESPACE' failed: 2013: Lost connection to MySQL server during query
             
            The result from queries just before the failure was:
            < snip >
            ALTER TABLE t_none IMPORT TABLESPACE;
            update t_none set b=substr(b,1);
            ALTER TABLE tpe_none IMPORT TABLESPACE;
            update tpe_none set b=substr(b,1);
            ALTER TABLE tp_none IMPORT TABLESPACE;
            update tp_none set b=substr(b,1);
            SET GLOBAL innodb_checksum_algorithm=none;
            ALTER TABLE tce_none DISCARD TABLESPACE;
            ALTER TABLE tc_none DISCARD TABLESPACE;
            ALTER TABLE te_none DISCARD TABLESPACE;
            ALTER TABLE t_none DISCARD TABLESPACE;
            ALTER TABLE tpe_none DISCARD TABLESPACE;
            ALTER TABLE tp_none DISCARD TABLESPACE;
            restore: tce_none .ibd and .cfg files
            restore: tc_none .ibd and .cfg files
            restore: te_none .ibd and .cfg files
            restore: t_none .ibd and .cfg files
            restore: tpe_none .ibd and .cfg files
            restore: tp_none .ibd and .cfg files
            ALTER TABLE tce_none IMPORT TABLESPACE;
             
            More results from queries before failure can be found in /home/ozlabs/build-mariadb-server-10.5-debug/mysql-test/var/4/log/innodb-checksum-algorithm.log
             
             
            Server [mysqld.1 - pid: 25209, winpid: 25209, exit: 256] failed during test run
            Server log from this test:
            ----------SERVER LOG START-----------
            2020-05-06 19:36:16 0 [Note] /home/ozlabs/build-mariadb-server-10.5-debug/sql/mariadbd (mysqld 10.5.3-MariaDB-debug-log) starting as process 25211 ...
            2020-05-06 19:36:16 0 [Warning] Could not increase number of max_open_files to more than 1024 (request: 32194)
            2020-05-06 19:36:16 0 [Warning] Changed limits: max_open_files: 1024  max_connections: 151 (was 151)  table_cache: 421 (was 2000)
            2020-05-06 19:36:16 0 [Note] Plugin 'partition' is disabled.
            2020-05-06 19:36:16 0 [Note] Plugin 'SEQUENCE' is disabled.
            2020-05-06 19:36:16 0 [Note] InnoDB: !!!!!!!! UNIV_DEBUG switched on !!!!!!!!!
            2020-05-06 19:36:16 0 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
            2020-05-06 19:36:16 0 [Note] InnoDB: Uses event mutexes
            2020-05-06 19:36:16 0 [Note] InnoDB: Compressed tables use zlib 1.2.7
            2020-05-06 19:36:16 0 [Note] InnoDB: Number of pools: 1
            2020-05-06 19:36:16 0 [Note] InnoDB: Using POWER8 crc32 instructions
            2020-05-06 19:36:16 0 [Note] mariadbd: O_TMPFILE is not supported on /home/ozlabs/build-mariadb-server-10.5-debug/mysql-test/var/tmp/4/mysqld.1 (disabling future attempts)
            2020-05-06 19:36:16 0 [Note] InnoDB: Initializing buffer pool, total size = 8388608, chunk size = 8388608
            2020-05-06 19:36:16 0 [Note] InnoDB: Completed initialization of buffer pool
            2020-05-06 19:36:16 0 [Note] InnoDB: If the mysqld execution user is authorized, page cleaner thread priority can be changed. See the man page of setpriority().
            2020-05-06 19:36:16 0 [Note] InnoDB: 128 rollback segments are active.
            2020-05-06 19:36:16 0 [Note] InnoDB: Creating shared tablespace for temporary tables
            2020-05-06 19:36:16 0 [Note] InnoDB: Setting file './ibtmp1' size to 12 MB. Physically writing the file full; Please wait ...
            2020-05-06 19:36:16 0 [Note] InnoDB: File './ibtmp1' size is now 12 MB.
            2020-05-06 19:36:16 0 [Note] InnoDB: 10.5.3 started; log sequence number 47785; transaction id 28
            2020-05-06 19:36:16 0 [Note] Plugin 'INNODB_SYS_DATAFILES' is disabled.
            2020-05-06 19:36:16 0 [Note] Plugin 'INNODB_SYS_TABLESTATS' is disabled.
            2020-05-06 19:36:16 0 [Note] Plugin 'INNODB_CMP' is disabled.
            2020-05-06 19:36:16 0 [Note] Plugin 'THREAD_POOL_WAITS' is disabled.
            2020-05-06 19:36:16 0 [Note] Plugin 'INNODB_CMP_RESET' is disabled.
            2020-05-06 19:36:16 0 [Note] Plugin 'THREAD_POOL_QUEUES' is disabled.
            2020-05-06 19:36:16 0 [Note] Plugin 'FEEDBACK' is disabled.
            2020-05-06 19:36:16 0 [Note] Plugin 'INNODB_FT_INDEX_TABLE' is disabled.
            2020-05-06 19:36:16 0 [Note] Plugin 'THREAD_POOL_GROUPS' is disabled.
            2020-05-06 19:36:16 0 [Note] Plugin 'INNODB_CMP_PER_INDEX_RESET' is disabled.
            2020-05-06 19:36:16 0 [Note] Plugin 'INNODB_FT_INDEX_CACHE' is disabled.
            2020-05-06 19:36:16 0 [Note] Plugin 'INNODB_FT_BEING_DELETED' is disabled.
            2020-05-06 19:36:16 0 [Note] InnoDB: Loading buffer pool(s) from /dev/shm/var_auto_ck8g/4/mysqld.1/data/ib_buffer_pool
            2020-05-06 19:36:16 0 [Note] Plugin 'INNODB_CMPMEM_RESET' is disabled.
            2020-05-06 19:36:16 0 [Note] Plugin 'INNODB_FT_DEFAULT_STOPWORD' is disabled.
            2020-05-06 19:36:16 0 [Note] Plugin 'INNODB_FT_CONFIG' is disabled.
            2020-05-06 19:36:16 0 [Note] Plugin 'INNODB_SYS_TABLESPACES' is disabled.
            2020-05-06 19:36:16 0 [Note] Plugin 'INNODB_SYS_SEMAPHORE_WAITS' is disabled.
            2020-05-06 19:36:16 0 [Note] Plugin 'INNODB_MUTEXES' is disabled.
            2020-05-06 19:36:16 0 [Note] Plugin 'user_variables' is disabled.
            2020-05-06 19:36:16 0 [Note] Plugin 'INNODB_TABLESPACES_ENCRYPTION' is disabled.
            2020-05-06 19:36:16 0 [Note] Plugin 'INNODB_FT_DELETED' is disabled.
            2020-05-06 19:36:16 0 [Note] Plugin 'THREAD_POOL_STATS' is disabled.
            2020-05-06 19:36:16 0 [Note] Plugin 'unix_socket' is disabled.
            2020-05-06 19:36:16 0 [Warning] /home/ozlabs/build-mariadb-server-10.5-debug/sql/mariadbd: unknown option '--loose-pam-debug'
            2020-05-06 19:36:16 0 [Warning] /home/ozlabs/build-mariadb-server-10.5-debug/sql/mariadbd: unknown option '--loose-aria'
            2020-05-06 19:36:16 0 [Note] InnoDB: Buffer pool(s) load completed at 200506 19:36:16
            2020-05-06 19:36:16 0 [Note] Server socket created on IP: '127.0.0.1'.
            2020-05-06 19:36:16 0 [Note] Reading of all Master_info entries succeeded
            2020-05-06 19:36:16 0 [Note] Added new Master_info '' to hash table
            2020-05-06 19:36:16 0 [Note] /home/ozlabs/build-mariadb-server-10.5-debug/sql/mariadbd: ready for connections.
            Version: '10.5.3-MariaDB-debug-log'  socket: '/home/ozlabs/build-mariadb-server-10.5-debug/mysql-test/var/tmp/4/mysqld.1.sock'  port: 16060  Source distribution
            2020-05-06 19:36:16 4 [Note] InnoDB: Creating #1 encryption thread id 70366185582672 total threads 4.
            2020-05-06 19:36:16 4 [Note] InnoDB: Creating #2 encryption thread id 70366177128528 total threads 4.
            2020-05-06 19:36:16 4 [Note] InnoDB: Creating #3 encryption thread id 70366168674384 total threads 4.
            2020-05-06 19:36:16 4 [Note] InnoDB: Creating #4 encryption thread id 70366160220240 total threads 4.
            2020-05-06 19:36:16 4 [Note] InnoDB: Sync to disk of `test`.`tce_crc32` started.
            2020-05-06 19:36:16 4 [Note] InnoDB: Stopping purge
            2020-05-06 19:36:16 4 [Note] InnoDB: Writing table metadata to './test/tce_crc32.cfg'
            2020-05-06 19:36:16 4 [Note] InnoDB: Table `test`.`tce_crc32` flushed to disk
            2020-05-06 19:36:16 4 [Note] InnoDB: Sync to disk of `test`.`tc_crc32` started.
            2020-05-06 19:36:16 4 [Note] InnoDB: Writing table metadata to './test/tc_crc32.cfg'
            2020-05-06 19:36:16 4 [Note] InnoDB: Table `test`.`tc_crc32` flushed to disk
            2020-05-06 19:36:16 4 [Note] InnoDB: Sync to disk of `test`.`te_crc32` started.
            2020-05-06 19:36:16 4 [Note] InnoDB: Writing table metadata to './test/te_crc32.cfg'
            2020-05-06 19:36:16 4 [Note] InnoDB: Table `test`.`te_crc32` flushed to disk
            2020-05-06 19:36:16 4 [Note] InnoDB: Sync to disk of `test`.`t_crc32` started.
            2020-05-06 19:36:16 4 [Note] InnoDB: Writing table metadata to './test/t_crc32.cfg'
            2020-05-06 19:36:16 4 [Note] InnoDB: Table `test`.`t_crc32` flushed to disk
            2020-05-06 19:36:16 4 [Note] InnoDB: Sync to disk of `test`.`tpe_crc32` started.
            2020-05-06 19:36:16 4 [Note] InnoDB: Writing table metadata to './test/tpe_crc32.cfg'
            2020-05-06 19:36:16 4 [Note] InnoDB: Table `test`.`tpe_crc32` flushed to disk
            2020-05-06 19:36:16 4 [Note] InnoDB: Sync to disk of `test`.`tp_crc32` started.
            2020-05-06 19:36:16 4 [Note] InnoDB: Writing table metadata to './test/tp_crc32.cfg'
            2020-05-06 19:36:16 4 [Note] InnoDB: Table `test`.`tp_crc32` flushed to disk
            2020-05-06 19:36:16 4 [Note] InnoDB: Deleting the meta-data file './test/tce_crc32.cfg'
            2020-05-06 19:36:16 4 [Note] InnoDB: Deleting the meta-data file './test/tc_crc32.cfg'
            2020-05-06 19:36:16 4 [Note] InnoDB: Deleting the meta-data file './test/te_crc32.cfg'
            2020-05-06 19:36:16 4 [Note] InnoDB: Deleting the meta-data file './test/t_crc32.cfg'
            2020-05-06 19:36:16 4 [Note] InnoDB: Deleting the meta-data file './test/tpe_crc32.cfg'
            2020-05-06 19:36:16 4 [Note] InnoDB: Deleting the meta-data file './test/tp_crc32.cfg'
            2020-05-06 19:36:16 4 [Note] InnoDB: Resuming purge
            2020-05-06 19:36:17 4 [Note] InnoDB: Importing tablespace for table 'test/tce_crc32' that was exported from host 'rhel77'
            2020-05-06 19:36:17 4 [Note] InnoDB: Phase I - Update all pages
            2020-05-06 19:36:17 4 [Note] InnoDB: Sync to disk
            2020-05-06 19:36:17 4 [Note] InnoDB: Sync to disk - done!
            2020-05-06 19:36:17 4 [Note] InnoDB: Phase III - Flush changes to disk
            2020-05-06 19:36:17 4 [Note] InnoDB: Phase IV - Flush complete
            2020-05-06 19:36:17 4 [Note] InnoDB: `test`.`tce_crc32` autoinc value set to 2
            2020-05-06 19:36:17 4 [Note] InnoDB: Importing tablespace for table 'test/tc_crc32' that was exported from host 'rhel77'
            2020-05-06 19:36:17 4 [Note] InnoDB: Phase I - Update all pages
            2020-05-06 19:36:17 4 [Note] InnoDB: Sync to disk
            2020-05-06 19:36:17 4 [Note] InnoDB: Sync to disk - done!
            2020-05-06 19:36:17 4 [Note] InnoDB: Phase III - Flush changes to disk
            2020-05-06 19:36:17 4 [Note] InnoDB: Phase IV - Flush complete
            2020-05-06 19:36:17 4 [Note] InnoDB: `test`.`tc_crc32` autoinc value set to 2
            2020-05-06 19:36:17 4 [Note] InnoDB: Importing tablespace for table 'test/te_crc32' that was exported from host 'rhel77'
            2020-05-06 19:36:17 4 [Note] InnoDB: Phase I - Update all pages
            2020-05-06 19:36:17 4 [Note] InnoDB: Sync to disk
            2020-05-06 19:36:17 4 [Note] InnoDB: Sync to disk - done!
            2020-05-06 19:36:17 4 [Note] InnoDB: Phase III - Flush changes to disk
            2020-05-06 19:36:17 4 [Note] InnoDB: Phase IV - Flush complete
            2020-05-06 19:36:17 4 [Note] InnoDB: `test`.`te_crc32` autoinc value set to 2
            2020-05-06 19:36:17 4 [Note] InnoDB: Importing tablespace for table 'test/t_crc32' that was exported from host 'rhel77'
            2020-05-06 19:36:17 4 [Note] InnoDB: Phase I - Update all pages
            2020-05-06 19:36:17 4 [Note] InnoDB: Sync to disk
            2020-05-06 19:36:17 4 [Note] InnoDB: Sync to disk - done!
            2020-05-06 19:36:17 4 [Note] InnoDB: Phase III - Flush changes to disk
            2020-05-06 19:36:17 4 [Note] InnoDB: Phase IV - Flush complete
            2020-05-06 19:36:17 4 [Note] InnoDB: `test`.`t_crc32` autoinc value set to 2
            2020-05-06 19:36:17 4 [Note] InnoDB: Importing tablespace for table 'test/tpe_crc32' that was exported from host 'rhel77'
            2020-05-06 19:36:17 4 [Note] InnoDB: Phase I - Update all pages
            2020-05-06 19:36:17 4 [Note] InnoDB: Sync to disk
            2020-05-06 19:36:17 4 [Note] InnoDB: Sync to disk - done!
            2020-05-06 19:36:17 4 [Note] InnoDB: Phase III - Flush changes to disk
            2020-05-06 19:36:17 4 [Note] InnoDB: Phase IV - Flush complete
            2020-05-06 19:36:17 4 [Note] InnoDB: `test`.`tpe_crc32` autoinc value set to 2
            2020-05-06 19:36:17 4 [Note] InnoDB: Importing tablespace for table 'test/tp_crc32' that was exported from host 'rhel77'
            2020-05-06 19:36:17 4 [Note] InnoDB: Phase I - Update all pages
            2020-05-06 19:36:17 4 [Note] InnoDB: Sync to disk
            2020-05-06 19:36:17 4 [Note] InnoDB: Sync to disk - done!
            2020-05-06 19:36:17 4 [Note] InnoDB: Phase III - Flush changes to disk
            2020-05-06 19:36:17 4 [Note] InnoDB: Phase IV - Flush complete
            2020-05-06 19:36:17 4 [Note] InnoDB: `test`.`tp_crc32` autoinc value set to 2
            2020-05-06 19:36:17 4 [Note] InnoDB: Importing tablespace for table 'test/tce_crc32' that was exported from host 'rhel77'
            2020-05-06 19:36:17 4 [Note] InnoDB: Phase I - Update all pages
            2020-05-06 19:36:17 4 [Note] InnoDB: Sync to disk
            2020-05-06 19:36:17 4 [Note] InnoDB: Sync to disk - done!
            2020-05-06 19:36:17 4 [Note] InnoDB: Phase III - Flush changes to disk
            2020-05-06 19:36:17 4 [Note] InnoDB: Phase IV - Flush complete
            2020-05-06 19:36:17 4 [Note] InnoDB: `test`.`tce_crc32` autoinc value set to 2
            2020-05-06 19:36:17 4 [Note] InnoDB: Importing tablespace for table 'test/tc_crc32' that was exported from host 'rhel77'
            2020-05-06 19:36:17 4 [Note] InnoDB: Phase I - Update all pages
            2020-05-06 19:36:17 4 [Note] InnoDB: Sync to disk
            2020-05-06 19:36:17 4 [Note] InnoDB: Sync to disk - done!
            2020-05-06 19:36:17 4 [Note] InnoDB: Phase III - Flush changes to disk
            2020-05-06 19:36:17 4 [Note] InnoDB: Phase IV - Flush complete
            2020-05-06 19:36:17 4 [Note] InnoDB: `test`.`tc_crc32` autoinc value set to 2
            2020-05-06 19:36:17 4 [Note] InnoDB: Importing tablespace for table 'test/te_crc32' that was exported from host 'rhel77'
            2020-05-06 19:36:17 4 [Note] InnoDB: Phase I - Update all pages
            2020-05-06 19:36:17 4 [Note] InnoDB: Sync to disk
            2020-05-06 19:36:17 4 [Note] InnoDB: Sync to disk - done!
            2020-05-06 19:36:17 4 [Note] InnoDB: Phase III - Flush changes to disk
            2020-05-06 19:36:17 4 [Note] InnoDB: Phase IV - Flush complete
            2020-05-06 19:36:17 4 [Note] InnoDB: `test`.`te_crc32` autoinc value set to 2
            2020-05-06 19:36:17 4 [Note] InnoDB: Importing tablespace for table 'test/t_crc32' that was exported from host 'rhel77'
            2020-05-06 19:36:17 4 [Note] InnoDB: Phase I - Update all pages
            2020-05-06 19:36:17 4 [Note] InnoDB: Sync to disk
            2020-05-06 19:36:17 4 [Note] InnoDB: Sync to disk - done!
            2020-05-06 19:36:17 4 [Note] InnoDB: Phase III - Flush changes to disk
            2020-05-06 19:36:17 4 [Note] InnoDB: Phase IV - Flush complete
            2020-05-06 19:36:17 4 [Note] InnoDB: `test`.`t_crc32` autoinc value set to 2
            2020-05-06 19:36:17 4 [Note] InnoDB: Importing tablespace for table 'test/tpe_crc32' that was exported from host 'rhel77'
            2020-05-06 19:36:17 4 [Note] InnoDB: Phase I - Update all pages
            2020-05-06 19:36:17 4 [Note] InnoDB: Sync to disk
            2020-05-06 19:36:17 4 [Note] InnoDB: Sync to disk - done!
            2020-05-06 19:36:17 4 [Note] InnoDB: Phase III - Flush changes to disk
            2020-05-06 19:36:17 4 [Note] InnoDB: Phase IV - Flush complete
            2020-05-06 19:36:17 4 [Note] InnoDB: `test`.`tpe_crc32` autoinc value set to 2
            2020-05-06 19:36:17 4 [Note] InnoDB: Importing tablespace for table 'test/tp_crc32' that was exported from host 'rhel77'
            2020-05-06 19:36:17 4 [Note] InnoDB: Phase I - Update all pages
            2020-05-06 19:36:17 4 [Note] InnoDB: Sync to disk
            2020-05-06 19:36:17 4 [Note] InnoDB: Sync to disk - done!
            2020-05-06 19:36:17 4 [Note] InnoDB: Phase III - Flush changes to disk
            2020-05-06 19:36:17 4 [Note] InnoDB: Phase IV - Flush complete
            2020-05-06 19:36:17 4 [Note] InnoDB: `test`.`tp_crc32` autoinc value set to 2
            2020-05-06 19:36:17 4 [Note] InnoDB: Importing tablespace for table 'test/tce_crc32' that was exported from host 'rhel77'
            2020-05-06 19:36:17 4 [Note] InnoDB: Phase I - Update all pages
            2020-05-06 19:36:17 4 [Note] InnoDB: Sync to disk
            2020-05-06 19:36:17 4 [Note] InnoDB: Sync to disk - done!
            2020-05-06 19:36:17 4 [Note] InnoDB: Phase III - Flush changes to disk
            2020-05-06 19:36:17 4 [Note] InnoDB: Phase IV - Flush complete
            2020-05-06 19:36:17 4 [Note] InnoDB: `test`.`tce_crc32` autoinc value set to 2
            2020-05-06 19:36:17 4 [Note] InnoDB: Importing tablespace for table 'test/tc_crc32' that was exported from host 'rhel77'
            2020-05-06 19:36:17 4 [Note] InnoDB: Phase I - Update all pages
            2020-05-06 19:36:17 4 [Note] InnoDB: Sync to disk
            2020-05-06 19:36:17 4 [Note] InnoDB: Sync to disk - done!
            2020-05-06 19:36:17 4 [Note] InnoDB: Phase III - Flush changes to disk
            2020-05-06 19:36:17 4 [Note] InnoDB: Phase IV - Flush complete
            2020-05-06 19:36:17 4 [Note] InnoDB: `test`.`tc_crc32` autoinc value set to 2
            2020-05-06 19:36:17 4 [Note] InnoDB: Importing tablespace for table 'test/te_crc32' that was exported from host 'rhel77'
            2020-05-06 19:36:17 4 [Note] InnoDB: Phase I - Update all pages
            2020-05-06 19:36:17 4 [Note] InnoDB: Sync to disk
            2020-05-06 19:36:17 4 [Note] InnoDB: Sync to disk - done!
            2020-05-06 19:36:17 4 [Note] InnoDB: Phase III - Flush changes to disk
            2020-05-06 19:36:17 4 [Note] InnoDB: Phase IV - Flush complete
            2020-05-06 19:36:17 4 [Note] InnoDB: `test`.`te_crc32` autoinc value set to 2
            2020-05-06 19:36:17 4 [Note] InnoDB: Importing tablespace for table 'test/t_crc32' that was exported from host 'rhel77'
            2020-05-06 19:36:17 4 [Note] InnoDB: Phase I - Update all pages
            2020-05-06 19:36:17 4 [Note] InnoDB: Sync to disk
            2020-05-06 19:36:17 4 [Note] InnoDB: Sync to disk - done!
            2020-05-06 19:36:17 4 [Note] InnoDB: Phase III - Flush changes to disk
            2020-05-06 19:36:17 4 [Note] InnoDB: Phase IV - Flush complete
            2020-05-06 19:36:17 4 [Note] InnoDB: `test`.`t_crc32` autoinc value set to 2
            2020-05-06 19:36:17 4 [Note] InnoDB: Importing tablespace for table 'test/tpe_crc32' that was exported from host 'rhel77'
            2020-05-06 19:36:17 4 [Note] InnoDB: Phase I - Update all pages
            2020-05-06 19:36:17 4 [Note] InnoDB: Sync to disk
            2020-05-06 19:36:17 4 [Note] InnoDB: Sync to disk - done!
            2020-05-06 19:36:17 4 [Note] InnoDB: Phase III - Flush changes to disk
            2020-05-06 19:36:17 4 [Note] InnoDB: Phase IV - Flush complete
            2020-05-06 19:36:17 4 [Note] InnoDB: `test`.`tpe_crc32` autoinc value set to 2
            2020-05-06 19:36:17 4 [Note] InnoDB: Importing tablespace for table 'test/tp_crc32' that was exported from host 'rhel77'
            2020-05-06 19:36:17 4 [Note] InnoDB: Phase I - Update all pages
            2020-05-06 19:36:17 4 [Note] InnoDB: Sync to disk
            2020-05-06 19:36:17 4 [Note] InnoDB: Sync to disk - done!
            2020-05-06 19:36:17 4 [Note] InnoDB: Phase III - Flush changes to disk
            2020-05-06 19:36:17 4 [Note] InnoDB: Phase IV - Flush complete
            2020-05-06 19:36:17 4 [Note] InnoDB: `test`.`tp_crc32` autoinc value set to 2
            2020-05-06 19:36:17 4 [Note] InnoDB: Sync to disk of `test`.`tce_innodb` started.
            2020-05-06 19:36:17 4 [Note] InnoDB: Stopping purge
            2020-05-06 19:36:17 4 [Note] InnoDB: Writing table metadata to './test/tce_innodb.cfg'
            2020-05-06 19:36:17 4 [Note] InnoDB: Table `test`.`tce_innodb` flushed to disk
            2020-05-06 19:36:17 4 [Note] InnoDB: Sync to disk of `test`.`tc_innodb` started.
            2020-05-06 19:36:17 4 [Note] InnoDB: Writing table metadata to './test/tc_innodb.cfg'
            2020-05-06 19:36:17 4 [Note] InnoDB: Table `test`.`tc_innodb` flushed to disk
            2020-05-06 19:36:17 4 [Note] InnoDB: Sync to disk of `test`.`te_innodb` started.
            2020-05-06 19:36:17 4 [Note] InnoDB: Writing table metadata to './test/te_innodb.cfg'
            2020-05-06 19:36:17 4 [Note] InnoDB: Table `test`.`te_innodb` flushed to disk
            2020-05-06 19:36:17 4 [Note] InnoDB: Sync to disk of `test`.`t_innodb` started.
            2020-05-06 19:36:17 4 [Note] InnoDB: Writing table metadata to './test/t_innodb.cfg'
            2020-05-06 19:36:17 4 [Note] InnoDB: Table `test`.`t_innodb` flushed to disk
            2020-05-06 19:36:17 4 [Note] InnoDB: Sync to disk of `test`.`tpe_innodb` started.
            2020-05-06 19:36:17 4 [Note] InnoDB: Writing table metadata to './test/tpe_innodb.cfg'
            2020-05-06 19:36:17 4 [Note] InnoDB: Table `test`.`tpe_innodb` flushed to disk
            2020-05-06 19:36:17 4 [Note] InnoDB: Sync to disk of `test`.`tp_innodb` started.
            2020-05-06 19:36:17 4 [Note] InnoDB: Writing table metadata to './test/tp_innodb.cfg'
            2020-05-06 19:36:17 4 [Note] InnoDB: Table `test`.`tp_innodb` flushed to disk
            2020-05-06 19:36:17 4 [Note] InnoDB: Deleting the meta-data file './test/tce_innodb.cfg'
            2020-05-06 19:36:17 4 [Note] InnoDB: Deleting the meta-data file './test/tc_innodb.cfg'
            2020-05-06 19:36:17 4 [Note] InnoDB: Deleting the meta-data file './test/te_innodb.cfg'
            2020-05-06 19:36:17 4 [Note] InnoDB: Deleting the meta-data file './test/t_innodb.cfg'
            2020-05-06 19:36:17 4 [Note] InnoDB: Deleting the meta-data file './test/tpe_innodb.cfg'
            2020-05-06 19:36:17 4 [Note] InnoDB: Deleting the meta-data file './test/tp_innodb.cfg'
            2020-05-06 19:36:17 4 [Note] InnoDB: Resuming purge
            2020-05-06 19:36:17 4 [Note] InnoDB: Importing tablespace for table 'test/tce_innodb' that was exported from host 'rhel77'
            2020-05-06 19:36:17 4 [Note] InnoDB: Phase I - Update all pages
            2020-05-06 19:36:17 4 [Note] InnoDB: Sync to disk
            2020-05-06 19:36:17 4 [Note] InnoDB: Sync to disk - done!
            2020-05-06 19:36:17 4 [Note] InnoDB: Phase III - Flush changes to disk
            2020-05-06 19:36:17 4 [Note] InnoDB: Phase IV - Flush complete
            2020-05-06 19:36:17 4 [Note] InnoDB: `test`.`tce_innodb` autoinc value set to 2
            2020-05-06 19:36:17 4 [Note] InnoDB: Importing tablespace for table 'test/tc_innodb' that was exported from host 'rhel77'
            2020-05-06 19:36:17 4 [Note] InnoDB: Phase I - Update all pages
            2020-05-06 19:36:17 4 [Note] InnoDB: Sync to disk
            2020-05-06 19:36:17 4 [Note] InnoDB: Sync to disk - done!
            2020-05-06 19:36:17 4 [Note] InnoDB: Phase III - Flush changes to disk
            2020-05-06 19:36:17 4 [Note] InnoDB: Phase IV - Flush complete
            2020-05-06 19:36:17 4 [Note] InnoDB: `test`.`tc_innodb` autoinc value set to 2
            2020-05-06 19:36:18 4 [Note] InnoDB: Importing tablespace for table 'test/te_innodb' that was exported from host 'rhel77'
            2020-05-06 19:36:18 4 [Note] InnoDB: Phase I - Update all pages
            2020-05-06 19:36:18 4 [Note] InnoDB: Sync to disk
            2020-05-06 19:36:18 4 [Note] InnoDB: Sync to disk - done!
            2020-05-06 19:36:18 4 [Note] InnoDB: Phase III - Flush changes to disk
            2020-05-06 19:36:18 4 [Note] InnoDB: Phase IV - Flush complete
            2020-05-06 19:36:18 4 [Note] InnoDB: `test`.`te_innodb` autoinc value set to 2
            2020-05-06 19:36:18 4 [Note] InnoDB: Importing tablespace for table 'test/t_innodb' that was exported from host 'rhel77'
            2020-05-06 19:36:18 4 [Note] InnoDB: Phase I - Update all pages
            2020-05-06 19:36:18 4 [Note] InnoDB: Sync to disk
            2020-05-06 19:36:18 4 [Note] InnoDB: Sync to disk - done!
            2020-05-06 19:36:18 4 [Note] InnoDB: Phase III - Flush changes to disk
            2020-05-06 19:36:18 4 [Note] InnoDB: Phase IV - Flush complete
            2020-05-06 19:36:18 4 [Note] InnoDB: `test`.`t_innodb` autoinc value set to 2
            2020-05-06 19:36:18 4 [Note] InnoDB: Importing tablespace for table 'test/tpe_innodb' that was exported from host 'rhel77'
            2020-05-06 19:36:18 4 [Note] InnoDB: Phase I - Update all pages
            2020-05-06 19:36:18 4 [Note] InnoDB: Sync to disk
            2020-05-06 19:36:18 4 [Note] InnoDB: Sync to disk - done!
            2020-05-06 19:36:18 4 [Note] InnoDB: Phase III - Flush changes to disk
            2020-05-06 19:36:18 4 [Note] InnoDB: Phase IV - Flush complete
            2020-05-06 19:36:18 4 [Note] InnoDB: `test`.`tpe_innodb` autoinc value set to 2
            2020-05-06 19:36:18 4 [Note] InnoDB: Importing tablespace for table 'test/tp_innodb' that was exported from host 'rhel77'
            2020-05-06 19:36:18 4 [Note] InnoDB: Phase I - Update all pages
            2020-05-06 19:36:18 4 [Note] InnoDB: Sync to disk
            2020-05-06 19:36:18 4 [Note] InnoDB: Sync to disk - done!
            2020-05-06 19:36:18 4 [Note] InnoDB: Phase III - Flush changes to disk
            2020-05-06 19:36:18 4 [Note] InnoDB: Phase IV - Flush complete
            2020-05-06 19:36:18 4 [Note] InnoDB: `test`.`tp_innodb` autoinc value set to 2
            2020-05-06 19:36:18 4 [Note] InnoDB: Importing tablespace for table 'test/tce_innodb' that was exported from host 'rhel77'
            2020-05-06 19:36:18 4 [Note] InnoDB: Phase I - Update all pages
            2020-05-06 19:36:18 4 [Note] InnoDB: Sync to disk
            2020-05-06 19:36:18 4 [Note] InnoDB: Sync to disk - done!
            2020-05-06 19:36:18 4 [Note] InnoDB: Phase III - Flush changes to disk
            2020-05-06 19:36:18 4 [Note] InnoDB: Phase IV - Flush complete
            2020-05-06 19:36:18 4 [Note] InnoDB: `test`.`tce_innodb` autoinc value set to 2
            2020-05-06 19:36:18 4 [Note] InnoDB: Importing tablespace for table 'test/tc_innodb' that was exported from host 'rhel77'
            2020-05-06 19:36:18 4 [Note] InnoDB: Phase I - Update all pages
            2020-05-06 19:36:18 4 [Note] InnoDB: Sync to disk
            2020-05-06 19:36:18 4 [Note] InnoDB: Sync to disk - done!
            2020-05-06 19:36:18 4 [Note] InnoDB: Phase III - Flush changes to disk
            2020-05-06 19:36:18 4 [Note] InnoDB: Phase IV - Flush complete
            2020-05-06 19:36:18 4 [Note] InnoDB: `test`.`tc_innodb` autoinc value set to 2
            2020-05-06 19:36:18 4 [Note] InnoDB: Importing tablespace for table 'test/te_innodb' that was exported from host 'rhel77'
            2020-05-06 19:36:18 4 [Note] InnoDB: Phase I - Update all pages
            2020-05-06 19:36:18 4 [Note] InnoDB: Sync to disk
            2020-05-06 19:36:18 4 [Note] InnoDB: Sync to disk - done!
            2020-05-06 19:36:18 4 [Note] InnoDB: Phase III - Flush changes to disk
            2020-05-06 19:36:18 4 [Note] InnoDB: Phase IV - Flush complete
            2020-05-06 19:36:18 4 [Note] InnoDB: `test`.`te_innodb` autoinc value set to 2
            2020-05-06 19:36:18 4 [Note] InnoDB: Importing tablespace for table 'test/t_innodb' that was exported from host 'rhel77'
            2020-05-06 19:36:18 4 [Note] InnoDB: Phase I - Update all pages
            2020-05-06 19:36:18 4 [Note] InnoDB: Sync to disk
            2020-05-06 19:36:18 4 [Note] InnoDB: Sync to disk - done!
            2020-05-06 19:36:18 4 [Note] InnoDB: Phase III - Flush changes to disk
            2020-05-06 19:36:18 4 [Note] InnoDB: Phase IV - Flush complete
            2020-05-06 19:36:18 4 [Note] InnoDB: `test`.`t_innodb` autoinc value set to 2
            2020-05-06 19:36:18 4 [Note] InnoDB: Importing tablespace for table 'test/tpe_innodb' that was exported from host 'rhel77'
            2020-05-06 19:36:18 4 [Note] InnoDB: Phase I - Update all pages
            2020-05-06 19:36:18 4 [Note] InnoDB: Sync to disk
            2020-05-06 19:36:18 4 [Note] InnoDB: Sync to disk - done!
            2020-05-06 19:36:18 4 [Note] InnoDB: Phase III - Flush changes to disk
            2020-05-06 19:36:18 4 [Note] InnoDB: Phase IV - Flush complete
            2020-05-06 19:36:18 4 [Note] InnoDB: `test`.`tpe_innodb` autoinc value set to 2
            2020-05-06 19:36:18 4 [Note] InnoDB: Importing tablespace for table 'test/tp_innodb' that was exported from host 'rhel77'
            2020-05-06 19:36:18 4 [Note] InnoDB: Phase I - Update all pages
            2020-05-06 19:36:18 4 [Note] InnoDB: Sync to disk
            2020-05-06 19:36:18 4 [Note] InnoDB: Sync to disk - done!
            2020-05-06 19:36:18 4 [Note] InnoDB: Phase III - Flush changes to disk
            2020-05-06 19:36:18 4 [Note] InnoDB: Phase IV - Flush complete
            2020-05-06 19:36:18 4 [Note] InnoDB: `test`.`tp_innodb` autoinc value set to 2
            2020-05-06 19:36:18 4 [Note] InnoDB: Importing tablespace for table 'test/tce_innodb' that was exported from host 'rhel77'
            2020-05-06 19:36:18 4 [Note] InnoDB: Phase I - Update all pages
            2020-05-06 19:36:18 4 [Note] InnoDB: Sync to disk
            2020-05-06 19:36:18 4 [Note] InnoDB: Sync to disk - done!
            2020-05-06 19:36:18 4 [Note] InnoDB: Phase III - Flush changes to disk
            2020-05-06 19:36:18 4 [Note] InnoDB: Phase IV - Flush complete
            2020-05-06 19:36:18 4 [Note] InnoDB: `test`.`tce_innodb` autoinc value set to 2
            2020-05-06 19:36:18 4 [Note] InnoDB: Importing tablespace for table 'test/tc_innodb' that was exported from host 'rhel77'
            2020-05-06 19:36:18 4 [Note] InnoDB: Phase I - Update all pages
            2020-05-06 19:36:18 4 [Note] InnoDB: Sync to disk
            2020-05-06 19:36:18 4 [Note] InnoDB: Sync to disk - done!
            2020-05-06 19:36:18 4 [Note] InnoDB: Phase III - Flush changes to disk
            2020-05-06 19:36:18 4 [Note] InnoDB: Phase IV - Flush complete
            2020-05-06 19:36:18 4 [Note] InnoDB: `test`.`tc_innodb` autoinc value set to 2
            2020-05-06 19:36:18 4 [Note] InnoDB: Importing tablespace for table 'test/te_innodb' that was exported from host 'rhel77'
            2020-05-06 19:36:18 4 [Note] InnoDB: Phase I - Update all pages
            2020-05-06 19:36:18 4 [Note] InnoDB: Sync to disk
            2020-05-06 19:36:18 4 [Note] InnoDB: Sync to disk - done!
            2020-05-06 19:36:18 4 [Note] InnoDB: Phase III - Flush changes to disk
            2020-05-06 19:36:18 4 [Note] InnoDB: Phase IV - Flush complete
            2020-05-06 19:36:18 4 [Note] InnoDB: `test`.`te_innodb` autoinc value set to 2
            2020-05-06 19:36:18 4 [Note] InnoDB: Importing tablespace for table 'test/t_innodb' that was exported from host 'rhel77'
            2020-05-06 19:36:18 4 [Note] InnoDB: Phase I - Update all pages
            2020-05-06 19:36:18 4 [Note] InnoDB: Sync to disk
            2020-05-06 19:36:18 4 [Note] InnoDB: Sync to disk - done!
            2020-05-06 19:36:18 4 [Note] InnoDB: Phase III - Flush changes to disk
            2020-05-06 19:36:18 4 [Note] InnoDB: Phase IV - Flush complete
            2020-05-06 19:36:18 4 [Note] InnoDB: `test`.`t_innodb` autoinc value set to 2
            2020-05-06 19:36:18 4 [Note] InnoDB: Importing tablespace for table 'test/tpe_innodb' that was exported from host 'rhel77'
            2020-05-06 19:36:18 4 [Note] InnoDB: Phase I - Update all pages
            2020-05-06 19:36:18 4 [Note] InnoDB: Sync to disk
            2020-05-06 19:36:18 4 [Note] InnoDB: Sync to disk - done!
            2020-05-06 19:36:18 4 [Note] InnoDB: Phase III - Flush changes to disk
            2020-05-06 19:36:18 4 [Note] InnoDB: Phase IV - Flush complete
            2020-05-06 19:36:18 4 [Note] InnoDB: `test`.`tpe_innodb` autoinc value set to 2
            2020-05-06 19:36:18 4 [Note] InnoDB: Importing tablespace for table 'test/tp_innodb' that was exported from host 'rhel77'
            2020-05-06 19:36:18 4 [Note] InnoDB: Phase I - Update all pages
            2020-05-06 19:36:18 4 [Note] InnoDB: Sync to disk
            2020-05-06 19:36:18 4 [Note] InnoDB: Sync to disk - done!
            2020-05-06 19:36:18 4 [Note] InnoDB: Phase III - Flush changes to disk
            2020-05-06 19:36:18 4 [Note] InnoDB: Phase IV - Flush complete
            2020-05-06 19:36:18 4 [Note] InnoDB: `test`.`tp_innodb` autoinc value set to 2
            2020-05-06 19:36:18 4 [Note] InnoDB: Sync to disk of `test`.`tce_none` started.
            2020-05-06 19:36:18 4 [Note] InnoDB: Stopping purge
            2020-05-06 19:36:18 4 [Note] InnoDB: Writing table metadata to './test/tce_none.cfg'
            2020-05-06 19:36:18 4 [Note] InnoDB: Table `test`.`tce_none` flushed to disk
            2020-05-06 19:36:18 4 [Note] InnoDB: Sync to disk of `test`.`tc_none` started.
            2020-05-06 19:36:18 4 [Note] InnoDB: Writing table metadata to './test/tc_none.cfg'
            2020-05-06 19:36:18 4 [Note] InnoDB: Table `test`.`tc_none` flushed to disk
            2020-05-06 19:36:18 4 [Note] InnoDB: Sync to disk of `test`.`te_none` started.
            2020-05-06 19:36:18 4 [Note] InnoDB: Writing table metadata to './test/te_none.cfg'
            2020-05-06 19:36:18 4 [Note] InnoDB: Table `test`.`te_none` flushed to disk
            2020-05-06 19:36:18 4 [Note] InnoDB: Sync to disk of `test`.`t_none` started.
            2020-05-06 19:36:18 4 [Note] InnoDB: Writing table metadata to './test/t_none.cfg'
            2020-05-06 19:36:18 4 [Note] InnoDB: Table `test`.`t_none` flushed to disk
            2020-05-06 19:36:18 4 [Note] InnoDB: Sync to disk of `test`.`tpe_none` started.
            2020-05-06 19:36:18 4 [Note] InnoDB: Writing table metadata to './test/tpe_none.cfg'
            2020-05-06 19:36:18 4 [Note] InnoDB: Table `test`.`tpe_none` flushed to disk
            2020-05-06 19:36:18 4 [Note] InnoDB: Sync to disk of `test`.`tp_none` started.
            2020-05-06 19:36:18 4 [Note] InnoDB: Writing table metadata to './test/tp_none.cfg'
            2020-05-06 19:36:18 4 [Note] InnoDB: Table `test`.`tp_none` flushed to disk
            2020-05-06 19:36:18 4 [Note] InnoDB: Deleting the meta-data file './test/tce_none.cfg'
            2020-05-06 19:36:18 4 [Note] InnoDB: Deleting the meta-data file './test/tc_none.cfg'
            2020-05-06 19:36:18 4 [Note] InnoDB: Deleting the meta-data file './test/te_none.cfg'
            2020-05-06 19:36:18 4 [Note] InnoDB: Deleting the meta-data file './test/t_none.cfg'
            2020-05-06 19:36:18 4 [Note] InnoDB: Deleting the meta-data file './test/tpe_none.cfg'
            2020-05-06 19:36:18 4 [Note] InnoDB: Deleting the meta-data file './test/tp_none.cfg'
            2020-05-06 19:36:18 4 [Note] InnoDB: Resuming purge
            2020-05-06 19:36:18 4 [Note] InnoDB: Importing tablespace for table 'test/tce_none' that was exported from host 'rhel77'
            2020-05-06 19:36:18 4 [Note] InnoDB: Phase I - Update all pages
            2020-05-06 19:36:18 4 [Note] InnoDB: Sync to disk
            2020-05-06 19:36:18 4 [Note] InnoDB: Sync to disk - done!
            2020-05-06 19:36:18 4 [Note] InnoDB: Phase III - Flush changes to disk
            2020-05-06 19:36:18 4 [Note] InnoDB: Phase IV - Flush complete
            2020-05-06 19:36:18 4 [Note] InnoDB: `test`.`tce_none` autoinc value set to 2
            2020-05-06 19:36:18 4 [Note] InnoDB: Importing tablespace for table 'test/tc_none' that was exported from host 'rhel77'
            2020-05-06 19:36:18 4 [Note] InnoDB: Phase I - Update all pages
            2020-05-06 19:36:18 4 [Note] InnoDB: Sync to disk
            2020-05-06 19:36:18 4 [Note] InnoDB: Sync to disk - done!
            2020-05-06 19:36:18 4 [Note] InnoDB: Phase III - Flush changes to disk
            2020-05-06 19:36:18 4 [Note] InnoDB: Phase IV - Flush complete
            2020-05-06 19:36:18 4 [Note] InnoDB: `test`.`tc_none` autoinc value set to 2
            2020-05-06 19:36:18 4 [Note] InnoDB: Importing tablespace for table 'test/te_none' that was exported from host 'rhel77'
            2020-05-06 19:36:18 4 [Note] InnoDB: Phase I - Update all pages
            2020-05-06 19:36:18 4 [Note] InnoDB: Sync to disk
            2020-05-06 19:36:18 4 [Note] InnoDB: Sync to disk - done!
            2020-05-06 19:36:18 4 [Note] InnoDB: Phase III - Flush changes to disk
            2020-05-06 19:36:18 4 [Note] InnoDB: Phase IV - Flush complete
            2020-05-06 19:36:19 4 [Note] InnoDB: `test`.`te_none` autoinc value set to 2
            2020-05-06 19:36:19 4 [Note] InnoDB: Importing tablespace for table 'test/t_none' that was exported from host 'rhel77'
            2020-05-06 19:36:19 4 [Note] InnoDB: Phase I - Update all pages
            2020-05-06 19:36:19 4 [Note] InnoDB: Sync to disk
            2020-05-06 19:36:19 4 [Note] InnoDB: Sync to disk - done!
            2020-05-06 19:36:19 4 [Note] InnoDB: Phase III - Flush changes to disk
            2020-05-06 19:36:19 4 [Note] InnoDB: Phase IV - Flush complete
            2020-05-06 19:36:19 4 [Note] InnoDB: `test`.`t_none` autoinc value set to 2
            2020-05-06 19:36:19 4 [Note] InnoDB: Importing tablespace for table 'test/tpe_none' that was exported from host 'rhel77'
            2020-05-06 19:36:19 4 [Note] InnoDB: Phase I - Update all pages
            2020-05-06 19:36:19 4 [Note] InnoDB: Sync to disk
            2020-05-06 19:36:19 4 [Note] InnoDB: Sync to disk - done!
            2020-05-06 19:36:19 4 [Note] InnoDB: Phase III - Flush changes to disk
            2020-05-06 19:36:19 4 [Note] InnoDB: Phase IV - Flush complete
            2020-05-06 19:36:19 4 [Note] InnoDB: `test`.`tpe_none` autoinc value set to 2
            2020-05-06 19:36:19 4 [Note] InnoDB: Importing tablespace for table 'test/tp_none' that was exported from host 'rhel77'
            2020-05-06 19:36:19 4 [Note] InnoDB: Phase I - Update all pages
            2020-05-06 19:36:19 4 [Note] InnoDB: Sync to disk
            2020-05-06 19:36:19 4 [Note] InnoDB: Sync to disk - done!
            2020-05-06 19:36:19 4 [Note] InnoDB: Phase III - Flush changes to disk
            2020-05-06 19:36:19 4 [Note] InnoDB: Phase IV - Flush complete
            2020-05-06 19:36:19 4 [Note] InnoDB: `test`.`tp_none` autoinc value set to 2
            2020-05-06 19:36:19 4 [Note] InnoDB: Importing tablespace for table 'test/tce_none' that was exported from host 'rhel77'
            2020-05-06 19:36:19 4 [Note] InnoDB: Phase I - Update all pages
            2020-05-06 19:36:19 4 [Note] InnoDB: Sync to disk
            2020-05-06 19:36:19 4 [Note] InnoDB: Sync to disk - done!
            2020-05-06 19:36:19 4 [Note] InnoDB: Phase III - Flush changes to disk
            2020-05-06 19:36:19 4 [Note] InnoDB: Phase IV - Flush complete
            2020-05-06 19:36:19 4 [Note] InnoDB: `test`.`tce_none` autoinc value set to 2
            2020-05-06 19:36:19 4 [Note] InnoDB: Importing tablespace for table 'test/tc_none' that was exported from host 'rhel77'
            2020-05-06 19:36:19 4 [Note] InnoDB: Phase I - Update all pages
            2020-05-06 19:36:19 4 [Note] InnoDB: Sync to disk
            2020-05-06 19:36:19 4 [Note] InnoDB: Sync to disk - done!
            2020-05-06 19:36:19 4 [Note] InnoDB: Phase III - Flush changes to disk
            2020-05-06 19:36:19 4 [Note] InnoDB: Phase IV - Flush complete
            2020-05-06 19:36:19 4 [Note] InnoDB: `test`.`tc_none` autoinc value set to 2
            2020-05-06 19:36:19 4 [Note] InnoDB: Importing tablespace for table 'test/te_none' that was exported from host 'rhel77'
            2020-05-06 19:36:19 4 [Note] InnoDB: Phase I - Update all pages
            2020-05-06 19:36:19 4 [Note] InnoDB: Sync to disk
            2020-05-06 19:36:19 4 [Note] InnoDB: Sync to disk - done!
            2020-05-06 19:36:19 4 [Note] InnoDB: Phase III - Flush changes to disk
            2020-05-06 19:36:19 4 [Note] InnoDB: Phase IV - Flush complete
            2020-05-06 19:36:19 4 [Note] InnoDB: `test`.`te_none` autoinc value set to 2
            2020-05-06 19:36:19 4 [Note] InnoDB: Importing tablespace for table 'test/t_none' that was exported from host 'rhel77'
            2020-05-06 19:36:19 4 [Note] InnoDB: Phase I - Update all pages
            2020-05-06 19:36:19 4 [Note] InnoDB: Sync to disk
            2020-05-06 19:36:19 4 [Note] InnoDB: Sync to disk - done!
            2020-05-06 19:36:19 4 [Note] InnoDB: Phase III - Flush changes to disk
            2020-05-06 19:36:19 4 [Note] InnoDB: Phase IV - Flush complete
            2020-05-06 19:36:19 4 [Note] InnoDB: `test`.`t_none` autoinc value set to 2
            2020-05-06 19:36:19 4 [Note] InnoDB: Importing tablespace for table 'test/tpe_none' that was exported from host 'rhel77'
            2020-05-06 19:36:19 4 [Note] InnoDB: Phase I - Update all pages
            2020-05-06 19:36:19 4 [Note] InnoDB: Sync to disk
            2020-05-06 19:36:19 4 [Note] InnoDB: Sync to disk - done!
            2020-05-06 19:36:19 4 [Note] InnoDB: Phase III - Flush changes to disk
            2020-05-06 19:36:19 4 [Note] InnoDB: Phase IV - Flush complete
            2020-05-06 19:36:19 4 [Note] InnoDB: `test`.`tpe_none` autoinc value set to 2
            2020-05-06 19:36:19 4 [Note] InnoDB: Importing tablespace for table 'test/tp_none' that was exported from host 'rhel77'
            2020-05-06 19:36:19 4 [Note] InnoDB: Phase I - Update all pages
            2020-05-06 19:36:19 4 [Note] InnoDB: Sync to disk
            2020-05-06 19:36:19 4 [Note] InnoDB: Sync to disk - done!
            2020-05-06 19:36:19 4 [Note] InnoDB: Phase III - Flush changes to disk
            2020-05-06 19:36:19 4 [Note] InnoDB: Phase IV - Flush complete
            2020-05-06 19:36:19 4 [Note] InnoDB: `test`.`tp_none` autoinc value set to 2
            mariadbd: /home/ozlabs/mariadb-server-10.5/storage/innobase/log/log0log.cc:1363: bool log_checkpoint(): Assertion `oldest_lsn >= log_sys.last_checkpoint_lsn' failed.
            200506 19:36:19 [ERROR] mysqld got signal 6 ;
             
             
            (gdb) bt full
            #0  0x00003fff93acffac in pthread_kill () from /lib64/libpthread.so.0
            No symbol table info available.
            #1  0x000000010bcdd024 in my_write_core (sig=6) at /home/ozlabs/mariadb-server-10.5/mysys/stacktrace.c:518
            No locals.
            #2  0x000000010b023834 in handle_fatal_signal (sig=6) at /home/ozlabs/mariadb-server-10.5/sql/signal_handler.cc:329
                    curr_time = 1588808179
                    tm = {tm_sec = 19, tm_min = 36, tm_hour = 19, tm_mday = 6, tm_mon = 4, tm_year = 120, tm_wday = 3, tm_yday = 126, tm_isdst = 1, tm_gmtoff = -14400, 
                      tm_zone = 0x100185ee660 "EDT"}
                    thd = 0x0
                    print_invalid_query_pointer = false
            #3  <signal handler called>
            No locals.
            #4  0x00003fff9322fc30 in raise () from /lib64/libc.so.6
            No symbol table info available.
            #5  0x00003fff93231f8c in abort () from /lib64/libc.so.6
            No symbol table info available.
            #6  0x00003fff93225754 in __assert_fail_base () from /lib64/libc.so.6
            No symbol table info available.
            #7  0x00003fff93225844 in __assert_fail () from /lib64/libc.so.6
            No symbol table info available.
            #8  0x000000010b769ff8 in log_checkpoint () at /home/ozlabs/mariadb-server-10.5/storage/innobase/log/log0log.cc:1363
                    __PRETTY_FUNCTION__ = "bool log_checkpoint()"
                    end_lsn = 2
                    oldest_lsn = 186431
                    flush_lsn = 70365187410496
                    do_write = false
            #9  0x000000010b926218 in srv_master_do_active_tasks () at /home/ozlabs/mariadb-server-10.5/storage/innobase/srv/srv0srv.cc:1868
                    cur_time = 1588808179
                    counter_time = 759646513533
            #10 0x000000010b926bf0 in srv_master_callback () at /home/ozlabs/mariadb-server-10.5/storage/innobase/srv/srv0srv.cc:2000
                    old_activity_count = 177
            #11 0x000000010bc06ac8 in tpool::thread_pool_generic::timer_generic::run (this=0x10018c31330) at /home/ozlabs/mariadb-server-10.5/tpool/tpool_generic.cc:299
                    expected = false
            #12 0x000000010bc06c08 in tpool::thread_pool_generic::timer_generic::execute (arg=0x10018c31330) at /home/ozlabs/mariadb-server-10.5/tpool/tpool_generic.cc:317
                    timer = 0x10018c31330
            #13 0x000000010bc11c28 in tpool::task::execute (this=0x10018c31370) at /home/ozlabs/mariadb-server-10.5/tpool/task.cc:52
            No locals.
            #14 0x000000010bc0403c in tpool::thread_pool_generic::worker_main (this=0x100187fd070, thread_var=0x1001880c780) at /home/ozlabs/mariadb-server-10.5/tpool/tpool_generic.cc:518
                    task = 0x10018c31370
            #15 0x000000010bc1116c in std::_Mem_fn<void (tpool::thread_pool_generic::*)(tpool::worker_data*)>::operator()<tpool::worker_data*, void>(tpool::thread_pool_generic*, tpool::worker_data*&&) const (this=0x3fff4c001780, __object=0x100187fd070) at /usr/include/c++/4.8.2/functional:601
            No locals.
            #16 0x000000010bc10fd4 in std::_Bind_simple<std::_Mem_fn<void (tpool::thread_pool_generic::*)(tpool::worker_data*)> (tpool::thread_pool_generic*, tpool::worker_data*)>::_M_invoke<0ul, 1ul>(std::_Index_tuple<0ul, 1ul>) (this=0x3fff4c001770) at /usr/include/c++/4.8.2/functional:1732
            No locals.
            #17 0x000000010bc10c58 in std::_Bind_simple<std::_Mem_fn<void (tpool::thread_pool_generic::*)(tpool::worker_data*)> (tpool::thread_pool_generic*, tpool::worker_data*)>::operator()() (this=0x3fff4c001770) at /usr/include/c++/4.8.2/functional:1720
            No locals.
            ---Type <return> to continue, or q <return> to quit---
            #18 0x000000010bc10b60 in std::thread::_Impl<std::_Bind_simple<std::_Mem_fn<void (tpool::thread_pool_generic::*)(tpool::worker_data*)> (tpool::thread_pool_generic*, tpool::worker_data*)> >::_M_run() (this=0x3fff4c001758) at /usr/include/c++/4.8.2/thread:115
            No locals.
            #19 0x00003fff9361c2a4 in ?? () from /lib64/libstdc++.so.6
            No symbol table info available.
            #20 0x00003fff93ac8cd4 in start_thread () from /lib64/libpthread.so.0
            No symbol table info available.
            #21 0x00003fff93317e94 in clone () from /lib64/libc.so.6
            No symbol table info available.
            (gdb) p log_sys
            $1 = {static FORMAT_3_23 = 0, static FORMAT_10_2 = 1, static FORMAT_10_3 = 103, static FORMAT_10_4 = 104, static FORMAT_ENCRYPTED = 2147483648, 
              static FORMAT_ENC_10_4 = 2147483752, static FORMAT_10_5 = 1346918739, static FORMAT_ENC_10_5 = 3494402387, lsn = {<std::__atomic_base<unsigned long>> = {
                  _M_i = 193590}, <No data fields>}, flushed_to_disk_lsn = {<std::__atomic_base<unsigned long>> = {_M_i = 193590}, <No data fields>}, buf_free = 54, 
              check_flush_or_checkpoint_ = {<std::atomic_bool> = {_M_base = {_M_i = false}}, <No data fields>}, mutex = {m_impl = {m_lock_word = {<std::__atomic_base<unsigned int>> = {
                      _M_i = 2}, <No data fields>}, m_event = 0x10018988e48, m_policy = {context = {<latch_t> = {
                        _vptr.latch_t = 0x10c7e1cf0 <vtable for MutexDebug<TTASEventMutex<GenericPolicy> >+16>, m_id = LATCH_ID_LOG_SYS, m_rw_lock = false}, 
                      m_mutex = 0x10d29a080 <log_sys+128>, m_filename = 0x10c165a08 "/home/ozlabs/mariadb-server-10.5/storage/innobase/log/log0log.cc", m_line = 1350, 
                      m_thread_id = 70365522948176, m_debug_mutex = {m_freed = false, m_mutex = {__data = {__lock = 0, __count = 0, __owner = 0, __nusers = 0, __kind = 0, __spins = 0, 
                            __elision = 0, __list = {__prev = 0x0, __next = 0x0}}, __size = '\000' <repeats 39 times>, __align = 0}}}, m_count = {m_spins = 0, m_waits = 0, m_calls = 0, 
                      m_enabled = false}, m_id = LATCH_ID_LOG_SYS}}, m_ptr = 0x10018670c00}, log_flush_order_mutex = {m_impl = {m_lock_word = {<std::__atomic_base<unsigned int>> = {
                      _M_i = 0}, <No data fields>}, m_event = 0x10018988f88, m_policy = {context = {<latch_t> = {
                        _vptr.latch_t = 0x10c7e1cf0 <vtable for MutexDebug<TTASEventMutex<GenericPolicy> >+16>, m_id = LATCH_ID_LOG_FLUSH_ORDER, m_rw_lock = false}, m_mutex = 0x0, 
                      m_filename = 0x0, m_line = 0, m_thread_id = 18446744073709551615, m_debug_mutex = {m_freed = false, m_mutex = {__data = {__lock = 0, __count = 0, __owner = 0, 
                            __nusers = 0, __kind = 0, __spins = 0, __elision = 0, __list = {__prev = 0x0, __next = 0x0}}, __size = '\000' <repeats 39 times>, __align = 0}}}, m_count = {
                      m_spins = 0, m_waits = 0, m_calls = 0, m_enabled = false}, m_id = LATCH_ID_LOG_FLUSH_ORDER}}, m_ptr = 0x10018670c80}, buf = 0x3fff8c1e0000 "\200", 
              flush_buf = 0x3fff8c0e0000 "\200", max_buf_free = 456704, log = {format = 1346918739, subformat = 2, file_size = 10485760, lsn = 193561, lsn_offset = 186905, fd = {
                  m_file = std::unique_ptr<file_io> containing 0x100189b3ae0, m_path = "./ib_logfile0"}, scanned_lsn = 47785}, buf_next_to_write = 54, write_lsn = 193590, 
              current_flush_lsn = 0, pending_flushes = {<std::__atomic_base<unsigned long>> = {_M_i = 0}, <No data fields>}, flushes = {<std::__atomic_base<unsigned long>> = {
                  _M_i = 317}, <No data fields>}, n_log_ios = 319, n_log_ios_old = 0, last_printout_time = 1588808176, log_capacity = 9435341, max_modified_age_async = 6811017, 
              max_modified_age_sync = 7297518, max_checkpoint_age_async = 7540769, max_checkpoint_age = 7784019, next_checkpoint_no = 52, last_checkpoint_lsn = 186446, 
              next_checkpoint_lsn = 186446, n_pending_checkpoint_writes = 0, 
              checkpoint_buf = "\000\000\000\000\000\000\000\063\000\000\000\000\000\002\330N\000\000\000\000\000\002\276N\000\000\000\000\000\020", '\000' <repeats 471 times>..., 
              m_initialised = true}
            (gdb)  p log_sys.last_checkpoint_lsn
            $2 = 186446
            (gdb) p log_sys.next_checkpoint_lsn
            $3 = 186446
            (gdb)  p log_sys.lsn
            $4 = {<std::__atomic_base<unsigned long>> = {_M_i = 193590}, <No data fields>}
            #8  0x000000010b769ff8 in log_checkpoint () at /home/ozlabs/mariadb-server-10.5/storage/innobase/log/log0log.cc:1363
            1363		ut_ad(oldest_lsn >= log_sys.last_checkpoint_lsn);
            (gdb) p oldest_lsn
            $5 = 186431
            (gdb)   p log_sys.last_checkpoint_lsn-oldest_lsn
            $6 = 15
            (gdb) p srv_stats
            $8 = {data_written = {m_counter = 32669696}, log_write_requests = {m_counter = 285}, log_writes = {m_counter = 317}, log_padded = {m_counter = 125440}, os_log_written = {
                m_counter = 433664}, os_log_pending_writes = {m_counter = 0}, log_waits = {m_counter = 0}, dblwr_writes = {m_counter = 65}, dblwr_pages_written = {m_counter = 851}, 
              buf_pool_write_requests = {m_counter = 6172}, buf_pool_wait_free = {m_counter = 0}, buf_pool_flushed = {m_counter = 1082}, buf_pool_reads = {m_counter = 453}, ...
              key_rotation_list_length = {m_counter = {{value = {<std::__atomic_base<unsigned long>> = {_M_i = 0}, <No data fields>}} <repeats 64 times>}}, n_temp_blocks_encrypted = {
                m_counter = {{value = {<std::__atomic_base<unsigned long>> = {_M_i = 0}, <No data fields>}} <repeats 64 times>}}, n_temp_blocks_decrypted = {m_counter = {{
                    value = {<std::__atomic_base<unsigned long>> = {_M_i = 0}, <No data fields>}} <repeats 64 times>}}, lock_deadlock_count = {m_counter = 0}}
            

            danblack Daniel Black added a comment - encryption.innodb-checksum-algorithm-16k,ctr,innodb test on Power9. 10.5-0781c91d288e528477e4ab446f91522a8802e5ec-Debug + 8399af81be0a87d1c0ea09164c05a9ac8eb715e2 revert encryption.innodb-checksum-algorithm '16k,ctr,innodb' w4 [ fail ] Test ended at 2020-05-06 19:36:19   CURRENT_TEST: encryption.innodb-checksum-algorithm mysqltest: At line 111: query 'ALTER TABLE tce_$checksum IMPORT TABLESPACE' failed: 2013: Lost connection to MySQL server during query   The result from queries just before the failure was: < snip > ALTER TABLE t_none IMPORT TABLESPACE; update t_none set b=substr(b,1); ALTER TABLE tpe_none IMPORT TABLESPACE; update tpe_none set b=substr(b,1); ALTER TABLE tp_none IMPORT TABLESPACE; update tp_none set b=substr(b,1); SET GLOBAL innodb_checksum_algorithm=none; ALTER TABLE tce_none DISCARD TABLESPACE; ALTER TABLE tc_none DISCARD TABLESPACE; ALTER TABLE te_none DISCARD TABLESPACE; ALTER TABLE t_none DISCARD TABLESPACE; ALTER TABLE tpe_none DISCARD TABLESPACE; ALTER TABLE tp_none DISCARD TABLESPACE; restore: tce_none .ibd and .cfg files restore: tc_none .ibd and .cfg files restore: te_none .ibd and .cfg files restore: t_none .ibd and .cfg files restore: tpe_none .ibd and .cfg files restore: tp_none .ibd and .cfg files ALTER TABLE tce_none IMPORT TABLESPACE;   More results from queries before failure can be found in /home/ozlabs/build-mariadb-server-10.5-debug/mysql-test/var/4/log/innodb-checksum-algorithm.log     Server [mysqld.1 - pid: 25209, winpid: 25209, exit: 256] failed during test run Server log from this test: ----------SERVER LOG START----------- 2020-05-06 19:36:16 0 [Note] /home/ozlabs/build-mariadb-server-10.5-debug/sql/mariadbd (mysqld 10.5.3-MariaDB-debug-log) starting as process 25211 ... 2020-05-06 19:36:16 0 [Warning] Could not increase number of max_open_files to more than 1024 (request: 32194) 2020-05-06 19:36:16 0 [Warning] Changed limits: max_open_files: 1024 max_connections: 151 (was 151) table_cache: 421 (was 2000) 2020-05-06 19:36:16 0 [Note] Plugin 'partition' is disabled. 2020-05-06 19:36:16 0 [Note] Plugin 'SEQUENCE' is disabled. 2020-05-06 19:36:16 0 [Note] InnoDB: !!!!!!!! UNIV_DEBUG switched on !!!!!!!!! 2020-05-06 19:36:16 0 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins 2020-05-06 19:36:16 0 [Note] InnoDB: Uses event mutexes 2020-05-06 19:36:16 0 [Note] InnoDB: Compressed tables use zlib 1.2.7 2020-05-06 19:36:16 0 [Note] InnoDB: Number of pools: 1 2020-05-06 19:36:16 0 [Note] InnoDB: Using POWER8 crc32 instructions 2020-05-06 19:36:16 0 [Note] mariadbd: O_TMPFILE is not supported on /home/ozlabs/build-mariadb-server-10.5-debug/mysql-test/var/tmp/4/mysqld.1 (disabling future attempts) 2020-05-06 19:36:16 0 [Note] InnoDB: Initializing buffer pool, total size = 8388608, chunk size = 8388608 2020-05-06 19:36:16 0 [Note] InnoDB: Completed initialization of buffer pool 2020-05-06 19:36:16 0 [Note] InnoDB: If the mysqld execution user is authorized, page cleaner thread priority can be changed. See the man page of setpriority(). 2020-05-06 19:36:16 0 [Note] InnoDB: 128 rollback segments are active. 2020-05-06 19:36:16 0 [Note] InnoDB: Creating shared tablespace for temporary tables 2020-05-06 19:36:16 0 [Note] InnoDB: Setting file './ibtmp1' size to 12 MB. Physically writing the file full; Please wait ... 2020-05-06 19:36:16 0 [Note] InnoDB: File './ibtmp1' size is now 12 MB. 2020-05-06 19:36:16 0 [Note] InnoDB: 10.5.3 started; log sequence number 47785; transaction id 28 2020-05-06 19:36:16 0 [Note] Plugin 'INNODB_SYS_DATAFILES' is disabled. 2020-05-06 19:36:16 0 [Note] Plugin 'INNODB_SYS_TABLESTATS' is disabled. 2020-05-06 19:36:16 0 [Note] Plugin 'INNODB_CMP' is disabled. 2020-05-06 19:36:16 0 [Note] Plugin 'THREAD_POOL_WAITS' is disabled. 2020-05-06 19:36:16 0 [Note] Plugin 'INNODB_CMP_RESET' is disabled. 2020-05-06 19:36:16 0 [Note] Plugin 'THREAD_POOL_QUEUES' is disabled. 2020-05-06 19:36:16 0 [Note] Plugin 'FEEDBACK' is disabled. 2020-05-06 19:36:16 0 [Note] Plugin 'INNODB_FT_INDEX_TABLE' is disabled. 2020-05-06 19:36:16 0 [Note] Plugin 'THREAD_POOL_GROUPS' is disabled. 2020-05-06 19:36:16 0 [Note] Plugin 'INNODB_CMP_PER_INDEX_RESET' is disabled. 2020-05-06 19:36:16 0 [Note] Plugin 'INNODB_FT_INDEX_CACHE' is disabled. 2020-05-06 19:36:16 0 [Note] Plugin 'INNODB_FT_BEING_DELETED' is disabled. 2020-05-06 19:36:16 0 [Note] InnoDB: Loading buffer pool(s) from /dev/shm/var_auto_ck8g/4/mysqld.1/data/ib_buffer_pool 2020-05-06 19:36:16 0 [Note] Plugin 'INNODB_CMPMEM_RESET' is disabled. 2020-05-06 19:36:16 0 [Note] Plugin 'INNODB_FT_DEFAULT_STOPWORD' is disabled. 2020-05-06 19:36:16 0 [Note] Plugin 'INNODB_FT_CONFIG' is disabled. 2020-05-06 19:36:16 0 [Note] Plugin 'INNODB_SYS_TABLESPACES' is disabled. 2020-05-06 19:36:16 0 [Note] Plugin 'INNODB_SYS_SEMAPHORE_WAITS' is disabled. 2020-05-06 19:36:16 0 [Note] Plugin 'INNODB_MUTEXES' is disabled. 2020-05-06 19:36:16 0 [Note] Plugin 'user_variables' is disabled. 2020-05-06 19:36:16 0 [Note] Plugin 'INNODB_TABLESPACES_ENCRYPTION' is disabled. 2020-05-06 19:36:16 0 [Note] Plugin 'INNODB_FT_DELETED' is disabled. 2020-05-06 19:36:16 0 [Note] Plugin 'THREAD_POOL_STATS' is disabled. 2020-05-06 19:36:16 0 [Note] Plugin 'unix_socket' is disabled. 2020-05-06 19:36:16 0 [Warning] /home/ozlabs/build-mariadb-server-10.5-debug/sql/mariadbd: unknown option '--loose-pam-debug' 2020-05-06 19:36:16 0 [Warning] /home/ozlabs/build-mariadb-server-10.5-debug/sql/mariadbd: unknown option '--loose-aria' 2020-05-06 19:36:16 0 [Note] InnoDB: Buffer pool(s) load completed at 200506 19:36:16 2020-05-06 19:36:16 0 [Note] Server socket created on IP: '127.0.0.1'. 2020-05-06 19:36:16 0 [Note] Reading of all Master_info entries succeeded 2020-05-06 19:36:16 0 [Note] Added new Master_info '' to hash table 2020-05-06 19:36:16 0 [Note] /home/ozlabs/build-mariadb-server-10.5-debug/sql/mariadbd: ready for connections. Version: '10.5.3-MariaDB-debug-log' socket: '/home/ozlabs/build-mariadb-server-10.5-debug/mysql-test/var/tmp/4/mysqld.1.sock' port: 16060 Source distribution 2020-05-06 19:36:16 4 [Note] InnoDB: Creating #1 encryption thread id 70366185582672 total threads 4. 2020-05-06 19:36:16 4 [Note] InnoDB: Creating #2 encryption thread id 70366177128528 total threads 4. 2020-05-06 19:36:16 4 [Note] InnoDB: Creating #3 encryption thread id 70366168674384 total threads 4. 2020-05-06 19:36:16 4 [Note] InnoDB: Creating #4 encryption thread id 70366160220240 total threads 4. 2020-05-06 19:36:16 4 [Note] InnoDB: Sync to disk of `test`.`tce_crc32` started. 2020-05-06 19:36:16 4 [Note] InnoDB: Stopping purge 2020-05-06 19:36:16 4 [Note] InnoDB: Writing table metadata to './test/tce_crc32.cfg' 2020-05-06 19:36:16 4 [Note] InnoDB: Table `test`.`tce_crc32` flushed to disk 2020-05-06 19:36:16 4 [Note] InnoDB: Sync to disk of `test`.`tc_crc32` started. 2020-05-06 19:36:16 4 [Note] InnoDB: Writing table metadata to './test/tc_crc32.cfg' 2020-05-06 19:36:16 4 [Note] InnoDB: Table `test`.`tc_crc32` flushed to disk 2020-05-06 19:36:16 4 [Note] InnoDB: Sync to disk of `test`.`te_crc32` started. 2020-05-06 19:36:16 4 [Note] InnoDB: Writing table metadata to './test/te_crc32.cfg' 2020-05-06 19:36:16 4 [Note] InnoDB: Table `test`.`te_crc32` flushed to disk 2020-05-06 19:36:16 4 [Note] InnoDB: Sync to disk of `test`.`t_crc32` started. 2020-05-06 19:36:16 4 [Note] InnoDB: Writing table metadata to './test/t_crc32.cfg' 2020-05-06 19:36:16 4 [Note] InnoDB: Table `test`.`t_crc32` flushed to disk 2020-05-06 19:36:16 4 [Note] InnoDB: Sync to disk of `test`.`tpe_crc32` started. 2020-05-06 19:36:16 4 [Note] InnoDB: Writing table metadata to './test/tpe_crc32.cfg' 2020-05-06 19:36:16 4 [Note] InnoDB: Table `test`.`tpe_crc32` flushed to disk 2020-05-06 19:36:16 4 [Note] InnoDB: Sync to disk of `test`.`tp_crc32` started. 2020-05-06 19:36:16 4 [Note] InnoDB: Writing table metadata to './test/tp_crc32.cfg' 2020-05-06 19:36:16 4 [Note] InnoDB: Table `test`.`tp_crc32` flushed to disk 2020-05-06 19:36:16 4 [Note] InnoDB: Deleting the meta-data file './test/tce_crc32.cfg' 2020-05-06 19:36:16 4 [Note] InnoDB: Deleting the meta-data file './test/tc_crc32.cfg' 2020-05-06 19:36:16 4 [Note] InnoDB: Deleting the meta-data file './test/te_crc32.cfg' 2020-05-06 19:36:16 4 [Note] InnoDB: Deleting the meta-data file './test/t_crc32.cfg' 2020-05-06 19:36:16 4 [Note] InnoDB: Deleting the meta-data file './test/tpe_crc32.cfg' 2020-05-06 19:36:16 4 [Note] InnoDB: Deleting the meta-data file './test/tp_crc32.cfg' 2020-05-06 19:36:16 4 [Note] InnoDB: Resuming purge 2020-05-06 19:36:17 4 [Note] InnoDB: Importing tablespace for table 'test/tce_crc32' that was exported from host 'rhel77' 2020-05-06 19:36:17 4 [Note] InnoDB: Phase I - Update all pages 2020-05-06 19:36:17 4 [Note] InnoDB: Sync to disk 2020-05-06 19:36:17 4 [Note] InnoDB: Sync to disk - done! 2020-05-06 19:36:17 4 [Note] InnoDB: Phase III - Flush changes to disk 2020-05-06 19:36:17 4 [Note] InnoDB: Phase IV - Flush complete 2020-05-06 19:36:17 4 [Note] InnoDB: `test`.`tce_crc32` autoinc value set to 2 2020-05-06 19:36:17 4 [Note] InnoDB: Importing tablespace for table 'test/tc_crc32' that was exported from host 'rhel77' 2020-05-06 19:36:17 4 [Note] InnoDB: Phase I - Update all pages 2020-05-06 19:36:17 4 [Note] InnoDB: Sync to disk 2020-05-06 19:36:17 4 [Note] InnoDB: Sync to disk - done! 2020-05-06 19:36:17 4 [Note] InnoDB: Phase III - Flush changes to disk 2020-05-06 19:36:17 4 [Note] InnoDB: Phase IV - Flush complete 2020-05-06 19:36:17 4 [Note] InnoDB: `test`.`tc_crc32` autoinc value set to 2 2020-05-06 19:36:17 4 [Note] InnoDB: Importing tablespace for table 'test/te_crc32' that was exported from host 'rhel77' 2020-05-06 19:36:17 4 [Note] InnoDB: Phase I - Update all pages 2020-05-06 19:36:17 4 [Note] InnoDB: Sync to disk 2020-05-06 19:36:17 4 [Note] InnoDB: Sync to disk - done! 2020-05-06 19:36:17 4 [Note] InnoDB: Phase III - Flush changes to disk 2020-05-06 19:36:17 4 [Note] InnoDB: Phase IV - Flush complete 2020-05-06 19:36:17 4 [Note] InnoDB: `test`.`te_crc32` autoinc value set to 2 2020-05-06 19:36:17 4 [Note] InnoDB: Importing tablespace for table 'test/t_crc32' that was exported from host 'rhel77' 2020-05-06 19:36:17 4 [Note] InnoDB: Phase I - Update all pages 2020-05-06 19:36:17 4 [Note] InnoDB: Sync to disk 2020-05-06 19:36:17 4 [Note] InnoDB: Sync to disk - done! 2020-05-06 19:36:17 4 [Note] InnoDB: Phase III - Flush changes to disk 2020-05-06 19:36:17 4 [Note] InnoDB: Phase IV - Flush complete 2020-05-06 19:36:17 4 [Note] InnoDB: `test`.`t_crc32` autoinc value set to 2 2020-05-06 19:36:17 4 [Note] InnoDB: Importing tablespace for table 'test/tpe_crc32' that was exported from host 'rhel77' 2020-05-06 19:36:17 4 [Note] InnoDB: Phase I - Update all pages 2020-05-06 19:36:17 4 [Note] InnoDB: Sync to disk 2020-05-06 19:36:17 4 [Note] InnoDB: Sync to disk - done! 2020-05-06 19:36:17 4 [Note] InnoDB: Phase III - Flush changes to disk 2020-05-06 19:36:17 4 [Note] InnoDB: Phase IV - Flush complete 2020-05-06 19:36:17 4 [Note] InnoDB: `test`.`tpe_crc32` autoinc value set to 2 2020-05-06 19:36:17 4 [Note] InnoDB: Importing tablespace for table 'test/tp_crc32' that was exported from host 'rhel77' 2020-05-06 19:36:17 4 [Note] InnoDB: Phase I - Update all pages 2020-05-06 19:36:17 4 [Note] InnoDB: Sync to disk 2020-05-06 19:36:17 4 [Note] InnoDB: Sync to disk - done! 2020-05-06 19:36:17 4 [Note] InnoDB: Phase III - Flush changes to disk 2020-05-06 19:36:17 4 [Note] InnoDB: Phase IV - Flush complete 2020-05-06 19:36:17 4 [Note] InnoDB: `test`.`tp_crc32` autoinc value set to 2 2020-05-06 19:36:17 4 [Note] InnoDB: Importing tablespace for table 'test/tce_crc32' that was exported from host 'rhel77' 2020-05-06 19:36:17 4 [Note] InnoDB: Phase I - Update all pages 2020-05-06 19:36:17 4 [Note] InnoDB: Sync to disk 2020-05-06 19:36:17 4 [Note] InnoDB: Sync to disk - done! 2020-05-06 19:36:17 4 [Note] InnoDB: Phase III - Flush changes to disk 2020-05-06 19:36:17 4 [Note] InnoDB: Phase IV - Flush complete 2020-05-06 19:36:17 4 [Note] InnoDB: `test`.`tce_crc32` autoinc value set to 2 2020-05-06 19:36:17 4 [Note] InnoDB: Importing tablespace for table 'test/tc_crc32' that was exported from host 'rhel77' 2020-05-06 19:36:17 4 [Note] InnoDB: Phase I - Update all pages 2020-05-06 19:36:17 4 [Note] InnoDB: Sync to disk 2020-05-06 19:36:17 4 [Note] InnoDB: Sync to disk - done! 2020-05-06 19:36:17 4 [Note] InnoDB: Phase III - Flush changes to disk 2020-05-06 19:36:17 4 [Note] InnoDB: Phase IV - Flush complete 2020-05-06 19:36:17 4 [Note] InnoDB: `test`.`tc_crc32` autoinc value set to 2 2020-05-06 19:36:17 4 [Note] InnoDB: Importing tablespace for table 'test/te_crc32' that was exported from host 'rhel77' 2020-05-06 19:36:17 4 [Note] InnoDB: Phase I - Update all pages 2020-05-06 19:36:17 4 [Note] InnoDB: Sync to disk 2020-05-06 19:36:17 4 [Note] InnoDB: Sync to disk - done! 2020-05-06 19:36:17 4 [Note] InnoDB: Phase III - Flush changes to disk 2020-05-06 19:36:17 4 [Note] InnoDB: Phase IV - Flush complete 2020-05-06 19:36:17 4 [Note] InnoDB: `test`.`te_crc32` autoinc value set to 2 2020-05-06 19:36:17 4 [Note] InnoDB: Importing tablespace for table 'test/t_crc32' that was exported from host 'rhel77' 2020-05-06 19:36:17 4 [Note] InnoDB: Phase I - Update all pages 2020-05-06 19:36:17 4 [Note] InnoDB: Sync to disk 2020-05-06 19:36:17 4 [Note] InnoDB: Sync to disk - done! 2020-05-06 19:36:17 4 [Note] InnoDB: Phase III - Flush changes to disk 2020-05-06 19:36:17 4 [Note] InnoDB: Phase IV - Flush complete 2020-05-06 19:36:17 4 [Note] InnoDB: `test`.`t_crc32` autoinc value set to 2 2020-05-06 19:36:17 4 [Note] InnoDB: Importing tablespace for table 'test/tpe_crc32' that was exported from host 'rhel77' 2020-05-06 19:36:17 4 [Note] InnoDB: Phase I - Update all pages 2020-05-06 19:36:17 4 [Note] InnoDB: Sync to disk 2020-05-06 19:36:17 4 [Note] InnoDB: Sync to disk - done! 2020-05-06 19:36:17 4 [Note] InnoDB: Phase III - Flush changes to disk 2020-05-06 19:36:17 4 [Note] InnoDB: Phase IV - Flush complete 2020-05-06 19:36:17 4 [Note] InnoDB: `test`.`tpe_crc32` autoinc value set to 2 2020-05-06 19:36:17 4 [Note] InnoDB: Importing tablespace for table 'test/tp_crc32' that was exported from host 'rhel77' 2020-05-06 19:36:17 4 [Note] InnoDB: Phase I - Update all pages 2020-05-06 19:36:17 4 [Note] InnoDB: Sync to disk 2020-05-06 19:36:17 4 [Note] InnoDB: Sync to disk - done! 2020-05-06 19:36:17 4 [Note] InnoDB: Phase III - Flush changes to disk 2020-05-06 19:36:17 4 [Note] InnoDB: Phase IV - Flush complete 2020-05-06 19:36:17 4 [Note] InnoDB: `test`.`tp_crc32` autoinc value set to 2 2020-05-06 19:36:17 4 [Note] InnoDB: Importing tablespace for table 'test/tce_crc32' that was exported from host 'rhel77' 2020-05-06 19:36:17 4 [Note] InnoDB: Phase I - Update all pages 2020-05-06 19:36:17 4 [Note] InnoDB: Sync to disk 2020-05-06 19:36:17 4 [Note] InnoDB: Sync to disk - done! 2020-05-06 19:36:17 4 [Note] InnoDB: Phase III - Flush changes to disk 2020-05-06 19:36:17 4 [Note] InnoDB: Phase IV - Flush complete 2020-05-06 19:36:17 4 [Note] InnoDB: `test`.`tce_crc32` autoinc value set to 2 2020-05-06 19:36:17 4 [Note] InnoDB: Importing tablespace for table 'test/tc_crc32' that was exported from host 'rhel77' 2020-05-06 19:36:17 4 [Note] InnoDB: Phase I - Update all pages 2020-05-06 19:36:17 4 [Note] InnoDB: Sync to disk 2020-05-06 19:36:17 4 [Note] InnoDB: Sync to disk - done! 2020-05-06 19:36:17 4 [Note] InnoDB: Phase III - Flush changes to disk 2020-05-06 19:36:17 4 [Note] InnoDB: Phase IV - Flush complete 2020-05-06 19:36:17 4 [Note] InnoDB: `test`.`tc_crc32` autoinc value set to 2 2020-05-06 19:36:17 4 [Note] InnoDB: Importing tablespace for table 'test/te_crc32' that was exported from host 'rhel77' 2020-05-06 19:36:17 4 [Note] InnoDB: Phase I - Update all pages 2020-05-06 19:36:17 4 [Note] InnoDB: Sync to disk 2020-05-06 19:36:17 4 [Note] InnoDB: Sync to disk - done! 2020-05-06 19:36:17 4 [Note] InnoDB: Phase III - Flush changes to disk 2020-05-06 19:36:17 4 [Note] InnoDB: Phase IV - Flush complete 2020-05-06 19:36:17 4 [Note] InnoDB: `test`.`te_crc32` autoinc value set to 2 2020-05-06 19:36:17 4 [Note] InnoDB: Importing tablespace for table 'test/t_crc32' that was exported from host 'rhel77' 2020-05-06 19:36:17 4 [Note] InnoDB: Phase I - Update all pages 2020-05-06 19:36:17 4 [Note] InnoDB: Sync to disk 2020-05-06 19:36:17 4 [Note] InnoDB: Sync to disk - done! 2020-05-06 19:36:17 4 [Note] InnoDB: Phase III - Flush changes to disk 2020-05-06 19:36:17 4 [Note] InnoDB: Phase IV - Flush complete 2020-05-06 19:36:17 4 [Note] InnoDB: `test`.`t_crc32` autoinc value set to 2 2020-05-06 19:36:17 4 [Note] InnoDB: Importing tablespace for table 'test/tpe_crc32' that was exported from host 'rhel77' 2020-05-06 19:36:17 4 [Note] InnoDB: Phase I - Update all pages 2020-05-06 19:36:17 4 [Note] InnoDB: Sync to disk 2020-05-06 19:36:17 4 [Note] InnoDB: Sync to disk - done! 2020-05-06 19:36:17 4 [Note] InnoDB: Phase III - Flush changes to disk 2020-05-06 19:36:17 4 [Note] InnoDB: Phase IV - Flush complete 2020-05-06 19:36:17 4 [Note] InnoDB: `test`.`tpe_crc32` autoinc value set to 2 2020-05-06 19:36:17 4 [Note] InnoDB: Importing tablespace for table 'test/tp_crc32' that was exported from host 'rhel77' 2020-05-06 19:36:17 4 [Note] InnoDB: Phase I - Update all pages 2020-05-06 19:36:17 4 [Note] InnoDB: Sync to disk 2020-05-06 19:36:17 4 [Note] InnoDB: Sync to disk - done! 2020-05-06 19:36:17 4 [Note] InnoDB: Phase III - Flush changes to disk 2020-05-06 19:36:17 4 [Note] InnoDB: Phase IV - Flush complete 2020-05-06 19:36:17 4 [Note] InnoDB: `test`.`tp_crc32` autoinc value set to 2 2020-05-06 19:36:17 4 [Note] InnoDB: Sync to disk of `test`.`tce_innodb` started. 2020-05-06 19:36:17 4 [Note] InnoDB: Stopping purge 2020-05-06 19:36:17 4 [Note] InnoDB: Writing table metadata to './test/tce_innodb.cfg' 2020-05-06 19:36:17 4 [Note] InnoDB: Table `test`.`tce_innodb` flushed to disk 2020-05-06 19:36:17 4 [Note] InnoDB: Sync to disk of `test`.`tc_innodb` started. 2020-05-06 19:36:17 4 [Note] InnoDB: Writing table metadata to './test/tc_innodb.cfg' 2020-05-06 19:36:17 4 [Note] InnoDB: Table `test`.`tc_innodb` flushed to disk 2020-05-06 19:36:17 4 [Note] InnoDB: Sync to disk of `test`.`te_innodb` started. 2020-05-06 19:36:17 4 [Note] InnoDB: Writing table metadata to './test/te_innodb.cfg' 2020-05-06 19:36:17 4 [Note] InnoDB: Table `test`.`te_innodb` flushed to disk 2020-05-06 19:36:17 4 [Note] InnoDB: Sync to disk of `test`.`t_innodb` started. 2020-05-06 19:36:17 4 [Note] InnoDB: Writing table metadata to './test/t_innodb.cfg' 2020-05-06 19:36:17 4 [Note] InnoDB: Table `test`.`t_innodb` flushed to disk 2020-05-06 19:36:17 4 [Note] InnoDB: Sync to disk of `test`.`tpe_innodb` started. 2020-05-06 19:36:17 4 [Note] InnoDB: Writing table metadata to './test/tpe_innodb.cfg' 2020-05-06 19:36:17 4 [Note] InnoDB: Table `test`.`tpe_innodb` flushed to disk 2020-05-06 19:36:17 4 [Note] InnoDB: Sync to disk of `test`.`tp_innodb` started. 2020-05-06 19:36:17 4 [Note] InnoDB: Writing table metadata to './test/tp_innodb.cfg' 2020-05-06 19:36:17 4 [Note] InnoDB: Table `test`.`tp_innodb` flushed to disk 2020-05-06 19:36:17 4 [Note] InnoDB: Deleting the meta-data file './test/tce_innodb.cfg' 2020-05-06 19:36:17 4 [Note] InnoDB: Deleting the meta-data file './test/tc_innodb.cfg' 2020-05-06 19:36:17 4 [Note] InnoDB: Deleting the meta-data file './test/te_innodb.cfg' 2020-05-06 19:36:17 4 [Note] InnoDB: Deleting the meta-data file './test/t_innodb.cfg' 2020-05-06 19:36:17 4 [Note] InnoDB: Deleting the meta-data file './test/tpe_innodb.cfg' 2020-05-06 19:36:17 4 [Note] InnoDB: Deleting the meta-data file './test/tp_innodb.cfg' 2020-05-06 19:36:17 4 [Note] InnoDB: Resuming purge 2020-05-06 19:36:17 4 [Note] InnoDB: Importing tablespace for table 'test/tce_innodb' that was exported from host 'rhel77' 2020-05-06 19:36:17 4 [Note] InnoDB: Phase I - Update all pages 2020-05-06 19:36:17 4 [Note] InnoDB: Sync to disk 2020-05-06 19:36:17 4 [Note] InnoDB: Sync to disk - done! 2020-05-06 19:36:17 4 [Note] InnoDB: Phase III - Flush changes to disk 2020-05-06 19:36:17 4 [Note] InnoDB: Phase IV - Flush complete 2020-05-06 19:36:17 4 [Note] InnoDB: `test`.`tce_innodb` autoinc value set to 2 2020-05-06 19:36:17 4 [Note] InnoDB: Importing tablespace for table 'test/tc_innodb' that was exported from host 'rhel77' 2020-05-06 19:36:17 4 [Note] InnoDB: Phase I - Update all pages 2020-05-06 19:36:17 4 [Note] InnoDB: Sync to disk 2020-05-06 19:36:17 4 [Note] InnoDB: Sync to disk - done! 2020-05-06 19:36:17 4 [Note] InnoDB: Phase III - Flush changes to disk 2020-05-06 19:36:17 4 [Note] InnoDB: Phase IV - Flush complete 2020-05-06 19:36:17 4 [Note] InnoDB: `test`.`tc_innodb` autoinc value set to 2 2020-05-06 19:36:18 4 [Note] InnoDB: Importing tablespace for table 'test/te_innodb' that was exported from host 'rhel77' 2020-05-06 19:36:18 4 [Note] InnoDB: Phase I - Update all pages 2020-05-06 19:36:18 4 [Note] InnoDB: Sync to disk 2020-05-06 19:36:18 4 [Note] InnoDB: Sync to disk - done! 2020-05-06 19:36:18 4 [Note] InnoDB: Phase III - Flush changes to disk 2020-05-06 19:36:18 4 [Note] InnoDB: Phase IV - Flush complete 2020-05-06 19:36:18 4 [Note] InnoDB: `test`.`te_innodb` autoinc value set to 2 2020-05-06 19:36:18 4 [Note] InnoDB: Importing tablespace for table 'test/t_innodb' that was exported from host 'rhel77' 2020-05-06 19:36:18 4 [Note] InnoDB: Phase I - Update all pages 2020-05-06 19:36:18 4 [Note] InnoDB: Sync to disk 2020-05-06 19:36:18 4 [Note] InnoDB: Sync to disk - done! 2020-05-06 19:36:18 4 [Note] InnoDB: Phase III - Flush changes to disk 2020-05-06 19:36:18 4 [Note] InnoDB: Phase IV - Flush complete 2020-05-06 19:36:18 4 [Note] InnoDB: `test`.`t_innodb` autoinc value set to 2 2020-05-06 19:36:18 4 [Note] InnoDB: Importing tablespace for table 'test/tpe_innodb' that was exported from host 'rhel77' 2020-05-06 19:36:18 4 [Note] InnoDB: Phase I - Update all pages 2020-05-06 19:36:18 4 [Note] InnoDB: Sync to disk 2020-05-06 19:36:18 4 [Note] InnoDB: Sync to disk - done! 2020-05-06 19:36:18 4 [Note] InnoDB: Phase III - Flush changes to disk 2020-05-06 19:36:18 4 [Note] InnoDB: Phase IV - Flush complete 2020-05-06 19:36:18 4 [Note] InnoDB: `test`.`tpe_innodb` autoinc value set to 2 2020-05-06 19:36:18 4 [Note] InnoDB: Importing tablespace for table 'test/tp_innodb' that was exported from host 'rhel77' 2020-05-06 19:36:18 4 [Note] InnoDB: Phase I - Update all pages 2020-05-06 19:36:18 4 [Note] InnoDB: Sync to disk 2020-05-06 19:36:18 4 [Note] InnoDB: Sync to disk - done! 2020-05-06 19:36:18 4 [Note] InnoDB: Phase III - Flush changes to disk 2020-05-06 19:36:18 4 [Note] InnoDB: Phase IV - Flush complete 2020-05-06 19:36:18 4 [Note] InnoDB: `test`.`tp_innodb` autoinc value set to 2 2020-05-06 19:36:18 4 [Note] InnoDB: Importing tablespace for table 'test/tce_innodb' that was exported from host 'rhel77' 2020-05-06 19:36:18 4 [Note] InnoDB: Phase I - Update all pages 2020-05-06 19:36:18 4 [Note] InnoDB: Sync to disk 2020-05-06 19:36:18 4 [Note] InnoDB: Sync to disk - done! 2020-05-06 19:36:18 4 [Note] InnoDB: Phase III - Flush changes to disk 2020-05-06 19:36:18 4 [Note] InnoDB: Phase IV - Flush complete 2020-05-06 19:36:18 4 [Note] InnoDB: `test`.`tce_innodb` autoinc value set to 2 2020-05-06 19:36:18 4 [Note] InnoDB: Importing tablespace for table 'test/tc_innodb' that was exported from host 'rhel77' 2020-05-06 19:36:18 4 [Note] InnoDB: Phase I - Update all pages 2020-05-06 19:36:18 4 [Note] InnoDB: Sync to disk 2020-05-06 19:36:18 4 [Note] InnoDB: Sync to disk - done! 2020-05-06 19:36:18 4 [Note] InnoDB: Phase III - Flush changes to disk 2020-05-06 19:36:18 4 [Note] InnoDB: Phase IV - Flush complete 2020-05-06 19:36:18 4 [Note] InnoDB: `test`.`tc_innodb` autoinc value set to 2 2020-05-06 19:36:18 4 [Note] InnoDB: Importing tablespace for table 'test/te_innodb' that was exported from host 'rhel77' 2020-05-06 19:36:18 4 [Note] InnoDB: Phase I - Update all pages 2020-05-06 19:36:18 4 [Note] InnoDB: Sync to disk 2020-05-06 19:36:18 4 [Note] InnoDB: Sync to disk - done! 2020-05-06 19:36:18 4 [Note] InnoDB: Phase III - Flush changes to disk 2020-05-06 19:36:18 4 [Note] InnoDB: Phase IV - Flush complete 2020-05-06 19:36:18 4 [Note] InnoDB: `test`.`te_innodb` autoinc value set to 2 2020-05-06 19:36:18 4 [Note] InnoDB: Importing tablespace for table 'test/t_innodb' that was exported from host 'rhel77' 2020-05-06 19:36:18 4 [Note] InnoDB: Phase I - Update all pages 2020-05-06 19:36:18 4 [Note] InnoDB: Sync to disk 2020-05-06 19:36:18 4 [Note] InnoDB: Sync to disk - done! 2020-05-06 19:36:18 4 [Note] InnoDB: Phase III - Flush changes to disk 2020-05-06 19:36:18 4 [Note] InnoDB: Phase IV - Flush complete 2020-05-06 19:36:18 4 [Note] InnoDB: `test`.`t_innodb` autoinc value set to 2 2020-05-06 19:36:18 4 [Note] InnoDB: Importing tablespace for table 'test/tpe_innodb' that was exported from host 'rhel77' 2020-05-06 19:36:18 4 [Note] InnoDB: Phase I - Update all pages 2020-05-06 19:36:18 4 [Note] InnoDB: Sync to disk 2020-05-06 19:36:18 4 [Note] InnoDB: Sync to disk - done! 2020-05-06 19:36:18 4 [Note] InnoDB: Phase III - Flush changes to disk 2020-05-06 19:36:18 4 [Note] InnoDB: Phase IV - Flush complete 2020-05-06 19:36:18 4 [Note] InnoDB: `test`.`tpe_innodb` autoinc value set to 2 2020-05-06 19:36:18 4 [Note] InnoDB: Importing tablespace for table 'test/tp_innodb' that was exported from host 'rhel77' 2020-05-06 19:36:18 4 [Note] InnoDB: Phase I - Update all pages 2020-05-06 19:36:18 4 [Note] InnoDB: Sync to disk 2020-05-06 19:36:18 4 [Note] InnoDB: Sync to disk - done! 2020-05-06 19:36:18 4 [Note] InnoDB: Phase III - Flush changes to disk 2020-05-06 19:36:18 4 [Note] InnoDB: Phase IV - Flush complete 2020-05-06 19:36:18 4 [Note] InnoDB: `test`.`tp_innodb` autoinc value set to 2 2020-05-06 19:36:18 4 [Note] InnoDB: Importing tablespace for table 'test/tce_innodb' that was exported from host 'rhel77' 2020-05-06 19:36:18 4 [Note] InnoDB: Phase I - Update all pages 2020-05-06 19:36:18 4 [Note] InnoDB: Sync to disk 2020-05-06 19:36:18 4 [Note] InnoDB: Sync to disk - done! 2020-05-06 19:36:18 4 [Note] InnoDB: Phase III - Flush changes to disk 2020-05-06 19:36:18 4 [Note] InnoDB: Phase IV - Flush complete 2020-05-06 19:36:18 4 [Note] InnoDB: `test`.`tce_innodb` autoinc value set to 2 2020-05-06 19:36:18 4 [Note] InnoDB: Importing tablespace for table 'test/tc_innodb' that was exported from host 'rhel77' 2020-05-06 19:36:18 4 [Note] InnoDB: Phase I - Update all pages 2020-05-06 19:36:18 4 [Note] InnoDB: Sync to disk 2020-05-06 19:36:18 4 [Note] InnoDB: Sync to disk - done! 2020-05-06 19:36:18 4 [Note] InnoDB: Phase III - Flush changes to disk 2020-05-06 19:36:18 4 [Note] InnoDB: Phase IV - Flush complete 2020-05-06 19:36:18 4 [Note] InnoDB: `test`.`tc_innodb` autoinc value set to 2 2020-05-06 19:36:18 4 [Note] InnoDB: Importing tablespace for table 'test/te_innodb' that was exported from host 'rhel77' 2020-05-06 19:36:18 4 [Note] InnoDB: Phase I - Update all pages 2020-05-06 19:36:18 4 [Note] InnoDB: Sync to disk 2020-05-06 19:36:18 4 [Note] InnoDB: Sync to disk - done! 2020-05-06 19:36:18 4 [Note] InnoDB: Phase III - Flush changes to disk 2020-05-06 19:36:18 4 [Note] InnoDB: Phase IV - Flush complete 2020-05-06 19:36:18 4 [Note] InnoDB: `test`.`te_innodb` autoinc value set to 2 2020-05-06 19:36:18 4 [Note] InnoDB: Importing tablespace for table 'test/t_innodb' that was exported from host 'rhel77' 2020-05-06 19:36:18 4 [Note] InnoDB: Phase I - Update all pages 2020-05-06 19:36:18 4 [Note] InnoDB: Sync to disk 2020-05-06 19:36:18 4 [Note] InnoDB: Sync to disk - done! 2020-05-06 19:36:18 4 [Note] InnoDB: Phase III - Flush changes to disk 2020-05-06 19:36:18 4 [Note] InnoDB: Phase IV - Flush complete 2020-05-06 19:36:18 4 [Note] InnoDB: `test`.`t_innodb` autoinc value set to 2 2020-05-06 19:36:18 4 [Note] InnoDB: Importing tablespace for table 'test/tpe_innodb' that was exported from host 'rhel77' 2020-05-06 19:36:18 4 [Note] InnoDB: Phase I - Update all pages 2020-05-06 19:36:18 4 [Note] InnoDB: Sync to disk 2020-05-06 19:36:18 4 [Note] InnoDB: Sync to disk - done! 2020-05-06 19:36:18 4 [Note] InnoDB: Phase III - Flush changes to disk 2020-05-06 19:36:18 4 [Note] InnoDB: Phase IV - Flush complete 2020-05-06 19:36:18 4 [Note] InnoDB: `test`.`tpe_innodb` autoinc value set to 2 2020-05-06 19:36:18 4 [Note] InnoDB: Importing tablespace for table 'test/tp_innodb' that was exported from host 'rhel77' 2020-05-06 19:36:18 4 [Note] InnoDB: Phase I - Update all pages 2020-05-06 19:36:18 4 [Note] InnoDB: Sync to disk 2020-05-06 19:36:18 4 [Note] InnoDB: Sync to disk - done! 2020-05-06 19:36:18 4 [Note] InnoDB: Phase III - Flush changes to disk 2020-05-06 19:36:18 4 [Note] InnoDB: Phase IV - Flush complete 2020-05-06 19:36:18 4 [Note] InnoDB: `test`.`tp_innodb` autoinc value set to 2 2020-05-06 19:36:18 4 [Note] InnoDB: Sync to disk of `test`.`tce_none` started. 2020-05-06 19:36:18 4 [Note] InnoDB: Stopping purge 2020-05-06 19:36:18 4 [Note] InnoDB: Writing table metadata to './test/tce_none.cfg' 2020-05-06 19:36:18 4 [Note] InnoDB: Table `test`.`tce_none` flushed to disk 2020-05-06 19:36:18 4 [Note] InnoDB: Sync to disk of `test`.`tc_none` started. 2020-05-06 19:36:18 4 [Note] InnoDB: Writing table metadata to './test/tc_none.cfg' 2020-05-06 19:36:18 4 [Note] InnoDB: Table `test`.`tc_none` flushed to disk 2020-05-06 19:36:18 4 [Note] InnoDB: Sync to disk of `test`.`te_none` started. 2020-05-06 19:36:18 4 [Note] InnoDB: Writing table metadata to './test/te_none.cfg' 2020-05-06 19:36:18 4 [Note] InnoDB: Table `test`.`te_none` flushed to disk 2020-05-06 19:36:18 4 [Note] InnoDB: Sync to disk of `test`.`t_none` started. 2020-05-06 19:36:18 4 [Note] InnoDB: Writing table metadata to './test/t_none.cfg' 2020-05-06 19:36:18 4 [Note] InnoDB: Table `test`.`t_none` flushed to disk 2020-05-06 19:36:18 4 [Note] InnoDB: Sync to disk of `test`.`tpe_none` started. 2020-05-06 19:36:18 4 [Note] InnoDB: Writing table metadata to './test/tpe_none.cfg' 2020-05-06 19:36:18 4 [Note] InnoDB: Table `test`.`tpe_none` flushed to disk 2020-05-06 19:36:18 4 [Note] InnoDB: Sync to disk of `test`.`tp_none` started. 2020-05-06 19:36:18 4 [Note] InnoDB: Writing table metadata to './test/tp_none.cfg' 2020-05-06 19:36:18 4 [Note] InnoDB: Table `test`.`tp_none` flushed to disk 2020-05-06 19:36:18 4 [Note] InnoDB: Deleting the meta-data file './test/tce_none.cfg' 2020-05-06 19:36:18 4 [Note] InnoDB: Deleting the meta-data file './test/tc_none.cfg' 2020-05-06 19:36:18 4 [Note] InnoDB: Deleting the meta-data file './test/te_none.cfg' 2020-05-06 19:36:18 4 [Note] InnoDB: Deleting the meta-data file './test/t_none.cfg' 2020-05-06 19:36:18 4 [Note] InnoDB: Deleting the meta-data file './test/tpe_none.cfg' 2020-05-06 19:36:18 4 [Note] InnoDB: Deleting the meta-data file './test/tp_none.cfg' 2020-05-06 19:36:18 4 [Note] InnoDB: Resuming purge 2020-05-06 19:36:18 4 [Note] InnoDB: Importing tablespace for table 'test/tce_none' that was exported from host 'rhel77' 2020-05-06 19:36:18 4 [Note] InnoDB: Phase I - Update all pages 2020-05-06 19:36:18 4 [Note] InnoDB: Sync to disk 2020-05-06 19:36:18 4 [Note] InnoDB: Sync to disk - done! 2020-05-06 19:36:18 4 [Note] InnoDB: Phase III - Flush changes to disk 2020-05-06 19:36:18 4 [Note] InnoDB: Phase IV - Flush complete 2020-05-06 19:36:18 4 [Note] InnoDB: `test`.`tce_none` autoinc value set to 2 2020-05-06 19:36:18 4 [Note] InnoDB: Importing tablespace for table 'test/tc_none' that was exported from host 'rhel77' 2020-05-06 19:36:18 4 [Note] InnoDB: Phase I - Update all pages 2020-05-06 19:36:18 4 [Note] InnoDB: Sync to disk 2020-05-06 19:36:18 4 [Note] InnoDB: Sync to disk - done! 2020-05-06 19:36:18 4 [Note] InnoDB: Phase III - Flush changes to disk 2020-05-06 19:36:18 4 [Note] InnoDB: Phase IV - Flush complete 2020-05-06 19:36:18 4 [Note] InnoDB: `test`.`tc_none` autoinc value set to 2 2020-05-06 19:36:18 4 [Note] InnoDB: Importing tablespace for table 'test/te_none' that was exported from host 'rhel77' 2020-05-06 19:36:18 4 [Note] InnoDB: Phase I - Update all pages 2020-05-06 19:36:18 4 [Note] InnoDB: Sync to disk 2020-05-06 19:36:18 4 [Note] InnoDB: Sync to disk - done! 2020-05-06 19:36:18 4 [Note] InnoDB: Phase III - Flush changes to disk 2020-05-06 19:36:18 4 [Note] InnoDB: Phase IV - Flush complete 2020-05-06 19:36:19 4 [Note] InnoDB: `test`.`te_none` autoinc value set to 2 2020-05-06 19:36:19 4 [Note] InnoDB: Importing tablespace for table 'test/t_none' that was exported from host 'rhel77' 2020-05-06 19:36:19 4 [Note] InnoDB: Phase I - Update all pages 2020-05-06 19:36:19 4 [Note] InnoDB: Sync to disk 2020-05-06 19:36:19 4 [Note] InnoDB: Sync to disk - done! 2020-05-06 19:36:19 4 [Note] InnoDB: Phase III - Flush changes to disk 2020-05-06 19:36:19 4 [Note] InnoDB: Phase IV - Flush complete 2020-05-06 19:36:19 4 [Note] InnoDB: `test`.`t_none` autoinc value set to 2 2020-05-06 19:36:19 4 [Note] InnoDB: Importing tablespace for table 'test/tpe_none' that was exported from host 'rhel77' 2020-05-06 19:36:19 4 [Note] InnoDB: Phase I - Update all pages 2020-05-06 19:36:19 4 [Note] InnoDB: Sync to disk 2020-05-06 19:36:19 4 [Note] InnoDB: Sync to disk - done! 2020-05-06 19:36:19 4 [Note] InnoDB: Phase III - Flush changes to disk 2020-05-06 19:36:19 4 [Note] InnoDB: Phase IV - Flush complete 2020-05-06 19:36:19 4 [Note] InnoDB: `test`.`tpe_none` autoinc value set to 2 2020-05-06 19:36:19 4 [Note] InnoDB: Importing tablespace for table 'test/tp_none' that was exported from host 'rhel77' 2020-05-06 19:36:19 4 [Note] InnoDB: Phase I - Update all pages 2020-05-06 19:36:19 4 [Note] InnoDB: Sync to disk 2020-05-06 19:36:19 4 [Note] InnoDB: Sync to disk - done! 2020-05-06 19:36:19 4 [Note] InnoDB: Phase III - Flush changes to disk 2020-05-06 19:36:19 4 [Note] InnoDB: Phase IV - Flush complete 2020-05-06 19:36:19 4 [Note] InnoDB: `test`.`tp_none` autoinc value set to 2 2020-05-06 19:36:19 4 [Note] InnoDB: Importing tablespace for table 'test/tce_none' that was exported from host 'rhel77' 2020-05-06 19:36:19 4 [Note] InnoDB: Phase I - Update all pages 2020-05-06 19:36:19 4 [Note] InnoDB: Sync to disk 2020-05-06 19:36:19 4 [Note] InnoDB: Sync to disk - done! 2020-05-06 19:36:19 4 [Note] InnoDB: Phase III - Flush changes to disk 2020-05-06 19:36:19 4 [Note] InnoDB: Phase IV - Flush complete 2020-05-06 19:36:19 4 [Note] InnoDB: `test`.`tce_none` autoinc value set to 2 2020-05-06 19:36:19 4 [Note] InnoDB: Importing tablespace for table 'test/tc_none' that was exported from host 'rhel77' 2020-05-06 19:36:19 4 [Note] InnoDB: Phase I - Update all pages 2020-05-06 19:36:19 4 [Note] InnoDB: Sync to disk 2020-05-06 19:36:19 4 [Note] InnoDB: Sync to disk - done! 2020-05-06 19:36:19 4 [Note] InnoDB: Phase III - Flush changes to disk 2020-05-06 19:36:19 4 [Note] InnoDB: Phase IV - Flush complete 2020-05-06 19:36:19 4 [Note] InnoDB: `test`.`tc_none` autoinc value set to 2 2020-05-06 19:36:19 4 [Note] InnoDB: Importing tablespace for table 'test/te_none' that was exported from host 'rhel77' 2020-05-06 19:36:19 4 [Note] InnoDB: Phase I - Update all pages 2020-05-06 19:36:19 4 [Note] InnoDB: Sync to disk 2020-05-06 19:36:19 4 [Note] InnoDB: Sync to disk - done! 2020-05-06 19:36:19 4 [Note] InnoDB: Phase III - Flush changes to disk 2020-05-06 19:36:19 4 [Note] InnoDB: Phase IV - Flush complete 2020-05-06 19:36:19 4 [Note] InnoDB: `test`.`te_none` autoinc value set to 2 2020-05-06 19:36:19 4 [Note] InnoDB: Importing tablespace for table 'test/t_none' that was exported from host 'rhel77' 2020-05-06 19:36:19 4 [Note] InnoDB: Phase I - Update all pages 2020-05-06 19:36:19 4 [Note] InnoDB: Sync to disk 2020-05-06 19:36:19 4 [Note] InnoDB: Sync to disk - done! 2020-05-06 19:36:19 4 [Note] InnoDB: Phase III - Flush changes to disk 2020-05-06 19:36:19 4 [Note] InnoDB: Phase IV - Flush complete 2020-05-06 19:36:19 4 [Note] InnoDB: `test`.`t_none` autoinc value set to 2 2020-05-06 19:36:19 4 [Note] InnoDB: Importing tablespace for table 'test/tpe_none' that was exported from host 'rhel77' 2020-05-06 19:36:19 4 [Note] InnoDB: Phase I - Update all pages 2020-05-06 19:36:19 4 [Note] InnoDB: Sync to disk 2020-05-06 19:36:19 4 [Note] InnoDB: Sync to disk - done! 2020-05-06 19:36:19 4 [Note] InnoDB: Phase III - Flush changes to disk 2020-05-06 19:36:19 4 [Note] InnoDB: Phase IV - Flush complete 2020-05-06 19:36:19 4 [Note] InnoDB: `test`.`tpe_none` autoinc value set to 2 2020-05-06 19:36:19 4 [Note] InnoDB: Importing tablespace for table 'test/tp_none' that was exported from host 'rhel77' 2020-05-06 19:36:19 4 [Note] InnoDB: Phase I - Update all pages 2020-05-06 19:36:19 4 [Note] InnoDB: Sync to disk 2020-05-06 19:36:19 4 [Note] InnoDB: Sync to disk - done! 2020-05-06 19:36:19 4 [Note] InnoDB: Phase III - Flush changes to disk 2020-05-06 19:36:19 4 [Note] InnoDB: Phase IV - Flush complete 2020-05-06 19:36:19 4 [Note] InnoDB: `test`.`tp_none` autoinc value set to 2 mariadbd: /home/ozlabs/mariadb-server-10.5/storage/innobase/log/log0log.cc:1363: bool log_checkpoint(): Assertion `oldest_lsn >= log_sys.last_checkpoint_lsn' failed. 200506 19:36:19 [ERROR] mysqld got signal 6 ;     (gdb) bt full #0 0x00003fff93acffac in pthread_kill () from /lib64/libpthread.so.0 No symbol table info available. #1 0x000000010bcdd024 in my_write_core (sig=6) at /home/ozlabs/mariadb-server-10.5/mysys/stacktrace.c:518 No locals. #2 0x000000010b023834 in handle_fatal_signal (sig=6) at /home/ozlabs/mariadb-server-10.5/sql/signal_handler.cc:329 curr_time = 1588808179 tm = {tm_sec = 19, tm_min = 36, tm_hour = 19, tm_mday = 6, tm_mon = 4, tm_year = 120, tm_wday = 3, tm_yday = 126, tm_isdst = 1, tm_gmtoff = -14400, tm_zone = 0x100185ee660 "EDT"} thd = 0x0 print_invalid_query_pointer = false #3 <signal handler called> No locals. #4 0x00003fff9322fc30 in raise () from /lib64/libc.so.6 No symbol table info available. #5 0x00003fff93231f8c in abort () from /lib64/libc.so.6 No symbol table info available. #6 0x00003fff93225754 in __assert_fail_base () from /lib64/libc.so.6 No symbol table info available. #7 0x00003fff93225844 in __assert_fail () from /lib64/libc.so.6 No symbol table info available. #8 0x000000010b769ff8 in log_checkpoint () at /home/ozlabs/mariadb-server-10.5/storage/innobase/log/log0log.cc:1363 __PRETTY_FUNCTION__ = "bool log_checkpoint()" end_lsn = 2 oldest_lsn = 186431 flush_lsn = 70365187410496 do_write = false #9 0x000000010b926218 in srv_master_do_active_tasks () at /home/ozlabs/mariadb-server-10.5/storage/innobase/srv/srv0srv.cc:1868 cur_time = 1588808179 counter_time = 759646513533 #10 0x000000010b926bf0 in srv_master_callback () at /home/ozlabs/mariadb-server-10.5/storage/innobase/srv/srv0srv.cc:2000 old_activity_count = 177 #11 0x000000010bc06ac8 in tpool::thread_pool_generic::timer_generic::run (this=0x10018c31330) at /home/ozlabs/mariadb-server-10.5/tpool/tpool_generic.cc:299 expected = false #12 0x000000010bc06c08 in tpool::thread_pool_generic::timer_generic::execute (arg=0x10018c31330) at /home/ozlabs/mariadb-server-10.5/tpool/tpool_generic.cc:317 timer = 0x10018c31330 #13 0x000000010bc11c28 in tpool::task::execute (this=0x10018c31370) at /home/ozlabs/mariadb-server-10.5/tpool/task.cc:52 No locals. #14 0x000000010bc0403c in tpool::thread_pool_generic::worker_main (this=0x100187fd070, thread_var=0x1001880c780) at /home/ozlabs/mariadb-server-10.5/tpool/tpool_generic.cc:518 task = 0x10018c31370 #15 0x000000010bc1116c in std::_Mem_fn<void (tpool::thread_pool_generic::*)(tpool::worker_data*)>::operator()<tpool::worker_data*, void>(tpool::thread_pool_generic*, tpool::worker_data*&&) const (this=0x3fff4c001780, __object=0x100187fd070) at /usr/include/c++/4.8.2/functional:601 No locals. #16 0x000000010bc10fd4 in std::_Bind_simple<std::_Mem_fn<void (tpool::thread_pool_generic::*)(tpool::worker_data*)> (tpool::thread_pool_generic*, tpool::worker_data*)>::_M_invoke<0ul, 1ul>(std::_Index_tuple<0ul, 1ul>) (this=0x3fff4c001770) at /usr/include/c++/4.8.2/functional:1732 No locals. #17 0x000000010bc10c58 in std::_Bind_simple<std::_Mem_fn<void (tpool::thread_pool_generic::*)(tpool::worker_data*)> (tpool::thread_pool_generic*, tpool::worker_data*)>::operator()() (this=0x3fff4c001770) at /usr/include/c++/4.8.2/functional:1720 No locals. ---Type <return> to continue, or q <return> to quit--- #18 0x000000010bc10b60 in std::thread::_Impl<std::_Bind_simple<std::_Mem_fn<void (tpool::thread_pool_generic::*)(tpool::worker_data*)> (tpool::thread_pool_generic*, tpool::worker_data*)> >::_M_run() (this=0x3fff4c001758) at /usr/include/c++/4.8.2/thread:115 No locals. #19 0x00003fff9361c2a4 in ?? () from /lib64/libstdc++.so.6 No symbol table info available. #20 0x00003fff93ac8cd4 in start_thread () from /lib64/libpthread.so.0 No symbol table info available. #21 0x00003fff93317e94 in clone () from /lib64/libc.so.6 No symbol table info available. (gdb) p log_sys $1 = {static FORMAT_3_23 = 0, static FORMAT_10_2 = 1, static FORMAT_10_3 = 103, static FORMAT_10_4 = 104, static FORMAT_ENCRYPTED = 2147483648, static FORMAT_ENC_10_4 = 2147483752, static FORMAT_10_5 = 1346918739, static FORMAT_ENC_10_5 = 3494402387, lsn = {<std::__atomic_base<unsigned long>> = { _M_i = 193590}, <No data fields>}, flushed_to_disk_lsn = {<std::__atomic_base<unsigned long>> = {_M_i = 193590}, <No data fields>}, buf_free = 54, check_flush_or_checkpoint_ = {<std::atomic_bool> = {_M_base = {_M_i = false}}, <No data fields>}, mutex = {m_impl = {m_lock_word = {<std::__atomic_base<unsigned int>> = { _M_i = 2}, <No data fields>}, m_event = 0x10018988e48, m_policy = {context = {<latch_t> = { _vptr.latch_t = 0x10c7e1cf0 <vtable for MutexDebug<TTASEventMutex<GenericPolicy> >+16>, m_id = LATCH_ID_LOG_SYS, m_rw_lock = false}, m_mutex = 0x10d29a080 <log_sys+128>, m_filename = 0x10c165a08 "/home/ozlabs/mariadb-server-10.5/storage/innobase/log/log0log.cc", m_line = 1350, m_thread_id = 70365522948176, m_debug_mutex = {m_freed = false, m_mutex = {__data = {__lock = 0, __count = 0, __owner = 0, __nusers = 0, __kind = 0, __spins = 0, __elision = 0, __list = {__prev = 0x0, __next = 0x0}}, __size = '\000' <repeats 39 times>, __align = 0}}}, m_count = {m_spins = 0, m_waits = 0, m_calls = 0, m_enabled = false}, m_id = LATCH_ID_LOG_SYS}}, m_ptr = 0x10018670c00}, log_flush_order_mutex = {m_impl = {m_lock_word = {<std::__atomic_base<unsigned int>> = { _M_i = 0}, <No data fields>}, m_event = 0x10018988f88, m_policy = {context = {<latch_t> = { _vptr.latch_t = 0x10c7e1cf0 <vtable for MutexDebug<TTASEventMutex<GenericPolicy> >+16>, m_id = LATCH_ID_LOG_FLUSH_ORDER, m_rw_lock = false}, m_mutex = 0x0, m_filename = 0x0, m_line = 0, m_thread_id = 18446744073709551615, m_debug_mutex = {m_freed = false, m_mutex = {__data = {__lock = 0, __count = 0, __owner = 0, __nusers = 0, __kind = 0, __spins = 0, __elision = 0, __list = {__prev = 0x0, __next = 0x0}}, __size = '\000' <repeats 39 times>, __align = 0}}}, m_count = { m_spins = 0, m_waits = 0, m_calls = 0, m_enabled = false}, m_id = LATCH_ID_LOG_FLUSH_ORDER}}, m_ptr = 0x10018670c80}, buf = 0x3fff8c1e0000 "\200", flush_buf = 0x3fff8c0e0000 "\200", max_buf_free = 456704, log = {format = 1346918739, subformat = 2, file_size = 10485760, lsn = 193561, lsn_offset = 186905, fd = { m_file = std::unique_ptr<file_io> containing 0x100189b3ae0, m_path = "./ib_logfile0"}, scanned_lsn = 47785}, buf_next_to_write = 54, write_lsn = 193590, current_flush_lsn = 0, pending_flushes = {<std::__atomic_base<unsigned long>> = {_M_i = 0}, <No data fields>}, flushes = {<std::__atomic_base<unsigned long>> = { _M_i = 317}, <No data fields>}, n_log_ios = 319, n_log_ios_old = 0, last_printout_time = 1588808176, log_capacity = 9435341, max_modified_age_async = 6811017, max_modified_age_sync = 7297518, max_checkpoint_age_async = 7540769, max_checkpoint_age = 7784019, next_checkpoint_no = 52, last_checkpoint_lsn = 186446, next_checkpoint_lsn = 186446, n_pending_checkpoint_writes = 0, checkpoint_buf = "\000\000\000\000\000\000\000\063\000\000\000\000\000\002\330N\000\000\000\000\000\002\276N\000\000\000\000\000\020", '\000' <repeats 471 times>..., m_initialised = true} (gdb) p log_sys.last_checkpoint_lsn $2 = 186446 (gdb) p log_sys.next_checkpoint_lsn $3 = 186446 (gdb) p log_sys.lsn $4 = {<std::__atomic_base<unsigned long>> = {_M_i = 193590}, <No data fields>} #8 0x000000010b769ff8 in log_checkpoint () at /home/ozlabs/mariadb-server-10.5/storage/innobase/log/log0log.cc:1363 1363 ut_ad(oldest_lsn >= log_sys.last_checkpoint_lsn); (gdb) p oldest_lsn $5 = 186431 (gdb) p log_sys.last_checkpoint_lsn-oldest_lsn $6 = 15 (gdb) p srv_stats $8 = {data_written = {m_counter = 32669696}, log_write_requests = {m_counter = 285}, log_writes = {m_counter = 317}, log_padded = {m_counter = 125440}, os_log_written = { m_counter = 433664}, os_log_pending_writes = {m_counter = 0}, log_waits = {m_counter = 0}, dblwr_writes = {m_counter = 65}, dblwr_pages_written = {m_counter = 851}, buf_pool_write_requests = {m_counter = 6172}, buf_pool_wait_free = {m_counter = 0}, buf_pool_flushed = {m_counter = 1082}, buf_pool_reads = {m_counter = 453}, ... key_rotation_list_length = {m_counter = {{value = {<std::__atomic_base<unsigned long>> = {_M_i = 0}, <No data fields>}} <repeats 64 times>}}, n_temp_blocks_encrypted = { m_counter = {{value = {<std::__atomic_base<unsigned long>> = {_M_i = 0}, <No data fields>}} <repeats 64 times>}}, n_temp_blocks_decrypted = {m_counter = {{ value = {<std::__atomic_base<unsigned long>> = {_M_i = 0}, <No data fields>}} <repeats 64 times>}}, lock_deadlock_count = {m_counter = 0}}

            I was able to produce an rr replay trace for this, by running

            while ./mtr --rr --parallel=auto encryption.innodb_encryption_discard_import{,,,,,,,,,,,,,,,}; do :; done
            

            (with a patched mtr to implement the rr record option).

            marko Marko Mäkelä added a comment - I was able to produce an rr replay trace for this, by running while ./mtr --rr --parallel=auto encryption.innodb_encryption_discard_import{,,,,,,,,,,,,,,,}; do :; done (with a patched mtr to implement the rr record option).

            In my rr replay trace, we had oldest_lsn = 9453700 and log_sys.last_checkpoint_lsn = 9453707.

            There appears to be a race condition in the following code:

            static
            lsn_t
            log_buf_pool_get_oldest_modification(void)
            /*======================================*/
            {
            	lsn_t	lsn;
             
            	ut_ad(log_mutex_own());
             
            	lsn = buf_pool_get_oldest_modification();
             
            	if (!lsn) {
             
            		lsn = log_sys.get_lsn();
            	}
             
            	return(lsn);
            }
            

            The function buf_pool_get_oldest_modification() would return 0, and we would read log_sys.lsn, protecting it via log_sys.mutex. That field had already been updated by mtr_t::finish_write(). But it had not updated the buf_page_t::oldest_modification yet:

            inline lsn_t mtr_t::finish_write(ulint len)
            {
            	ut_ad(m_log_mode == MTR_LOG_ALL);
            	ut_ad(log_mutex_own());
            	ut_ad(m_log.size() == len);
            	ut_ad(len > 0);
             
            	lsn_t start_lsn;
             
            	if (m_log.is_small()) {
            		const mtr_buf_t::block_t* front = m_log.front();
            		ut_ad(len <= front->used());
             
            		m_commit_lsn = log_reserve_and_write_fast(front->begin(), len,
            							  &start_lsn);
            

            The caller mtr_t::commit() is releasing log_sys.mutex before invoking mtr_t::release_resources(). Thus, log_buf_pool_get_oldest_modification() may observe that the buffer pool is clean, and it will use the value of log_sys.lsn=9453707 as a substitute. In fact, the caller log_checkpoint() would proceed all the way to log_write_checkpoint_info(), falsely claiming that the checkpoint completed to LSN 9453707, even though the mtr_t::release_resources() did not even execute yet. In my trace, that execution occurred after the checkpoint was completed.

            On a subsequent log_checkpoint() call, the assertion would fail.

            The problem appears to have been introduced by a change in MySQL 5.5.10:
            https://github.com/MariaDB/server/commit/a52c4820a30a69522c9876f06510662bf063bcc3
            https://github.com/MariaDB/server/commit/626d26f351a6cb5d013b5cd0df924608b5f66695

            For some reason, I found two commits for the change. Because the InnoDB change history was not merged to the code base until some later point in time, the code paths are wrong in these commits.

            @@ -184,25 +244,12 @@ mtr_commit(
             #ifndef UNIV_HOTBACKUP
             	/* This is a dirty read, for debugging. */
             	ut_ad(!recv_no_log_write);
            -	write_log = mtr->modifications && mtr->n_log_recs;
             
            -	if (write_log) {
            +	if (mtr->modifications && mtr->n_log_recs) {
             		mtr_log_reserve_and_write(mtr);
             	}
             
            -	/* We first update the modification info to buffer pages, and only
            -	after that release the log mutex: this guarantees that when the log
            -	mutex is free, all buffer pages contain an up-to-date info of their
            -	modifications. This fact is used in making a checkpoint when we look
            -	at the oldest modification of any page in the buffer pool. It is also
            -	required when we insert modified buffer pages in to the flush list
            -	which must be sorted on oldest_modification. */
            -
             	mtr_memo_pop_all(mtr);
            -
            -	if (write_log) {
            -		log_release();
            -	}
             #endif /* !UNIV_HOTBACKUP */
             
             	ut_d(mtr->state = MTR_COMMITTED);
            

            The above change must have broken the oldest_lsn check in log_checkpoint().

            marko Marko Mäkelä added a comment - In my rr replay trace, we had oldest_lsn = 9453700 and log_sys.last_checkpoint_lsn = 9453707 . There appears to be a race condition in the following code: static lsn_t log_buf_pool_get_oldest_modification( void ) /*======================================*/ { lsn_t lsn;   ut_ad(log_mutex_own());   lsn = buf_pool_get_oldest_modification();   if (!lsn) {   lsn = log_sys.get_lsn(); }   return (lsn); } The function buf_pool_get_oldest_modification() would return 0, and we would read log_sys.lsn , protecting it via log_sys.mutex . That field had already been updated by mtr_t::finish_write() . But it had not updated the buf_page_t::oldest_modification yet: inline lsn_t mtr_t::finish_write(ulint len) { ut_ad(m_log_mode == MTR_LOG_ALL); ut_ad(log_mutex_own()); ut_ad(m_log.size() == len); ut_ad(len > 0);   lsn_t start_lsn;   if (m_log.is_small()) { const mtr_buf_t::block_t* front = m_log.front(); ut_ad(len <= front->used());   m_commit_lsn = log_reserve_and_write_fast(front->begin(), len, &start_lsn); The caller mtr_t::commit() is releasing log_sys.mutex before invoking mtr_t::release_resources() . Thus, log_buf_pool_get_oldest_modification() may observe that the buffer pool is clean, and it will use the value of log_sys.lsn=9453707 as a substitute. In fact, the caller log_checkpoint() would proceed all the way to log_write_checkpoint_info() , falsely claiming that the checkpoint completed to LSN 9453707, even though the mtr_t::release_resources() did not even execute yet. In my trace, that execution occurred after the checkpoint was completed. On a subsequent log_checkpoint() call, the assertion would fail. The problem appears to have been introduced by a change in MySQL 5.5.10: https://github.com/MariaDB/server/commit/a52c4820a30a69522c9876f06510662bf063bcc3 https://github.com/MariaDB/server/commit/626d26f351a6cb5d013b5cd0df924608b5f66695 For some reason, I found two commits for the change. Because the InnoDB change history was not merged to the code base until some later point in time, the code paths are wrong in these commits. @@ -184,25 +244,12 @@ mtr_commit( #ifndef UNIV_HOTBACKUP /* This is a dirty read, for debugging. */ ut_ad(!recv_no_log_write); - write_log = mtr->modifications && mtr->n_log_recs; - if (write_log) { + if (mtr->modifications && mtr->n_log_recs) { mtr_log_reserve_and_write(mtr); } - /* We first update the modification info to buffer pages, and only - after that release the log mutex: this guarantees that when the log - mutex is free, all buffer pages contain an up-to-date info of their - modifications. This fact is used in making a checkpoint when we look - at the oldest modification of any page in the buffer pool. It is also - required when we insert modified buffer pages in to the flush list - which must be sorted on oldest_modification. */ - mtr_memo_pop_all(mtr); - - if (write_log) { - log_release(); - } #endif /* !UNIV_HOTBACKUP */ ut_d(mtr->state = MTR_COMMITTED); The above change must have broken the oldest_lsn check in log_checkpoint() .

            I missed the fact that MDEV-15058 introduced this race condition by removing the acquisition of the log_sys.flush_order_mutex from buf_pool_get_oldest_modification(). For all other callers except log_buf_pool_get_oldest_modification(), it seems to be fine and is avoiding an unnecessary mutex acquisition.

            marko Marko Mäkelä added a comment - I missed the fact that MDEV-15058 introduced this race condition by removing the acquisition of the log_sys.flush_order_mutex from buf_pool_get_oldest_modification() . For all other callers except log_buf_pool_get_oldest_modification() , it seems to be fine and is avoiding an unnecessary mutex acquisition.

            People

              marko Marko Mäkelä
              marko Marko Mäkelä
              Votes:
              0 Vote for this issue
              Watchers:
              6 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.