On SHOW BINLOG/RELAYLOG EVENTS

Some notes after working with SHOW BINLOG EVENTS and SHOW RELAYLOG EVENTS statements; there are a few gotchas and some interesting facts. My reflections also follow.

I’m calling these commands from orchestrator when working with Pseudo-GTID (which I do alot). I prefer to work with agent-free design, where a single, remote service can do everything: examine replication status, scan binary logs for information, and recover broken topologies via gluing together servers that were not previously directly associated.

Alas, documentation is short on these commands, and some stuff I learned the hard way.

Basically, SHOW BINLOG/RELAYLOG EVENTS commands are a poor man’s replacement to mysqlbinlog, only you can issue them on MySQL protocol, and you do not have to have the binary/relay log files locally on your host.

Fun fact

The binary logs are called so because they are compressed. You are familiar with the binlog position you see on SHOW MASTER STATUS or SHOW SLAVE STATUS. You are familiar with the binlog position as you see it when you execute “mysqlbinlog mybinlog.001234”. The position of a new entry equals to the file size of the binary log at that time. If:

$ ls -l master/data/mysql-bin.015901
-rw-rw---- 1 user user 401408 Jul 18 02:44 master/data/mysql-bin.015901

Then the next entry will be at position 401408, as this is the file size in bytes.

And so when MySQL writes an entry to the binary log, it (of course) knows the entry’s position in the binary log, but then also immediately knows the position of the next entry.

We’ll revisit this fact later.

Output of SHOW BINLOG/RELAYLOG EVENTS

The output of both statement depends on the binlog_format. In Statement Based Replication it may look like:

$gt; SHOW BINLOG EVENTS IN 'mysql-bin.015903' LIMIT 40,20;
+------------------+------+------------+-----------+-------------+---------------------------------------------------------------------------------------------------------------------+
| Log_name         | Pos  | Event_type | Server_id | End_log_pos | Info                                                                                                                |
+------------------+------+------------+-----------+-------------+---------------------------------------------------------------------------------------------------------------------+
| mysql-bin.015903 | 3650 | Gtid       |         1 |        3698 | SET @@SESSION.GTID_NEXT= '230ea8ea-81e3-11e4-972a-e25ec4bd140a:790000'                                              |
| mysql-bin.015903 | 3698 | Query      |         1 |        3785 | BEGIN                                                                                                               |
| mysql-bin.015903 | 3785 | User var   |         1 |        3832 | @`id`=7                                                                                                             |
| mysql-bin.015903 | 3832 | Query      |         1 |        3969 | use `test`; replace into test.t (id, i, t) values (@id, @id, now())                                                 |
| mysql-bin.015903 | 3969 | Xid        |         1 |        4000 | COMMIT /* xid=967 */                                                                                                |
| mysql-bin.015903 | 4000 | Gtid       |         1 |        4048 | SET @@SESSION.GTID_NEXT= '230ea8ea-81e3-11e4-972a-e25ec4bd140a:790001'                                              |
| mysql-bin.015903 | 4048 | Query      |         1 |        4135 | BEGIN                                                                                                               |
| mysql-bin.015903 | 4135 | User var   |         1 |        4182 | @`id`=9                                                                                                             |
| mysql-bin.015903 | 4182 | Query      |         1 |        4319 | use `test`; replace into test.t (id, i, t) values (@id, @id, now())                                                 |
| mysql-bin.015903 | 4319 | Xid        |         1 |        4350 | COMMIT /* xid=969 */                                                                                                |
| mysql-bin.015903 | 4350 | Gtid       |         1 |        4398 | SET @@SESSION.GTID_NEXT= '230ea8ea-81e3-11e4-972a-e25ec4bd140a:790002'                                              |
| mysql-bin.015903 | 4398 | Query      |         1 |        4576 | use `meta`; drop view if exists `meta`.`_pseudo_gtid_hint__asc(55B50F9C:00000000000000D4:C96BF9F7)` |
| mysql-bin.015903 | 4576 | Gtid       |         1 |        4624 | SET @@SESSION.GTID_NEXT= '230ea8ea-81e3-11e4-972a-e25ec4bd140a:790003'                                              |
| mysql-bin.015903 | 4624 | Query      |         1 |        4711 | BEGIN                                                                                                               |
| mysql-bin.015903 | 4711 | User var   |         1 |        4758 | @`id`=6                                                                                                             |
| mysql-bin.015903 | 4758 | Query      |         1 |        4895 | use `test`; replace into test.t (id, i, t) values (@id, @id, now())                                                 |
| mysql-bin.015903 | 4895 | Xid        |         1 |        4926 | COMMIT /* xid=971 */                                                                                                |
| mysql-bin.015903 | 4926 | Gtid       |         1 |        4974 | SET @@SESSION.GTID_NEXT= '230ea8ea-81e3-11e4-972a-e25ec4bd140a:790004'                                              |
| mysql-bin.015903 | 4974 | Query      |         1 |        5077 | BEGIN                                                                                                               |
| mysql-bin.015903 | 5077 | User var   |         1 |        5133 | @`hostname`=_utf8 0x736E6F6163682D616D7339 COLLATE utf8_general_ci                                                  |
+------------------+------+------------+-----------+-------------+---------------------------------------------------------------------------------------------------------------------+

