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

[27 Jul 2020 6:00] Pranay Motupalli
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.
[27 Jul 2020 6:01] Pranay Motupalli
Test outputs

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

[27 Jul 2020 6:02] Pranay Motupalli
Test Outputs formatted image

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

[27 Jul 2020 6:12] Pranay Motupalli
gdb and tracing.txt

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

[30 Jul 2020 4:15] MySQL Verification Team
Hello Pranay,

Thank you for the report and test case.

regards,
Umesh
[13 Aug 2020 19:09] Pedro Figueiredo
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,
[13 Aug 2020 19:11] Pedro Figueiredo
isolation_level_test_case.diff

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

[25 Aug 2020 13:56] Pedro Figueiredo
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,
[25 Aug 2020 13:57] Pedro Figueiredo
isolation_level_02.test

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