MySQL Bugs: #12335: If execution stored procedures interleaves, the slave may get out of sync

Bug #12335	If execution stored procedures interleaves, the slave may get out of sync
Submitted:	3 Aug 2005 7:02	Modified:	13 Oct 2005 2:47
Reporter:	Sergey Petrunya	Email Updates:
Status:	Closed	Impact on me:	None
Category:	MySQL Server: Replication	Severity:	S3 (Non-critical)
Version:	5.0	OS:	Any
Assigned to:		CPU Architecture:	Any
Tags:	name_const

Description:
This started to happen because of fix for BUG#11126 (actually this bug is created to track an isolated part BUG#11126 separately)

How to repeat:
n/a

Before fix for BUG#11126 was applied, "CALL sproc" statements were executed as follows:

lock all tables used by sproc body
execute sproc;
unlock tables;
write statement to binlog;

This caused exection of SPs that modify the same data to be serialized, and replaying the binary log produced correct results.

Fix for BUG#11126 makes "CALL sproc()" statements (when they are not invoked from FUNCTIONs/TRIGGERs) to be executed as follows:

for each procedure statement 
{ 
  lock the tables statement uses;
  execute the statement; 
  unlock tables;
}
write the "CALL sproc()" statement to binlog;

Execution of PROCEDUREs may interleave, and replaying the "CALL sproc()" statements may produce incorrect results.

Here is a test case that demonstrates the problem:
connect (c1,localhost,root,,);
connect (c2,localhost,root,,);

connection c1;
drop table if exists t1;
create table t1(a int);

delimiter //;
create procedure p1()
begin
  insert into t1 values (4);
  select get_lock("test", 100);
  update t1 set a=a+4 where a=4;
end//
create procedure p2()
begin
  update t1 set a=a+1;
end//

delimiter ;//

connection c1;
 select get_lock("test", 200);

connection c2;
send call p1();

connection c1;
call p2();
select release_lock("test");

connection c2;
reap
select * from t1; -- This will show  one row with a=5
show binlog events;
-- replaying binlog:
drop table t1;
create table t1(a int);
call p2();
call p1();
select * from t1; --This will show one row with a=8.

PROPOSAL HOW TO FIX THIS BUG

1. HISTORY 
See comment to BUG#8072 for other ideas/options we had. 

2. PER-STATEMENT PROCEDURE REPLICATION
We will fix this as follows: 

ON MASTER:  
Each statement a prelocking-free SP executes (except for CALL to another
prelocking-free SP) is written into binlog separately. 

ON SLAVE/MYSQLBINLOG:
No changes required ? (but see 2.2)

We, however, can't directly replicate all statements SP executes. Here is
the list of issues and how they will be addressed:

2.1 USE OF SP VARIABLES
If SP executes something like
INSERT INTO t1 VALUES(spvar)"
we can't write that into binlog because SP variables can only be used from
within SP. 
The solution is to rewrite the query - replace 'spvar' with its value. 

(Possible issue: SP variable spvar with value 'foo' may have different 
collation/coercibility/other propery then literal 'foo'.

Looking at the code we don't see when this happens but this could be a bug.
We can't tell - there is no spec for SP vars. Anyway if we hit this, we'll
replace "spvar" with "somefunc(spvar_value)" which will have the same
properties as reference to spvar)

2.3 SET SPVAR=spfunc_with_side_effect(...)
We'll put "SET @dummy_session_var=spfunc_with_side_effect(..)" into binary
log.

2.2 CURSOR OPEN STATEMENT
With current SP cursor implementation opening a cursor causes its query to be
executed, and all rows to be retrieved. Query execution may use stored
functions that have side effects. 
We can replicate this either by 
 * putting appopriate "DO ... " statement into binlog.
 * putting the "SELECT... " statement into binlog (and perhaps we'll need to
   make sure slave binlog thread can execute SELECT statements)

