Details
-
Bug
-
Status: Closed (View Workflow)
-
Major
-
Resolution: Fixed
-
10.5.1, 10.5.2, 10.5.3
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
- is caused by
-
MDEV-15058 Remove multiple InnoDB buffer pool instances
-
- Closed
-
- is duplicated by
-
MDEV-22213 innodb.101_compatibility crashes with assert "mlog_checkpoint_lsn <= recovered_lsn"
-
- Closed
-
- relates to
-
MDEV-16896 encryption.innodb-checksum-algorithm failed in buildbot, apparently server crashed
-
- Closed
-
-
MDEV-33363 CI failure: innodb.import_corrupted: Assertion failed: oldest_lsn > log_sys.last_checkpoint_lsn
-
- Closed
-
Activity
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).
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.
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.