Hi Mike,
Sorry, I was busy with other development tasks.
In the error log that you attached, the first startup upgrades the
redo log from the pre-MySQL 5.7.9/MariaDB 10.2.2 format:
2018-01-08 5:39:50 140390495905984 [Note] InnoDB: Upgrading redo
log: 2*536870912 bytes; LSN=1395657325222
2018-01-08 5:39:50 140390495905984 [Note] InnoDB: Upgrading redo
log: 2*536870912 bytes; LSN=1395657325222
2018-01-08 5:39:50 140390495905984 [Note] InnoDB: Starting to
delete and rewrite log files.
2018-01-08 5:39:50 140390495905984 [Note] InnoDB: Setting log
file ./ib_logfile101 size to 536870912 bytes
2018-01-08 5:39:50 140390495905984 [Note] InnoDB: Setting log
file ./ib_logfile1 size to 536870912 bytes
2018-01-08 5:39:50 140390495905984 [Note] InnoDB: Renaming log
file ./ib_logfile101 to ./ib_logfile0
2018-01-08 5:39:50 140390495905984 [Note] InnoDB: New log files
created, LSN=1395657325222
2018-01-08 6:01:49 140390495905984 [Note] InnoDB: 128 out of 128
rollback segments are active.
This should not count as a crash recovery, because we would refuse
startup unless the redo log was logically empty (crash-upgrade). So,
something is wrong already here. There is one more strange thing from
that startup:
2018-01-08 6:01:49 140390495905984 [Note] InnoDB: Waiting for
purge to start
2018-01-08 6:01:49 140390495905984 [Note] InnoDB: 5.7.20 started;
log sequence number 0
Why is it reporting 0 instead of 1395657325222 or more? We are missing
an assignment srv_start_lsn = log_sys->lsn when upgrading the redo log.
Then, there is an apparently clean shutdown and subsequent startup
with no sign of any crash recovery taking place. But still we have the
following delay:
2018-01-08 8:23:03 140364886096064 [Note] InnoDB: Highest
supported file format is Barracuda.
2018-01-08 8:45:14 140364886096064 [Note] InnoDB: 128 out of 128
rollback segments are active.
There are only two assignments recv_needed_recovery=true. Together
with the assignments, we should output one of the following messages:
[Note] InnoDB: Starting crash recovery from checkpoint LSN=_
[Note] InnoDB: The log sequence number _ in the system tablespace
does not match the log sequence number _ in the ib_logfiles!
But, I do not see either message in the log excerpt.
Oh, now I realize that I was misled by the following in the gdb trace
that you previously attached:
#11 0x0000558a37dd1c24 in fil_ibd_open (validate=<optimized out>, validate@entry=true, fix_dict=<optimized out>, purpose=purpose@entry=FIL_TYPE_TABLESPACE, id=1233316, flags=<optimized out>,
space_name=<optimized out>, path_in=0x558a8d79af60 "./ddx_lab_801002/pickups.ibd") at /home/buildbot/buildbot/build/mariadb-10.2.12/storage/innobase/fil/fil0fil.cc:4211
#12 0x0000558a37db15c9 in dict_check_sys_tables (validate=true) at /home/buildbot/buildbot/build/mariadb-10.2.12/storage/innobase/dict/dict0load.cc:1482
#13 dict_check_tablespaces_and_store_max_id (validate=<optimized out>) at /home/buildbot/buildbot/build/mariadb-10.2.12/storage/innobase/dict/dict0load.cc:1537
Actually, we do not know what the value of the parameter was in stack
frame 13. It might very well have been passed as 'false'.
In dict_check_sys_tables() I see this code which is not present in
MySQL 5.7:
/* Check that the .ibd file exists. */
validate = true; /* Encryption */
dberr_t err = fil_ibd_open(
validate,
Thie above assignment 'validate = true' is the smoking gun! It was
added in MariaDB 10.2.2
<https://github.com/MariaDB/server/commit/2e814d4702d71a04388386a9f591d14a35980bfe>,
apparently by mistake. I just checked the differences in the function
dict_check_sys_tables() between MariaDB 10.2 and MySQL 5.7, and this
assignment is the only one that does not make any sense whatsoever.
I will shortly push a fix.
Thank you for your patience (and sorry for the pun)!
Marko
--
Marko Mäkelä, Lead Developer InnoDB
MariaDB Corporation
DON’T MISS
M|18
MariaDB User Conference
February 26 - 27, 2018
New York City
https://m18.mariadb.com/
