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, commit ab1e6fefd 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@eggplant.ws> 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
mariadb-server-10.2_10.2.11+maria~xenial_amd64.deb
mariadb-server-core-10.2-dbgsym_10.2.11+maria~xenial_amd64.deb
mariadb-server-core-10.2_10.2.11+maria~xenial_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/