MySQL Logging – Can Queries Write to Binary Log Before Execution Completes?

logMySQLmysql-5.5

I have a Database which is a Slave and a Master. e.g. it replicates data from our main site, and then onwards to a set of slave databases. (this is mainly a test facility so not monitored out of hours).

On Sunday morning at 7:55 it started executing an INSERT query. This is a standard query that executes thousands of times a day. Its a single query, not part of a transaction. There are no triggers on that table. This table (and all others) are INNODB.

But, on this occasion it got stuck. When I came in the office today it had been running for 24 hours (apparently). And replication was a day behind.

However, when I looked in the Binary logs it showed as COMMITed.

#160814  7:55:25 server id 21  end_log_pos 103319397    Query   thread_id=635785334 exec_time=4294967294    error_code=0
SET TIMESTAMP=1471157725/*!*/;
INSERT INTO tablename . . . 
/*!*/;
# at 103319397
#160814  7:55:25 server id 21  end_log_pos 103319424    Xid = 284047583
COMMIT/*!*/;
# at 103319424

I checked the Slave databases, and it was on present on there as you'd expect.

I have a monitoring system which records (amongst other things) the processlist, and it shows that for that INSERT query it was perpetually stuck at STATE = UPDATE.

I also checked the slow query log to see if it was in there, and it wasn't.

My understanding was that a query couldn't be written to the binary log until it was commmited on the master, so can anyone explain what has happenned here?

There was a knock on affect in that once out test system tried to connect at 8:38 this morning, the first SELECT query also got stuck, and then it refused all connetions. So I was forced to restart the database.
At which point it ran crash recovery, and carried on as if nothing had happenned.

It is MySQL 5.5.47 and using Statement Based Replication.

Best Answer

If you're getting conflicting info from different sources, use the official documentation:

http://dev.mysql.com/doc/refman/5.5/en/binary-log.html

Binary logging is done immediately after a statement or transaction completes but before any locks are released or any commit is done. This ensures that the log is logged in commit order.

This means there is a narrow window in which a failure could cause an uncommitted transaction to exist in the binary log but not in the database. This seems to be what has happened in your case.

For example, if you are using InnoDB tables and the MySQL server processes a COMMIT statement, it writes the whole transaction to the binary log and then commits this transaction into InnoDB. If the server crashes between those two operations, the transaction is rolled back by InnoDB at restart but still exists in the binary log. To resolve this, you should set --innodb_support_xa to 1. Although this option is related to the support of XA transactions in InnoDB, it also ensures that the binary log and InnoDB data files are synchronized.

OPTION 1

Skip the error, wait 5 seconds, and view the Slave Status. Here the 5 steps for Skipping an Error

STOP SLAVE;
SET GLOBAL SQL_SLAVE_SKIP_COUNTER = 1;
START SLAVE;
SELECT SLEEP(5);
SHOW SLAVE STATUS\G

When you view the Slave Status, here is what to expect

If Seconds_Behind_Master is NULL
- Replication is Broken : Look for Tell-Tale Signs
- If Error Number is 1062 again, Repeat the 5 steps for Skipping an Error
If Seconds_Behind_Master is a Number
- Replication is running
- When Seconds_Behind_Master > 0, Replication is Catching Up.
- When Seconds_Behind_Master = 0, Replication is Fully Caught Up.

OPTION 2

Remove the row to allow replication to continue

Delete the row from the table on the Slave and do the following 4 Steps for Skipping an Error:

STOP SLAVE;
START SLAVE;
SELECT SLEEP(5);
SHOW SLAVE STATUS\G

At the risk of sounding redundant...

When you view the Slave Status, here is what to expect

If Seconds_Behind_Master is NULL
- Replication is Broken : Look for Tell-Tale Signs
- If Error Number is 1062 again, delete the row Repeat the 4 steps for Skipping an Error
If Seconds_Behind_Master is a Number
- Replication is running
- When Seconds_Behind_Master > 0, Replication is Catching Up.
- When Seconds_Behind_Master = 0, Replication is Fully Caught Up.

What if there are just too many duplicate key issues? Here are some of my earlier posts concerning how to use MAATKIT's mk-table-checksum, mk-table-sync, pt-table-checksum, pt-table-sync:

MySQL Error – Impossible to Write to Binary Log

There are 3 methods that MySQL can use to write to the binary logs:

STATEMENT

This means that every SQL statement on the master is recorded in the log, and executed on the slave. This can cause problems if the SQL statement contains statements such as "NOW()", "RAND()" and anything non-deterministic. This also requires support from the storage engine in use.
ROW

This means that every row that is changed by a statement is individually recorded in the binary log. This gives larger binary logs (generally) than statement based logging, but is almost always guaranteed to give the exact replication needed.
MIXED

This allows MySQL to choose between binary and row based logging as required.

If you're getting this error, one suggestion is to change the BINLOG_FORMAT variable to MIXED. This allows MySQL to automatically switch between ROW and STATEMENT based logging as required.

Best Answer

Related Solutions

MySQL Replication – Fixing Replication Errors

OPTION 1

OPTION 2

MySQL Error – Impossible to Write to Binary Log

Related Question