The binary logging format in MySQL has been ROW by default since MySQL 5.7, yet there are still many users sticking with STATEMENT or MIXED formats for various reasons. In some cases, there is just simple hesitation from changing something that has worked for years on legacy applications. But in others, there may be serious blockers, most typically missing primary keys in badly designed schemas, which would lead to serious performance issues on the replicas.
As a Support Engineer, I can still see quite a few customers using STATEMENT or MIXED formats, even if they are already on MySQL 8.0. In many cases this is OK, but recently I had to deal with a pretty nasty case, where not using ROW format was found to cause the replicas to silently lose data updates, without raising any replication errors! Was it some really rare edge use case? Not at all! Let me demonstrate a very simple test case below to illustrate how easy it is to end up in such a bad situation.
— source
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 | mysql> select @@binlog_format,@@system_time_zone; +-----------------+--------------------+ | @@binlog_format | @@system_time_zone | +-----------------+--------------------+ | STATEMENT | BST | +-----------------+--------------------+ 1 row in set (0.00 sec) mysql> CREATE TABLE `test1` ( -> `id` int(11) NOT NULL AUTO_INCREMENT, -> `d` timestamp NOT NULL DEFAULT CURRENT_TIMESTAMP ON UPDATE CURRENT_TIMESTAMP, -> `a` varchar(30) NOT NULL, -> `name` varchar(25) DEFAULT NULL, -> PRIMARY KEY (`a`), -> UNIQUE KEY `id` (`id`) -> ) ENGINE=InnoDB; Query OK, 0 rows affected, 1 warning (0.02 sec) mysql> insert into test1 values (null,now(),"test1",0); Query OK, 1 row affected (0.00 sec) mysql> insert into test1 values (null,now(),"test2",0); Query OK, 1 row affected (0.01 sec) mysql> insert into test1 values (null,now(),"test3",0); Query OK, 1 row affected (0.01 sec) mysql> select * from test1; +----+---------------------+-------+------+ | id | d | a | name | +----+---------------------+-------+------+ | 1 | 2022-05-22 10:13:37 | test1 | 0 | | 2 | 2022-05-22 10:13:37 | test2 | 0 | | 3 | 2022-05-22 10:13:38 | test3 | 0 | +----+---------------------+-------+------+ 3 rows in set (0.00 sec) |
— replica
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 | mysql> select @@system_time_zone; +--------------------+ | @@system_time_zone | +--------------------+ | UTC | +--------------------+ 1 row in set (0.00 sec) mysql> select * from db1.test1; +----+---------------------+-------+------+ | id | d | a | name | +----+---------------------+-------+------+ | 1 | 2022-05-22 09:13:37 | test1 | 0 | | 2 | 2022-05-22 09:13:37 | test2 | 0 | | 3 | 2022-05-22 09:13:38 | test3 | 0 | +----+---------------------+-------+------+ 3 rows in set (0.00 sec) |
— source
1 2 3 4 5 6 7 8 9 10 11 12 13 | mysql> UPDATE test1 SET name = 'foobar', d = CURRENT_TIMESTAMP WHERE a = 'test1' AND d = '2022-05-22 10:13:37'; Query OK, 1 row affected (0.00 sec) Rows matched: 1 Changed: 1 Warnings: 0 mysql> select * from test1; +----+---------------------+-------+--------+ | id | d | a | name | +----+---------------------+-------+--------+ | 1 | 2022-05-22 10:16:15 | test1 | foobar | | 2 | 2022-05-22 10:13:37 | test2 | 0 | | 3 | 2022-05-22 10:13:38 | test3 | 0 | +----+---------------------+-------+--------+ 3 rows in set (0.00 sec) |
— replica
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 | mysql> select * from db1.test1; +----+---------------------+-------+------+ | id | d | a | name | +----+---------------------+-------+------+ | 1 | 2022-05-22 09:13:37 | test1 | 0 | | 2 | 2022-05-22 09:13:37 | test2 | 0 | | 3 | 2022-05-22 09:13:38 | test3 | 0 | +----+---------------------+-------+------+ 3 rows in set (0.00 sec) mysql> pager egrep "Running|SQL_Error" PAGER set to 'egrep "Running|SQL_Error"' mysql > show replica statusG Replica_IO_Running: Yes Replica_SQL_Running: Yes Last_SQL_Error: Replica_SQL_Running_State: Replica has read all relay log; waiting for more updates Last_SQL_Error_Timestamp: 1 row in set (0.00 sec) |
Another test, using UTC_TIME() compared against a column that was populated using the CURRENT_TIMESTAMP function:
— source
1 2 3 4 5 6 7 | mysql> select * from test1 WHERE TIME(d) > DATE_SUB(UTC_TIME(), INTERVAL 11 HOUR) AND id=3; +----+---------------------+-------+------+ | id | d | a | name | +----+---------------------+-------+------+ | 3 | 2022-05-22 10:13:38 | test3 | 0 | +----+---------------------+-------+------+ 1 row in set (0.00 sec) |
— replica
1 2 | mysql> select * from test1 WHERE TIME(d) > DATE_SUB(UTC_TIME(), INTERVAL 11 HOUR) AND id=3; Empty set (0.00 sec) |
Therefore, when a similar condition is used for update:
— source
1 2 3 4 5 6 7 8 9 10 11 | mysql> update test1 set name="bar" WHERE TIME(d) > DATE_SUB(UTC_TIME(), INTERVAL 11 HOUR) AND id=3; Query OK, 1 row affected (0.00 sec) Rows matched: 1 Changed: 1 Warnings: 0 mysql> select * from test1 where id=3; +----+---------------------+-------+------+ | id | d | a | name | +----+---------------------+-------+------+ | 3 | 2022-05-22 22:12:15 | test3 | bar | +----+---------------------+-------+------+ 1 row in set (0.01 sec) |
— replica
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 | mysql> select * from test1 where id=3; +----+---------------------+-------+------+ | id | d | a | name | +----+---------------------+-------+------+ | 3 | 2022-05-22 09:13:38 | test3 | 0 | +----+---------------------+-------+------+ 1 row in set (0.01 sec) mysql > show replica statusG Replica_IO_Running: Yes Replica_SQL_Running: Yes Last_SQL_Error: Replica_SQL_Running_State: Replica has read all relay log; waiting for more updates Last_SQL_Error_Timestamp: 1 row in set (0.00 sec) |
Again replica ignored the update while there is no replication error reported. This particular scenario can be expected to happen really often in geographically-distributed database environments.
As the functions used here are not considered unsafe for replication, two usual safety actions are not performed:
- no warning is printed in the error log when the STATEMENT format used
- replication event is not logged in RBR format when the MIXED format is used but rather left the original query as it is
I find this potentially dangerous and hence reported it: https://bugs.mysql.com/bug.php?id=107293
Summary
ROW-based replication has become the standard in MySQL and is the most reliable one. It is also the only one permitted for virtually synchronous replication solutions like Percona XtraDB Cluster/Galera and MySQL Group Replication.
At the same time, STATEMENT or even MIXED format, may lead to data consistency issues, which can be undetected for a long time, making it very difficult to investigate when finally replication error happens as a result.
If there is anything that has prevented you from switching to ROW format yet, the sooner you deal with it the better.
Hi there, nice work with these findings, we had similar issues with MIXED format in my organization.
The issue itself is not the updates but the INSERT that failed, since all statements seem ACID complain, updates are a byproduct.
Check the datetime on master vs replica “10:13:37” “09:13:37”
Unless server date/time are the same this is bound to happen, even in different time zones, we solved it by setting them all in the same timezone as master. This had the pluss of also helping when checking server events outside mysql.
I can’t recall the exact config, but there was a setting (current time =NOW) where mysql master sent the value of current time inside the binlog to the replicas and the now() used that value.
Any replication performance difference between mixed and row-based replication?
Did you guys do any stress test and compare them?