MySQL Bugs: #100328: Inconsistent behavior with isolation levels when binlog enabled

Bug #100328	Inconsistent behavior with isolation levels when binlog enabled
Submitted:	27 Jul 2020 6:00	Modified:	23 Oct 2020 10:22
Reporter:	Pranay Motupalli	Email Updates:
Status:	Verified	Impact on me:	None
Category:	MySQL Server: InnoDB storage engine	Severity:	S2 (Serious)
Version:	5.6,5.7,8.0	OS:	Any
Assigned to:		CPU Architecture:	Any

Description:
For a dummy update statement in REPEATABLE-READ isolation level, the output of the select before and after update changes with binlog_format.

Test:
====

[ Check attached items for test outputs for all the major versions ]

Note: **** Check Repro Steps in How to Repeat Section before going through the attached test outputs for better understanding of test outputs are of 2nd session ****

Test Summary:
============

binlog_format = Statement
#########################

5.5, 5.6, 5.7, 8.0  -> Shows the UPDATED value in the second trx.

Binlog_format = ROW
###################

5.5 -> Shows the UPDATED value in the second trx.

5.6,5.7,8.0 -> Shows the CONSISTENT value in the second trx.

log_bin = 0:
###########

5.5, 5.6, 5.7, 8.0  -> Shows the UPDATED value in the second trx.

How to repeat:
General Repro Steps:
===================

CREATE TABLE `t1` (
`id` int(11) DEFAULT NULL,
`name` varchar(20) DEFAULT NULL
) ENGINE=InnoDB DEFAULT CHARSET=latin1;

insert into t1 values(1,'abc');

Note: ISOLATION LEVEL is constant through out all the tests [ REPEATABLE-READ ]

General Steps followed for repro:
================================

Session 1:
=========

BEGIN;

SELECT * FROM t1;

Session 2:
==========
BEGIN;

SELECT * FROM t1; ----> Note this output

Session 1:
=========

UPDATE t1 SET name='xyz' WHERE id=1;

COMMIT;

Session 2:
=========

UPDATE t1 SET name='xyz' WHERE id=1;

SELECT * FROM t1; ----> Note this output and compare it with before select output in the same session.

COMMIT; 

Issue:
=====

[ Please check the attached items for the stacktrace and gdb debugging ]

Before performing update operation, MySQL compares input and output record buffers. However, table->write_set bitmap and table->read_set bitmap are being changed (set to same) in the function TABLE::mark_columns_per_binlog_row_image if binlog_format='ROW' and based on this, update operation is skipped for binlog_format='ROW'.

This is not the case for binlog_format='STATEMENT' as mark_columns_per_binlog_row_image does nothing and returns back. In this case, table->write_set bitmap and table->read_set bitmap are different and update operation happens. So, when we execute the same select again, I would get the updated value. Its the same case when binary logging is disabled.

This issue is present on 5.6,5.7,8.0 ( since the introduction of binlog_row_image ). This issue is not present on 5.5 and it does produce consistent view irrespective of binlog_format.

Ideally, we shouldn't depend on binlog_format here and the behavior should be consistent irrespective of binlog_format/log_bin.

Test outputs

Attachment: Test Ouputs.txt (text/plain), 17.65 KiB.

Test Outputs formatted image

Attachment: image.png (image/png, text), 1.05 MiB.

gdb and tracing.txt

Attachment: gdb and tracing.txt (text/plain), 8.30 KiB.

Hello Pranay,

Thank you for the report and test case.

regards,
Umesh

Posted by developer:
 
Hi.

AFAICS, this bug is also reproducible without binary logging enabled, more
specifically, whenever the following conditions are met:

1. Two concurrent transactions, T1 and T2 want to update the same column of the
   same record.

2. T1 commits before T2 executes the update.

3. In T2 if the column being updated (in the `TABLE::write_set` bitmap) is also
   in the `TABLE::read_set` bitmap and the new column value provided in T2 is
   exactly the same as in T1.

Please, check the attached diff `isolation_level_test_case.diff` (debug sync
point and MTR test) for a more clear example. Execute MTR with
`--mysqld=--skip-log-bin`:

    $ ./mtr --no-check-testcases --mysqld=--skip-log-bin isolation_level

The issue is more visible with binary logging enabled since it changes write set
and read set bitmaps, in some cases setting all bits to 1 in both.

Since the issue only happens when the column updated value is the same in both
transactions, it doesn't seem related to binary logging. Therefore, IMHO,
analysis from the Optimizer team is needed in order to understand what is
happening with the update plan.

Thank you for your time.

Regards,

isolation_level_test_case.diff

Attachment: isolation_level_test_case.diff (text/x-patch), 3.58 KiB.

Posted by developer:
 
The problem is reproducible without artificially setting the column bit in `read_set` bitmap, as visible in the `isolation_level_02.test` file, attached.

Regards,

isolation_level_02.test

Attachment: isolation_level_02.test (application/octet-stream, text), 2.40 KiB.

Posted by developer:
 
Hello!

The following simple test case for MTR framework shows that the problem is repeatable without binary log enabled and without additional changes to code to adjust the read-set bitmap:

--enable_connect_log
create table t(a int, b int) engine=innodb;
insert into t values (1, 0), (2, 1), (3, 2);

set transaction isolation level repeatable read;
begin;
select * from t;

connect (addconroot1, localhost, root,,);
begin;
update t set a = 10 where b = 1;
commit;

connection default;
select * from t;
update t set a = 10 where a;
select * from t;
# The above returns (which is wrong!)
# a      b
# 10     0
# 2      1
# 10     2

commit;

In fact with this test case the problem is repeatable even in 5.5 tree (for 5.5.65-git to be exact).

Posted by developer:
 
Bug #104986/#33385596 "Weird SELECT View when a record is modified to a same value by two transactions" has been marked as a duplicate of this one.

Related:
 https://bugs.mysql.com/bug.php?id=107887

This bug is the original bug report for the following bug, as well:

https://bugs.mysql.com/bug.php?id=114389