Description:
There are two problems, but only one fix, so I'm reporting them as one bug.
(P1) Assume:
- There are three servers replicating in a chain:
master_1 -> master_2 -> master_3
- Each server has local time, and the servers reside in Reykjavik, Stockholm,
and Helsinki, respectively. So when master_1 has system time 9:00, then
master_2 has system time 10:00 and master_3 has system time 11:00.
Further, assume that master_1 executes a query at 9:00, and the query is replicated to master_2 and master_3 instantly. Then:
- The query is binlogged with time 9:00 on master_1
- When master_3 receives the query, the query still has timestamp 9:00, but
master_3 has system time 11:00.
- master_3 knows that its clock is 1 hour ahead of master_2. I.e.:
mi->clock_diff_with_master = 3600
- master_3 takes the known difference between its own clock and the immediate
master master_2 into account when computing seconds_behind_master. However,
the event's timestamp is stored relative to the original master's system
time. So master_3 will report Seconds_behind_master as:
11:00 - 9:00 - mi->clock_diff_with_master = 1 hour.
This is wrong since master_3 is not behind master_2 at all.
(P2) mi->clock_diff_with_master is lost when the IO thread reconnects. So if the SQL thread is behind the IO thread and the user issues CHANGE MASTER to another server that has a different clock difference, then Seconds_behind_master will be wrong for the events of the relay log that originate from the first master.
A problem similar to (P1) exists in the current work-in-progress implementation of WL#344. The fix outlined below would fix the problem also for WL#344.
How to repeat:
Difficult to setup since it requires three different computers.
Suggested fix:
Actions:
(A1) Clarify if seconds_behind_master denotes:
(A1-1) the number of seconds behind the immediate master (master_2); or
(A1-2) the number of seconds behind the originating master (master_1).
(A2) Ensure it works consistently with the semantics defined in (A1).
I think (A1-1) makes more sense than (A1-2). (If we used (A1-2), and master_1 and master_2 would both receive updates from clients, then seconds_behind_master on master_3 would alternate between the time that master_3 is behind master_2 and the time that master_3 is behind master_1. That would be unusable.)
To understand the fix, we need to understand more of the background. Some background facts:
(F1) Every binlog event has a timestamp. The timestamp is equivalent to the
return value of the mysql function UNIX_TIMESTAMP() on the server where
the query was first executed. In other words, it is set to the value of
the mysql variable @@session.timestamp if @@session.timestamp is set; or
to the return value of the C function call time(0) at the start of the
query otherwise.
(F2) When the binlog is copied to the slave relay log, the timestamp is
preserved. When the slave SQL thread executes the event, it first sets the
slave SQL thread's @@session.timestamp to the event's timestamp.
(F3) A consequence of (F1) and (F2): when the query is binlogged on the slave,
it still has the same timestamp as it had on the master.
(F3) A consequence of (F1) and (F2): when queries like
'INSERT INTO t1 VALUES(UNIX_TIMESTAMP())' are executed on the slave, the
inserted value is the time that the query was executed on the originating
master. This prevents the slave from going out of sync.
(F4) When the IO thread starts, it computes the difference in system clock
between itself and its master (it does this by connecting to the master as
a client and executing 'SELECT UNIX_TIMESTAMP()', and subtracts the return
value of the C function call time(0)). The difference is stored in
mi->clock_diff_with_master.
(F5) When the slave computes Seconds_behind_master is computed, it uses the
last timestamp of any event retrieved from the master, and adds
mi->clock_diff_with_master to it.
Due to (F3), we have to keep the time that the query was executed on the originating master as part of the event, at least for Query_log_events. In order to not break replication from old to new server, we even have to keep this time in the event's timestamp. But we can change the timestamp of other event types, and we can add new status variables to Query_log_events (unknown status variables are ignored on old servers).
So a suggested fix is to change the binlog format as follows:
(B1) Add a new status variable to Query_log_event, say
Q_IMMEDIATE_MASTER_TIMESTAMP
(B2) For event types other than Query_log_event, the event's timestamp is
modified as follows: if the event is in a binlog, it holds the time when
the event was executed on the server that wrote the binlog. If the event
is in a relay log, it holds the time when the event was executed on the
immediate master, using the slave's system clock (i.e., the time
difference between the master and the slave is taken into account in this
timestamp).
(B3) For Query_log_events, the event's timestamp holds the time that the event
was executed on the original server (just like before the bugfix). The
status variable Q_IMMEDIATE_MASTER_TIMESTAMP holds the same thing that
other events have in their timestamps.
The new format can be implemented as follows:
(I1) Add a new field to THD, say real_start_time, that holds the time that
UNIX_TIMESTAMP() would return if @@session.timestamp was not set.
(I2) Remove Log_event::when, add the new field
Log_event::last_executed_timestamp, and add the new field
Query_log_event::original_timestamp.
Query_log_event::original_timestamp holds the value that UNIX_TIMESTAMP()
would return on the original master.
Log_event::last_executed_timestamp holds the time when the event was
executed on the immediate master (if the event is read from a relay log)
or the time when the event was executed on the same server (if the event
was created by this server or if it was read from a binlog by
mysqlbinlog). All these times are relative to the system time of the
*current* server.)
(I3) In Log_event::Log_event(const char *buf...), read the event's timestamp
into Log_event::last_executed_timestamp.
(I4) In Log_event::write_header(), write THD::real_start_time as the timestamp
of non-Query_log_events, and write Query_log_event::original_timestamp as
the timestamp of Query_log_events.
(I5) In Query_log_event::write(IO_CACHE*), write the new status variable. It
should have the value Log_event::last_executed_timestamp.
(I6) In Query_log_event::Query_log_event(const char *buf...):
(1) copy Log_event::last_executed_timestamp to
Query_log_event::original_timestamp
(2) check if the event has the new status variable. If it has, read the
new status variable into Log_event::last_executed_timestamp. Otherwise,
set Log_event::last_executed_timestamp = -1
(I7) In the IO thread, when it reads a Query_log_event that has the new status
variable, add mi->clock_diff_with_master to the new status variable before
writing to the relay log.
(I8) In the IO thread, when it reads a non-Query_log_event, add
mi->clock_diff_with_master to the event's timestamp before writing to the
relay log.
(I9) In Query_log_event::do_apply_event(), set @@session.timestamp to
Query_log_event::original_timestamp (instead of to Log_event::when).
(I10) When computing seconds_behind_master: if
Log_event::last_executed_timestamp == -1, then the event is a
Query_log_event originating from an old server. Return
Query_log_event::original_timestamp + mi->clock_diff_with_master.
Otherwise, return Log_event::last_executed_timestamp.
(I probably made some mistakes in the implementation, but I think the architecture should work).
Description: There are two problems, but only one fix, so I'm reporting them as one bug. (P1) Assume: - There are three servers replicating in a chain: master_1 -> master_2 -> master_3 - Each server has local time, and the servers reside in Reykjavik, Stockholm, and Helsinki, respectively. So when master_1 has system time 9:00, then master_2 has system time 10:00 and master_3 has system time 11:00. Further, assume that master_1 executes a query at 9:00, and the query is replicated to master_2 and master_3 instantly. Then: - The query is binlogged with time 9:00 on master_1 - When master_3 receives the query, the query still has timestamp 9:00, but master_3 has system time 11:00. - master_3 knows that its clock is 1 hour ahead of master_2. I.e.: mi->clock_diff_with_master = 3600 - master_3 takes the known difference between its own clock and the immediate master master_2 into account when computing seconds_behind_master. However, the event's timestamp is stored relative to the original master's system time. So master_3 will report Seconds_behind_master as: 11:00 - 9:00 - mi->clock_diff_with_master = 1 hour. This is wrong since master_3 is not behind master_2 at all. (P2) mi->clock_diff_with_master is lost when the IO thread reconnects. So if the SQL thread is behind the IO thread and the user issues CHANGE MASTER to another server that has a different clock difference, then Seconds_behind_master will be wrong for the events of the relay log that originate from the first master. A problem similar to (P1) exists in the current work-in-progress implementation of WL#344. The fix outlined below would fix the problem also for WL#344. How to repeat: Difficult to setup since it requires three different computers. Suggested fix: Actions: (A1) Clarify if seconds_behind_master denotes: (A1-1) the number of seconds behind the immediate master (master_2); or (A1-2) the number of seconds behind the originating master (master_1). (A2) Ensure it works consistently with the semantics defined in (A1). I think (A1-1) makes more sense than (A1-2). (If we used (A1-2), and master_1 and master_2 would both receive updates from clients, then seconds_behind_master on master_3 would alternate between the time that master_3 is behind master_2 and the time that master_3 is behind master_1. That would be unusable.) To understand the fix, we need to understand more of the background. Some background facts: (F1) Every binlog event has a timestamp. The timestamp is equivalent to the return value of the mysql function UNIX_TIMESTAMP() on the server where the query was first executed. In other words, it is set to the value of the mysql variable @@session.timestamp if @@session.timestamp is set; or to the return value of the C function call time(0) at the start of the query otherwise. (F2) When the binlog is copied to the slave relay log, the timestamp is preserved. When the slave SQL thread executes the event, it first sets the slave SQL thread's @@session.timestamp to the event's timestamp. (F3) A consequence of (F1) and (F2): when the query is binlogged on the slave, it still has the same timestamp as it had on the master. (F3) A consequence of (F1) and (F2): when queries like 'INSERT INTO t1 VALUES(UNIX_TIMESTAMP())' are executed on the slave, the inserted value is the time that the query was executed on the originating master. This prevents the slave from going out of sync. (F4) When the IO thread starts, it computes the difference in system clock between itself and its master (it does this by connecting to the master as a client and executing 'SELECT UNIX_TIMESTAMP()', and subtracts the return value of the C function call time(0)). The difference is stored in mi->clock_diff_with_master. (F5) When the slave computes Seconds_behind_master is computed, it uses the last timestamp of any event retrieved from the master, and adds mi->clock_diff_with_master to it. Due to (F3), we have to keep the time that the query was executed on the originating master as part of the event, at least for Query_log_events. In order to not break replication from old to new server, we even have to keep this time in the event's timestamp. But we can change the timestamp of other event types, and we can add new status variables to Query_log_events (unknown status variables are ignored on old servers). So a suggested fix is to change the binlog format as follows: (B1) Add a new status variable to Query_log_event, say Q_IMMEDIATE_MASTER_TIMESTAMP (B2) For event types other than Query_log_event, the event's timestamp is modified as follows: if the event is in a binlog, it holds the time when the event was executed on the server that wrote the binlog. If the event is in a relay log, it holds the time when the event was executed on the immediate master, using the slave's system clock (i.e., the time difference between the master and the slave is taken into account in this timestamp). (B3) For Query_log_events, the event's timestamp holds the time that the event was executed on the original server (just like before the bugfix). The status variable Q_IMMEDIATE_MASTER_TIMESTAMP holds the same thing that other events have in their timestamps. The new format can be implemented as follows: (I1) Add a new field to THD, say real_start_time, that holds the time that UNIX_TIMESTAMP() would return if @@session.timestamp was not set. (I2) Remove Log_event::when, add the new field Log_event::last_executed_timestamp, and add the new field Query_log_event::original_timestamp. Query_log_event::original_timestamp holds the value that UNIX_TIMESTAMP() would return on the original master. Log_event::last_executed_timestamp holds the time when the event was executed on the immediate master (if the event is read from a relay log) or the time when the event was executed on the same server (if the event was created by this server or if it was read from a binlog by mysqlbinlog). All these times are relative to the system time of the *current* server.) (I3) In Log_event::Log_event(const char *buf...), read the event's timestamp into Log_event::last_executed_timestamp. (I4) In Log_event::write_header(), write THD::real_start_time as the timestamp of non-Query_log_events, and write Query_log_event::original_timestamp as the timestamp of Query_log_events. (I5) In Query_log_event::write(IO_CACHE*), write the new status variable. It should have the value Log_event::last_executed_timestamp. (I6) In Query_log_event::Query_log_event(const char *buf...): (1) copy Log_event::last_executed_timestamp to Query_log_event::original_timestamp (2) check if the event has the new status variable. If it has, read the new status variable into Log_event::last_executed_timestamp. Otherwise, set Log_event::last_executed_timestamp = -1 (I7) In the IO thread, when it reads a Query_log_event that has the new status variable, add mi->clock_diff_with_master to the new status variable before writing to the relay log. (I8) In the IO thread, when it reads a non-Query_log_event, add mi->clock_diff_with_master to the event's timestamp before writing to the relay log. (I9) In Query_log_event::do_apply_event(), set @@session.timestamp to Query_log_event::original_timestamp (instead of to Log_event::when). (I10) When computing seconds_behind_master: if Log_event::last_executed_timestamp == -1, then the event is a Query_log_event originating from an old server. Return Query_log_event::original_timestamp + mi->clock_diff_with_master. Otherwise, return Log_event::last_executed_timestamp. (I probably made some mistakes in the implementation, but I think the architecture should work).