| Bug #120471 | binary log violates read after write (commit) consistency | ||
|---|---|---|---|
| Submitted: | 14 May 0:08 | Modified: | 14 May 0:09 |
| Reporter: | Morgan Tocker | Email Updates: | |
| Status: | Open | Impact on me: | |
| Category: | MySQL Server: Replication | Severity: | S1 (Critical) |
| Version: | 8.0.43, 8.0.46, 8.4.9, 9.7.0 | OS: | Any (reproduced on macOS and Linux) |
| Assigned to: | CPU Architecture: | Any | |
[14 May 0:09]
Morgan Tocker
repro.sh
Attachment: repro.sh (text/x-sh), 9.27 KiB.
[14 May 0:09]
Morgan Tocker
Results from running the attached script: mtocker@BLKD5234QXY40 read-after-write-violation % ./repro.sh -t 240 -w 8 -u msandbox -p msandbox Server settings: version=8.0.43 binlog_format=ROW binlog_row_image=FULL binlog_order_commits=1 sync_binlog=1 innodb_flush_log_at_trx_commit=1 starting binlog tail from BLKD5234QXY40-bin.000027 writers=8 max_duration=240s recheck_delay=100ms first miss observed: id=931 (row event delivered, fresh SELECT does not see the row) -- re-checking after 100ms MISSING (delayed) id=931 -- row became visible after 100ms SUMMARY: writers=8 events_observed=931 FAIL: binlog_order_commits=ON contract was violated. Row event was observed in the binlog stream but the corresponding row only became visible to a fresh SELECT after 100ms (id=931). The visibility lag is transient but it is still a contract violation. mtocker@BLKD5234QXY40 read-after-write-violation % ./repro.sh -t 240 -w 8 -u msandbox -p msandbox -P 8046 Server settings: version=8.0.46 binlog_format=ROW binlog_row_image=FULL binlog_order_commits=1 sync_binlog=1 innodb_flush_log_at_trx_commit=1 starting binlog tail from binlog.000001 writers=8 max_duration=240s recheck_delay=100ms first miss observed: id=1736 (row event delivered, fresh SELECT does not see the row) -- re-checking after 100ms MISSING (delayed) id=1736 -- row became visible after 100ms SUMMARY: writers=8 events_observed=1736 FAIL: binlog_order_commits=ON contract was violated. Row event was observed in the binlog stream but the corresponding row only became visible to a fresh SELECT after 100ms (id=1736). The visibility lag is transient but it is still a contract violation. mtocker@BLKD5234QXY40 read-after-write-violation % ./repro.sh -t 240 -w 8 -u msandbox -p msandbox -P 8409 Server settings: version=8.4.9 binlog_format=ROW binlog_row_image=FULL binlog_order_commits=1 sync_binlog=1 innodb_flush_log_at_trx_commit=1 starting binlog tail from binlog.000001 writers=8 max_duration=240s recheck_delay=100ms first miss observed: id=929 (row event delivered, fresh SELECT does not see the row) -- re-checking after 100ms MISSING (delayed) id=929 -- row became visible after 100ms SUMMARY: writers=8 events_observed=929 FAIL: binlog_order_commits=ON contract was violated. Row event was observed in the binlog stream but the corresponding row only became visible to a fresh SELECT after 100ms (id=929). The visibility lag is transient but it is still a contract violation. mtocker@BLKD5234QXY40 read-after-write-violation % ./repro.sh -t 240 -w 8 -u msandbox -p msandbox -P 9700 Server settings: version=9.7.0 binlog_format=ROW binlog_row_image=FULL binlog_order_commits=1 sync_binlog=1 innodb_flush_log_at_trx_commit=1 starting binlog tail from binlog.000002 writers=8 max_duration=240s recheck_delay=100ms first miss observed: id=920 (row event delivered, fresh SELECT does not see the row) -- re-checking after 100ms MISSING (delayed) id=920 -- row became visible after 100ms SUMMARY: writers=8 events_observed=920 FAIL: binlog_order_commits=ON contract was violated. Row event was observed in the binlog stream but the corresponding row only became visible to a fresh SELECT after 100ms (id=920). The visibility lag is transient but it is still a contract violation.
Description: Under `binlog_order_commits=ON` (default) an entry in the binary log should mean that the rows are visible to new sessions if they were to be read back. That is because the binary log contains _committed_ changes. However, there is a race which I can consistently reproduce with the minimal testcase. This is critical to tools such as those for online schema change. We detected this in Spirit and have had to workaround it. I have reproduced on MySQL 8.0.43, 8.0.46, 8.4.9, 9.7.0. Originally I thought it was Linux specific, but I can reproduce on macOS with ARM hardware as well. How to repeat: Concurrently execute in parallel: BEGIN; INSERT INTO t (payload) VALUES ('x'); UPDATE t SET payload = 'x2' WHERE id = LAST_INSERT_ID(); COMMIT; .. then try to read the data back. I will upload a shell script which can be used to reproduce.