maria-discuss team mailing list archive

[Marko Mäkelä <marko.makela@xxxxxxxxxxx>]

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/