Wednesday, October 31, 2012

Binlogs 101

The mysqlbinlog are not new. We often reference it and all of the valuable information that it provides. I thought it might be useful to show some simple examples on how to get some of that information, for those unfamiliar with the mysqlbinlog tool.

For this example, I used the MySQL benchmark tools to populate data.

You can review binary log events a couple if different ways.
You can use the command line :

      mysqlbinlog mysql56rc-bin.000010
or within MySQL via a simple query.
      SHOW BINLOG EVENTS IN 'mysql56rc-bin.000010' ;

These will both dump out all of the data, and this demo currently has 2284725 rows of data, to much to review one by one.

Keep in mind that some of the differences between these two options. You will gather more information via the command line mysqlbinlog versus just the query "SHOW BINLOG EVENTS".

example: If we wanted to get an idea of how long a query took to run?

# mysqlbinlog mysql56rc-bin.000010
....
# at 915
#121031  7:52:49 server id 1  end_log_pos 1029 CRC32 0xd3201bdc         Query   thread_id=47    exec_time=0     error_code=0
...
insert into bench1 values ('C',2,9997,6)
....

I could also be more direct and check the logs for just that bin log position: 
# mysqlbinlog mysql56rc-bin.000010 --start-position=915 --stop-position=1029


The mysqlbinlog will also allow you to gather an idea of the execution time a query took on a master server. It is not perfect when checking the same query on a slave. Baron has a blog about this if you want to learn more.

We are unable to see execution time via the "SHOW BINLOG EVENTS".

MySQL 5.6 RC> SHOW BINLOG EVENTS IN 'mysql56rc-bin.000010' FROM  915 LIMIT 1\G
*************************** 1. row ***************************
   Log_name: mysql56rc-bin.000010
        Pos: 915
 Event_type: Query
  Server_id: 1
End_log_pos: 1029
       Info: use `test`; insert into bench1 values ('C',2,9997,6)
1 row in set (0.00 sec)


The mysqlbinlog also allows you to be able to search within a date range.

# mysqlbinlog mysql56rc-bin.000010 --start-datetime="2012-10-31 07:52:49" --stop-datetime="2012-10-31 07:52:50"

# at 915
#121031  7:52:49 server id 1  end_log_pos 1029 CRC32 0xd3201bdc         Query   thread_id=47    exec_time=0     error_code=0
SET TIMESTAMP=1351695169/*!*/;
insert into bench1 values ('C',2,9997,6)
/*!*/;


This is just a simple small sample intro into MySQL Binlog. Find more information via these great blogs and sites.

http://dev.mysql.com/doc/refman/5.6/en/mysqlbinlog.html
http://www.pythian.com/news/1174/mysqlbinlog-tips-and-tricks/
http://ronaldbradford.com/blog/tag/mysqlbinlog/
http://dev.mysql.com/doc/refman/5.6/en/mysqlbinlog-backup.html
http://flylib.com/books/en/2.304.1.130/1/
http://www.databasejournal.com/features/mysql/article.php/3903646/Inside-MySQL-Binary-Logs.htm
http://www.mysqlperformanceblog.com/2011/01/31/what-is-exec_time-in-binary-logs/