Bug #47678 Changes to n-tables that happen early in a trans. are only flushed upon commit
Submitted: 28 Sep 2009 15:26 Modified: 19 Dec 2009 11:39
Reporter: Alfranio Correia Email Updates:
Status: Closed Impact on me:
None 
Category:MySQL Server: Row Based Replication ( RBR ) Severity:S3 (Non-critical)
Version:5.1 OS:Any
Assigned to: Alfranio Correia CPU Architecture:Any
Tags: regression
Triage: Triaged: D2 (Serious)

[28 Sep 2009 15:26] Alfranio Correia
Description:
In RBR, changes to non-transactional tables that happen early in a transaction are
not immediately flushed upon committing a statement. This behavior may, however, break consistency since changes done to non-transactional tables become
immediately visible to other connections.

How to repeat:
Test case:
----------

--source include/have_binlog_format_row.inc
--source include/have_innodb.inc

CREATE TABLE tt (a int) engine=innodb;
CREATE TABLE nt (a int) engine=myisam;

BEGIN;
INSERT INTO nt VALUES(1);
INSERT INTO nt VALUES(2);
INSERT INTO nt VALUES(3);
INSERT INTO tt VALUES(1);
INSERT INTO tt VALUES(2);
INSERT INTO nt VALUES(4);
INSERT INTO tt VALUES(3);
COMMIT;

SHOW BINLOG EVENTS;

DROP TABLE tt;
DROP TABLE nt;

exit;

We have the wrong ouput:
------------------------

master-bin.000001       306     Query   1       374     BEGIN
master-bin.000001       374     Table_map       1       415     table_id: 23 (test.nt)
master-bin.000001       415     Write_rows      1       449     table_id: 23 flags: STMT_END_F
master-bin.000001       449     Table_map       1       490     table_id: 23 (test.nt)
master-bin.000001       490     Write_rows      1       524     table_id: 23 flags: STMT_END_F
master-bin.000001       524     Table_map       1       565     table_id: 23 (test.nt)
master-bin.000001       565     Write_rows      1       599     table_id: 23 flags: STMT_END_F
master-bin.000001       599     Table_map       1       640     table_id: 24 (test.tt)
master-bin.000001       640     Write_rows      1       674     table_id: 24 flags: STMT_END_F
master-bin.000001       674     Table_map       1       715     table_id: 24 (test.tt)
master-bin.000001       715     Write_rows      1       749     table_id: 24 flags: STMT_END_F
master-bin.000001       749     Table_map       1       790     table_id: 23 (test.nt)
master-bin.000001       790     Write_rows      1       824     table_id: 23 flags: STMT_END_F
master-bin.000001       824     Table_map       1       865     table_id: 24 (test.tt)
master-bin.000001       865     Write_rows      1       899     table_id: 24 flags: STMT_END_F
master-bin.000001       899     Xid     1       926     COMMIT /* xid=15 */

The correct output should be:
-----------------------------

master-bin.000001       4       Format_desc     1       106     Server ver: 5.1.40-debug-log, Binlog ver: 4
master-bin.000001       106     Query   1       206     use `test`; CREATE TABLE tt (a int) engine=innodb  
master-bin.000001       206     Query   1       306     use `test`; CREATE TABLE nt (a int) engine=myisam  
master-bin.000001       306     Query   1       374     BEGIN                                              
master-bin.000001       374     Table_map       1       415     table_id: 23 (test.nt)                     
master-bin.000001       415     Write_rows      1       449     table_id: 23 flags: STMT_END_F             
master-bin.000001       449     Query   1       518     COMMIT                                             
master-bin.000001       518     Query   1       586     BEGIN                                              
master-bin.000001       586     Table_map       1       627     table_id: 23 (test.nt)                     
master-bin.000001       627     Write_rows      1       661     table_id: 23 flags: STMT_END_F             
master-bin.000001       661     Query   1       730     COMMIT                                             
master-bin.000001       730     Query   1       798     BEGIN                                              
master-bin.000001       798     Table_map       1       839     table_id: 23 (test.nt)                     
master-bin.000001       839     Write_rows      1       873     table_id: 23 flags: STMT_END_F             
master-bin.000001       873     Query   1       942     COMMIT                                             
master-bin.000001       942     Query   1       1010    BEGIN                                              
master-bin.000001       1010    Table_map       1       1051    table_id: 24 (test.tt)                     
master-bin.000001       1051    Write_rows      1       1085    table_id: 24 flags: STMT_END_F             
master-bin.000001       1085    Table_map       1       1126    table_id: 24 (test.tt)                     
master-bin.000001       1126    Write_rows      1       1160    table_id: 24 flags: STMT_END_F             
master-bin.000001       1160    Table_map       1       1201    table_id: 23 (test.nt)                     
master-bin.000001       1201    Write_rows      1       1235    table_id: 23 flags: STMT_END_F             
master-bin.000001       1235    Table_map       1       1276    table_id: 24 (test.tt)                     
master-bin.000001       1276    Write_rows      1       1310    table_id: 24 flags: STMT_END_F             
master-bin.000001       1310    Xid     1       1337    COMMIT /* xid=15 */

Suggested fix:
=== modified file 'sql/log.cc'
--- sql/log.cc  2009-09-28 12:55:54 +0000
+++ sql/log.cc  2009-09-28 14:22:43 +0000
@@ -1538,7 +1538,10 @@
               YESNO(in_transaction),
               YESNO(thd->transaction.all.modified_non_trans_table),
               YESNO(thd->transaction.stmt.modified_non_trans_table)));
