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, 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/