Bug #49559 Log empty epoch does not log transaction which update nothing
Submitted: 9 Dec 2009 13:54 Modified: 29 Mar 2010 6:37
Reporter: Geert Vanderkelen Email Updates:
Status: Closed Impact on me:
None 
Category:MySQL Cluster: Replication Severity:S3 (Non-critical)
Version:mysql-5.1-telco-7.0 OS:Any
Assigned to: Martin Skold CPU Architecture:Any
Tags: mysql-5.1.39-ndb-7.0.9

[9 Dec 2009 13:54] Geert Vanderkelen 
Description:
Doing 3 inserts and deleting these same 3 rows right away result in an empty transaction, which is not binary logged, even though --ndb-log-empty-epochs is active for mysqld.

How to repeat:
Relevant mysqld configuration
[mysqld]
server_id = 100
log_bin = machA
binlog_format = ROW
ndbcluster
ndb_connectstring = localhost:1186
ndb-log-orig = 1
ndb-log-empty-epochs = 1

CREATE TABLE t1 (
id INT UNSIGNED NOT NULL AUTO_INCREMENT,
c1 VARCHAR(30),
PRIMARY KEY (id)
) ENGINE=ndb;

mysql> SELECT HEX(epoch) AS "MasterEpoch",inserts,deletes FROM mysql.ndb_binlog_index ORDER BY epoch DESC;
Empty set (0.00 sec)

BEGIN;
 INSERT INTO t1 (c1) VALUES ('aaa'),('bbb'),('ccc');
 DELETE FROM t1 WHERE id IN (1,2,3);
COMMIT;

mysql> SELECT HEX(epoch) AS "MasterEpoch",inserts,deletes FROM mysql.ndb_binlog_index ORDER BY epoch DESC;
Empty set (0.00 sec)

The following however works (whether ndb-log-empty-epochs is set or not):

 BEGIN;
   INSERT INTO t1 (c1) VALUES ('aaa'),('bbb'),('ccc');
 COMMIT;
 BEGIN;
   DELETE FROM t1 WHERE id IN (1,2,3);
 COMMIT;

mysql> SELECT HEX(epoch) AS "MasterEpoch",inserts,deletes FROM mysql.ndb_binlog_index ORDER BY epoch DESC;
+-------------+---------+---------+
| MasterEpoch | inserts | deletes |
+-------------+---------+---------+
| F7900000011 |       3 |       3 |
+-------------+---------+---------+
[9 Dec 2009 14:16] Geert Vanderkelen 
Verified using 7.0.9b
[9 Dec 2009 14:40] Geert Vanderkelen 
It looks like it works using 6.3.28:

> SELECT HEX(epoch) AS "MasterEpoch",inserts,deletes FROM mysql.ndb_binlog_index ORDER BY epoch DESC;
+-------------+---------+---------+
| MasterEpoch | inserts | deletes |
+-------------+---------+---------+
| 8500000004  |       3 |       0 |
+-------------+---------+---------+

but why 3 inserts?
[14 Dec 2009 14:24] Jørgen Austvik 
Documentation should be added for this flag
[9 Feb 2010 11:32] Martin Skold 
=== modified file 'sql/ha_ndbcluster_binlog.cc'
--- sql/ha_ndbcluster_binlog.cc	2010-01-27 09:29:10 +0000
+++ sql/ha_ndbcluster_binlog.cc	2010-02-04 09:05:40 +0000
@@ -5922,7 +5922,9 @@ restart_cluster_failure:
         }
       }
     }
-    else if (res > 0)
+    else if (res > 0 ||
+             (opt_ndb_log_empty_epochs &&
+              gci > ndb_latest_handled_binlog_epoch))
     {
       DBUG_PRINT("info", ("pollEvents res: %d", res));
       thd->proc_info= "Processing events";
@@ -5966,6 +5968,35 @@ restart_cluster_failure:
       }
       NdbEventOperation *pOp= i_ndb->nextEvent();
       ndb_binlog_index_row _row;
