Bug #46554 RBR: pending rows event can be flushed too soon sometimes.
Submitted: 4 Aug 2009 19:50 Modified: 29 Nov 2010 13:45
Reporter: Alfranio Tavares Correia Junior Email Updates:
Status: Closed Impact on me:
None 
Category:MySQL Server: Row Based Replication ( RBR ) Severity:S3 (Non-critical)
Version:6.0-codebase, mysql-next-mr-wl5092 OS:Any
Assigned to: Luis Soares CPU Architecture:Any
Tags: performance, row-based replication

[4 Aug 2009 19:50] Alfranio Tavares Correia Junior
Description:
Delete operations in row mode are creating an event per row what may unnecessarily increase the size of the binary logs and harm replication's
performance.  

How to repeat:
Run the test case below in both 5.1 and azalea 

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

CREATE TABLE t1(a INT PRIMARY KEY, data VARCHAR(100)) ENGINE=Innodb;

INSERT INTO t1 VALUES (1,'a'), (2,'b'), (3, 'c');

DELETE FROM t1;

SHOW BINLOG EVENTS;

DROP TABLE t1;

exit;

Result for the delete operation in 5.1:

master-bin.000001       430     Query   1       498     BEGIN
master-bin.000001       498     Table_map       1       542     table_id: 23 (test.t1)
master-bin.000001       542     Delete_rows     1       595     table_id: 23 flags: STMT_END_F
master-bin.000001       595     Xid     1       622     COMMIT /* xid=23 */

Result for the delete operation in azalea:

master-bin.000001       431     Query   1       499     BEGIN
master-bin.000001       499     Table_map       1       543     table_id: 25 (test.t1)
master-bin.000001       543     Delete_rows     1       577     table_id: 25
master-bin.000001       577     Delete_rows     1       611     table_id: 25
master-bin.000001       611     Delete_rows     1       645     table_id: 25 flags: STMT_END_F
master-bin.000001       645     Xid     1       672     COMMIT /* xid=27 */
[1 Jun 2010 18:22] 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/109801

3151 Luis Soares	2010-06-01
      BUG#46554: RBR: pending rows event can be flushed too soon
      sometimes.
      
      While packing a record into an rows event, the server performs
      several checks to see if a new rows event is needed. Among the
      conditions checked, there's one that deals with the pending
      event ('p') bitmaps and the table ('t') the server accessed for
      the current record. If they are different, then 'p' is flushed
      and a new pending event, 'e', is created. If not, then the same
      pending event is used. However, the only bitmaps compared are
      't'->write_set against 'p'->get_cols(), which in some cases,
      means we are comparing write_sets against read_sets! In current
      versions of the server this may not be a big of a deal (as both
      read and write sets are always fully set).
      
      On the other hand, for the 6.0 codebase this is not the
      case. This means that if the table has a PK, only some columns
      will be flagged in the read_set. In these cases the write_set and
      the read_set will most likely not match causing the pending to be
      flushed.  Additionally, the write_set is meaningless for delete
      events and the read_set is meaningless for write events! So
      comparison must take into account the type of the event to choose
      what bitmap to take from the table to make the comparison.
      
      As stated, this is the case for 6.0 codebase, but also WL#5092
      based tree is affected because the user is given the option to
      choose whether to log partial (so not all columns will be flagged
      in the read and write set) or full rows, accentuating this
      problem.
      
      Finally, This seems to be in fact a regression introduced by
      patch for BUG#33055 plus a post-merge fix that is related:
       - sp1r-mkindahl@dl145h.mysql.com-20080211101647-37854
      
      Since BUG#33055 was backported to WL#5092 tree, this regression
      tagged along.
      
      To fix this problem, we deploy a member function in
      Rows_log_event that is used to perform the correct comparison of
      the pending and table bitmaps.
     @ mysql-test/suite/binlog/t/binlog_row_binlog.test
        Added test case from the bug report.
     @ mysql-test/suite/perfschema/r/binlog_mix.result
        Removing spurious events from the result file.
     @ mysql-test/suite/perfschema/r/binlog_row.result
        Removing spurious events from the result file.
     @ sql/log_event.h
        1. Added utility member function to compare read and write bitmaps.
        2. Added get_cols_ai accessor for m_cols_ai.
     @ sql/sql_class.cc
        Replaced bitmap check with the proper call to the newly introduced
        member function that compares bitmaps according to the event type.
