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

Pretty useful!

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 --start-datetime and --stop-datetime , both of which accept DATETIME or 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 mysqlbinlog.01, .02, .03 and so on, you can use mysqlbinlog.[0-9]* to match all of them.

When it comes to --start-position, --start-datetime, –-stop-position and --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”.

* For those of you unfamiliar with Unix tools, wc -l returns a count of lines from its input, a file or stream; head shows you only the top few lines of its input. back