+      if (!pOp)
+      {
+        /*
+          Must be an empty epoch since the condition
+          (opt_ndb_log_empty_epochs &&
+           gci > ndb_latest_handled_binlog_epoch)
+          must be true we write empty epoch into
+          ndb_binlog_index
+        */
+        DBUG_PRINT("info", ("Writing empty epoch for gci %llu", gci));
+        ndb_binlog_index_row *rows= &_row;
+        bzero((char*)&_row, sizeof(_row));
+        thd->variables.character_set_client= &my_charset_latin1;
+        injector::transaction trans;
+        if (!trans.good())
+        {
+          DBUG_PRINT("info", ("Initializing transaction"));
+          inj->new_trans(thd, &trans);
+        }        
+        injector::transaction::binlog_pos start= trans.start_pos();
+        rows->gci= (gci >> 32); // Expose gci hi/lo
+        rows->epoch= gci;
+        rows->master_log_file= start.file_name();
+        rows->master_log_pos= start.file_pos();
+        if (ndb_log_binlog_index)
+        {
+          ndb_add_ndb_binlog_index(thd, rows);
+        }
+      }
       while (pOp != NULL)
       {
         ndb_binlog_index_row *rows= &_row;

=== modified file 'sql/set_var.cc'
--- sql/set_var.cc	2009-12-17 15:43:35 +0000
+++ sql/set_var.cc	2010-02-01 16:19:30 +0000
@@ -75,6 +75,7 @@ extern ulong ndb_report_thresh_binlog_me
 extern my_bool ndb_log_binlog_index;
 extern my_bool opt_ndb_log_update_as_write;
 extern my_bool opt_ndb_log_updated_only;
+extern my_bool opt_ndb_log_empty_epochs;
 #endif
 
 extern CHARSET_INFO *character_set_filesystem;
@@ -687,6 +688,8 @@ static sys_var_bool_ptr
 sys_ndb_log_update_as_write(&vars, "ndb_log_update_as_write", &opt_ndb_log_update_as_write);
 static sys_var_bool_ptr
 sys_ndb_log_updated_only(&vars, "ndb_log_updated_only", &opt_ndb_log_updated_only);
+static sys_var_bool_ptr
+sys_ndb_log_empty_epochs(&vars, "ndb_log_empty_epochs", &opt_ndb_log_empty_epochs);
 static sys_var_thd_bool
 sys_ndb_use_exact_count(&vars, "ndb_use_exact_count", &SV::ndb_use_exact_count);
 static sys_var_thd_bool
[22 Mar 2010 14: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/104007

3164 Martin Skold	2010-03-22
      Bug#49559 Log empty epoch does not log transaction which update nothing: Added handling of empty epochs if --ndb-log-empty-epochs is set
      added:
        mysql-test/suite/rpl_ndb/r/rpl_ndb_empty_epoch.result
        mysql-test/suite/rpl_ndb/t/rpl_ndb_empty_epoch.test
      modified:
        sql/ha_ndbcluster_binlog.cc
        sql/set_var.cc
[23 Mar 2010 8:41] 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/104052

3471 Martin Skold	2010-03-23 [merge]
      Merge
      added:
        mysql-test/suite/rpl_ndb/r/rpl_ndb_empty_epoch.result
        mysql-test/suite/rpl_ndb/t/rpl_ndb_empty_epoch.test
      modified:
        mysql-test/suite/ndb/r/ndb_basic.result
        sql/ha_ndbcluster_binlog.cc
        sql/set_var.cc
[23 Mar 2010 10:30] 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/104064

3533 Martin Skold	2010-03-23 [merge]
      Modified
      added:
        mysql-test/suite/rpl_ndb/r/rpl_ndb_empty_epoch.result
        mysql-test/suite/rpl_ndb/t/rpl_ndb_empty_epoch.test
      modified:
        mysql-test/suite/ndb/r/ndb_basic.result
        sql/ha_ndbcluster_binlog.cc
        sql/set_var.cc
[24 Mar 2010 15:12] 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/104221

3168 Martin Skold	2010-03-24
      Bug#49559 Log empty epoch does not log transaction which update nothing: Fixed valgrind detected issue, restart transaction for each iteration
      modified:
        sql/ha_ndbcluster_binlog.cc
[24 Mar 2010 15:33] Bugs System 
Pushed into 5.1.44-ndb-7.0.14 (revid:jonas@mysql.com-20100324152816-b75ufa5800qh1a5x) (version source revid:jonas@mysql.com-20100324152816-b75ufa5800qh1a5x) (merge vers: 5.1.44-ndb-7.0.14) (pib:16)
[25 Mar 2010 8:42] Martin Skold 
Pushed to mysql-5.1-telco-6.3 - mysql-5.1-telco-7.0 - mysql-5.1-telco-7.1
[29 Mar 2010 6:37] Jon Stephens 
Documented bugfix in the NDB-6.3.33, 7.0.14, and 7.1.3 changelogs, as follows:

        The --ndb-log-empty-epochs option did not work correctly.

Closed.