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
-
-
- Closed
-
- relates to
-
-
- Closed
-
-
-
- Closed
-
Activity
it is reproducible for me as ./mtr innodb-checksum-algorithm,4k,cbc --repeat=100 and buildbot cross reference of this test shows assertion/crash with this test
|
10.5 5f5c63e0fe6eac59 |
encryption.innodb-checksum-algorithm '4k,cbc,innodb' w6 [ 18 fail ]
|
Test ended at 2020-03-24 16:23:08
|
|
|
CURRENT_TEST: encryption.innodb-checksum-algorithm
|
mysqltest: At line 109: query 'DROP TABLE tce_$checksum, tc_$checksum, te_$checksum,
|
t_$checksum, tpe_$checksum, tp_$checksum' failed: 2013: Lost connection to MySQL server during query
|
|
|
The result from queries just before the failure was:
|
< snip >
|
update tc_crc32 set b=substr(b,1);
|
ALTER TABLE te_crc32 IMPORT TABLESPACE;
|
update te_crc32 set b=substr(b,1);
|
ALTER TABLE t_crc32 IMPORT TABLESPACE;
|
update t_crc32 set b=substr(b,1);
|
ALTER TABLE tpe_crc32 IMPORT TABLESPACE;
|
update tpe_crc32 set b=substr(b,1);
|
ALTER TABLE tp_crc32 IMPORT TABLESPACE;
|
update tp_crc32 set b=substr(b,1);
|
CHECK TABLE tce_crc32, tc_crc32, te_crc32,
|
t_crc32, tpe_crc32, tp_crc32;
|
Table Op Msg_type Msg_text
|
test.tce_crc32 check status OK
|
test.tc_crc32 check status OK
|
test.te_crc32 check status OK
|
test.t_crc32 check status OK
|
test.tpe_crc32 check status OK
|
test.tp_crc32 check status OK
|
DROP TABLE tce_crc32, tc_crc32, te_crc32,
|
t_crc32, tpe_crc32, tp_crc32;
|
|
|
More results from queries before failure can be found in /10.5/mysql-test/var/6/log/innodb-checksum-algorithm.log
|
|
|
|
|
Server [mysqld.1 - pid: 58586, winpid: 58586, exit: 256] failed during test run
|
Server log from this test:
|
----------SERVER LOG START-----------
|
2020-03-24 16:23:06 72 [Note] InnoDB: Creating #1 encryption thread id 140621311080192 total threads 4.
|
2020-03-24 16:23:06 72 [Note] InnoDB: Creating #2 encryption thread id 140621319563008 total threads 4.
|
2020-03-24 16:23:06 72 [Note] InnoDB: Creating #3 encryption thread id 140621336528640 total threads 4.
|
2020-03-24 16:23:06 72 [Note] InnoDB: Creating #4 encryption thread id 140621328045824 total threads 4.
|
2020-03-24 16:23:06 72 [Note] InnoDB: Sync to disk of `test`.`tce_crc32` started.
|
2020-03-24 16:23:06 72 [Note] InnoDB: Stopping purge
|
2020-03-24 16:23:06 72 [Note] InnoDB: Writing table metadata to './test/tce_crc32.cfg'
|
2020-03-24 16:23:06 72 [Note] InnoDB: Table `test`.`tce_crc32` flushed to disk
|
2020-03-24 16:23:06 72 [Note] InnoDB: Sync to disk of `test`.`tc_crc32` started.
|
2020-03-24 16:23:06 72 [Note] InnoDB: Writing table metadata to './test/tc_crc32.cfg'
|
2020-03-24 16:23:06 72 [Note] InnoDB: Table `test`.`tc_crc32` flushed to disk
|
2020-03-24 16:23:06 72 [Note] InnoDB: Sync to disk of `test`.`te_crc32` started.
|
2020-03-24 16:23:06 72 [Note] InnoDB: Writing table metadata to './test/te_crc32.cfg'
|
2020-03-24 16:23:06 72 [Note] InnoDB: Table `test`.`te_crc32` flushed to disk
|
2020-03-24 16:23:06 72 [Note] InnoDB: Sync to disk of `test`.`t_crc32` started.
|
2020-03-24 16:23:06 72 [Note] InnoDB: Writing table metadata to './test/t_crc32.cfg'
|
2020-03-24 16:23:06 72 [Note] InnoDB: Table `test`.`t_crc32` flushed to disk
|
2020-03-24 16:23:06 72 [Note] InnoDB: Sync to disk of `test`.`tpe_crc32` started.
|
2020-03-24 16:23:06 72 [Note] InnoDB: Writing table metadata to './test/tpe_crc32.cfg'
|
2020-03-24 16:23:06 72 [Note] InnoDB: Table `test`.`tpe_crc32` flushed to disk
|
2020-03-24 16:23:06 72 [Note] InnoDB: Sync to disk of `test`.`tp_crc32` started.
|
2020-03-24 16:23:06 72 [Note] InnoDB: Writing table metadata to './test/tp_crc32.cfg'
|
2020-03-24 16:23:06 72 [Note] InnoDB: Table `test`.`tp_crc32` flushed to disk
|
2020-03-24 16:23:06 72 [Note] InnoDB: Deleting the meta-data file './test/tce_crc32.cfg'
|
2020-03-24 16:23:06 72 [Note] InnoDB: Deleting the meta-data file './test/tc_crc32.cfg'
|
2020-03-24 16:23:06 72 [Note] InnoDB: Deleting the meta-data file './test/te_crc32.cfg'
|
2020-03-24 16:23:06 72 [Note] InnoDB: Deleting the meta-data file './test/t_crc32.cfg'
|
2020-03-24 16:23:06 72 [Note] InnoDB: Deleting the meta-data file './test/tpe_crc32.cfg'
|
2020-03-24 16:23:06 72 [Note] InnoDB: Deleting the meta-data file './test/tp_crc32.cfg'
|
2020-03-24 16:23:06 72 [Note] InnoDB: Resuming purge
|
2020-03-24 16:23:06 72 [Note] InnoDB: Importing tablespace for table 'test/tce_crc32' that was exported from host 'test64'
|
2020-03-24 16:23:06 72 [Note] InnoDB: Phase I - Update all pages
|
2020-03-24 16:23:06 72 [Note] InnoDB: Sync to disk
|
2020-03-24 16:23:06 72 [Note] InnoDB: Sync to disk - done!
|
2020-03-24 16:23:06 72 [Note] InnoDB: Phase III - Flush changes to disk
|
2020-03-24 16:23:06 72 [Note] InnoDB: Phase IV - Flush complete
|
2020-03-24 16:23:06 72 [Note] InnoDB: `test`.`tce_crc32` autoinc value set to 2
|
2020-03-24 16:23:06 72 [Note] InnoDB: Importing tablespace for table 'test/tc_crc32' that was exported from host 'test64'
|
2020-03-24 16:23:06 72 [Note] InnoDB: Phase I - Update all pages
|
2020-03-24 16:23:06 72 [Note] InnoDB: Sync to disk
|
2020-03-24 16:23:06 72 [Note] InnoDB: Sync to disk - done!
|
2020-03-24 16:23:06 72 [Note] InnoDB: Phase III - Flush changes to disk
|
2020-03-24 16:23:06 72 [Note] InnoDB: Phase IV - Flush complete
|
2020-03-24 16:23:06 72 [Note] InnoDB: `test`.`tc_crc32` autoinc value set to 2
|
2020-03-24 16:23:06 72 [Note] InnoDB: Importing tablespace for table 'test/te_crc32' that was exported from host 'test64'
|
2020-03-24 16:23:06 72 [Note] InnoDB: Phase I - Update all pages
|
2020-03-24 16:23:06 72 [Note] InnoDB: Sync to disk
|
2020-03-24 16:23:06 72 [Note] InnoDB: Sync to disk - done!
|
2020-03-24 16:23:06 72 [Note] InnoDB: Phase III - Flush changes to disk
|
2020-03-24 16:23:06 72 [Note] InnoDB: Phase IV - Flush complete
|
2020-03-24 16:23:06 72 [Note] InnoDB: `test`.`te_crc32` autoinc value set to 2
|
2020-03-24 16:23:06 72 [Note] InnoDB: Importing tablespace for table 'test/t_crc32' that was exported from host 'test64'
|
2020-03-24 16:23:06 72 [Note] InnoDB: Phase I - Update all pages
|
2020-03-24 16:23:06 72 [Note] InnoDB: Sync to disk
|
2020-03-24 16:23:06 72 [Note] InnoDB: Sync to disk - done!
|
2020-03-24 16:23:06 72 [Note] InnoDB: Phase III - Flush changes to disk
|
2020-03-24 16:23:06 72 [Note] InnoDB: Phase IV - Flush complete
|
2020-03-24 16:23:06 72 [Note] InnoDB: `test`.`t_crc32` autoinc value set to 2
|
2020-03-24 16:23:06 72 [Note] InnoDB: Importing tablespace for table 'test/tpe_crc32' that was exported from host 'test64'
|
2020-03-24 16:23:06 72 [Note] InnoDB: Phase I - Update all pages
|
2020-03-24 16:23:06 72 [Note] InnoDB: Sync to disk
|
2020-03-24 16:23:06 72 [Note] InnoDB: Sync to disk - done!
|
2020-03-24 16:23:06 72 [Note] InnoDB: Phase III - Flush changes to disk
|
2020-03-24 16:23:06 72 [Note] InnoDB: Phase IV - Flush complete
|
2020-03-24 16:23:06 72 [Note] InnoDB: `test`.`tpe_crc32` autoinc value set to 2
|
2020-03-24 16:23:06 72 [Note] InnoDB: Importing tablespace for table 'test/tp_crc32' that was exported from host 'test64'
|
2020-03-24 16:23:06 72 [Note] InnoDB: Phase I - Update all pages
|
2020-03-24 16:23:06 72 [Note] InnoDB: Sync to disk
|
2020-03-24 16:23:06 72 [Note] InnoDB: Sync to disk - done!
|
2020-03-24 16:23:06 72 [Note] InnoDB: Phase III - Flush changes to disk
|
2020-03-24 16:23:06 72 [Note] InnoDB: Phase IV - Flush complete
|
2020-03-24 16:23:06 72 [Note] InnoDB: `test`.`tp_crc32` autoinc value set to 2
|
2020-03-24 16:23:06 72 [Note] InnoDB: Importing tablespace for table 'test/tce_crc32' that was exported from host 'test64'
|
2020-03-24 16:23:06 72 [Note] InnoDB: Phase I - Update all pages
|
2020-03-24 16:23:06 72 [Note] InnoDB: Sync to disk
|
2020-03-24 16:23:06 72 [Note] InnoDB: Sync to disk - done!
|
2020-03-24 16:23:06 72 [Note] InnoDB: Phase III - Flush changes to disk
|
2020-03-24 16:23:06 72 [Note] InnoDB: Phase IV - Flush complete
|
2020-03-24 16:23:06 72 [Note] InnoDB: `test`.`tce_crc32` autoinc value set to 2
|
2020-03-24 16:23:06 72 [Note] InnoDB: Importing tablespace for table 'test/tc_crc32' that was exported from host 'test64'
|
2020-03-24 16:23:06 72 [Note] InnoDB: Phase I - Update all pages
|
2020-03-24 16:23:06 72 [Note] InnoDB: Sync to disk
|
2020-03-24 16:23:06 72 [Note] InnoDB: Sync to disk - done!
|
2020-03-24 16:23:06 72 [Note] InnoDB: Phase III - Flush changes to disk
|
2020-03-24 16:23:06 72 [Note] InnoDB: Phase IV - Flush complete
|
2020-03-24 16:23:06 72 [Note] InnoDB: `test`.`tc_crc32` autoinc value set to 2
|
2020-03-24 16:23:06 72 [Note] InnoDB: Importing tablespace for table 'test/te_crc32' that was exported from host 'test64'
|
2020-03-24 16:23:06 72 [Note] InnoDB: Phase I - Update all pages
|
2020-03-24 16:23:06 72 [Note] InnoDB: Sync to disk
|
2020-03-24 16:23:06 72 [Note] InnoDB: Sync to disk - done!
|
2020-03-24 16:23:06 72 [Note] InnoDB: Phase III - Flush changes to disk
|
2020-03-24 16:23:06 72 [Note] InnoDB: Phase IV - Flush complete
|
2020-03-24 16:23:06 72 [Note] InnoDB: `test`.`te_crc32` autoinc value set to 2
|
2020-03-24 16:23:06 72 [Note] InnoDB: Importing tablespace for table 'test/t_crc32' that was exported from host 'test64'
|
2020-03-24 16:23:06 72 [Note] InnoDB: Phase I - Update all pages
|
2020-03-24 16:23:06 72 [Note] InnoDB: Sync to disk
|
2020-03-24 16:23:06 72 [Note] InnoDB: Sync to disk - done!
|
2020-03-24 16:23:06 72 [Note] InnoDB: Phase III - Flush changes to disk
|
2020-03-24 16:23:06 72 [Note] InnoDB: Phase IV - Flush complete
|
2020-03-24 16:23:06 72 [Note] InnoDB: `test`.`t_crc32` autoinc value set to 2
|
2020-03-24 16:23:06 72 [Note] InnoDB: Importing tablespace for table 'test/tpe_crc32' that was exported from host 'test64'
|
2020-03-24 16:23:06 72 [Note] InnoDB: Phase I - Update all pages
|
2020-03-24 16:23:06 72 [Note] InnoDB: Sync to disk
|
2020-03-24 16:23:06 72 [Note] InnoDB: Sync to disk - done!
|
2020-03-24 16:23:06 72 [Note] InnoDB: Phase III - Flush changes to disk
|
2020-03-24 16:23:06 72 [Note] InnoDB: Phase IV - Flush complete
|
2020-03-24 16:23:06 72 [Note] InnoDB: `test`.`tpe_crc32` autoinc value set to 2
|
2020-03-24 16:23:06 72 [Note] InnoDB: Importing tablespace for table 'test/tp_crc32' that was exported from host 'test64'
|
2020-03-24 16:23:06 72 [Note] InnoDB: Phase I - Update all pages
|
2020-03-24 16:23:06 72 [Note] InnoDB: Sync to disk
|
2020-03-24 16:23:06 72 [Note] InnoDB: Sync to disk - done!
|
2020-03-24 16:23:06 72 [Note] InnoDB: Phase III - Flush changes to disk
|
2020-03-24 16:23:06 72 [Note] InnoDB: Phase IV - Flush complete
|
2020-03-24 16:23:06 72 [Note] InnoDB: `test`.`tp_crc32` autoinc value set to 2
|
2020-03-24 16:23:07 72 [Note] InnoDB: Importing tablespace for table 'test/tce_crc32' that was exported from host 'test64'
|
2020-03-24 16:23:07 72 [Note] InnoDB: Phase I - Update all pages
|
2020-03-24 16:23:07 72 [Note] InnoDB: Sync to disk
|
2020-03-24 16:23:07 72 [Note] InnoDB: Sync to disk - done!
|
2020-03-24 16:23:07 72 [Note] InnoDB: Phase III - Flush changes to disk
|
2020-03-24 16:23:07 72 [Note] InnoDB: Phase IV - Flush complete
|
2020-03-24 16:23:07 72 [Note] InnoDB: `test`.`tce_crc32` autoinc value set to 2
|
2020-03-24 16:23:07 72 [Note] InnoDB: Importing tablespace for table 'test/tc_crc32' that was exported from host 'test64'
|
2020-03-24 16:23:07 72 [Note] InnoDB: Phase I - Update all pages
|
2020-03-24 16:23:07 72 [Note] InnoDB: Sync to disk
|
2020-03-24 16:23:07 72 [Note] InnoDB: Sync to disk - done!
|
2020-03-24 16:23:07 72 [Note] InnoDB: Phase III - Flush changes to disk
|
2020-03-24 16:23:07 72 [Note] InnoDB: Phase IV - Flush complete
|
2020-03-24 16:23:07 72 [Note] InnoDB: `test`.`tc_crc32` autoinc value set to 2
|
2020-03-24 16:23:07 72 [Note] InnoDB: Importing tablespace for table 'test/te_crc32' that was exported from host 'test64'
|
2020-03-24 16:23:07 72 [Note] InnoDB: Phase I - Update all pages
|
2020-03-24 16:23:07 72 [Note] InnoDB: Sync to disk
|
2020-03-24 16:23:07 72 [Note] InnoDB: Sync to disk - done!
|
2020-03-24 16:23:07 72 [Note] InnoDB: Phase III - Flush changes to disk
|
2020-03-24 16:23:07 72 [Note] InnoDB: Phase IV - Flush complete
|
2020-03-24 16:23:07 72 [Note] InnoDB: `test`.`te_crc32` autoinc value set to 2
|
2020-03-24 16:23:07 72 [Note] InnoDB: Importing tablespace for table 'test/t_crc32' that was exported from host 'test64'
|
2020-03-24 16:23:07 72 [Note] InnoDB: Phase I - Update all pages
|
2020-03-24 16:23:07 72 [Note] InnoDB: Sync to disk
|
2020-03-24 16:23:07 72 [Note] InnoDB: Sync to disk - done!
|
2020-03-24 16:23:07 72 [Note] InnoDB: Phase III - Flush changes to disk
|
2020-03-24 16:23:07 72 [Note] InnoDB: Phase IV - Flush complete
|
2020-03-24 16:23:07 72 [Note] InnoDB: `test`.`t_crc32` autoinc value set to 2
|
2020-03-24 16:23:07 72 [Note] InnoDB: Importing tablespace for table 'test/tpe_crc32' that was exported from host 'test64'
|
2020-03-24 16:23:07 72 [Note] InnoDB: Phase I - Update all pages
|
2020-03-24 16:23:07 72 [Note] InnoDB: Sync to disk
|
2020-03-24 16:23:07 72 [Note] InnoDB: Sync to disk - done!
|
2020-03-24 16:23:07 72 [Note] InnoDB: Phase III - Flush changes to disk
|
2020-03-24 16:23:07 72 [Note] InnoDB: Phase IV - Flush complete
|
2020-03-24 16:23:07 72 [Note] InnoDB: `test`.`tpe_crc32` autoinc value set to 2
|
2020-03-24 16:23:07 72 [Note] InnoDB: Importing tablespace for table 'test/tp_crc32' that was exported from host 'test64'
|
2020-03-24 16:23:07 72 [Note] InnoDB: Phase I - Update all pages
|
2020-03-24 16:23:07 72 [Note] InnoDB: Sync to disk
|
2020-03-24 16:23:07 72 [Note] InnoDB: Sync to disk - done!
|
2020-03-24 16:23:07 72 [Note] InnoDB: Phase III - Flush changes to disk
|
2020-03-24 16:23:07 72 [Note] InnoDB: Phase IV - Flush complete
|
2020-03-24 16:23:07 72 [Note] InnoDB: `test`.`tp_crc32` autoinc value set to 2
|
mysqld: /10.5/storage/innobase/log/log0log.cc:1367: bool log_checkpoint(): Assertion `oldest_lsn >= log_sys.last_checkpoint_lsn' failed.
|
200324 16:23:07 [ERROR] mysqld got signal 6 ;
|
This could be because you hit a bug. It is also possible that this binary
|
or one of the libraries it was linked against is corrupt, improperly built,
|
or misconfigured. This error can also be caused by malfunctioning hardware.
|
|
|
To report this bug, see https://mariadb.com/kb/en/reporting-bugs
|
|
|
We will try our best to scrape up some info that will hopefully help
|
diagnose the problem, but since we have already crashed,
|
something is definitely wrong and this may fail.
|
|
|
Server version: 10.5.2-MariaDB-debug-log
|
key_buffer_size=1048576
|
read_buffer_size=131072
|
max_used_connections=1
|
max_threads=153
|
thread_count=2
|
It is possible that mysqld could use up to
|
key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 63698 K bytes of memory
|
Hope that's ok; if not, decrease some variables in the equation.
|
|
|
Thread pointer: 0x0
|
Attempting backtrace. You can use the following information to find out
|
where mysqld died. If you see no messages after this, something went
|
terribly wrong...
|
stack_bottom = 0x0 thread_stack 0x5fc00
|
??:0(__interceptor_timerfd_gettime)[0x7fe5041855fd]
|
/10.5/sql/mysqld(my_print_stacktrace+0xb5)[0x5617feb4a657]
|
/10.5/sql/mysqld(handle_fatal_signal+0x9df)[0x5617fd5ff84b]
|
??:0(__restore_rt)[0x7fe5040ca730]
|
linux/raise.c:51(__GI_raise)[0x7fe50362e7bb]
|
stdlib/abort.c:81(__GI_abort)[0x7fe503619535]
|
intl/loadmsgcat.c:1177(_nl_load_domain)[0x7fe50361940f]
|
??:0(__assert_fail)[0x7fe503627102]
|
/10.5/sql/mysqld(+0x2e53f4e)[0x5617fe2b1f4e]
|
log/log0log.cc:1369(log_checkpoint())[0x5617fe541865]
|
srv/srv0srv.cc:1870(srv_master_do_active_tasks())[0x5617fe5424c1]
|
srv/srv0srv.cc:2001(srv_master_callback)[0x5617fe9830dc]
|
tpool/tpool_generic.cc:300(tpool::thread_pool_generic::timer_generic::run())[0x5617fe98331f]
|
tpool/tpool_generic.cc:318(tpool::thread_pool_generic::timer_generic::execute(void*))[0x5617fe9902f1]
|
tpool/task.cc:53(tpool::task::execute())[0x5617fe97f229]
|
tpool/tpool_generic.cc:516(tpool::thread_pool_generic::worker_main(tpool::worker_data*))[0x5617fe987fe8]
|
bits/invoke.h:73(void std::__invoke_impl<void, void (tpool::thread_pool_generic::*)(tpool::worker_data*), tpool::thread_pool_generic*, tpool::worker_data*>(std::__invoke_memfun_deref, void (tpool::thread_pool_generic::*&&)(tpool::worker_data*), tpool::thread_pool_generic*&&, tpool::worker_data*&&))[0x5617fe985d78]
|
bits/invoke.h:96(std::__invoke_result<void (tpool::thread_pool_generic::*)(tpool::worker_data*), tpool::thread_pool_generic*, tpool::worker_data*>::type std::__invoke<void (tpool::thread_pool_generic::*)(tpool::worker_data*), tpool::thread_pool_generic*, tpool::worker_data*>(void (tpool::thread_pool_generic::*&&)(tpool::worker_data*), tpool::thread_pool_generic*&&, tpool::worker_data*&&))[0x5617fe98f341]
|
8/thread:244(decltype (__invoke((_S_declval<0ul>)(), (_S_declval<1ul>)(), (_S_declval<2ul>)())) std::thread::_Invoker<std::tuple<void (tpool::thread_pool_generic::*)(tpool::worker_data*), tpool::thread_pool_generic*, tpool::worker_data*> >::_M_invoke<0ul, 1ul, 2ul>(std::_Index_tuple<0ul, 1ul, 2ul>))[0x5617fe98f297]
|
8/thread:250(std::thread::_Invoker<std::tuple<void (tpool::thread_pool_generic::*)(tpool::worker_data*), tpool::thread_pool_generic*, tpool::worker_data*> >::operator()())[0x5617fe98f206]
|
??:0(std::error_code::default_error_condition() const)[0x7fe503a10b2f]
|
nptl/pthread_create.c:487(start_thread)[0x7fe5040bffa3]
|
/lib/x86_64-linux-gnu/libc.so.6(clone+0x3f)[0x7fe5036f04cf]
|
The manual page at http://dev.mysql.com/doc/mysql/en/crashing.html contains
|
information that should help you find out what is causing the crash.
|
Writing a core file...
|
Working directory at /10.5/mysql-test/var/6/mysqld.1/data
|
Resource Limits:
|
Limit Soft Limit Hard Limit Units
|
Max cpu time unlimited unlimited seconds
|
Max file size unlimited unlimited bytes
|
Max data size unlimited unlimited bytes
|
Max stack size 8388608 unlimited bytes
|
Max core file size 0 0 bytes
|
Max resident set unlimited unlimited bytes
|
Max processes 515503 515503 processes
|
Max open files 1024 1024 files
|
Max locked memory 67108864 67108864 bytes
|
Max address space unlimited unlimited bytes
|
Max file locks unlimited unlimited locks
|
Max pending signals 515503 515503 signals
|
Max msgqueue size 819200 819200 bytes
|
Max nice priority 0 0
|
Max realtime priority 0 0
|
Max realtime timeout unlimited unlimited us
|
Core pattern: core
|
|
|
----------SERVER LOG END-------------
|
alice, are you able to repeat this with ./mtr --rr using the patch from MDEV-22179? With rr replay, it would become trivial to debug concurrency bugs like this.
I believe that this bug should also be repeatable with RQG. It could help to use innodb_encrypt_tables, innodb_page_size=64k and innodb_checksum_algorithm=crc32, to make page flushing as slow as possible. (The default 10.5 innodb_checksum_algorithm=full_crc32 would only compute one checksum per page.) We should only need lots of writes, and frequent checkpoints. Checkpoints can be triggered in debug builds with the following:
SET GLOBAL innodb_log_checkpoint_now=ON; |
We might also want to set --debug-dbug=d,ib_log_checkpoint_avoid to forbid checkpoints being from being triggered by background activity. Repeating this bug might require that there be long enough pauses between checkpoints.
We got one more occurrence on kvm-asan, on shutdown:
|
bb-10.5-release f3a4b1692a4161dceca14117a5940388d0f8b370 |
2020-04-07 16:13:45 0 [Note] /home/buildbot/buildbot/build/mariadb-10.5.3/sql/mariadbd (initiated by: root[root] @ localhost []): Normal shutdown
|
2020-04-07 16:13:45 0 [Note] Event Scheduler: Purging the queue. 0 events
|
2020-04-07 16:13:45 0 [Note] InnoDB: FTS optimize thread exiting.
|
mariadbd: /home/buildbot/buildbot/build/mariadb-10.5.3/storage/innobase/log/log0log.cc:1367: bool log_checkpoint(): Assertion `oldest_lsn >= log_sys.last_checkpoint_lsn' failed.
|
…
|
2020-04-07 16:13:49 0 [ERROR] InnoDB: Tablespace 1069 was not found at ./test/#sql-ib-foo.ibd.
|
2020-04-07 16:13:49 0 [ERROR] InnoDB: Set innodb_force_recovery=1 to ignore this and to permanently lose all changes to the tablespace.
|
2020-04-07 16:13:49 0 [ERROR] InnoDB: Plugin initialization aborted at srv0start.cc[1537] with error Tablespace not found
|
2020-04-07 16:13:49 0 [Note] InnoDB: Starting shutdown...
|
2020-04-07 16:13:49 0 [ERROR] Plugin 'InnoDB' init function returned error.
|
2020-04-07 16:13:49 0 [ERROR] Plugin 'InnoDB' registration as a STORAGE ENGINE failed.
|
This represented itself as a test failure:
|
bb-10.5-release f3a4b1692a4161dceca14117a5940388d0f8b370 |
CURRENT_TEST: innodb.drop_table_background
|
mysqltest: At line 40: query 'CREATE TABLE t (a INT) ENGINE=InnoDB' failed: 1286: Unknown storage engine 'InnoDB'
|
This occurred once again on win32-debug, on bb-10.5-release:
|
10.5 fbe2712705d464bf8488df249c36115e2c1f63f7 minus 62903434eb009cb0bcd5003b0a45914bd4c09886 |
innodb.autoinc_persist 'innodb' w4 [ pass ] 22525
|
innodb.blob-update-debug 'innodb' w4 [ pass ] 39
|
innodb.blob_unique2pk 'innodb' w4 [ pass ] 119
|
innodb.count_distinct 'innodb' w4 [ pass ] 31
|
innodb.create-index 'innodb' w4 [ pass ] 29
|
innodb.deadlock_detect 'innodb' w4 [ pass ] 3086
|
innodb.default_row_format_alter 'innodb' w4 [ pass ] 292
|
innodb.default_row_format_compatibility 'innodb' w4 [ pass ] 385
|
innodb.drop_table_background 'innodb' w4 [ fail ]
|
Test ended at 2020-04-25 15:14:18
|
|
|
CURRENT_TEST: innodb.drop_table_background
|
mysqltest: At line 40: query 'CREATE TABLE t (a INT) ENGINE=InnoDB' failed: 1286: Unknown storage engine 'InnoDB'
|
Above, I am including all previous tests on this worker since the server was restarted. The server error log shows some import/export diagnostic messages from preceding tests, which might correlate with the assertion failure:
|
10.5 fbe2712705d464bf8488df249c36115e2c1f63f7 minus 62903434eb009cb0bcd5003b0a45914bd4c09886 |
CURRENT_TEST: innodb.autoinc_persist
|
[snip lots of output until the last server restart]
|
Version: '10.5.3-MariaDB-debug-log' socket: '' port: 16060 Source distribution
|
2020-04-25 15:14:03 3 [Note] InnoDB: Sync to disk of `test`.`t33` started.
|
2020-04-25 15:14:03 3 [Note] InnoDB: Stopping purge
|
2020-04-25 15:14:03 3 [Note] InnoDB: Writing table metadata to '.\test\t33.cfg'
|
2020-04-25 15:14:03 3 [Note] InnoDB: Table `test`.`t33` flushed to disk
|
2020-04-25 15:14:03 3 [Note] InnoDB: Deleting the meta-data file '.\test\t33.cfg'
|
2020-04-25 15:14:03 3 [Note] InnoDB: Resuming purge
|
2020-04-25 15:14:03 3 [Note] InnoDB: Importing tablespace for table 'test/t33' that was exported from host 'MariaDB-04'
|
2020-04-25 15:14:03 3 [Note] InnoDB: Phase I - Update all pages
|
2020-04-25 15:14:03 3 [Note] InnoDB: Sync to disk
|
2020-04-25 15:14:03 3 [Note] InnoDB: Sync to disk - done!
|
2020-04-25 15:14:03 3 [Note] InnoDB: Phase III - Flush changes to disk
|
2020-04-25 15:14:03 3 [Note] InnoDB: Phase IV - Flush complete
|
2020-04-25 15:14:03 3 [Note] InnoDB: `test`.`t33` autoinc value set to 4
|
CURRENT_TEST: innodb.blob-update-debug
|
CURRENT_TEST: innodb.blob_unique2pk
|
CURRENT_TEST: innodb.count_distinct
|
CURRENT_TEST: innodb.create-index
|
CURRENT_TEST: innodb.deadlock_detect
|
CURRENT_TEST: innodb.default_row_format_alter
|
CURRENT_TEST: innodb.default_row_format_compatibility
|
2020-04-25 15:14:11 32 [Note] InnoDB: Sync to disk of `test`.`tab` started.
|
2020-04-25 15:14:11 32 [Note] InnoDB: Stopping purge
|
2020-04-25 15:14:11 32 [Note] InnoDB: Writing table metadata to '.\test\tab.cfg'
|
2020-04-25 15:14:11 32 [Note] InnoDB: Table `test`.`tab` flushed to disk
|
2020-04-25 15:14:11 32 [Note] InnoDB: Deleting the meta-data file '.\test\tab.cfg'
|
2020-04-25 15:14:11 32 [Note] InnoDB: Resuming purge
|
2020-04-25 15:14:11 32 [Note] InnoDB: Importing tablespace for table 'test/tab' that was exported from host 'MariaDB-04'
|
2020-04-25 15:14:11 32 [Note] InnoDB: Discarding tablespace of table `test`.`tab`: Generic error
|
2020-04-25 15:14:11 32 [Note] InnoDB: Deleting .\test\tab.ibd
|
2020-04-25 15:14:11 32 [Note] InnoDB: Importing tablespace for table 'test/tab' that was exported from host 'MariaDB-04'
|
2020-04-25 15:14:11 32 [Note] InnoDB: Phase I - Update all pages
|
2020-04-25 15:14:11 32 [Note] InnoDB: Discarding tablespace of table `test`.`tab`: I/O error
|
2020-04-25 15:14:11 32 [Note] InnoDB: Importing tablespace for table 'test/tab' that was exported from host 'MariaDB-04'
|
2020-04-25 15:14:11 32 [Note] InnoDB: Phase I - Update all pages
|
2020-04-25 15:14:11 32 [Note] InnoDB: Sync to disk
|
2020-04-25 15:14:11 32 [Note] InnoDB: Sync to disk - done!
|
2020-04-25 15:14:11 32 [Note] InnoDB: Phase III - Flush changes to disk
|
2020-04-25 15:14:11 32 [Note] InnoDB: Phase IV - Flush complete
|
CURRENT_TEST: innodb.drop_table_background
|
2020-04-25 15:14:12 36 [Note] InnoDB: Deferring DROP TABLE `test`.`t10`; renaming to test/#sql-ib844
|
2020-04-25 15:14:13 36 [Note] InnoDB: Deferring DROP TABLE `test`.`t9`; renaming to test/#sql-ib845
|
2020-04-25 15:14:13 36 [Note] InnoDB: Deferring DROP TABLE `test`.`t8`; renaming to test/#sql-ib846
|
2020-04-25 15:14:13 36 [Note] InnoDB: Deferring DROP TABLE `test`.`t7`; renaming to test/#sql-ib847
|
2020-04-25 15:14:13 36 [Note] InnoDB: Deferring DROP TABLE `test`.`t6`; renaming to test/#sql-ib848
|
2020-04-25 15:14:13 36 [Note] InnoDB: Deferring DROP TABLE `test`.`t5`; renaming to test/#sql-ib849
|
2020-04-25 15:14:13 36 [Note] InnoDB: Deferring DROP TABLE `test`.`t4`; renaming to test/#sql-ib850
|
2020-04-25 15:14:13 36 [Note] InnoDB: Deferring DROP TABLE `test`.`t3`; renaming to test/#sql-ib851
|
2020-04-25 15:14:13 36 [Note] InnoDB: Deferring DROP TABLE `test`.`t2`; renaming to test/#sql-ib852
|
2020-04-25 15:14:13 36 [Note] InnoDB: Deferring DROP TABLE `test`.`t1`; renaming to test/#sql-ib853
|
2020-04-25 15:14:13 36 [Note] InnoDB: Deferring DROP TABLE `test`.`target`; renaming to test/#sql-ib854
|
2020-04-25 15:14:13 36 [Note] InnoDB: Deferring DROP TABLE `test`.`t`; renaming to test/#sql-ib842
|
2020-04-25 15:14:13 0 [Note] D:/win32-debug/build/sql//Debug/mariadbd.exe (initiated by: root[root] @ localhost [::1]): Normal shutdown
|
2020-04-25 15:14:13 0 [Note] Event Scheduler: Purging the queue. 0 events
|
2020-04-25 15:14:13 0 [Note] InnoDB: FTS optimize thread exiting.
|
Assertion failed: oldest_lsn >= log_sys.last_checkpoint_lsn, file D:\win32-debug\build\src\storage\innobase\log\log0log.cc, line 1367
|
The previously kvm-asan failure has very similar server error log output:
|
bb-10.5-release f3a4b1692a4161dceca14117a5940388d0f8b370 |
CURRENT_TEST: innodb.autoinc_persist
|
[snip lots of output until the last server restart]
|
Version: '10.5.3-MariaDB-debug-log' socket: '/dev/shm/var/tmp/4/mysqld.1.sock' port: 16060 Source distribution
|
2020-04-07 16:13:38 3 [Note] InnoDB: Sync to disk of `test`.`t33` started.
|
2020-04-07 16:13:38 3 [Note] InnoDB: Stopping purge
|
2020-04-07 16:13:38 3 [Note] InnoDB: Writing table metadata to './test/t33.cfg'
|
2020-04-07 16:13:38 3 [Note] InnoDB: Table `test`.`t33` flushed to disk
|
2020-04-07 16:13:38 3 [Note] InnoDB: Deleting the meta-data file './test/t33.cfg'
|
2020-04-07 16:13:38 3 [Note] InnoDB: Resuming purge
|
2020-04-07 16:13:38 3 [Note] InnoDB: Importing tablespace for table 'test/t33' that was exported from host 'ubuntu-focal-amd64'
|
2020-04-07 16:13:38 3 [Note] InnoDB: Phase I - Update all pages
|
2020-04-07 16:13:38 3 [Note] InnoDB: Sync to disk
|
2020-04-07 16:13:38 3 [Note] InnoDB: Sync to disk - done!
|
2020-04-07 16:13:38 3 [Note] InnoDB: Phase III - Flush changes to disk
|
2020-04-07 16:13:38 3 [Note] InnoDB: Phase IV - Flush complete
|
2020-04-07 16:13:38 3 [Note] InnoDB: `test`.`t33` autoinc value set to 4
|
CURRENT_TEST: innodb.blob-update-debug
|
CURRENT_TEST: innodb.blob_unique2pk
|
CURRENT_TEST: innodb.count_distinct
|
CURRENT_TEST: innodb.create-index
|
CURRENT_TEST: innodb.deadlock_detect
|
CURRENT_TEST: innodb.default_row_format_alter
|
CURRENT_TEST: innodb.default_row_format_compatibility
|
2020-04-07 16:13:44 32 [Note] InnoDB: Sync to disk of `test`.`tab` started.
|
2020-04-07 16:13:44 32 [Note] InnoDB: Stopping purge
|
2020-04-07 16:13:44 32 [Note] InnoDB: Writing table metadata to './test/tab.cfg'
|
2020-04-07 16:13:44 32 [Note] InnoDB: Table `test`.`tab` flushed to disk
|
2020-04-07 16:13:44 32 [Note] InnoDB: Deleting the meta-data file './test/tab.cfg'
|
2020-04-07 16:13:44 32 [Note] InnoDB: Resuming purge
|
2020-04-07 16:13:44 32 [Note] InnoDB: Importing tablespace for table 'test/tab' that was exported from host 'ubuntu-focal-amd64'
|
2020-04-07 16:13:44 32 [Note] InnoDB: Discarding tablespace of table `test`.`tab`: Generic error
|
2020-04-07 16:13:44 32 [Note] InnoDB: Deleting ./test/tab.ibd
|
2020-04-07 16:13:44 32 [Note] InnoDB: Importing tablespace for table 'test/tab' that was exported from host 'ubuntu-focal-amd64'
|
2020-04-07 16:13:44 32 [Note] InnoDB: Phase I - Update all pages
|
2020-04-07 16:13:44 32 [Note] InnoDB: Discarding tablespace of table `test`.`tab`: I/O error
|
2020-04-07 16:13:44 32 [Note] InnoDB: Importing tablespace for table 'test/tab' that was exported from host 'ubuntu-focal-amd64'
|
2020-04-07 16:13:44 32 [Note] InnoDB: Phase I - Update all pages
|
2020-04-07 16:13:44 32 [Note] InnoDB: Sync to disk
|
2020-04-07 16:13:44 32 [Note] InnoDB: Sync to disk - done!
|
2020-04-07 16:13:44 32 [Note] InnoDB: Phase III - Flush changes to disk
|
2020-04-07 16:13:44 32 [Note] InnoDB: Phase IV - Flush complete
|
CURRENT_TEST: innodb.drop_table_background
|
2020-04-07 16:13:45 36 [Note] InnoDB: Deferring DROP TABLE `test`.`t10`; renaming to test/#sql-ib1090
|
2020-04-07 16:13:45 36 [Note] InnoDB: Deferring DROP TABLE `test`.`t9`; renaming to test/#sql-ib1091
|
2020-04-07 16:13:45 36 [Note] InnoDB: Deferring DROP TABLE `test`.`t8`; renaming to test/#sql-ib1092
|
2020-04-07 16:13:45 36 [Note] InnoDB: Deferring DROP TABLE `test`.`t7`; renaming to test/#sql-ib1093
|
2020-04-07 16:13:45 36 [Note] InnoDB: Deferring DROP TABLE `test`.`t6`; renaming to test/#sql-ib1094
|
2020-04-07 16:13:45 36 [Note] InnoDB: Deferring DROP TABLE `test`.`t5`; renaming to test/#sql-ib1095
|
2020-04-07 16:13:45 36 [Note] InnoDB: Deferring DROP TABLE `test`.`t4`; renaming to test/#sql-ib1096
|
2020-04-07 16:13:45 36 [Note] InnoDB: Deferring DROP TABLE `test`.`t3`; renaming to test/#sql-ib1097
|
2020-04-07 16:13:45 36 [Note] InnoDB: Deferring DROP TABLE `test`.`t2`; renaming to test/#sql-ib1098
|
2020-04-07 16:13:45 36 [Note] InnoDB: Deferring DROP TABLE `test`.`t1`; renaming to test/#sql-ib1099
|
2020-04-07 16:13:45 36 [Note] InnoDB: Deferring DROP TABLE `test`.`target`; renaming to test/#sql-ib1100
|
2020-04-07 16:13:45 36 [Note] InnoDB: Deferring DROP TABLE `test`.`t`; renaming to test/#sql-ib1088
|
2020-04-07 16:13:45 0 [Note] /home/buildbot/buildbot/build/mariadb-10.5.3/sql/mariadbd (initiated by: root[root] @ localhost []): Normal shutdown
|
2020-04-07 16:13:45 0 [Note] Event Scheduler: Purging the queue. 0 events
|
2020-04-07 16:13:45 0 [Note] InnoDB: FTS optimize thread exiting.
|
mariadbd: /home/buildbot/buildbot/build/mariadb-10.5.3/storage/innobase/log/log0log.cc:1367: bool log_checkpoint(): Assertion `oldest_lsn >= log_sys.last_checkpoint_lsn' failed.
|
Assuming that the failures are strongly correlated with import/export operations, the above logs suggest that the failure could be reproduced with the following:
./mtr --no-reorder innodb.autoinc_persist innodb.default_row_format_compatibility innodb.drop_table_background
|
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.
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.
Unless I am mistaken about the assertion, in non-debug builds the problem is reported by log_close():
<< checkpoint_ageI suspect that we may be missing log_free_check() in some code paths (possibly in addition to the one in row_import_for_mysql()), or the logic around that function is not accurate.