mysqlbinlog Tips and Tricks
So, you have a binlog. You want to find out something specific that happened inside of it. What to do?
mysqlbinlog has some neat features, which I thought we would look at here.
I should first explain what
mysqlbinlog really is. It is a tool that lets you analyze and view the binlogs/relaylogs from mysql, which are stored in binary format. This tool converts them to plaintext, so that they’re human-readable.
For the first tip, let’s start with the
--read-from-remote-server option, which allows you to examine a binlog on a master server in order, perhaps, to dump it onto your slave and compare master/slave logs for potential problems*.
$ mysqlbinlog --read-from-remote-server -uwesterlund -p mysql-bin.000001 -h 127.0.0.1 -P 3306 | head -5 Enter password: /*!40019 SET @@session.max_insert_delayed_threads=0*/; /*!50003 SET @OLD_COMPLETION_TYPE=@@COMPLETION_TYPE,COMPLETION_TYPE=0*/; DELIMITER /*!*/; # at 4 #080815 19:25:23 server id 101 end_log_pos 107 Start: binlog v 4, server v 6.0.5-alpha-log created 080815 19:25:23 at startup
Now, let’s assume we have a binlog that is 94 lines long*:
$ mysqlbinlog --read-from-remote-server -uwesterlund -p mysql-bin.000001 -h 127.0.0.1 -P 3306 | wc -l Enter password: 94
If we know that we have correctly replicated all data until position 932, we can make less output for our plaintext file*:
$ mysqlbinlog --read-from-remote-server -uwesterlund -p mysql-bin.000001 -h 127.0.0.1 -P 3306 --start-position=932 | wc -l Enter password: 57
And even better if we know between which two locations we need to look, but one problem is that we need to know both the start position and stop position, we can’t just insert a random value.
First looking at the binlog and show what it would look like:
# at 1132 #080815 19:25:25 server id 101 end_log_pos 1217 Query thread_id=1 exec_time=8 error_code=0 SET TIMESTAMP=1218821125/*!*/; flush privileges /*!*/; # at 1217 #080815 19:34:41 server id 101 end_log_pos 1307 Query thread_id=8 exec_time=1 error_code=0 SET TIMESTAMP=1218821681/*!*/; create database blogs
then trying to start at position 1200: (just like inserting a random value instead of an actual position):
$ mysqlbinlog mysql-bin.000001 --start-position=1200 /*!40019 SET @@session.max_insert_delayed_threads=0*/; /*!50003 SET @OLD_COMPLETION_TYPE=@@COMPLETION_TYPE,COMPLETION_TYPE=0*/; DELIMITER /*!*/; # at 4 #080815 19:25:30 server id 102 end_log_pos 107 Start: binlog v 4, server v 6.0.5-alpha-log created 080815 19:25:30 at startup # Warning: this binlog was not closed properly. Most probably mysqld crashed writing it. ROLLBACK/*!*/; BINLOG ' CrylSA9mAAAAZwAAAGsAAAABAAQANi4wLjUtYWxwaGEtbG9nAAAAAAAAAAAAAAAAAAAAAAAAAAAA AAAAAAAAAAAAAAAAAAAKvKVIEzgNAAgAEgAEBAQEEgAAVAAEGggAAAAICAgCAA== '/*!*/; ERROR: Error in Log_event::read_log_event(): 'Event too big', data_len: 1818850921, event_type: 115 DELIMITER ; # End of log file ROLLBACK /* added by mysqlbinlog */; /*!50003 SET COMPLETION_TYPE=@OLD_COMPLETION_TYPE*/;
So the error we see here is:
ERROR: Error in Log_event::read_log_event(): 'Event too big', data_len: 1818850921, event_type: 115
We can pinpoint specific locations this way*:
$ mysqlbinlog --read-from-remote-server -uwesterlund -p mysql-bin.000001 -h 127.0.0.1 -P 3306 --start-position=932 --stop-position=1132 | wc -l Enter password: 32
But what if your developer says, “I ran a statement at exactly 19:34:55 and I can’t remember what the statement was, can you help me find out?” Sure, you can look at which binlog contains that one, and dump the whole thing, then search for 19:34:55 (granted, the clocks have to be synchronized, it won’t be pretty if the developer’s clock is three minutes off). But, there’s also another way:
$ mysqlbinlog --read-from-remote-server -uwesterlund -p mysql-bin.[0-9]* -h 127.0.0.1 -P 3306 --start-datetime="2008-08-15 19:34:55" --stop-datetime="2008-08-15 19:34:56" Enter password: #080815 19:34:55 server id 101 end_log_pos 1426 Query thread_id=8 exec_time=0 error_code=0 use blogs/*!*/; SET TIMESTAMP=1218821695/*!*/; SET @@session.pseudo_thread_id=8/*!*/; SET @@session.foreign_key_checks=1, @@session.sql_auto_is_null=1, @@session.unique_checks=1/*!*/; SET @@session.sql_mode=0/*!*/; SET @@session.auto_increment_increment=2, @@session.auto_increment_offset=1/*!*/; /*!\C latin1 *//*!*/; SET @@session.character_set_client=8,@@session.collation_connection=8,@@session.collation_server=8/*!*/; SET @@session.lc_time_names=0/*!*/; SET @@session.collation_database=DEFAULT/*!*/; create table t1 (a int auto_increment primary key) /*!*/; # at 1426 #080815 19:34:55 server id 101 end_log_pos 1454 Intvar SET INSERT_ID=1/*!*/; # at 1454 #080815 19:34:55 server id 101 end_log_pos 1567 Query thread_id=8 exec_time=0 error_code=0 SET TIMESTAMP=1218821695/*!*/; insert into t1 values (NULL), (NULL), (NULL) /*!*/; DELIMITER ; # End of log file ROLLBACK /* added by mysqlbinlog */; /*!50003 SET COMPLETION_TYPE=@OLD_COMPLETION_TYPE*/;
So this introduced us to
--stop-datetime , both of which accept
TIMESTAMP entries, and which together set the start/stop of what kind of information we’re interested in.
Also, if you have a problem on your master, but your slaves are fine, and you need to restore the master, you can use
--skip-write-binlog to avoid the point-in-time recovery to replicate to the slaves, which would cause more problems.
Another point that I touched on above is the option to use certain regexps, i.e., instead of listing
.03 and so on, you can use
mysqlbinlog.[0-9]* to match all of them.
When it comes to
--stop-datetime, they can be used together. So if you know that at
10:00:01 someone dropped your main database, and your last backup has a start position of
1454, you can do this . . .
mysqlbinlog binlog.02 --start-position=1454 --stop-datetime="2008-08-15 10:00:00"
. . . to recover from that point to a second before your crash. (Unless you used the earlier method to find out the exact position of the drop, in which case: recover to it, then skip one entry on your slave, and continue from there.)
Now for the last of these gems. What do you do when you have 500mb of binlog that check for corruption? Do you dump it to a plaintext and read through it looking for errors? No. What you want to do is run
mysqlbinlog binlog.000003 binlog.000004 > /dev/null. That will return an error if there’s any problem with the binlog, for example, “Event too big”.