The first thing to note is that there’s far less data in this output as compared to mysqlbinlog‘s. For example, you can’t see the TIMESTAMP at which the queries were issued. You can’t see additional metadata like RAND() seed. Thus far it is documented.

You do know the binlog file name, position, end-position (which is the position of the next entry), originating server_id.

However with Row Based Replication things are even less informative:

$gt; SHOW BINLOG EVENTS IN 'mysql-bin.015902' LIMIT 20,20;
+------------------+------+-------------+-----------+-------------+------------------------------------------------------------------------+
| Log_name         | Pos  | Event_type  | Server_id | End_log_pos | Info                                                                   |
+------------------+------+-------------+-----------+-------------+------------------------------------------------------------------------+
| mysql-bin.015902 | 1365 | Query       |         1 |        1453 | BEGIN                                                                  |
| mysql-bin.015902 | 1453 | Table_map   |         1 |        1535 | table_id: 71 (meta.pseudo_gtid_status)                                 |
| mysql-bin.015902 | 1535 | Update_rows |         1 |        1829 | table_id: 71 flags: STMT_END_F                                         |
| mysql-bin.015902 | 1829 | Xid         |         1 |        1860 | COMMIT /* xid=26 */                                                    |
| mysql-bin.015902 | 1860 | Gtid        |         1 |        1908 | SET @@SESSION.GTID_NEXT= '230ea8ea-81e3-11e4-972a-e25ec4bd140a:789767' |
| mysql-bin.015902 | 1908 | Query       |         1 |        1988 | BEGIN                                                                  |
| mysql-bin.015902 | 1988 | Table_map   |         1 |        2035 | table_id: 70 (test.t)                                                  |
| mysql-bin.015902 | 2035 | Update_rows |         1 |        2129 | table_id: 70 flags: STMT_END_F                                         |
| mysql-bin.015902 | 2129 | Xid         |         1 |        2160 | COMMIT /* xid=29 */                                                    |
| mysql-bin.015902 | 2160 | Gtid        |         1 |        2208 | SET @@SESSION.GTID_NEXT= '230ea8ea-81e3-11e4-972a-e25ec4bd140a:789768' |
| mysql-bin.015902 | 2208 | Query       |         1 |        2288 | BEGIN                                                                  |
| mysql-bin.015902 | 2288 | Table_map   |         1 |        2335 | table_id: 70 (test.t)                                                  |
| mysql-bin.015902 | 2335 | Update_rows |         1 |        2429 | table_id: 70 flags: STMT_END_F                                         |
| mysql-bin.015902 | 2429 | Xid         |         1 |        2460 | COMMIT /* xid=32 */                                                    |
| mysql-bin.015902 | 2460 | Gtid        |         1 |        2508 | SET @@SESSION.GTID_NEXT= '230ea8ea-81e3-11e4-972a-e25ec4bd140a:789769' |
| mysql-bin.015902 | 2508 | Query       |         1 |        2588 | BEGIN                                                                  |
| mysql-bin.015902 | 2588 | Table_map   |         1 |        2635 | table_id: 70 (test.t)                                                  |
| mysql-bin.015902 | 2635 | Update_rows |         1 |        2729 | table_id: 70 flags: STMT_END_F                                         |
| mysql-bin.015902 | 2729 | Xid         |         1 |        2760 | COMMIT /* xid=34 */                                                    |
| mysql-bin.015902 | 2760 | Gtid        |         1 |        2808 | SET @@SESSION.GTID_NEXT= '230ea8ea-81e3-11e4-972a-e25ec4bd140a:789770' |
+------------------+------+-------------+-----------+-------------+------------------------------------------------------------------------+

