maria-discuss team mailing list archive

[Michael Caplan <michael@xxxxxxxxxxx>]

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/

2018-01-08  5:39:45 140390495905984 [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-08  5:39:45 140390495905984 [ERROR] mysqld: File '/var/lib/mysql/mysql.key' not found (Errcode: 2 "No such file or directory")
2018-01-08  5:39:45 140390495905984 [ERROR] Plugin 'file_key_management' init function returned error.
2018-01-08  5:39:45 140390495905984 [ERROR] Plugin 'file_key_management' registration as a ENCRYPTION failed.
2018-01-08  5:39:45 140390495905984 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
2018-01-08  5:39:45 140390495905984 [Note] InnoDB: Uses event mutexes
2018-01-08  5:39:45 140390495905984 [Note] InnoDB: Compressed tables use zlib 1.2.8
2018-01-08  5:39:45 140390495905984 [Note] InnoDB: Using Linux native AIO
2018-01-08  5:39:45 140390495905984 [Note] InnoDB: Number of pools: 1
2018-01-08  5:39:45 140390495905984 [Note] InnoDB: Using SSE2 crc32 instructions
2018-01-08  5:39:45 140390495905984 [Note] InnoDB: Initializing buffer pool, total size = 54G, instances = 8, chunk size = 128M
2018-01-08  5:39:49 140390495905984 [Note] InnoDB: Completed initialization of buffer pool
2018-01-08  5:39:49 140328162707200 [Note] InnoDB: If the mysqld execution user is authorized, page cleaner thread priority can be changed. See the man page of setpriority().
2018-01-08  5:39:49 140390495905984 [Note] InnoDB: Highest supported file format is Barracuda.
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.
2018-01-08  6:01:49 140390495905984 [Note] InnoDB: Creating sys_virtual system tables.
2018-01-08  6:01:49 140390495905984 [Note] InnoDB: Creating shared tablespace for temporary tables
2018-01-08  6:01:49 140390495905984 [Note] InnoDB: Setting file './ibtmp1' size to 12 MB. Physically writing the file full; Please wait ...
2018-01-08  6:01:49 140390495905984 [Note] InnoDB: File './ibtmp1' size is now 12 MB.
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
2018-01-08  6:01:49 140329441281792 [Note] InnoDB: Loading buffer pool(s) from /var/lib/mysql/ib_buffer_pool
2018-01-08  6:01:49 140329441281792 [Note] InnoDB: Cannot open '/var/lib/mysql/ib_buffer_pool' for reading: No such file or directory
2018-01-08  6:01:49 140390495905984 [Note] Plugin 'FEEDBACK' is disabled.
2018-01-08  6:01:49 140390495905984 [Note] Recovering after a crash using /var/lib/mysql/mysql-bin
2018-01-08  6:01:50 140390495905984 [Note] Starting crash recovery...
2018-01-08  6:01:50 140390495905984 [Note] Crash recovery finished.
2018-01-08  6:01:50 140390495176448 [Warning] Failed to load slave replication state from table mysql.gtid_slave_pos: 1146: Table 'mysql.gtid_slave_pos' doesn't exist
2018-01-08  6:01:50 140390495905984 [Note] Server socket created on IP: '::'.
2018-01-08  6:01:50 140390495905984 [Warning] 'user' entry 'root@usaddxprdsqlpm1' ignored in --skip-name-resolve mode.
2018-01-08  6:01:50 140390495905984 [Warning] 'proxies_priv' entry '@% root@usaddxprdsqlpm1' ignored in --skip-name-resolve mode.
2018-01-08  6:01:50 140390495905984 [ERROR] Missing system table mysql.roles_mapping; please run mysql_upgrade to create it
2018-01-08  6:01:50 140390495905984 [ERROR] Incorrect definition of table mysql.event: expected column 'sql_mode' at position 14 to have type set('REAL_AS_FLOAT','PIPES_AS_CONCAT','ANSI_QUOTES','IGNORE_SPACE','IGNORE_BAD_TABLE_OPTIONS','ONLY_FULL_GROUP_BY','NO_UNSIGNED_SUBTRACTION','NO_DIR_IN_CREATE','POSTGRESQL','ORACLE','MSSQL','DB2','MAXDB','NO_KEY_OPTIONS','NO_TABLE_OPTIONS','NO_FIELD_OPTIONS','MYSQL323','MYSQL40','ANSI','NO_AUTO_VALUE_ON_ZERO','NO_BACKSLASH_ESCAPES','STRICT_TRANS_TABLES','STRICT_ALL_TABLES','NO_ZERO_IN_DATE','NO_ZERO_DATE','INVALID_DATES','ERROR_FOR_DIVISION_BY_ZERO','TRADITIONAL','NO_AUTO_CREATE_USER','HIGH_NOT_PRECEDENCE','NO_ENGINE_SUBSTITUTION','PAD_CHAR_TO_FULL_LENGTH'), found type set('REAL_AS_FLOAT','PIPES_AS_CONCAT','ANSI_QUOTES','IGNORE_SPACE','NOT_USED','ONLY_FULL_GROUP_BY','NO_UNSIGNED_SUBTRACTION','NO_DIR_IN_CREATE','POSTGRESQL','ORACLE','MSSQL','DB2','MAXDB','NO_KEY_OPTIONS','NO_TABLE_OPTIONS','NO_FIELD_OPTIONS','MYSQL323','MYSQL40','ANSI','NO_AUTO_VALUE_ON_ZERO','NO_BACKSLASH_ESCAPES','STRICT_TRANS_TABLES','STRICT_A
2018-01-08  6:01:50 140390495905984 [ERROR] mysqld: Event Scheduler: An error occurred when initializing system tables. Disabling the Event Scheduler.
2018-01-08  6:01:50 140390404646656 [Warning] Failed to load slave replication state from table mysql.gtid_slave_pos: 1146: Table 'mysql.gtid_slave_pos' doesn't exist
2018-01-08  6:01:50 140390495905984 [Note] Reading of all Master_info entries succeded
2018-01-08  6:01:50 140390495905984 [Note] Added new Master_info '' to hash table
2018-01-08  6:01:50 140390495905984 [Note] /usr/sbin/mysqld: ready for connections.
Version: '10.2.12-MariaDB-10.2.12+maria~xenial-log'  socket: '/var/lib/mysql/mysql.sock'  port: 3306  mariadb.org binary distribution
2018-01-08  7:23:15 140390404343552 [Warning] 'user' entry 'root@usaddxprdsqlpm1' ignored in --skip-name-resolve mode.
2018-01-08  7:23:15 140390404343552 [Warning] 'proxies_priv' entry '@% root@usaddxprdsqlpm1' ignored in --skip-name-resolve mode.
2018-01-08  7:55:54 140390404343552 [Warning] Access denied for user 'root'@'::1' (using password: YES)
2018-01-08  8:01:12 140390404343552 [Note] Master connection name: ''  Master_info_file: 'master.info'  Relay_info_file: 'relay-log.info'
2018-01-08  8:01:12 140390404343552 [Note] 'CHANGE MASTER TO executed'. Previous state master_host='', master_port='3306', master_log_file='', master_log_pos='4'. New state master_host='10.60.205.161', master_port='3306', master_log_file='mysql-bin.003924', master_log_pos='149450826'.
2018-01-08  8:02:13 140390404040448 [Note] Slave I/O thread: connected to master 'replication@10.60.205.161:3306',replication started in log 'mysql-bin.003924' at position 149450826
2018-01-08  8:02:13 140390403737344 [Note] Slave SQL thread initialized, starting replication in log 'mysql-bin.003924' at position 149450826, relay log '/var/lib/mysql/relay-bin.000001' position: 4
2018-01-08  8:03:37 140390403737344 [Warning] 'user' entry 'root@usaddxprdsqlpm1' ignored in --skip-name-resolve mode.
2018-01-08  8:03:37 140390403737344 [Warning] 'proxies_priv' entry '@% root@usaddxprdsqlpm1' ignored in --skip-name-resolve mode.
2018-01-08  8:22:07 140390404343552 [Note] /usr/sbin/mysqld (unknown): Normal shutdown
2018-01-08  8:22:07 140390404343552 [Note] Event Scheduler: Purging the queue. 0 events
2018-01-08  8:22:07 140390403737344 [Note] Error reading relay log event: slave SQL thread was killed
2018-01-08  8:22:07 140390403737344 [Note] Slave SQL thread exiting, replication stopped in log 'mysql-bin.003924' at position 317481649
2018-01-08  8:22:07 140329552975616 [Note] InnoDB: FTS optimize thread exiting.
2018-01-08  8:22:07 140390404040448 [Note] Slave I/O thread exiting, read up to log 'mysql-bin.003924', position 317481649
2018-01-08  8:22:08 140390404343552 [Note] InnoDB: Starting shutdown...
2018-01-08  8:22:08 140329441281792 [Note] InnoDB: Dumping buffer pool(s) to /var/lib/mysql/ib_buffer_pool
2018-01-08  8:22:08 140329441281792 [Note] InnoDB: Instance 0, restricted to 110592 pages due to innodb_buf_pool_dump_pct=25
2018-01-08  8:22:08 140329441281792 [Note] InnoDB: Instance 1, restricted to 110592 pages due to innodb_buf_pool_dump_pct=25
2018-01-08  8:22:08 140329441281792 [Note] InnoDB: Instance 2, restricted to 110592 pages due to innodb_buf_pool_dump_pct=25
2018-01-08  8:22:08 140329441281792 [Note] InnoDB: Instance 3, restricted to 110592 pages due to innodb_buf_pool_dump_pct=25
2018-01-08  8:22:08 140329441281792 [Note] InnoDB: Instance 4, restricted to 110592 pages due to innodb_buf_pool_dump_pct=25
2018-01-08  8:22:08 140329441281792 [Note] InnoDB: Instance 5, restricted to 110592 pages due to innodb_buf_pool_dump_pct=25
2018-01-08  8:22:09 140329441281792 [Note] InnoDB: Instance 6, restricted to 110592 pages due to innodb_buf_pool_dump_pct=25
2018-01-08  8:22:09 140329441281792 [Note] InnoDB: Instance 7, restricted to 110592 pages due to innodb_buf_pool_dump_pct=25
2018-01-08  8:22:09 140329441281792 [Note] InnoDB: Buffer pool(s) dump completed at 180108  8:22:09
2018-01-08  8:22:46 140390404343552 [Note] InnoDB: Shutdown completed; log sequence number 1395793946459
2018-01-08  8:22:46 140390404343552 [Note] InnoDB: Removed temporary tablespace data file: "ibtmp1"
2018-01-08  8:22:46 140390404343552 [Note] /usr/sbin/mysqld: Shutdown complete

2018-01-08  8:23:01 140364886096064 [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-08  8:23:01 140364886096064 [ERROR] mysqld: File '/var/lib/mysql/mysql.key' not found (Errcode: 2 "No such file or directory")
2018-01-08  8:23:01 140364886096064 [ERROR] Plugin 'file_key_management' init function returned error.
2018-01-08  8:23:01 140364886096064 [ERROR] Plugin 'file_key_management' registration as a ENCRYPTION failed.
2018-01-08  8:23:01 140364886096064 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
2018-01-08  8:23:01 140364886096064 [Note] InnoDB: Uses event mutexes
2018-01-08  8:23:01 140364886096064 [Note] InnoDB: Compressed tables use zlib 1.2.8
2018-01-08  8:23:01 140364886096064 [Note] InnoDB: Using Linux native AIO
2018-01-08  8:23:01 140364886096064 [Note] InnoDB: Number of pools: 1
2018-01-08  8:23:01 140364886096064 [Note] InnoDB: Using SSE2 crc32 instructions
2018-01-08  8:23:01 140364886096064 [Note] InnoDB: Initializing buffer pool, total size = 54G, instances = 8, chunk size = 128M
2018-01-08  8:23:03 140364886096064 [Note] InnoDB: Completed initialization of buffer pool
2018-01-08  8:23:03 140302555825920 [Note] InnoDB: If the mysqld execution user is authorized, page cleaner thread priority can be changed. See the man page of setpriority().
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.
2018-01-08  8:45:14 140364886096064 [Note] InnoDB: Creating shared tablespace for temporary tables
2018-01-08  8:45:14 140364886096064 [Note] InnoDB: Setting file './ibtmp1' size to 12 MB. Physically writing the file full; Please wait ...
2018-01-08  8:45:14 140364886096064 [Note] InnoDB: File './ibtmp1' size is now 12 MB.
2018-01-08  8:45:14 140364886096064 [Note] InnoDB: Waiting for purge to start
2018-01-08  8:45:14 140364886096064 [Note] InnoDB: 5.7.20 started; log sequence number 1395793946459
2018-01-08  8:45:14 140303562438400 [Note] InnoDB: Loading buffer pool(s) from /var/lib/mysql/ib_buffer_pool
2018-01-08  8:45:14 140364886096064 [Note] Plugin 'FEEDBACK' is disabled.
2018-01-08  8:45:14 140364886096064 [Note] Server socket created on IP: '::'.
2018-01-08  8:45:14 140364886096064 [Warning] 'user' entry 'root@usaddxprdsqlpm1' ignored in --skip-name-resolve mode.
2018-01-08  8:45:14 140364886096064 [Warning] 'proxies_priv' entry '@% root@usaddxprdsqlpm1' ignored in --skip-name-resolve mode.
2018-01-08  8:45:14 140364886096064 [Note] Reading of all Master_info entries succeded
2018-01-08  8:45:14 140364886096064 [Note] Added new Master_info '' to hash table
2018-01-08  8:45:14 140364886096064 [Note] /usr/sbin/mysqld: ready for connections.
Version: '10.2.12-MariaDB-10.2.12+maria~xenial-log'  socket: '/var/lib/mysql/mysql.sock'  port: 3306  mariadb.org binary distribution