MySQL 5.1 introduces row-based binary logging. In fact, the default binary logging format in GA versions of MySQL 5.1 is ‘MIXED’ STATEMENT*; The binlog_format variable can still be changed per sessions which means it is possible that some of your binary log entries will be written in a row-based fashion instead of the actual statement which changed data, even when the global setting on the master is to write binary logs in statement mode. The row-based format does offer advantages particularly if triggers or stored procedures are used, or if non-deterministic functions like RAND() are used in DML statements.
A statement based replication slave can get out of sync with the master fairly easily, especially if data is changed on the slave. It is possible for a statement to execute successfully on a slave even if the data is not 100% in sync, so MySQL doesn’t know anything is wrong. This isn’t the case with row-based replication. Only actual changes are written to the database with row-based logs. Take as an example a DELETE statement which does not modify any rows. No binary logging will be performed by this statement in row-based logs, but the DELETE will be written to a statement based binary log. Since row-based logs only contain information about changed rows, a replication slave which does not find a row referenced in a row-based log will immediately return an error: HA_ERR_KEY_NOT_FOUND.
This is probably best shown by example. First, let’s create a test table on a MySQL master database and populate it with some data.
|
1 |
CREATE TABLE `t1` (<br>`c1` int(11) NOT NULL AUTO_INCREMENT,<br>PRIMARY KEY (`c1`)<br>) ENGINE=InnoDB;<br>Query OK, 1 row affected (0.02 sec) |
Insert a single “seed” row into the table:
|
1 |
INSERT INTO repl.t1 VALUES ();<br>Query OK, 1 row affected (0.00 sec) |
INSERT … SELECT a few times to get some dummy data:
|
1 |
insert into repl.t1 select NULL from t1;<br>Query OK, 1 row affected (0.01 sec)<br>Records: 1 Duplicates: 0 Warnings: 0<br><br>insert into repl.t1 select NULL from t1;<br>Query OK, 2 rows affected (0.01 sec)<br>Records: 2 Duplicates: 0 Warnings: 0<br><br>...<br><br>insert into repl.t1 select NULL from t1;<br>Query OK, 32768 rows affected (0.62 sec)<br>Records: 32768 Duplicates: 0 Warnings: 0 |
Verify that we have a reasonable amount of data to play with:
|
1 |
select count(*) from t1;<br>+----------+<br>| count(*) |<br>+----------+<br>| 65536 |<br>+----------+<br>1 row in set (0.02 sec) |
My test setup includes a MySQL slave. After the above setup completes, I am going to change data on the slave by truncating t1. After truncation:
|
1 |
select count(*)<br>from t1 as empty_table_on_the_slave;<br>+----------+<br>| count(*) |<br>+----------+<br>| 0 |<br>+----------+<br>1 row in set (0.00 sec) |
Now, lets make a modification on the master:
|
1 |
update repl.t1 set c1 = c1 + 100000 where c1 = 1;<br>Query OK, 1 row affected (0.02 sec)<br>Rows matched: 1 Changed: 1 Warnings: 0 |
On the slave, SHOW SLAVE STATUS now reports an error (many fields omitted):
|
1 |
SHOW SLAVE STATUSG<br>Relay_Log_File: mysql_sandbox25162-relay-bin.000002<br>Relay_Log_Pos: 340718<br>Slave_SQL_Running: No<br>Last_Errno: 1032<br>Last_Error: Could not execute Update_rows event on table repl.t1; Can't find record in 't1', Error_code: 1032; handler error HA_ERR_KEY_NOT_FOUND; the event's master log mysql-bin.000001, end_log_pos 340718 |
This error message is telling us that a row that was modified on the master can not be found on the slave:HA_ERR_KEY_NOT_FOUND. It doesn’t tell us what row it couldn’t find though. In our simple example, we know that all the rows are missing, and the one in particular that the server is trying to find is c1=1, but how can we find that out if we don’t know the conditions under which replication went out of sync?
To determine exactly what row is having an issue, we can use the ‘mysqlbinlog’ utility in combination with the slave relay log. Examining the output of SHOW SLAVE STATUS, we can see that the slave is currently executing at relay log file: mysql_sandbox25162-relay-bin.000002 at position: 340718. MySQL 5.1 ships with a new version of mysqlbinlog that includes new options that make decoding RBR statements possible. These options are “–base64-output” and “-v”. For debugging row-based logs, I suggest ‘–base64-output=decode-rows -v”. This omits any base64 output and instead replaces the output with semi-valid SQL statements. I say semi-valid because the statements do not include column names. Column names are not included in the binary log, only positions.
mysqlbinlog mysql_sandbox25162-relay-bin.000005 –base64-output=decode-rows -v > decoded.log
Examine the decoded binary log with the ‘less’ utility, and search forward for the value 340718:
|
1 |
# at 340718<br>#100506 12:42:56 server id 1 end_log_pos 340637 Query thread_id=6 exec_time=0 error_code=0<br>SET TIMESTAMP=1273174976/*!*/;<br>BEGIN<br>/*!*/;<br># at 340782<br># at 340823<br>#100506 12:42:56 server id 1 end_log_pos 340678 Table_map: `repl`.`t1` mapped to number 15<br>#100506 12:42:56 server id 1 end_log_pos 340718 Update_rows: table id 15 flags: STMT_END_F<br>### UPDATE repl.t1<br>### WHERE<br>### @1=1<br>### SET<br>### @1=100001<br># at 340863<br>#100506 12:42:56 server id 1 end_log_pos 340745 Xid = 51<br>COMMIT/*!*/;<br># at 340890 |
As you can see, the RBR entry has been decoded as an update statement. The OLD value (the row that is missing) is represented in the WHERE clause. The binary log does not carry column names, so each column is represented by the column position prefixed with @.
There you have it. You can now find out exactly which row is missing and begin your investigation as to why it is missing. You may have to do a bit more leg work if many rows were modified during a transaction.
You should always set read_only = true on your MySQL slaves to prevent accidental changes in data from happening!
*edit*
The MySQL 5.1 default binary logging format changed back to STATEMENT in MySQL 5.1.29.
Resources
RELATED POSTS
