MySQL Bugs: #54562: SBR mistakes SAVEPOINT statement for accessing a transactional table

Bug #54562	SBR mistakes SAVEPOINT statement for accessing a transactional table
Submitted:	16 Jun 2010 19:18
Reporter:	Elena Stepanova	Email Updates:
Status:	Verified	Impact on me:	None
Category:	MySQL Server: Replication	Severity:	S3 (Non-critical)
Version:	5.5.3-m3, 5.5.5-m3	OS:	Any
Assigned to:	Assigned Account	CPU Architecture:	Any
Tags:	regression

Description:
In the test case below, even although only non-transactional table is used, the second delete (after SAVEPOINT) causes a warning "Statement is unsafe because it accesses a non-transactional table after accessing a transactional table within the same transaction", and the binlog starts behaving as if there was indeed a mix of txn/non-txn tables, i.e. the second delete is not written into the binary log until commit, which can easily cause replication failure or inconsistency between master and slave if the concurrent connection uses the same data.

Output from the test case, delete from tbnum0_eng1 where f1=82 is held off in the binary log.

SET GLOBAL binlog_direct_non_transactional_updates=0;
drop database if exists systest2;
create database systest2;
use systest2;
CREATE TABLE systest2.tbnum0_eng1 (f1 tinyint) ENGINE = MyISAM;
INSERT INTO systest2.tbnum0_eng1 VALUES (82),(83),(98),(99);
FLUSH LOGS;
USE systest2;
start transaction;
delete from tbnum0_eng1 where f1=83;
SHOW BINLOG EVENTS IN 'master-bin.000002';
Log_name        Pos     Event_type      Server_id       End_log_pos     Info
master-bin.000002       4       Format_desc     1       107     Server ver: 5.5.5-m3-log, Binlog ver: 4
master-bin.000002       107     Query   1       179     BEGIN
master-bin.000002       179     Query   1       281     use `systest2`; delete from tbnum0_eng1 where f1=83
master-bin.000002       281     Query   1       354     COMMIT
savepoint svpt1;
delete from tbnum0_eng1 where f1=82;
Warnings:
Note    1592    Unsafe statement written to the binary log using statement format since BINLOG_FORMAT = STATEMENT. Statement is unsafe because it accesses a non-transactional table after accessing a transactional table within the same transaction.
SHOW BINLOG EVENTS IN 'master-bin.000002';
Log_name        Pos     Event_type      Server_id       End_log_pos     Info
master-bin.000002       4       Format_desc     1       107     Server ver: 5.5.5-m3-log, Binlog ver: 4
master-bin.000002       107     Query   1       179     BEGIN
master-bin.000002       179     Query   1       281     use `systest2`; delete from tbnum0_eng1 where f1=83
master-bin.000002       281     Query   1       354     COMMIT
USE systest2;
delete from tbnum0_eng1 where f1=99;
SHOW BINLOG EVENTS IN 'master-bin.000002';
Log_name        Pos     Event_type      Server_id       End_log_pos     Info
master-bin.000002       4       Format_desc     1       107     Server ver: 5.5.5-m3-log, Binlog ver: 4
master-bin.000002       107     Query   1       179     BEGIN
master-bin.000002       179     Query   1       281     use `systest2`; delete from tbnum0_eng1 where f1=83
master-bin.000002       281     Query   1       354     COMMIT
master-bin.000002       354     Query   1       426     BEGIN
master-bin.000002       426     Query   1       528     use `systest2`; delete from tbnum0_eng1 where f1=99
master-bin.000002       528     Query   1       601     COMMIT
commit;
SHOW BINLOG EVENTS IN 'master-bin.000002';
Log_name        Pos     Event_type      Server_id       End_log_pos     Info
master-bin.000002       4       Format_desc     1       107     Server ver: 5.5.5-m3-log, Binlog ver: 4
master-bin.000002       107     Query   1       179     BEGIN
master-bin.000002       179     Query   1       281     use `systest2`; delete from tbnum0_eng1 where f1=83
master-bin.000002       281     Query   1       354     COMMIT
master-bin.000002       354     Query   1       426     BEGIN
master-bin.000002       426     Query   1       528     use `systest2`; delete from tbnum0_eng1 where f1=99
master-bin.000002       528     Query   1       601     COMMIT
master-bin.000002       601     Query   1       673     BEGIN
master-bin.000002       673     Query   1       755     SAVEPOINT svpt1
master-bin.000002       755     Query   1       857     use `systest2`; delete from tbnum0_eng1 where f1=82
master-bin.000002       857     Query   1       930     COMMIT
DROP DATABASE systest2;

Reproducible on 5.5.x-m3, not reproducible on 5.1 and 5.5.2-m2.