2.3 OTHER SP-SPECIFIC STATEMENTS MAY BE SKIPPED
All other SP-specific statements (FETCH, CLOSE, etc) don't modify tables
and so should not be written into binary log.

2.4 SP-SPECIFIC ENVIRONMENT
We may need to set sql_mode, current database and other environment that
SP sets for its statements. (perhaps the current code will already handle
this, just need to check)

PROPOSAL HOW TO FIX THIS BUG

1. HISTORY 
* See comment to BUG#8072 for other ideas/options we had. 
* Added SELECT ... INTO statement missed in prev. version.
 
2. PER-STATEMENT PROCEDURE REPLICATION
We will fix this as follows: 

ON MASTER:  
Each statement a prelocking-free SP executes (except for CALL to another
prelocking-free SP) is written into binlog separately. 

ON SLAVE/MYSQLBINLOG:
See section 2.3: we may need to make slave to be able to execute SELECT 
statements.

We, however, can't directly replicate all statements SP executes. Here is
the list of issues and how they will be addressed:
 
 
2.1 USE OF SP VARIABLES
If SP executes something like
INSERT INTO t1 VALUES(spvar)"
we can't write that into binlog because SP variables can only be used from
within SP. 
The solution is to rewrite the query - replace 'spvar' with its value. 

(Possible issue: SP variable spvar with value 'foo' may have different 
collation/coercibility/other propery then literal 'foo'.

Looking at the code we don't see when this happens but this could be a bug.
We can't tell - there is no spec for SP vars. Anyway if we hit this, we'll
replace "spvar" with "somefunc(spvar_value)" which will have the same
properties as reference to spvar)
 
 
2.2 SET SPVAR=spfunc_with_side_effect(...)
We'll put "SET @dummy_session_var=spfunc_with_side_effect(..)" into binary
log.
 
 
2.3 CURSOR OPEN STATEMENT
With current SP cursor implementation opening a cursor causes its query to be
executed, and all rows to be retrieved. Query execution may use stored
functions that have side effects. 
We can replicate this either by 
 * putting appopriate "DO ... " statement into binlog.
 * putting the "SELECT... " statement into binlog (and perhaps we'll need to
   make sure slave binlog thread can execute SELECT statements)
 
 
2.4 SELECT ... INTO spvar,...
The INTO ... part should be replaced with 'LIMIT 1' when writing into
binlog.
 
 
2.5 OTHER SP-SPECIFIC STATEMENTS MAY BE SKIPPED
All other SP-specific statements (FETCH, CLOSE, etc) don't modify tables
and so should not be written into binary log.
 
 
2.6 SP-SPECIFIC ENVIRONMENT
We may need to set sql_mode, current database and other environment that
SP sets for its statements. (perhaps the current code will already handle
this, just need to check)

Consider this case:
Thread t1 executes p1: 
create procedure p1()
begin
  insert into t1 values (sfunc1(1)); --(1)
  -- time X
  insert into t1 values (sfunc1(1)); --(2)
end //

thread2, at time X does:

drop function sfunc1;
create function sfunc1 <different body>

With current SP cache architecture thread 1 will use old definition of
sfunc() at location (2).

In binary log we will get:

insert into t1 values (sfunc1(1)); 
drop function sfunc();
create function sfunc <different body>
insert into t1 values (sfunc1(1));

which cause an effect different from one on the master.

A possible solution to the problem in previous comment: 
Allow to have several caches in a thread, and add a command to switch between the caches (each cache on the slave/mysqlbinlog-reader side corresponds to one thread on the master).

Test Case for rbr:
# Includes
-- source include/have_binlog_format_row.inc
-- source include/have_innodb.inc
-- source include/master-slave.inc

# Begin clean up test section
connection master;
--disable_warnings
DROP PROCEDURE IF EXISTS test.p1;
DROP PROCEDURE IF EXISTS test.p2;
DROP TABLE IF EXISTS test.t2;
--enable_warnings
# End of cleanup

