← Back to team overview

maria-discuss team mailing list archive

Re: MariaDB-10.2.11 Long Time To Start

 

Hi Marko,

I've been reading more into --innodb-force-recovery and trying to understand the state of my new slaves.

If I understand what you are saying, the current databases are in an unrecovered state and requires crash recovery.  If that is the case, should my log file indicate this the case when I restart.

To be sure, when I shutdown, it looks like it is shutting down cleanly:

2018-01-07 19:51:13 140398761576192 [Note] Error reading relay log event: slave SQL thread was killed 2018-01-07 19:51:13 140398761576192 [Note] Slave SQL thread exiting, replication stopped in log 'mysql-bin.003923' at position 662261965 2018-01-07 19:51:13 140398761879296 [Note] Slave I/O thread exiting, read up to log 'mysql-bin.003923', position 662261965 2018-01-07 19:51:37 140398761576192 [Note] /usr/sbin/mysqld (unknown): Normal shutdown 2018-01-07 19:51:37 140398761576192 [Note] Event Scheduler: Purging the queue. 0 events 2018-01-07 19:51:37 140338008692480 [Note] InnoDB: FTS optimize thread exiting.
2018-01-07 19:51:38 140398761576192 [Note] InnoDB: Starting shutdown...
2018-01-07 19:51:38 140337896998656 [Note] InnoDB: Dumping buffer pool(s) to /var/lib/mysql/ib_buffer_pool 2018-01-07 19:51:38 140337896998656 [Note] InnoDB: Instance 0, restricted to 110592 pages due to innodb_buf_pool_dump_pct=25 2018-01-07 19:51:38 140337896998656 [Note] InnoDB: Instance 1, restricted to 110592 pages due to innodb_buf_pool_dump_pct=25 2018-01-07 19:51:38 140337896998656 [Note] InnoDB: Instance 2, restricted to 110592 pages due to innodb_buf_pool_dump_pct=25 2018-01-07 19:51:38 140337896998656 [Note] InnoDB: Instance 3, restricted to 110592 pages due to innodb_buf_pool_dump_pct=25 2018-01-07 19:51:38 140337896998656 [Note] InnoDB: Instance 4, restricted to 110592 pages due to innodb_buf_pool_dump_pct=25 2018-01-07 19:51:38 140337896998656 [Note] InnoDB: Instance 5, restricted to 110592 pages due to innodb_buf_pool_dump_pct=25 2018-01-07 19:51:38 140337896998656 [Note] InnoDB: Instance 6, restricted to 110592 pages due to innodb_buf_pool_dump_pct=25 2018-01-07 19:51:38 140337896998656 [Note] InnoDB: Instance 7, restricted to 110592 pages due to innodb_buf_pool_dump_pct=25 2018-01-07 19:51:38 140337896998656 [Note] InnoDB: Buffer pool(s) dump completed at 180107 19:51:38 2018-01-07 19:52:10 140398761576192 [Note] InnoDB: Shutdown completed; log sequence number 1395535052281 2018-01-07 19:52:10 140398761576192 [Note] InnoDB: Removed temporary tablespace data file: "ibtmp1" 2018-01-07 19:52:10 140398761576192 [Note] /usr/sbin/mysqld: Shutdown complete

Startup also seems to run clean too (except for the long time):

2018-01-07 19:52:12 140563014502592 [Note] Using unique option prefix 'myisam-recover' is error-prone and can break in the future. Please use the full name 'myisam-recover-options' instead. 2018-01-07 19:52:12 140563014502592 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
2018-01-07 19:52:12 140563014502592 [Note] InnoDB: Uses event mutexes
2018-01-07 19:52:12 140563014502592 [Note] InnoDB: Compressed tables use zlib 1.2.8
2018-01-07 19:52:12 140563014502592 [Note] InnoDB: Using Linux native AIO
2018-01-07 19:52:12 140563014502592 [Note] InnoDB: Number of pools: 1
2018-01-07 19:52:12 140563014502592 [Note] InnoDB: Using SSE2 crc32 instructions 2018-01-07 19:52:12 140563014502592 [Note] InnoDB: Initializing buffer pool, total size = 54G, instances = 8, chunk size = 128M 2018-01-07 19:52:14 140563014502592 [Note] InnoDB: Completed initialization of buffer pool 2018-01-07 19:52:14 140500678067968 [Note] InnoDB: If the mysqld execution user is authorized, page cleaner thread priority can be changed. See the man page of setpriority(). 2018-01-07 19:52:14 140563014502592 [Note] InnoDB: Highest supported file format is Barracuda. 2018-01-07 20:20:49 140563014502592 [Note] InnoDB: 128 out of 128 rollback segments are active. 2018-01-07 20:20:49 140563014502592 [Note] InnoDB: Creating shared tablespace for temporary tables 2018-01-07 20:20:49 140563014502592 [Note] InnoDB: Setting file './ibtmp1' size to 12 MB. Physically writing the file full; Please wait ... 2018-01-07 20:20:49 140563014502592 [Note] InnoDB: File './ibtmp1' size is now 12 MB. 2018-01-07 20:20:49 140563014502592 [Note] InnoDB: Waiting for purge to start 2018-01-07 20:20:49 140563014502592 [Note] InnoDB: 5.7.20 started; log sequence number 1395535052281 2018-01-07 20:20:49 140502034765568 [Note] InnoDB: Loading buffer pool(s) from /var/lib/mysql/ib_buffer_pool
2018-01-07 20:20:49 140563014502592 [Note] Plugin 'FEEDBACK' is disabled.
2018-01-07 20:20:49 140563014502592 [Note] Server socket created on IP: '::'. 2018-01-07 20:20:49 140563014502592 [Note] Reading of all Master_info entries succeded 2018-01-07 20:20:49 140563014502592 [Note] Added new Master_info '' to hash table 2018-01-07 20:20:49 140563014502592 [Note] /usr/sbin/mysqld: ready for connections. Version: '10.2.11-MariaDB-10.2.11+maria~xenial-log' socket: '/var/lib/mysql/mysql.sock'  port: 3306  mariadb.org binary distribution


