MySQL Bugs: #35217: Strange ndb_binlog_index error inserting rows in MyISAM table

Bug #35217	Strange ndb_binlog_index error inserting rows in MyISAM table
Submitted:	11 Mar 2008 14:48	Modified:	12 Aug 2010 11:26
Reporter:	Emanuele Guarneri	Email Updates:
Status:	Closed	Impact on me:	None
Category:	MySQL Cluster: Replication	Severity:	S3 (Non-critical)
Version:	mysql-5.1-telco-6.2	OS:	Linux (RedHat)
Assigned to:	Frazer Clement	CPU Architecture:	Any
Tags:	5.1.22-ndb-6.3.6, mysqld binlog writing row ndb_binlog_index

Description:
I've build a REPLICATED environment with two clusters and a bunch of mysqld each.
There's a master-slave architecture .

When I insert a lot of rows (using a script) in a table (MyISAM) using a script (so VERY FAST WAY) connected to the MASTER,    I see a lot of errors in the log (SLAVE side) of mysqld that acts as a slave.

080311  8:16:07 [Note] NDB Binlog: logging ./all_tog/lemon (UPDATED,USE_WRITE)

080311  8:17:27 [ERROR] NDB Binlog: Writing row to ndb_binlog_index: 121

080311  8:17:27 [ERROR] NDB Binlog: Writing row to ndb_binlog_index: 121

080311  8:17:28 [ERROR] NDB Binlog: Writing row to ndb_binlog_index: 121

The rows are inserted correctly.

But I don't know why I got these errors in my log.

How to repeat:
Run again my script.

Suggested fix:
Do not run in a FAST WAY.

I've tried to put "sleep 2/3" to slow my script.

And it works !!!!
So it's something concerned the speed of writing rows.

Could it be ??

Thank you for the report.

Could you please provide your script which shows the problem?

Script that insert any rows (very fast, of course) in a test-table

Attachment: seed_gen.sh (application/octet-stream, text), 478 bytes.

No feedback was provided for this bug for over a month, so it is
being suspended automatically. If you are able to provide the
information that was originally requested, please do so and change
the status of the bug back to "Open".

Another observation:

we see those 121 errors for inserting into ndb_binlog_index on a cluster with two API nodes writing binlog. Both API nodes get the same errors at the same time. This must be something systematic and may be related to the actual epoch numbers.

Also receiving this error and willing to work with dev team to find resolution.

[ERROR] NDB Binlog: Writing row to ndb_binlog_index: 121

2 datanodes; 2a pi; 4 slaves

In our setup it seems also to be related with REPLACE commands; or at least;

081119 14:48:20 [ERROR] Slave SQL: Could not execute Write_rows event on table db.table; Duplicate entry '12253' for key 'PRIMARY', Error_code: 1
062; handler error HA_ERR_FOUND_DUPP_KEY; the event's master log daisycon-sql02-bin.000128, end_log_pos 4341916, Error_code: 1062
081119 14:48:20 [Warning] Slave: Duplicate entry '12253' for key 'PRIMARY' Error_code: 1062
081119 14:48:20 [ERROR] Error running query, slave SQL thread aborted. Fix the problem, and restart the slave SQL thread with "SLAVE START". We stopped at log
 'daisycon-sql02-bin.000128' position 4340627

Funny a duplicate error with a REPLACE command ?

Same problem on 5.1.29-ndb-6.3.19-telco here!

Regards,
Robert

(repost)
Workaround, preventing the flooding:

Something that worked fine in one case, is to remove the primary key from the
mysql.ndb_binlog_index table (which is MyISAM btw).
If you do this, you should consider that this table can become big, and if you use
ndb_binlog_index to lookup things, it will be dead slow.

So, for those that do not do (geographic) replication of any NDB table, but still have a
Cluster attached in their Master/Slave(s) setups:

 mysql> USE mysql;
 mysql> SET SQL_LOG_BIN = 0;
 mysql> TRUNCATE ndb_binlog_index;
 mysql> ALTER TABLE ndb_binlog_index DROP PRIMARY KEY;

It should prevent the flooding of the logs. Note that binary logging is disabled for that session! Just in case so it doesn't break MySQL servers which don't have the mysql.ndb_binlog_index table.

BTW, truncating this table from time to time is also good.

The current code in 6.2.19+, 6.3.22+, 7.0.2+ branches includes more debugging output in this error scenario.  If an insert into the ndb_binlog_index table fails, the failing primary key will be output.

None of the logs in the attached issues contain this debugging output, so it's not clear that this problem has been reproduced recently.

A reproduction with the debugging output should help clarify whether the problem is due to coding error (a bug), or procedural error in the management of the ndb_binlog_index table.

No feedback was provided for this bug for over a month, so it is
being suspended automatically. If you are able to provide the
information that was originally requested, please do so and change
the status of the bug back to "Open".

from the error log of a 5.1.32-ndb-6.3.24 installation:

2010-04-07T17:30:12+01:00 <daemon,err> mysqld: 100407 17:30:12 [ERROR]
NDB Binlog: Writing row (11231432/4,0,0/0) to ndb_binlog_index: 121
2010-04-07T17:30:13+01:00 <daemon,err> mysqld: 100407 17:30:13 [ERROR]
NDB Binlog: Writing row (11231432/6,0,0/0) to ndb_binlog_index: 121
2010-04-07T17:30:13+01:00 <daemon,err> mysqld: 100407 17:30:13 [ERROR]
NDB Binlog: Writing row (11231432/7,0,0/0) to ndb_binlog_index: 121
2010-04-07T17:30:13+01:00 <daemon,err> mysqld: 100407 17:30:13 [ERROR]
NDB Binlog: Writing row (11231432/8,0,0/0) to ndb_binlog_index: 121
2010-04-07T17:30:13+01:00 <daemon,err> mysqld: 100407 17:30:13 [ERROR]
NDB Binlog: Writing row (11231432/9,0,0/0) to ndb_binlog_index: 121
2010-04-07T17:30:13+01:00 <daemon,err> mysqld: 100407 17:30:13 [ERROR]
NDB Binlog: Writing row (11231433/1,0,0/0) to ndb_binlog_index: 121
2010-04-07T17:30:13+01:00 <daemon,err> mysqld: 100407 17:30:13 [ERROR]
NDB Binlog: Writing row (11231433/2,0,0/0) to ndb_binlog_index: 121
2010-04-07T17:30:13+01:00 <daemon,err> mysqld: 100407 17:30:13 [ERROR]
NDB Binlog: Writing row (11231433/3,0,0/0) to ndb_binlog_index: 121
2010-04-07T17:30:13+01:00 <daemon,err> mysqld: 100407 17:30:13 [ERROR]
NDB Binlog: Writing row (11231433/4,0,0/0) to ndb_binlog_index: 121
2010-04-07T17:30:14+01:00 <daemon,err> mysqld: 100407 17:30:14 [ERROR]
NDB Binlog: Writing row (11231433/6,0,0/0) to ndb_binlog_index: 121
2010-04-07T17:30:14+01:00 <daemon,err> mysqld: 100407 17:30:14 [ERROR]
NDB Binlog: Writing row (11231433/7,0,0/0) to ndb_binlog_index: 121
2010-04-07T17:30:14+01:00 <daemon,err> mysqld: 100407 17:30:14 [ERROR]
NDB Binlog: Writing row (11231433/8,0,0/0) to ndb_binlog_index: 121
2010-04-07T17:30:14+01:00 <daemon,err> mysqld: 100407 17:30:14 [ERROR]
NDB Binlog: Writing row (11231433/9,0,0/0) to ndb_binlog_index: 121
2010-04-07T17:30:14+01:00 <daemon,err> mysqld: 100407 17:30:14 [ERROR]
NDB Binlog: Writing row (11231434/1,0,0/0) to ndb_binlog_index: 121

Frazer, can you reinvestigate this with the latest issues that has been added

Some additional details:

When GCI < 0x200000 no error
When 0x200000 < GCI < 0x400000 error 121 and only mgcp 0,2,4,6,8 are inserted in binlog_index
When 0x400000 < GCI < 0x800000 error 121 and only mgcp 0,4,8 are inserted in binlog_index
When 0x800000 < GCI error 121 and only mgcp 0,8 are inserted in binlog_index.

Some additional details:

When GCI < 0x200000 no error
When 0x200000 < GCI < 0x400000 error 121 and only mgcp 0,2,4,6,8 are inserted in binlog_index
When 0x400000 < GCI < 0x800000 error 121 and only mgcp 0,4,8 are inserted in binlog_index
When 0x800000 < GCI error 121 and only mgcp 0,8 are inserted in binlog_index.

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/113540

3114 Frazer Clement	2010-07-14
      Bug#35217 Strange ndb_binlog_index error inserting rows in MyISAM table
      
      Fix to problem where WRITE_ROW error 121 was seen by MySQLD when Inserting 
      rows into the ndb_binlog_index table.
      
      The problem was due to the Ndb storage engine handler calling the wrong 
      overloaded variant of a Server internal Api.  This resulted in the 
      64-bit integer epoch being mapped to a 64-bit double precision floating
      point number, with a loss of accuracy for numbers greater than 2^53.  
      The loss of accuracy results in duplicate key errors when the number is
      used as a key.
      
      A testcase is added which verifies that large epoch values do not 
      result in duplicates. 
      
      Other incorrect usage of the Field::store() api is corrected here.

Fix pushed to 
6.2.19
6.3.36
7.0.17
7.1.6

Documented bugfix in the NDB-6.2.19, 6.3.36, 7.0.17, and 7.1.6 changelogs, as follows:

        When inserting rows into the mysql.ndb_binlog_index table,
        duplicate key errors occurred when the size of the epoch number
        (a 64-bit integer) exceeded 2^53. This happened because the NDB
        storage engine handler called the wrong overloaded variant of a
        MySQL Server internal API (the Field::store() method), which
        resulted in the epoch being mapped to a 64-bit double precision
        floating point number and a corrseponding loss of accuracy for
        numbers greater than 2^53.

Closed.

Thank you for your bug report. This issue has been committed to our source repository of that product and will be incorporated into the next release.

If necessary, you can access the source repository and build the latest available version, including the bug fix. More information about accessing the source trees is available at

    http://dev.mysql.com/doc/en/installing-source.html

Frazer: Can you update bug-report with information about in which version
  this was really a problem. So that it can be documented properly.
  If I understood our conversation early correctly,
    it was really only a problem for 6.2/6.3...

/Jonas

Status should be NDI.

The identified problem existed in the 6.2 and 6.3 releases.  The 7.0 and 7.1 releases did not contain the problem as it was fixed as part of a Compiler warnings cleanup as part of Windows porting.

revno: 2856.1.59
committer: Stewart Smith <stewart@flamingspork.com>
branch nick: win-ndbwin32
timestamp: Wed 2008-10-08 12:08:06 +1100
message:
  Fix warning: C4244: 'argument' : conversion from 'Uint64' to 'double', possible loss of data
  
  Wrong method being called.

This was pushed to 6.4.0.

Removed the changelog entry from the 7.0 and 7.1 changelogs, since the issue does not occur there.

This issue is still seen in NDB version Server version: 5.6.29-ndb-7.4.11-cluster-commercial-advanced-log MySQL Cluster Server - Advanced Edition (Commercial).
This means that this was not fixed.