Implement HeartbeatLogEvent

I ended up debbugging a slow startup with pymysqlreplication,
the stream "stucked" for a few seconds before seeing first events coming in.
For that purpose I ended up implementing HeartbeatLogEvent and
documenting observed mysql behavior.

Signed-off-by: Arthur Gautier <[email protected]>

Author: Arthur Gautier

pymysqlreplication/binlogstream.py

@@ -14,7 +14,7 @@
     QueryEvent, RotateEvent, FormatDescriptionEvent,
     XidEvent, GtidEvent, StopEvent,
     BeginLoadQueryEvent, ExecuteLoadQueryEvent,
-    NotImplementedEvent)
+    HeartbeatLogEvent, NotImplementedEvent)
 from .row_event import (
     UpdateRowsEvent, WriteRowsEvent, DeleteRowsEvent, TableMapEvent)
 
@@ -450,7 +450,9 @@ def _allowed_event_list(self, only_events, ignored_events,
                 WriteRowsEvent,
                 DeleteRowsEvent,
                 TableMapEvent,
-                NotImplementedEvent))
+                HeartbeatLogEvent,
+                NotImplementedEvent,
+                ))
         if ignored_events is not None:
             for e in ignored_events:
                 events.remove(e)

pymysqlreplication/event.py

@@ -119,6 +119,43 @@ def _dump(self):
         print("Transaction ID: %d" % (self.xid))
 
 
+class HeartbeatLogEvent(BinLogEvent):
+    """A Heartbeat event
+    Heartbeats are sent by the master only if there are no unsent events in the
+    binary log file for a period longer than the interval defined by
+    MASTER_HEARTBEAT_PERIOD connection setting.
+
+    A mysql server will also play those to the slave for each skipped
+    events in the log. I (baloo) believe the intention is to make the slave
+    bump its position so that if a disconnection occurs, the slave only
+    reconnects from the last skipped position (see Binlog_sender::send_events
+    in sql/rpl_binlog_sender.cc). That makes 106 bytes of data for skipped
+    event in the binlog. *this is also the case with GTID replication*. To
+    mitigate such behavior, you are expected to keep the binlog small (see
+    max_binlog_size, defaults to 1G).
+    In such a case, the timestamp will be 0 (as in 1970-01-01T00:00:00)
+    to notify the slave of a skipped event.
+
+
+    Attributes:
+        ident: Name of the current binlog
+
+    Note:
+        behavior changed after ced9292eb87b061fb7b8ac2190f01e9dec18f3d7
+        and the timestamp is now always 0.
+    """
+
+    def __init__(self, from_packet, event_size, table_map, ctl_connection, **kwargs):
+        super(HeartbeatLogEvent, self).__init__(from_packet, event_size,
+                                                table_map, ctl_connection,
+                                                **kwargs)
+        self.ident = self.packet.read(event_size).decode()
+
+    def _dump(self):
+        super(HeartbeatLogEvent, self)._dump()
+        print("Current binlog: %s" % (self.ident))
+
+
 class QueryEvent(BinLogEvent):
     '''This evenement is trigger when a query is run of the database.
     Only replicated queries are logged.'''

pymysqlreplication/packet.py

@@ -70,6 +70,7 @@ class BinLogPacketWrapper(object):
         constants.STOP_EVENT: event.StopEvent,
         constants.BEGIN_LOAD_QUERY_EVENT: event.BeginLoadQueryEvent,
         constants.EXECUTE_LOAD_QUERY_EVENT: event.ExecuteLoadQueryEvent,
+        constants.HEARTBEAT_LOG_EVENT: event.HeartbeatLogEvent,
         # row_event
         constants.UPDATE_ROWS_EVENT_V1: row_event.UpdateRowsEvent,
         constants.WRITE_ROWS_EVENT_V1: row_event.WriteRowsEvent,