What’s this? We don’t get the statement anymore. I mean, sure, this is RBR, but there’s no more info! All we knows is there was an Update_rows on test.t; that also only after we’ve crossed two different entries, one mapping a test.t to 70, the other telling us an UPDATE operation was made on 70.

This is the reason why Pseudo GTID injection is made via DDL.

With RBR we also get some excessive information. The table_id mentioned above is true for this server; but on a slave the table would have a different id. The SHOW output would look different. Likewise, the commit number as in “COMMIT /* xid=32 */” changes from server to server. There are also other entries which may look different; character encoding changes shape. Really weird stuff.

The output of SHOW RELAYLOG EVENTS is very similar, except for the following:

1. Obviously we’re parsing and outputting relay logs
2. Pos column relates to the position in the relay log where the entry starts (makes sense)
3. End_log_pos column relates to the next binlog position of the master’s binary log that correlates to this query. Read that again. There is no telling what the end-log-pos is for the relay log entry. We’ll revisit that shortly.

Locking issues

Unfortunately, issuing a SHOW BINLOG EVENTS completely locks down the binary logs on the server.

Yes. This means you cannot write to the binary logs while issuing the SHOW statement. And that means you cannot write, everything piles up and your server is under complete lock down.

Before you throw your hands up in the air and move on to read something that can cheer you up, note that things are not completely bad. We are able at Booking.com to scan 24 hours worth of binary logs (i.e. dozens of hundreds of binary logs) on business-critical MySQL masters without making an impact. How?

SHOW…LIMIT offset, row_count vs SHOW…FROM pos LIMIT row_count

Of course the solution is to do many small steps instead of few giant steps. Reading all of a binary log’s entries is suicidal to your application & database. The SHOW BINLOG/RELAYLOG EVENTS statements support a LIMIT clause.

As per previous example, you may:

SHOW BINLOG EVENTS IN 'mysql-bin.015903' LIMIT 40,20;

This skips 40 entries (offset), then reads 20 (row_count).

However much like non-indexed table scan, to skip the first 40 entries you must nonetheless iterate them. Since we don’t know exactly where in the binlog the 41st entry begins, we need to unpack the binary log from start and find it out the full-scan way.

Don’t iterate a binary log’s entries via LIMIT 0,1000; LIMIT 1000,1000; LIMIT 2000,1000; … This is O(n²)

In contrast, you may:

SHOW BINLOG EVENTS IN 'mysql-bin.015903' FROM 3650 LIMIT 20;

Remember that an entry’s position is the binlog file size at the time before the entry was written? To execute the above MySQL merely seeks the binlog file 3650 bytes ahead. No scan required.

You must provide with a valid position value. If I just guess my way:

> SHOW BINLOG EVENTS IN 'mysql-bin.015903' FROM 3651 LIMIT 20;
ERROR 1220 (HY000): Error when executing command SHOW BINLOG EVENTS: Wrong offset or I/O error

And so you must have prior knowledge about positions. This is fine if you’re scanning a binary log: you simply read the End_log_pos of the last entry you’ve just read and memorize it. Thus, to scan a binary log, you can:

> SHOW BINLOG EVENTS IN 'mysql-bin.015903' LIMIT 20;

> SHOW BINLOG EVENTS IN 'mysql-bin.015903' FROM 1499 LIMIT 20;

> SHOW BINLOG EVENTS IN 'mysql-bin.015903' FROM 3651 LIMIT 20;

But it’s more difficult to do this for relay logs: remember that the End_log_pos in SHOW RELAYLOG EVENTS relates to the next position in the master’s binary log. So you need to resort to an off-by-one or something. However the good news is that reading relay logs does not block writes on your server.

Locking thoughts

As per my comments in the bug report, I don’t see why SHOW BINLOG EVENTS should always lock writes:

• If we’re scanning an old binary log (not the one being written to) then obviously we should not be blocking writes.
• If we’re scanning the current binlog, but are known to end with a statement that is already written (i.e. not trying to scan past the current writing position) then we should not be blocking writes.
• OK to block writes when trying to read past current position.
• OK to block on a FLUSH MASTER LOGS, PURGE MASTER LOGS

Why is the output so limited?

I’m actually unsure why the output of these commands is so limited as compared to the mysqlbinlog output. A replicating slave talks to the master over MySQL protocol; the slave does get all the data right. It does get event metadata (timestamp, random seed, session variable). It does get complete statement/row data. What I’m saying is that this functionality is already built in; it could be very easily added to the SHOW commands.