-  if (!in_transaction || all)
+  if (!in_transaction || all ||
+      (!all && !trx_data->at_least_one_stmt_committed &&
+      !stmt_has_updated_trans_table(thd) &&
+      thd->transaction.stmt.modified_non_trans_table))
   {
     Query_log_event qev(thd, STRING_WITH_LEN("COMMIT"), TRUE, TRUE, 0);
     error= binlog_end_trans(thd, trx_data, &qev, all);
[28 Sep 2009 15:32] Alfranio Correia
The suggested fix is based on BUG#47287.
[29 Sep 2009 9:17] Bugs System
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/commits/84962

3140 Alfranio Correia	2009-09-29
      BUG#47678 Changes to n-tables that happen early in a trans. are only flushed upon commit
      
        Let
          - T be a transactional table and N non-transactional table.
          - B be begin, C commit and R rollback.
          - N be a statement that accesses and changes only N-tables.
          - T be a statement that accesses and changes only T-tables.
      
      In RBR, changes to N-tables that happen early in a transaction are not immediately flushed
      upon committing a statement. This behavior may, however, break consistency in the presence
      of concurrency since changes done to N-tables become immediately visible to other
      connections. To fix this problem, we do the following:
      
        . B N N T C would log - B N C B N C B T C.
        . B N N T R would log - B N C B N C B T R.
      
      Note that, we are not preserving history from the master as we are introducing a commit that
      never happened. However, this seems to be more acceptable than the possibility of breaking
      consistency in the presense of concurrency.
[6 Oct 2009 0:54] Bugs System
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/commits/85810

3140 Alfranio Correia	2009-10-06
      BUG#47678 Changes to n-tables that happen early in a trans. are only flushed upon commit
      
        Let
          - T be a transactional table and N non-transactional table.
          - B be begin, C commit and R rollback.
          - N be a statement that accesses and changes only N-tables.
          - T be a statement that accesses and changes only T-tables.
      
      In RBR, changes to N-tables that happen early in a transaction are not immediately flushed
      upon committing a statement. This behavior may, however, break consistency in the presence
      of concurrency since changes done to N-tables become immediately visible to other
      connections. To fix this problem, we do the following:
      
        . B N N T C would log - B N C B N C B T C.
        . B N N T R would log - B N C B N C B T R.
      
      Note that we are not preserving history from the master as we are introducing a commit that
      never happened. However, this seems to be more acceptable than the possibility of breaking
      consistency in the presence of concurrency.
[7 Oct 2009 18:00] Alfranio Correia
Pushed to mysql-5.1-bugteam and mysql-pe.
[14 Oct 2009 14:39] Bugs System
Pushed into 5.1.41 (revid:joro@sun.com-20091014143611-cphb0enjlx6lpat1) (version source revid:alfranio.correia@sun.com-20091006102536-3puq0gqxwe5oqid5) (merge vers: 5.1.40) (pib:13)
[15 Oct 2009 7:55] Jon Stephens
Documented bugfix in the 5.1.41 changelog as follows:

        When using row-based replication, changes to non-transactional
        tables that occurred early in a transaction were not immediately
        flushed upon committing a statement. This behavior could break
        consistency since changes made to non-transactional tables
        become immediately visible to other connections.

Set status to NDI in case of additional pushes.

(If this won't get pushed further, you can go ahead and close. Thanks!)
[22 Oct 2009 6:35] Bugs System
Pushed into 6.0.14-alpha (revid:alik@sun.com-20091022063126-l0qzirh9xyhp0bpc) (version source revid:alik@sun.com-20091019135554-s1pvptt6i750lfhv) (merge vers: 6.0.14-alpha) (pib:13)
[22 Oct 2009 7:07] Bugs System
Pushed into 5.5.0-beta (revid:alik@sun.com-20091022060553-znkmxm0g0gm6ckvw) (version source revid:alik@sun.com-20091015131113-wldlkdtoe9oebb2z) (merge vers: 5.5.0-beta) (pib:13)
[22 Oct 2009 15:13] Jon Stephens
Also documented in the 5.5.0 and 6.0.14 changelogs.

Closed.
[18 Dec 2009 10:33] Bugs System
Pushed into 5.1.41-ndb-7.1.0 (revid:jonas@mysql.com-20091218102229-64tk47xonu3dv6r6) (version source revid:jonas@mysql.com-20091218095730-26gwjidfsdw45dto) (merge vers: 5.1.41-ndb-7.1.0) (pib:15)
[18 Dec 2009 10:49] Bugs System
Pushed into 5.1.41-ndb-6.2.19 (revid:jonas@mysql.com-20091218100224-vtzr0fahhsuhjsmt) (version source revid:jonas@mysql.com-20091217101452-qwzyaig50w74xmye) (merge vers: 5.1.41-ndb-6.2.19) (pib:15)
[18 Dec 2009 11:04] Bugs System
Pushed into 5.1.41-ndb-6.3.31 (revid:jonas@mysql.com-20091218100616-75d9tek96o6ob6k0) (version source revid:jonas@mysql.com-20091217154335-290no45qdins5bwo) (merge vers: 5.1.41-ndb-6.3.31) (pib:15)
[18 Dec 2009 11:19] Bugs System
Pushed into 5.1.41-ndb-7.0.11 (revid:jonas@mysql.com-20091218101303-ga32mrnr15jsa606) (version source revid:jonas@mysql.com-20091218064304-ezreonykd9f4kelk) (merge vers: 5.1.41-ndb-7.0.11) (pib:15)
[19 Dec 2009 11:39] Jon Stephens
No additional changelog entries needed. Setting back to Closed state.