[14 Jun 2010 0:57] 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/110959

3151 Luis Soares	2010-06-14
      BUG#46554: RBR: pending rows event can be flushed too soon
      sometimes.
      
      While packing a record into an rows event, the server performs
      several checks to see if a new rows event is needed. Among the
      conditions checked, there's one that deals with bitmaps from the
      pending event ('p') and the table ('t') that the server accessed
      for the current record. If they are different, then 'p' is
      flushed and a new pending event, 'np', is created. If not, then
      'p' is used. However, the only bitmaps compared are
      't'->write_set against 'p'->get_cols(), which in some cases,
      means we are comparing bitmaps related to write_sets (the ones
      from 't') against bitmaps related to read_sets (the ones from
      'p')!  In current versions of the server this issue is masked (as
      both read and write sets are always fully set).
      
      On the other hand, for 6.0 codebase this was not the case
      because if the table has a PK, only some columns will be flagged
      in the read_set. In such cases the write_set and the read_set
      will most likely not match causing the pending to be flushed.
      Additionally, the write_set is meaningless for delete events and
      the read_set is meaningless for write events! So comparison must
      take into account the type of the event to choose what bitmap to
      take from the table to make the comparison.
      
      As stated, this was the case for 6.0 codebase, but also for trees
      patched with WL#5092, because the user is given the option
      to choose whether to log partial (not all columns will be flagged
      in the read and write set) or full rows. If the user chooses to
      log partial rows, the problem may surface.
      
      Finally, This seems to be in fact a regression introduced by
      patch for BUG#33055 plus a post-merge fix that is related:
       - sp1r-mkindahl@dl145h.mysql.com-20080211101647-37854
      
      Since BUG#33055 was backported to WL#5092 tree, this regression
      tagged along.
      
      To fix this problem, we deploy a member function in
      Rows_log_event that is used to perform the correct comparison of
      the pending and table bitmaps.
     @ mysql-test/suite/binlog/t/binlog_row_binlog.test
        Added test case from the bug report.
     @ mysql-test/suite/perfschema/r/binlog_mix.result
        Removing spurious events from the result file.
     @ mysql-test/suite/perfschema/r/binlog_row.result
        Removing spurious events from the result file.
     @ sql/log_event.h
        1. Added utility member function to compare read and write bitmaps.
        2. Added get_cols_ai accessor for m_cols_ai.
     @ sql/sql_class.cc
        Replaced bitmap check with the proper call to the newly introduced
        member function that compares bitmaps according to the event type.
[16 Jun 2010 17:29] Luis Soares
Queued in mysql-5.1-rpl-wl5092 and mysql-next-mr-wl5092.
PUSHES:
- http://pb2.norway.sun.com/web.py?template=push_details&push=1344573
- http://pb2.norway.sun.com/web.py?template=push_details&push=1344586
[8 Oct 2010 13:29] Bugs System
Pushed into mysql-next-mr (revid:alexander.nozdrin@oracle.com-20101008132832-pbzewvmi9f365ak4) (version source revid:alexander.nozdrin@oracle.com-20101008132832-pbzewvmi9f365ak4) (pib:21)
[13 Nov 2010 16:23] Bugs System
Pushed into mysql-trunk 5.6.99-m5 (revid:alexander.nozdrin@oracle.com-20101113155825-czmva9kg4n31anmu) (version source revid:vasil.dimov@oracle.com-20100629074804-359l9m9gniauxr94) (merge vers: 5.6.99-m4) (pib:21)
[29 Nov 2010 13:45] Jon Stephens
Does not appear to affect any release version; closed without further action.