mysqlbinlog Tips and Tricks

Aug 18, 2008 / By Nicklas Westerlund

Tags:

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

8 Responses to “mysqlbinlog Tips and Tricks”

  • Nice. Good to know about MySQL analog of Oracle LogMiner.
    Thanks Nick!

  • Abhishek says:

    Realy its very helpful. Thanks Buddy

  • Nicklas Westerlund says:

    Thanks Alex and Abhishek — is there any other topic you’d like me to explain in further detail?

    Nick.

  • Partho Roy says:

    Hi Nick
    Your article is great
    When I run the Master MySql server in Linux and the Slave in Windows I have an issue of maintaing case sensitive of Table Column names. IS there a way out.
    Would appreciate a reply.
    Thanks

  • Shantanu Oak says:

    0 * * * * mysqlbinlog –read-from-remote-server -h 127.0.0.1 -uwesterlund -p -P 3306 mysql-bin.* –start-datetime=”`date +%Y-%m-%d’ ‘%H:00:00 -d\”1 hour ago\”`” –stop-datetime=”`date +%Y-%m-%d’ ‘%H:00:00`” | awk ‘/tbl_company/,/;/’ | replace tbl_company db.tbl_company | mysql -h 172.29.0.131 -uusrname -ppasswd mydb

    I have set a crontab that will check the bin-logs every hour for entries related to a particular table and update it on some other server. I use this method when I want to update only one table and don’t need replication.

    set global sql_slave_skip_counter = 1
    is the line I need to run if I want to skip one line on slave.

    And yes, Unix knowledge does help :)

  • Nicklas Westerlund says:

    @Partho:

    Thanks, I appreciate it.
    Not really, although I would recommend you to set lower_case_table_names=1 (on both machines, unless you have table1 and Table1). This will store all tables as lowercase, and will also convert it for you (So SELECT a,b FROM C; will be SELECT a,b FROM c;)

    However, you’d have to convert all your tables to lowercase on linux first.

    Another option might be to set it to 0 on linux and 2 on windows, but there’s some drawbacks to that as well.

    For a more descriptive walk through, please visit: http://dev.mysql.com/doc/refman/5.0/en/identifier-case-sensitivity.html
    which has use cases as well.

    @Shantanu:
    Yes, you are right that unix knowledge does help — unless you’re a windows DBA I guess. (But even then, having some unix knowledge would be beneficial). Thanks for commenting!

  • Hi Nick,

    I would like to know that whether mysqlbinlog –read-from-remote-server can be used to replicate data to a slave mysql server using script. If yes is it successfull. Although there will be a delay, depending on the cron executing the script.

    I have a situation, where i need to get data from different mysql server on server called report server. Actually, i am working on this.

    Please give your comments.

    Thanks,
    Krishna Chandra Prajapati

  • Nizar Yousri M. Azmi says:

    Well, that was so helpful, but i still have a question if you’d thankfully help me with… I am trying to read a binlog from a remote host everything works fine but during the read operation i get

    Got error reading packet from server: Lost connection to MySQL server during query
    DELIMITER ;
    # End of log file
    ROLLBACK /* added by mysqlbinlog */;
    /*!50003 SET COMPLETION_TYPE=@OLD_COMPLETION_TYPE*/;

    I am not quite familiar with what actually happened. Has the read operation been Rolled back. I mean has it been undone. If that’s the case how can i get rid of this error. What i think happened is the connection timed out during the read operation, also if that’s the case how can i configure it right to not time out during this operation.?!

    Any help would be appreciated. Thanks

Leave a Reply

  • (will not be published)

XHTML: You can use these tags: <a href="" title=""> <abbr title=""> <acronym title=""> <b> <blockquote cite=""> <cite> <code> <del datetime=""> <em> <i> <q cite=""> <strike> <strong>