# Begin test section 1

CREATE TABLE test.t1(a INT,PRIMARY KEY(a))ENGINE=INNODB;

delimiter |;
CREATE PROCEDURE test.p1()
BEGIN
  INSERT INTO test.t1 VALUES (4);
  SELECT  get_lock("test", 100);
  UPDATE test.t1 set a=a+4 WHERE a=4;
END|
CREATE PROCEDURE test.p2()
BEGIN
  UPDATE test.t1 SET a=a+1;
END|
delimiter ;|

SELECT get_lock("test", 200);

connection master1;
send CALL test.p1();

connection master;
CALL test.p2();
SELECT release_lock("test");
SELECT * FROM test.t1;
show binlog events;

connection slave;
SELECT * FROM test.t1;

connection master;
DROP TABLE IF EXISTS test.t1;
CREATE TABLE test.t1(a INT,PRIMARY KEY(a))ENGINE=INNODB;
CALL test.p2();
CALL test.p1();
SELECT * FROM test.t1;

connection slave;
SELECT * FROM test.t1;
connection master;
show binlog events from 719;

DROP PROCEDURE IF EXISTS test.p1;
DROP PROCEDURE IF EXISTS test.p2;
DROP TABLE IF EXISTS test.t1;
----------
results
----------
+ CREATE TABLE test.t1(a INT,PRIMARY KEY(a))ENGINE=INNODB;
+ CREATE PROCEDURE test.p1()
+ BEGIN
+ INSERT INTO test.t1 VALUES (4);
+ SELECT  get_lock("test", 100);
+ UPDATE test.t1 set a=a+4 WHERE a=4;
+ END|
+ CREATE PROCEDURE test.p2()
+ BEGIN
+ UPDATE test.t1 SET a=a+1;
+ END|
+ SELECT get_lock("test", 200);
+ get_lock("test", 200)
+ 1
+  CALL test.p1();
+ CALL test.p2();
+ SELECT release_lock("test");
+ release_lock("test")
+ 1
+ SELECT * FROM test.t1;
+ a
+ 5
+ show binlog events;
+ Log_name      Pos     Event_type      Server_id       End_log_pos     Info
+ master-bin.000001     4       Format_desc     1       102     Server ver: 5.0.12-beta-log, Binlog ver: 4
+ master-bin.000001     102     Query   1       193     use `test`; DROP TABLE IF EXISTS test.t2
+ master-bin.000001     193     Query   1       311     use `test`; CREATE TABLE test.t1(a INT,PRIMARY KEY(a))ENGINE=INNODB
+ master-bin.000001     311     Query   1       509     use `test`; CREATE PROCEDURE test.p1()
+ BEGIN
+ INSERT INTO test.t1 VALUES (4);
+ SELECT  get_lock("test", 100);
+ UPDATE test.t1 set a=a+4 WHERE a=4;
+ END
+ master-bin.000001     509     Query   1       634     use `test`; CREATE PROCEDURE test.p2()
+ BEGIN
+ UPDATE test.t1 SET a=a+1;
+ END
+ master-bin.000001     634     Query   1       719     use `test`; CALL test.p2()
+ master-bin.000001     719     Query   1       804     use `test`; CALL test.p1()
+ SELECT * FROM test.t1;
+ a
+ DROP TABLE IF EXISTS test.t1;
+ CREATE TABLE test.t1(a INT,PRIMARY KEY(a))ENGINE=INNODB;
+ CALL test.p2();
+ CALL test.p1();
+ get_lock("test", 100)
+ 0
+ SELECT * FROM test.t1;
+ a
+ 8
+ SELECT * FROM test.t1;
+ a
+ show binlog events from 719;
+ Log_name      Pos     Event_type      Server_id       End_log_pos     Info
+ master-bin.000001     719     Query   1       804     use `test`; CALL test.p1()
+ master-bin.000001     804     Query   1       895     use `test`; DROP TABLE IF EXISTS test.t1
+ master-bin.000001     895     Query   1       1013    use `test`; CREATE TABLE test.t1(a INT,PRIMARY KEY(a))ENGINE=INNODB
+ master-bin.000001     1013    Query   1       1090    use `test`; CALL test.p2()
+ master-bin.000001     1090    Query   1       1175    use `test`; CALL test.p1()

