Obtaining binlog coordinates after crash recovery

Hey all - in MySQL < 8.0, following crash recovery, the binlog coordinates to which InnoDB recovered were displayed in the .err log. For example:

2018-05-24 14:05:31 16098 [Note] Plugin 'FEDERATED' is disabled.
2018-05-24 14:05:31 16098 [Note] InnoDB: Using atomics to ref count buffer pool pages
2018-05-24 14:05:31 16098 [Note] InnoDB: The InnoDB memory heap is disabled
2018-05-24 14:05:31 16098 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
2018-05-24 14:05:31 16098 [Note] InnoDB: Memory barrier is not used
2018-05-24 14:05:31 16098 [Note] InnoDB: Compressed tables use zlib 1.2.3
2018-05-24 14:05:31 16098 [Note] InnoDB: Using Linux native AIO
2018-05-24 14:05:31 16098 [Note] InnoDB: Using CPU crc32 instructions
2018-05-24 14:05:31 16098 [Note] InnoDB: Initializing buffer pool, size = 1.0G
2018-05-24 14:05:31 16098 [Note] InnoDB: Completed initialization of buffer pool
2018-05-24 14:05:31 16098 [Note] InnoDB: Highest supported file format is Barracuda.
2018-05-24 14:05:31 16098 [Note] InnoDB: The log sequence numbers 2812209 and 2812209 in ibdata files do not match the log sequence number 48593147 in the ib_logfiles!
2018-05-24 14:05:31 16098 [Note] InnoDB: Database was not shutdown normally!
2018-05-24 14:05:31 16098 [Note] InnoDB: Starting crash recovery.
2018-05-24 14:05:31 16098 [Note] InnoDB: Reading tablespace information from the .ibd files...
2018-05-24 14:05:31 16098 [Note] InnoDB: Restoring possible half-written data pages
2018-05-24 14:05:31 16098 [Note] InnoDB: from the doublewrite buffer...
InnoDB: Last MySQL binlog file position 0 23195778, file name mysql-bin.000005 <--- ** THIS LINE **
2018-05-24 14:05:31 16098 [Note] InnoDB: 128 rollback segment(s) are active.
2018-05-24 14:05:31 16098 [Note] InnoDB: Waiting for purge to start
2018-05-24 14:05:31 16098 [Note] InnoDB: 5.6.32 started; log sequence number 48593147

Note the line labeled “THIS LINE”. In MySQL 8.0, we no longer see this information:

2021-02-02T19:48:51.378475Z 0 [System] [MY-010116] [Server] /sso/sfw/mysql/bin/mysqld (mysqld 8.0.23) starting as process 23900
2021-02-02T19:48:51.448273Z 1 [System] [MY-013576] [InnoDB] InnoDB initialization has started.
2021-02-02T19:48:53.616044Z 1 [System] [MY-013577] [InnoDB] InnoDB initialization has ended.
2021-02-02T19:48:54.529151Z 0 [System] [MY-011323] [Server] X Plugin ready for connections. Bind-address: '::' port: 33060, socket: /tmp/mysqlx.sock
2021-02-02T19:48:54.571252Z 0 [System] [MY-010229] [Server] Starting XA crash recovery...
2021-02-02T19:48:54.579919Z 0 [System] [MY-010232] [Server] XA crash recovery finished.
2021-02-02T19:48:54.667175Z 0 [Warning] [MY-010068] [Server] CA certificate ca.pem is self signed.
2021-02-02T19:48:54.667460Z 0 [System] [MY-013602] [Server] Channel mysql_main configured to support TLS. Encrypted connections are now supported for this channel.
2021-02-02T19:48:54.711383Z 0 [System] [MY-010931] [Server] /sso/sfw/mysql/bin/mysqld: ready for connections. Version: '8.0.23' socket: '/tmp/mysql.sock' port: 3306 MySQL Community Server - GPL.

In 8.0, how can I determine the binlog coordinates following crash recovery? Without it, there is no way to perform additional PIT recovery using binlogs (i.e., I don’t know at what coordinates to start applying binlogs).

Thanks
Rob

1 Like

Since you are running Community Edition, I suggest you open a bug/feature at https://bugs.mysql.com/

Did your 8.0 actually crash? Did you simulate a crash using kill -9 ? The log file you show for 8.0 is not the same crash situation as your 5.6 logs show.

1 Like

Thanks. Opened a bug/feature.

In both cases, InnoDB DML is running against a database. A filesystem snapshot of the data directory is taken while the database is running (in effect, the snapshot is crash consistent). Then MySQL is stopped and the snapshot is restored and MySQL restarted. This is how we have been backing up MySQL < 8.0. It works well and we’ve been able to perform PIT recovery using the binlog coordinates in the .err log.

1 Like