I guess I'm at a loss with regards to understanding the state of my current database slave.  It is not reporting that crash recovery is required, yet you seem to be suggesting that under the hood it is going through motions to perform a crash recovery?


Any recommendations for next steps?

Thanks,

Mike



On 2018-01-12 08:42 PM, Michael Caplan wrote:

Hi Marko,

Not sure how I missed your reply.  Sorry for the delayed response.

To give you a complete picture, this fresh install of MariaDB was populated with data copied from MySQL 5.6.  The data was copied via rsync (https://www.stephenrlang.com/2016/08/setting-up-mysql-master-slave-replication-with-rsync/), mysql_upgrade, and here we are.  Prior to the upgrade to 10.2, I did need to go through a crash recover back in Sept. 2017, but it seemed to recover just fine.  Here is a snippet from back then:

2017-09-17 09:23:59 16441 [Note] InnoDB: Database was not shutdown normally!
2017-09-17 09:23:59 16441 [Note] InnoDB: Starting crash recovery.
2017-09-17 09:23:59 16441 [Note] InnoDB: Reading tablespace information from the .ibd files... 2017-09-17 10:21:30 16441 [Note] InnoDB: Restoring possible half-written data pages
2017-09-17 10:21:30 16441 [Note] InnoDB: from the doublewrite buffer...
InnoDB: Doing recovery: scanned up to log sequence number 1183264246272
InnoDB: Doing recovery: scanned up to log sequence number 1183266067498
2017-09-17 10:21:32 16441 [Note] InnoDB: Starting an apply batch of log records to the database... InnoDB: Progress in percent: 0 1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42 43 44 45 46 47 48 49 50 51 52 53 54 55 56 57 58 59 60 61  62 63 64 65 66 67 68 69 70 71 72 73 74 75 76 77 78 79 80 81 82 83 84 85 86 87 88 89 90 91 92 93 94 95 96 97 98 99
InnoDB: Apply batch completed
InnoDB: Last MySQL binlog file position 0 133845121, file name mysql-bin.003599 2017-09-17 10:22:22 16441 [Note] InnoDB: 128 rollback segment(s) are active.
2017-09-17 10:22:22 16441 [Note] InnoDB: Waiting for purge to start
2017-09-17 10:22:23 16441 [Note] InnoDB:  Percona XtraDB (http://www.percona.com) 5.6.16-64.2 started; log sequence number 1183266067498 2017-09-17 10:22:23 16441 [Note] Recovering after a crash using /var/lib/mysql/mysql-bin
2017-09-17 10:22:24 16441 [Note] Starting crash recovery...
2017-09-17 10:22:24 16441 [Note] Crash recovery finished.


I've restarted a few times since then without any known issue seen in the log.


Fast forward to the migration to 10.2.  Following the rsync process, upon initial startup of MariaDB, it did report a crash recovery.  (see attached log).  The recovery seemed  to run just fine, and no issues reported in the log following mysql_upgrade. I've restarted numerous times since then, and the log file isn't reporting anything funky that my newb eyes can see.


For where I am right now, would the recommended resolution would be to restart once with --innodb-force-recovery=1  ?


Thanks again for for your thorough analysis and easy to understand explanation.

Best,

Mike



On 2018-01-10 05:15 PM, Marko Mäkelä wrote:
Hi Michael,

Thanks! In the stack trace, I see fsp_flags_try_adjust(), a function that I had to introduce to fix a file format compatibility problem that had been introduced in MariaDB 10.1.0: MDEV-11623 <https://jira.mariadb.org/browse/MDEV-11623>, commit ab1e6fefd <https://github.com/MariaDB/server/commit/ab1e6fefd869242d962cb91a006f37bb9ad534a7> in MariaDB 10.1.21, 10.2.4. The format compatibility problem mostly affects a non-default innodb_page_size.

However, the "root cause" for this slowdown is the validate=true in the following code in the function innobase_start_or_create_for_mysql():

            bool validate = recv_needed_recovery
                && srv_force_recovery == 0;

dict_check_tablespaces_and_store_max_id(validate);

Normally, we should have validate=false, because no crash recovery should be needed. If the server was not shut down cleanly, then there should be a startup message "Starting crash recovery", and recv_needed_recovery should hold. The variable srv_force_recovery is tied to the parameter innodb_force_recovery, which is 0 by default.

To me, this looks like it could be 'working as designed'. But, you did not share the server error log from the very start. Was there a crash recovery message? If not, then it is an interesting bug.

If you copied the data files from a file system snapshot from a running server, then it is very likely that crash recovery was needed. You could work around this by setting --innodb-force-recovery=1 when starting up. But beware that this will cause InnoDB to ignore certain errors. Maybe a better idea would be to invoke "mariabackup --prepare" and "mariabackup --copy-back" in order to apply the redo log before starting up the server on the copied files. And while you are at it, you could also use "mariabackup --backup" and skip the file system snapshot.

Best regards,

Marko

On Tue, Jan 9, 2018 at 4:32 PM, Michael Caplan <michael@xxxxxxxxxxx <mailto:michael@xxxxxxxxxxx>> wrote:

    Hi Marko,

    Thanks for your patience with me.  I think I have better material
    for you to look at now.

    Best,

    Mike



    On 2018-01-09 03:17 AM, Marko Mäkelä wrote:
    Michael,

    Sorry, I now realize that you must likely have used a stripped
    executable, and therefore the symbols for the InnoDB functions
    are missing (displayed as ?? in the stack trace output from
    gdb). As far as I understand, gdb should be able to resolve the
    symbols if you install the separate debug symbol package:

    sudo apt install mariadb-server-core-10.2-dbgsym

    I tried to find the installation package corresponding to
    '10.2.11-MariaDB-10.2.11+maria~xenial-log' so that I would be
    able to resolve the stack trace manually. As a developer,
    normally I work with code that I build myself from the source
    code, and therefore I am a bit bad at giving advice that applies
    to the packaged code.

    I downloaded and extracted the files from the following packages:
    mariadb-server-10.2-dbgsym_10.2.11+maria~xenial_amd64.deb
    <http://mirror.netinch.com/pub/mariadb//mariadb-10.2.11/repo/ubuntu/pool/main/m/mariadb-10.2/mariadb-server-10.2-dbgsym_10.2.11+maria%7Exenial_amd64.deb>
    mariadb-server-10.2_10.2.11+maria~xenial_amd64.deb
    <http://mirror.netinch.com/pub/mariadb//mariadb-10.2.11/repo/ubuntu/pool/main/m/mariadb-10.2/mariadb-server-10.2_10.2.11+maria%7Exenial_amd64.deb>
    mariadb-server-core-10.2-dbgsym_10.2.11+maria~xenial_amd64.deb
    <http://mirror.netinch.com/pub/mariadb//mariadb-10.2.11/repo/ubuntu/pool/main/m/mariadb-10.2/mariadb-server-core-10.2-dbgsym_10.2.11+maria%7Exenial_amd64.deb>
    mariadb-server-core-10.2_10.2.11+maria~xenial_amd64.deb
    <http://mirror.netinch.com/pub/mariadb//mariadb-10.2.11/repo/ubuntu/pool/main/m/mariadb-10.2/mariadb-server-core-10.2_10.2.11+maria%7Exenial_amd64.deb>

    The server executable /usr/sbin/mysqld is included in the
    mysql-server-core package. Unfortunately I was unable to match
    that executable with the addresses from your gdb output. I did
    the following:

    file mysqld
    mysqld: ELF 64-bit LSB shared object, x86-64, version 1
    (GNU/Linux), dynamically linked, interpreter
    /lib64/ld-linux-x86-64.so.2, for GNU/Linux 2.6.32,
    BuildID[sha1]=7649cc717c0ee820185a633fd27692f3b9160bed, stripped

    gdb mysqld
    symbol-file
    ../lib/debug/.build-id/76/49cc717c0ee820185a633fd27692f3b9160bed.debug

    followed by a number of gdb commands. I expected the least
    significant 12 bits of the addresses to match in the disassembly
    of ha_initialize_handlerton() and plugin_init(), but that was
    not the case. Maybe I did something wrong.

    So, can you please install the debug symbol package and try again?

    Best regards,

    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/




_______________________________________________
Mailing list: https://launchpad.net/~maria-discuss
Post to     : maria-discuss@xxxxxxxxxxxxxxxxxxx
Unsubscribe : https://launchpad.net/~maria-discuss
More help   : https://help.launchpad.net/ListHelp


Follow ups

References