Slave.err log:

050813 15:57:48 [ERROR] Slave: Error 'PROCEDURE test.p1 can't return a result set in the given context' on query. Default database: 'test'. Query: 'call test.p1()', Error_code: 1312
050813 15:57:48 [ERROR] Error running query, slave SQL thread aborted. Fix the problem, and restart the slave SQL thread with "SLAVE START". We stopped at log 'master-bin.000001' position 706

Got into unexpected difficulties with binlogging function calls that modify both transactional and non-transactional tables.
THe pile of other non-significant problems too turned out to be bigger then expected.

A patch for this bug has been committed. After review, it may
be pushed to the relevant source trees for release in the next
version. You can access the patch from:

  http://lists.mysql.com/internals/28730

A patch for this bug has been committed. After review, it may
be pushed to the relevant source trees for release in the next
version. You can access the patch from:

  http://lists.mysql.com/internals/28832

A patch for this bug has been committed. After review, it may
be pushed to the relevant source trees for release in the next
version. You can access the patch from:

  http://lists.mysql.com/internals/28837

Reviewed by Monty and Igor.

Fix pushed into 5.0.13 tree

An isolated part of this bug persists as BUG#12815

Noted in 5.0.13 changelog.

Here are more details about the change, as requested by support team:

1. SELECTs 
SELECTs are not written into binary log. Still statements like
"SELECT spfunc_with_side_effect(t1.x) FROM t1" is replicated correctly.
This is achieved by using the following technique:
When MySQL invokes a FUNCTION it catches all binlog write attempts made 
from inside the function. If there were binlog write attempts during
FUNCTION invocation, MySQL writes "DO spfunc(<param values>)" into the
binary log.

Example:

CREATE FUNCTION f1(a INT) RETURNS INT
BEGIN
  IF (a < 3) THEN 
    INSERT INTO t2 VALUES (a);
  END IF;
END

CREATE TABLE t1 (a INT);
INSERT INTO t1 VALUES (1),(2),(3);

Now if one runs 

SELECT f1(a) FROM t1;

MySQL will write 

DO f1(1);
DO f1(2);

into the binary log.

Before the fix for this bug SELECT statements were not replicated at all which could cause updates on the master to be not applied on the slave.
Fix for BUG#12844 made SET statement use this technique too.

2. CALLs
CALL statements are now never written to binary log.
When the master executes "CALL sproc()" it writes each statement executed
inside the procedure separatey.

When a statement is written to binary log, references to local SP variables
are substituted with "NAME_CONST('sp-variable-name', <variable-value>)". The
statement obtained by this substitution has the same effect as original one
but can be run by slave SQL thread (or any mysql client so one can run
mysqlbinlog output to it as usual).

NAME_CONST('name', value) is a function that returns value of value which
has a name property of 'name':

mysql> select NAME_CONST('name', 3);
+------+
| name |
+------+
|    3 |
+------+
1 row in set (0.00 sec)

We discourage use of this "function" by the users. Attempts to evaluate this
function with non-constant arguments will produce an error.

If a procedure executes a SELECT ... [INTO ...] statement, it is processed 
as described in section 1. The same function-call-catching technique is used
to catch data-modifiying FUNCTION calls made when evaluating PROCEDURE
parameters and executing SP-specific constructs like 
"IF (sp_func_with_side_effect()) THEN...".

Changelog entry was moved to 5.0.12 (the
fix was backported).

Paul's latest comment indicates a changelog entry is in place, closing.