With the massive amount of improvements between 5.6 and 8.0, it is quite possible that your snapshots in 8.0 are safe/consistent in such a way that innodb does not need to perform a crash recovery and thus the information is not being displayed. If you have the ability, I would test your 8.0 as such: put some load on it, sysbench for example, or execute a big UPDATE (several hundred thousand rows) and while the update is happening, kill -9. That will certainly cause a crash recovery process. Then you can determine if the info is there or not for certainty.

1 Like

That’s possible. Unfortunately, it doesn’t help my usecase. If all my data is in InnoDB, and my InnoDB datafiles and logfiles are all on the same filesystem, then I should be able to snapshot the filesystem and use that for recovery (i.e., no need for flush tables with read lock). In order to use that snapshot for recovery and perform PIT recovery to a time after the snapshot was taken, I need to know the coordinates at the moment the snapshot was completed.

There has to be a way to surface that info. MySQL Enterprise Backup does. Percona XtraBackup does. I’ll grab the XtraBackup source code and see if I can figure it out.

1 Like

@rowagn, PXB uses FTWRL and/or LOCK BINLOG FOR BACKUP to acquire the binlog position at the time of the backup:

https://www.percona.com/doc/percona-server/5.7/management/backup_locks.html
https://www.percona.com/doc/percona-server/8.0/management/backup_locks.html

2 Likes

Thanks. I got excited when I saw LOCK BINLOG FOR BACKUP (thinking I could run that, note the coordinates, take the snap, and release the lock) but it disappeared in 8.0.

mysql> select version();
±----------+
| version() |
±----------+
| 8.0.22-13 |
±----------+
1 row in set (0.00 sec)

mysql> lock binlog for backup;
ERROR 1064 (42000): You have an error in your SQL syntax; check the manual that corresponds to your MySQL server version for the right syntax to use near ‘binlog for backup’ at line 1

There has to be a way to do this.

Do you know of any plans to make XtraBackup work with snapshots? That would be killer. Instead of copying nTB of data, just note the coordinates and snapshot the filesystem.

1 Like

My apologies, LBFB is a Percona-specific feature. If LBFB is not available, then XB simply does a FTWRL to acquire the binlog position.

For snapshot backups, this is how it’s always been, for the past 10+ years: lock tables, note position, take snapshot, release lock. Nothing has changed except better ways to do the locking. Percona introduced LBFB many years ago to handle consistent backups between engines.

Percona is an enhanced drop-in replacement for Community. Is there some reason you can’t swap and gain this functionality? Unlike MariaDB, Percona is not a fork of MySQL; we are a downstream rebase.

1 Like

Yes, this IS with Percona Server (not Oracle’s):

[root@ip-10-239-209-134 ~]# /sso/sfw/mysql/bin/mysql -uroot -pxxx
mysql: [Warning] Using a password on the command line interface can be insecure.
Welcome to the MySQL monitor. Commands end with ; or \g.
Your MySQL connection id is 3554
Server version: 8.0.22-13 Percona Server (GPL), Release 13, Revision 6f7822f

Copyright © 2009-2020 Percona LLC and/or its affiliates
Copyright © 2000, 2020, Oracle and/or its affiliates. All rights reserved.

Oracle is a registered trademark of Oracle Corporation and/or its
affiliates. Other names may be trademarks of their respective
owners.

Type ‘help;’ or ‘\h’ for help. Type ‘\c’ to clear the current input statement.

mysql> lock binlog for backup;
ERROR 1064 (42000): You have an error in your SQL syntax; check the manual that corresponds to your MySQL server version for the right syntax to use near ‘binlog for backup’ at line 1

1 Like

Ah, but this comment at Backup Locks is very interesting:

Thus, under active LOCK TABLES FOR BACKUP , the binary log coordinates in InnoDB are consistent with its redo log and any non-transactional updates (as the latter are blocked by LOCK TABLES FOR BACKUP ).

So if I am reading that correctly, I believe if I execute LOCK TABLES FOR BACKUP, then the binary log should reflect the state of InnoDB when I take the snapshot. And, if I restore the snapshot, I should be able to just tail the last binlog (as it exists on the snapshot) and get the coordinates that correspond with InnoDB (i.e., the largest coordinates in the binlog should indicate where I need to start any subsequent binlog apply to complete a PITR to a time after the snapshot was taken).

I’m going to test this, but it sounds like exactly what I need.

1 Like

Apologies, you above log showed MySQL Community in the tag. Let me know if the LTFB works for you.

1 Like

My idea seems to work. I ran ten concurrent transactions and took a snap while they were running. Then I stopped mysqld, copied off the binlogs, restored the snap, started mysqld. Then I used mysqlbinlog to dump the n-1th binlog to last.sql (use n-1 because MySQL advances the binlog when it restarts). last.sql now contains the coordinates of the last transaction committed to InnoDB. To perform further PITR, I ran mysqlbinlog against the the binlogs I copied off before restoring the snap with --start-position=coordinate of the last committed TX.

2 Likes

Excellent! Glad you got it sorted out.

1 Like