Workarounds: 
- set binlog_direct_non_transactional_updates=1 (might be dangerous for some other cases);
- do not use transactional context (start transaction, savepoint) with non-transactional tables.

How to repeat:
--source include/have_log_bin.inc
--source include/have_binlog_format_statement.inc

SET GLOBAL binlog_direct_non_transactional_updates=0;

--disable_warnings
drop database if exists systest2;
--enable_warnings

create database systest2;
use systest2;

CREATE TABLE systest2.tbnum0_eng1 (f1 tinyint) ENGINE = MyISAM;
INSERT INTO systest2.tbnum0_eng1 VALUES (82),(83),(98),(99);
FLUSH LOGS;

--connect (con51,localhost,root,,test)
	USE systest2;
	start transaction;
	delete from tbnum0_eng1 where f1=83;
	SHOW BINLOG EVENTS IN 'master-bin.000002';

	savepoint svpt1;
	delete from tbnum0_eng1 where f1=82;
	SHOW BINLOG EVENTS IN 'master-bin.000002';

--connect (con52,localhost,root,,test)
	USE systest2;
	delete from tbnum0_eng1 where f1=99;
	SHOW BINLOG EVENTS IN 'master-bin.000002';

--connection con51
	commit;
	SHOW BINLOG EVENTS IN 'master-bin.000002';

--disconnect con51
--disconnect con52

--connection default
DROP DATABASE systest2;

--exit

Suggested fix:
If possible do not treat the flow as mixed (in this case it looks like using T-cache only makes it more unsafe); if not possible and if it stays unsafe for SBR, produce a more appropriate warning.

Context: 
   binlog_direct_non_transactional_updates= 0
   binlog_format= STATEMENT

The "savepoint"  is written to the T-cache (i.e. trx-cache) as expected and after that any non-transactional statement is written to the T-cache because it is assumed that a transactional engine was updated. This happens due to the following code:

bool trans_has_updated_trans_table(const THD* thd)
{
  binlog_cache_mngr *const cache_mngr=
    (binlog_cache_mngr*) thd_get_ha_data(thd, binlog_hton);

  return (cache_mngr ? !cache_mngr->trx_cache.empty() : 0);
}

Obviously, the same binlog record shuffling and eventual replication failure happens if instead of SAVEPOINT statement we update a temporary table, even if it is a pure MyISAM table; the same warning "Statement is unsafe because it accesses a non-transactional table after accessing a transactional table within the same transaction" is thrown in this case. 
This is old news that temporary tables behave somewhat like transactional tables (added mostly for SystemQA as an explanation why the failure is so widespread in system tests); but again -- if it is not fixable, it makes sense at least to produce a more appropriate message.

Test case with temporary tables instead of SAVEPOINT:

--source include/have_log_bin.inc
--source include/have_binlog_format_statement.inc

SET GLOBAL binlog_direct_non_transactional_updates=0;

--disable_warnings
drop database if exists systest2;
--enable_warnings

create database systest2;
use systest2;

CREATE TABLE systest2.tbnum0_eng1 (f1 tinyint) ENGINE = MyISAM;
INSERT INTO systest2.tbnum0_eng1 VALUES (82),(83),(98),(99);
FLUSH LOGS;

--connect (con51,localhost,root,,test)
	CREATE TEMPORARY TABLE systest2.tmp ( i INT ) ENGINE = MyISAM;
	INSERT INTO systest2.tmp VALUES (1), (2), (3);
	USE systest2;
	start transaction;
	delete from tbnum0_eng1 where f1=83;
	SHOW BINLOG EVENTS IN 'master-bin.000002';

	DELETE FROM tmp WHERE i = 1;
	delete from tbnum0_eng1 where f1=82;
	SHOW BINLOG EVENTS IN 'master-bin.000002';

--connect (con52,localhost,root,,test)
	USE systest2;
	delete from tbnum0_eng1 where f1=99;
	SHOW BINLOG EVENTS IN 'master-bin.000002';

--connection con51
	commit;
	SHOW BINLOG EVENTS IN 'master-bin.000002';

--disconnect con51
--disconnect con52

--connection default
DROP DATABASE systest2;

--exit

See also BUG#47326.

See also BUG#47327.

Comments "[9 Jul 15:50] Elena Stepanova" are no valid afte BUG#53452.

Basically, the comments say that spurious warning messages may be printed out when temporary tables are used. This happened because temporary tables were handle somehow like transactional tables in what concerned writes to the binary log.

However, after BUG#53452, temporary tables are handled according to the engine in use and the spurious warnings described in "[9 Jul 15:50] Elena Stepanova"  don't happen.