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
_______________________________________________
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
