One of the more useful tools available to an administrator is the client
program mysqlbinlog. This is a small program that can investigate the contents of
binlog files as well as relay logfiles . In addition to reading binlog
files locally, mysqlbinlog can also
fetch binlog files remotely from other servers.
Note:
The mysqlbinlog tool normally outputs the
contents of the binary log in a form that can be executed by sending
them to a running server. When statement-based replication is employed,
the statements executed are emitted as SQL statements. For row-based
replication,mysqlbinlog generates some additional data
necessary to handle row-based replication.
1. Basic Usage
Let’s start with a simple example where we create a binlog file and then look at it using mysqlbinlog. We will start up a client
connected to the master and execute the following commands to see how
they end up in the binary log:
mysqld1> RESET MASTER;
Query OK, 0 rows affected (0.01 sec)
mysqld1> CREATE TABLE employee (
-> id INT AUTO_INCREMENT,
-> name CHAR(64) NOT NULL,
-> email CHAR(64),
-> password CHAR(64),
-> PRIMARY KEY (id)
-> );
Query OK, 0 rows affected (0.00 sec)
mysqld1> SET @password = PASSWORD('xyzzy');
Query OK, 0 rows affected (0.00 sec)
mysqld1> INSERT INTO employee(name,email,password)
-> VALUES ('mats','mats@example.com',@password);
Query OK, 1 row affected (0.01 sec)
mysqld1> SHOW BINARY LOGS;
+--------------------+-----------+
| Log_name | File_size |
+--------------------+-----------+
| mysqld1-bin.000038 | 670 |
+--------------------+-----------+
1 row in set (0.00 sec)
Let’s now use mysqlbinlog to
dump the contents of the binlog file master-bin.000038, which is where all the
commands ended up. The output shown in Example 1 has been edited
slightly to fit the page.
Example 1. Output from execution of mysqlbinlog
$ sudo mysqlbinlog \
> --short-form \
> --force-if-open \
> --base64-output=never \
> /var/lib/mysql1/mysqld1-bin.000038
1 /*!40019 SET @@session.max_insert_delayed_threads=0*/;
2 /*!50003 SET @OLD_COMPLETION_TYPE=@@COMPLETION_TYPE,COMPLETION_TYPE=0*/;
3 DELIMITER /*!*/;
4 ROLLBACK/*!*/;
5 use test/*!*/;
6 SET TIMESTAMP=1264227693/*!*/;
7 SET @@session.pseudo_thread_id=999999999/*!*/;
8 SET @@session.foreign_key_checks=1, @@session.sql_auto_is_null=1,
@@session.unique_checks=1, @@session.autocommit=1/*!*/;
9 SET @@session.sql_mode=0/*!*/;
10 SET @@session.auto_increment_increment=1,
@@session.auto_increment_offset=1/*!*/;
11 /*!\C latin1 *//*!*/;
12 SET @@session.character_set_client=8,@@session.collation_connection=8,
@@session.collation_server=8/*!*/;
13 SET @@session.lc_time_names=0/*!*/;
14 SET @@session.collation_database=DEFAULT/*!*/;
15 CREATE TABLE employee (
16 id INT AUTO_INCREMENT,
17 name CHAR(64) NOT NULL,
18 email CHAR(64),
19 password CHAR(64),
20 PRIMARY KEY (id)
21 ) ENGINE=InnoDB
22 /*!*/;
23 SET TIMESTAMP=1264227693/*!*/;
24 BEGIN
25 /*!*/;
26 SET INSERT_ID=1/*!*/;
27 SET @`password`:=_latin1 0x2A31353141463... COLLATE `latin1_swedish_ci`/*!*/;
28 SET TIMESTAMP=1264227693/*!*/;
29 INSERT INTO employee(name,email,password)
30 VALUES ('mats','mats@example.com',@password)
31 /*!*/;
32 COMMIT/*!*/;
33 DELIMITER ;
34 # End of log file
35 ROLLBACK /* added by mysqlbinlog */;
36 /*!50003 SET COMPLETION_TYPE=@OLD_COMPLETION_TYPE*/;
|
To get this output, we use three options:
--short-form
With this option, mysqlbinlog prints only information
about the SQL statements issued, and leaves out comments with
information about the events in the binary log. This option is
useful when mysqlbinlog is used
only to play back the events to a server. If you want to
investigate the binary log for problems, you will need these
comments and should not use this option.
--force-if-open
If the binlog file is not closed properly, either because
the binlog file is still being written to or because the server
crashed, mysqlbinlog will print
a warning that this binlog file was not closed properly. This
option prevents the printing of that warning.
--base64-output=never
This prevents mysqlbinlog from printing base64-encoded
events. If mysqlbinlog has to
print base64-encoded events, it will also print the Format
description event of the binary log to show the encoding
used. For statement-based replication, this is not necessary, so
this option is used to suppress that event.
In Example 1, lines
1–4 contain the preamble printed in every output. Line 3 sets a
delimiter that is unlikely to occur elsewhere in the file. The delimiter
is also designed to appear as a comment in processing languages that do
not recognize the setting of the delimiter.
The rollback on line 4 is issued to ensure the output is not
accidentally put inside a transaction because a transaction was started
on the client before the output was fed into the client.
We can skip momentarily to the end of the output—lines 33–35—to
see the counterpart to lines 1–4. They restore the values set in the
preamble and roll back any open transaction. This is necessary in case
the binlog file was truncated in the middle of a transaction, to prevent
any SQL code following this output from being included in a transaction.
The use statement on line 5 is printed whenever the database is changed.
Even though the binary log specifies the current database before each
SQL statement, mysqlbinlog shows only
the changes to the current database. When a use statement appears, it is the first line of
a new event.
The first line that is guaranteed to be in the output for each
event is SET TIMESTAMP, as shown on
lines 6 and 23. This statement gives the timestamp when the event started executing in seconds
since the epoch.
Lines 8–14 contain general settings, but like use on line 5, they are printed only for the
first event and whenever their values change.
Because the INSERT statement on
lines 29–30 is inserting into a table with an autoincrement column using
a user-defined variable, the INSERT_ID session variable on line 26 and the
user-defined variable on line 27 are set before the statement. This is
the result of the Intvar and User_var events in the binary log.
If you omit the --short-form
option, each event in the output will be preceded by some
comments about the event that generated the lines. You can
see these comments, which start with hash marks (#) in Example 2.
Example 2. Interpreting the comments in mysqlbinlog output
$ sudo mysqlbinlog \
> --force-if-open \
> --base64-output=never \
> /var/lib/mysql1/mysqld1-bin.000038
.
.
.
1 # at 386
2 #100123 7:21:33 server id 1 end_log_pos 414 Intvar
3 SET INSERT_ID=1/*!*/;
4 # at 414
5 #100123 7:21:33 server id 1 end_log_pos 496 User_var
6 SET @`password`:=_latin1 0x2A313531...838 COLLATE `latin1_swedish_ci`/*!*/;
7 # at 496
8 #100123 7:21:33 server id 1 end_log_pos 643
Query thread_id=6 exec_time=0 error_code=0
9 SET TIMESTAMP=1264227693/*!*/;
10 INSERT INTO employee(name,email,password)
11 VALUES ('mats','mats@example.com',@password)
12 /*!*/;
13 # at 643
14 #100123 7:21:33 server id 1 end_log_pos 670 Xid = 218
15 COMMIT/*!*/;
16 DELIMITER ;
17 # End of log file
18 ROLLBACK /* added by mysqlbinlog */;
19 /*!50003 SET COMPLETION_TYPE=@OLD_COMPLETION_TYPE*/;
|
The first line of the comment gives the byte position of the
event, and the second line contains other information about the event.
Consider, for example, the INSERT
statement line:
# at 496
#100123 7:21:33 server id 1 end_log_pos 643 Query thread_id=6
exec_time=0 error_code=0
The various parts of the comments have the following
meanings:
at 496
The byte position where the event starts; that is, the first
byte of the event.
100123 7:21:33
The timestamp of the event as a datetime (date plus time). This is the
time when the query started executing or when the events were
written to the binary log.
server_id 1
The server ID of the server that generated the event. This
server ID is used to set the pseudo_thread_id session variable, and a
line setting this variable is printed if the event is
thread-specific and the server ID is different from the previously
printed ID.
end_log_pos 643
The byte position of the event that follows this event. By
taking the difference between this value and the position where
the event starts, you can get the length of the event.
Query
The type of event. In Example 2, you can see
several different types of events, such as User_var,
Intvar, and Xid.
The fields after these are event-specific, and hence different for
each event. For the Query event, we can
see two additional fields:
thread_id=6
The ID of the thread that executed the event. This is used
to handle thread-specific queries, such as queries that access
temporary tables.
exec_time=0
The execution time of the query in seconds.
Example 1 and Example 2 dump the output of
a single file, but mysqlbinlog
accepts multiple files as well. If several binlog files are given, they will be processed in
order.
Warning:
The files are printed in the order you request them, and there
is no checking that the Rotate
event ending each file refers to the next file in sequence. The
responsibility for ensuring that these binlog files make up part of a
real binary log lies on the user.
Thanks to the way the binlog files are named, submitting
multiple files to mysqlbinlog—such
as by using * as a file-globbing
wildcard—is usually not a problem. Let's look at what happens when the
binlog file counter, which is used as an extension to the filename,
goes from 999999 to 1000000:
$ ls mysqld1-bin.[0-9]*
mysqld1-bin.000007 mysqld1-bin.000011 mysqld1-bin.000039
mysqld1-bin.000008 mysqld1-bin.000035 mysqld1-bin.1000000
mysqld1-bin.000009 mysqld1-bin.000037 mysqld1-bin.999998
mysqld1-bin.000010 mysqld1-bin.000038 mysqld1-bin.999999
As you can see, the last binlog file to be created is listed
before the two binlog files that are earlier in binary log order. So
it is worth checking the names of the files before you use
wildcards.
Since your binlog files are usually pretty large, you won’t want
to print the entire contents of the binlog files and browse them.
Instead, there are a few options you can use to limit the output so that
only a range of the events is printed.
start-position= bytepos
The byte position of the first event to dump. Note that if
several binlog files are supplied to mysqlbinlog, this position will be
interpreted as the position in the first file
in the sequence.
If an event does not start at the position given, mysqlbinlog will still try to interpret
the bytes starting at that position as an event, which usually
leads to garbage output.
stop-position= bytepos
The byte position of the last event to print. If no event
ends at that position, the last event printed will be the event
with a position that precedes bytepos.
If multiple binlog files are given, the position will be the
position of the last file in the
sequence.
start-datetime= datetime
Prints only events that have a timestamp at or after
datetime. This will work correctly when
multiple files are given—if all events of a file are before the
datetime, all events will be
skipped—but there is no checking that the events are printed in
order according to their timestamps.
stop-datetime= datetime
Prints only events that have a timestamp before
datetime. This is an exclusive range,
meaning that if an event is marked 2010-01-24 07:58:32 and that exact
datetime is given, the event will not be
printed.
Note that since the timestamp of the event uses the start time of the
statement but events are ordered in the binary log based on the
commit time, it is possible to have events with a timestamp that
comes before the timestamp of the preceding event. Since mysqlbinlog stops at the first event
with a timestamp outside the range, there might be events that
aren’t displayed because they have timestamps before datetime.
1.1. Reading remote files
As well as reading files on a local filesystem, the
mysqlbinlog utility can also read binlog files from a remote server. It does this by using
the same mechanism that the slaves use to connect to a master and ask
for events. This can be practical in some cases, since it does not
require a shell account on the machine to read the binlog files, just
a user on the server with REPLICATION SLAVE
privileges.
To handle remote reading of binlog files, include the --read-from-remote-server option along with
a host and user for connecting to the server, and optionally a port
(if different from the default) and a password.
When reading from a remote server, give just the name of the
binlog file, not the full path.
So to read the Query
event from Example 2 remotely, the
command would look something like the following (the server prompts
for a password, but it is not output when you enter it):
$ sudo mysqlbinlog
> --read-from-remote-server
> --host=master.example.com
> --base64-output=never
> --user=repl_user --password
> --start-position=386 --stop-position=643
> mysqld1-bin.000038
Enter password:
/*!40019 SET @@session.max_insert_delayed_threads=0*/;
/*!50003 SET @OLD_COMPLETION_TYPE=@@COMPLETION_TYPE,COMPLETION_TYPE=0*/;
DELIMITER /*!*/;
# at 386
#100123 7:21:33 server id 1 end_log_pos 0 Start: binlog v 4,
server v 5.1.37-1ubuntu5-log created 100123 7:21:33
# at 386
#100123 7:21:33 server id 1 end_log_pos 414 Intvar
SET INSERT_ID=1/*!*/;
# at 414
#100123 7:21:33 server id 1 end_log_pos 496 User_var
SET @`password`:=_latin1 0x2A3135314146364...38 COLLATE `latin1_swedish_ci`/*!*/;
# at 496
#100123 7:21:33 server id 1 end_log_pos 643 Query thread_id=6
exec_time=0 error_code=0
use test/*!*/;
SET TIMESTAMP=1264227693/*!*/;
SET @@session.pseudo_thread_id=6/*!*/;
SET @@session.foreign_key_checks=1, @@session.sql_auto_is_null=1,
@@session.unique_checks=1, @@session.autocommit=1/*!*/;
SET @@session.sql_mode=0/*!*/;
SET @@session.auto_increment_increment=1, @@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/*!*/;
INSERT INTO employee(name,email,password)
VALUES ('mats','mats@example.com',@password)
/*!*/;
DELIMITER ;
# End of log file
ROLLBACK /* added by mysqlbinlog */;
/*!50003 SET COMPLETION_TYPE=@OLD_COMPLETION_TYPE*/;
