Skip to content

Commit 746c217

Browse files
teng-lifacebook-github-bot
teng-li
authored and
facebook-github-bot
committed
Let Master Only Send Timestamped Heartbeat Event when waiting for new trxs
Summary: Let master only send HB timestamp while waiting for new trx, this will fix the SBM being inaccurate when the slave is stopped and trying to catchup from the master. Squash with: D5006919 Reviewed By: abhinav04sharma Differential Revision: D5590444 fbshipit-source-id: 620dd48
1 parent eb7b1df commit 746c217

File tree

4 files changed

+258
-13
lines changed

4 files changed

+258
-13
lines changed

‎mysql-test/suite/rpl/include/rpl_heartbeat_zero_timestamp_input.inc

Lines changed: 38 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,38 @@
1+
################################################################################
2+
# The workload generator on the master for rpl_heartbeat_zero_timestamp
3+
################################################################################
4+
5+
# Create the databases and tables
6+
7+
--disable_query_log
8+
--disable_result_log
9+
10+
let $i = $databases;
11+
12+
while ($i)
13+
{
14+
eval drop database if exists test$i;
15+
eval create database test$i;
16+
eval use test$i;
17+
eval drop table if exists t$i;
18+
eval create table t$i (a int) engine=InnoDB;
19+
dec $i;
20+
}
21+
22+
# Run the queries
23+
24+
while ($iter)
25+
{
26+
let $i=$databases;
27+
28+
while ($i)
29+
{
30+
eval use test$i;
31+
eval insert into t$i values ($iter);
32+
dec $i;
33+
}
34+
dec $iter;
35+
}
36+
37+
--enable_result_log
38+
--enable_query_log

‎mysql-test/suite/rpl/r/rpl_heartbeat_zero_timestamp.result

Lines changed: 38 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,38 @@
1+
include/master-slave.inc
2+
[connection master]
3+
include/rpl_set_gtid_mode.inc
4+
include/stop_slave.inc
5+
set @save.slave_parallel_workers= @@global.slave_parallel_workers;
6+
SET @@global.slave_parallel_workers= 4;
7+
CHANGE MASTER TO MASTER_AUTO_POSITION=1;
8+
include/start_slave.inc
9+
SET GLOBAL DEBUG="+d, send_zero_hb_event";
10+
include/sync_slave_sql_with_master.inc
11+
include/stop_slave.inc
12+
CHANGE MASTER TO MASTER_HEARTBEAT_PERIOD=0.1;
13+
include/start_slave.inc
14+
include/assert.inc [Seconds behind master should be bigger than zero after creating the lag for MTS]
15+
include/sync_slave_sql_with_master.inc
16+
include/stop_slave.inc
17+
SET @@global.slave_parallel_workers= 0;
18+
include/start_slave.inc
19+
include/assert.inc [Seconds behind master should be bigger than zero after creating the lag for non-MTS]
20+
use test4;
21+
drop table if exists t4;
22+
drop database if exists test4;
23+
use test3;
24+
drop table if exists t3;
25+
drop database if exists test3;
26+
use test2;
27+
drop table if exists t2;
28+
drop database if exists test2;
29+
use test1;
30+
drop table if exists t1;
31+
drop database if exists test1;
32+
SET GLOBAL DEBUG="-d, send_zero_hb_event";
33+
include/sync_slave_sql_with_master.inc
34+
include/stop_slave.inc
35+
set @@global.slave_parallel_workers= @save.slave_parallel_workers;
36+
CHANGE MASTER TO MASTER_HEARTBEAT_PERIOD=60.000;
37+
include/start_slave.inc
38+
include/rpl_end.inc

‎mysql-test/suite/rpl/t/rpl_heartbeat_zero_timestamp.test

Lines changed: 119 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,119 @@
1+
################################################################################
2+
# Testing the second behind master is correct with timestamp in HB event
3+
################################################################################
4+
5+
source include/not_valgrind.inc;
6+
source include/not_parallel.inc;
7+
8+
# Start a new master-slave
9+
--disable_warnings
10+
--source include/have_binlog_format_row.inc
11+
--source include/master-slave.inc
12+
--source include/rpl_set_gtid_mode.inc
13+
--enable_warnings
14+
15+
--source include/have_gtid.inc
16+
17+
# Enable MTS
18+
--connection slave
19+
--source include/stop_slave.inc
20+
set @save.slave_parallel_workers= @@global.slave_parallel_workers;
21+
SET @@global.slave_parallel_workers= 4;
22+
CHANGE MASTER TO MASTER_AUTO_POSITION=1;
23+
--source include/start_slave.inc
24+
25+
# Run a few queries on the master to create skip scneario
26+
--connection master
27+
SET GLOBAL DEBUG="+d, send_zero_hb_event";
28+
let $databases = 4;
29+
let $iter = 10;
30+
--source suite/rpl/include/rpl_heartbeat_zero_timestamp_input.inc
31+
# Make sure that the slave has caught up to the master
32+
--source include/sync_slave_sql_with_master.inc
33+
34+
35+
# Stop the slave
36+
--connection slave
37+
--source include/stop_slave.inc
38+
39+
40+
# Create a lag on the master by running many queries
41+
--connection master
42+
let $databases = 4;
43+
let $iter = 10000;
44+
--source suite/rpl/include/rpl_heartbeat_zero_timestamp_input.inc
45+
46+
47+
# Now start slave again so that we can get some HB during skipping
48+
--connection slave
49+
# Create some lag
50+
let $lagging_sec = 5;
51+
sleep $lagging_sec;
52+
# Set HB event interval small enough
53+
let $old_slave_heartbeat_period= query_get_value(SHOW GLOBAL STATUS LIKE 'slave_heartbeat_period', Value, 1);
54+
let $new_slave_heartbeat_period= 0.1;
55+
# Since the skiping is really small, after this, for sure we should get the event
56+
let $skipping_guarantee_sleep= 1;
57+
eval CHANGE MASTER TO MASTER_HEARTBEAT_PERIOD=$new_slave_heartbeat_period;
58+
--source include/start_slave.inc
59+
60+
# Sleep so that we for sure get the binlog events
61+
sleep $skipping_guarantee_sleep;
62+
let $sbm= query_get_value("SHOW SLAVE STATUS", Seconds_Behind_Master, 1);
63+
# Assertion
64+
--let $assert_text = Seconds behind master should be bigger than zero after creating the lag for MTS
65+
--let $assert_cond = $sbm > $lagging_sec;
66+
--source include/assert.inc
67+
68+
69+
# Catch up
70+
--connection master
71+
--source include/sync_slave_sql_with_master.inc
72+
73+
74+
# Now test by disabling MTS
75+
--connection slave
76+
--source include/stop_slave.inc
77+
SET @@global.slave_parallel_workers= 0;
78+
--source include/not_mts_slave_parallel_workers.inc
79+
80+
81+
# Create a lag on the master
82+
--connection master
83+
let $databases = 4;
84+
let $iter = 10000;
85+
--source suite/rpl/include/rpl_heartbeat_zero_timestamp_input.inc
86+
87+
88+
--connection slave
89+
# Create some lag
90+
sleep $lagging_sec;
91+
--source include/start_slave.inc
92+
# Sleep so that we for sure get the HB events
93+
sleep $skipping_guarantee_sleep;
94+
let $sbm= query_get_value("SHOW SLAVE STATUS", Seconds_Behind_Master, 1);
95+
# Assertion
96+
--let $assert_text = Seconds behind master should be bigger than zero after creating the lag for non-MTS
97+
--let $assert_cond = $sbm > $lagging_sec
98+
--source include/assert.inc
99+
100+
# clean up
101+
--connection master
102+
let $i = $databases;
103+
while ($i)
104+
{
105+
eval use test$i;
106+
eval drop table if exists t$i;
107+
eval drop database if exists test$i;
108+
dec $i;
109+
}
110+
SET GLOBAL DEBUG="-d, send_zero_hb_event";
111+
--source include/sync_slave_sql_with_master.inc
112+
113+
--connection slave
114+
--source include/stop_slave.inc
115+
set @@global.slave_parallel_workers= @save.slave_parallel_workers;
116+
eval CHANGE MASTER TO MASTER_HEARTBEAT_PERIOD=$old_slave_heartbeat_period;
117+
--source include/start_slave.inc
118+
119+
--source include/rpl_end.inc

‎sql/rpl_master.cc

Lines changed: 63 additions & 13 deletions
Original file line numberDiff line numberDiff line change
@@ -808,8 +808,10 @@ static ulonglong get_heartbeat_period(THD * thd)
808808
@param packet buffer to store the heartbeat instance
809809
@param event_coordinates binlog file name and position of the last
810810
real event master sent from binlog
811+
@param send_timestamp flag enables sending the HB event with
812+
the current timestamp: time().
811813
812-
@note
814+
@note
813815
Among three essential pieces of heartbeat data Log_event::when
814816
is computed locally.
815817
The error to send is serious and should force terminating
@@ -818,17 +820,22 @@ static ulonglong get_heartbeat_period(THD * thd)
818820
static int send_heartbeat_event(NET* net, String* packet,
819821
const struct event_coordinates *coord,
820822
bool is_semi_sync_slave,
821-
uint8 checksum_alg_arg)
823+
uint8 checksum_alg_arg,
824+
bool send_timestamp)
822825
{
823826
DBUG_ENTER("send_heartbeat_event");
824827
char header[LOG_EVENT_HEADER_LEN];
825828
my_bool do_checksum= checksum_alg_arg != BINLOG_CHECKSUM_ALG_OFF &&
826829
checksum_alg_arg != BINLOG_CHECKSUM_ALG_UNDEF;
827830

828-
// NOTE: if @last_master_timestamp is provided we're a slave and we use this
829-
// value in the HB event otherwise we use now()
830-
time_t ts= mysql_bin_log.last_master_timestamp.load();
831-
if (!ts) ts= time(0);
831+
time_t ts= 0;
832+
833+
if (send_timestamp) {
834+
// NOTE: if @last_master_timestamp is provided we're a slave and we use this
835+
// value in the HB event otherwise we use now()
836+
ts= mysql_bin_log.last_master_timestamp.load();
837+
if (!ts) ts= time(0);
838+
}
832839
memcpy(header, &ts, 4);
833840

834841
header[EVENT_TYPE_OFFSET] = HEARTBEAT_LOG_EVENT;
@@ -880,6 +887,15 @@ static int send_heartbeat_event(NET* net, String* packet,
880887
later. Note that, the caller has to send the last skipped coordinates
881888
to this function.
882889
890+
Note that this function will not send HeartBeat events that carry the current
891+
timestamp. This this because this function is ONLY used to send HB update
892+
when the previous transaction has been skipped. Note that HB events'
893+
timestamps will be used by the slave to calculate the seconds behind master.
894+
895+
The only place that makes sense for the event to carry a timestamp is when
896+
the master is waiting on the update and keeping sending HB events to keep
897+
the connection.
898+
883899
@param[in] net This master-slave network handler
884900
@param[in] packet packet that is to be sent to the slave.
885901
@param[in] last_skip_coord coordinates for last skipped transaction
@@ -904,17 +920,24 @@ static int send_last_skip_group_heartbeat(THD *thd, NET* net, String *packet,
904920
String save_packet;
905921
int save_offset= *ev_offset;
906922

907-
/* Save the current read packet */
923+
/* Save the current read packet */
908924
save_packet.swap(*packet);
909925

910926
if (reset_transmit_packet(thd, 0, ev_offset, errmsg, observe_transmission,
911927
packet, packet_buffer, packet_buffer_size,
912928
semi_sync_slave))
913929
DBUG_RETURN(-1);
914930

915-
/* Send heart beat event to the slave to update slave threads coordinates */
916-
if (send_heartbeat_event(net, packet, last_skip_coord,
917-
semi_sync_slave, checksum_alg_arg))
931+
/**
932+
* Send heart beat event to the slave to update slave threads coordinates
933+
* Note that we will not send timestamp in these heart beat events
934+
*/
935+
if (send_heartbeat_event(net,
936+
packet,
937+
last_skip_coord,
938+
semi_sync_slave,
939+
checksum_alg_arg,
940+
false))
918941
{
919942
*errmsg= "Failed on my_net_write()";
920943
my_errno= ER_UNKNOWN_ERROR;
@@ -1922,6 +1945,10 @@ void mysql_binlog_send(THD* thd, char* log_ident, my_off_t pos,
19221945
// Both diff_timespec() and heartbeat_period are in nano seconds.
19231946
time_for_hb_event= (diff_timespec(cur_clock, last_event_sent_ts) >=
19241947
heartbeat_period);
1948+
DBUG_EXECUTE_IF("send_zero_hb_event",
1949+
{
1950+
time_for_hb_event= true;
1951+
});
19251952
}
19261953

19271954
if ((!skip_group && last_skip_group
@@ -1938,6 +1965,10 @@ void mysql_binlog_send(THD* thd, char* log_ident, my_off_t pos,
19381965
is the first event to be sent to the slave. In this case, it is
19391966
no need to send a HB event (which might have coordinates
19401967
of previous binlog file).
1968+
1969+
This heartbeat event sending only happens when the master is in the
1970+
middle or has just completed skipping all the trxs. Therefore, HB
1971+
shouldn't carry Timestamp.
19411972
*/
19421973

19431974
if (send_last_skip_group_heartbeat(thd, net, packet, p_last_skip_coord,
@@ -2210,6 +2241,10 @@ void mysql_binlog_send(THD* thd, char* log_ident, my_off_t pos,
22102241
If the heartbeat is on, it is better to send a heartbeat
22112242
event as the time_out of certain functions (Ex: master_pos_wait()
22122243
or semi sync ack timeout) might be less than heartbeat period.
2244+
2245+
This can happen when the slave has exact same GTID as the master.
2246+
In this case, we still send the first HB with 0 timestamp to be
2247+
safe since the follow up HB with carry the right timestamp
22132248
*/
22142249
if (skip_group)
22152250
{
@@ -2254,8 +2289,19 @@ void mysql_binlog_send(THD* thd, char* log_ident, my_off_t pos,
22542289
thd->EXIT_COND(&old_stage);
22552290
GOTO_ERR;
22562291
}
2257-
if (send_heartbeat_event(net, packet, p_coord,
2258-
semi_sync_slave, current_checksum_alg))
2292+
/**
2293+
* HB events sent here are essentially when the master is waiting
2294+
* on updates and send HB to keep the connection connected.
2295+
*
2296+
* This is the only place that sending HB with Timestamp makes
2297+
* sense and won't break monotonic TS calculated SBM
2298+
*/
2299+
if (send_heartbeat_event(net,
2300+
packet,
2301+
p_coord,
2302+
semi_sync_slave,
2303+
current_checksum_alg,
2304+
true))
22592305
{
22602306
errmsg = "Failed on my_net_write()";
22612307
my_errno= ER_UNKNOWN_ERROR;
@@ -2357,7 +2403,11 @@ void mysql_binlog_send(THD* thd, char* log_ident, my_off_t pos,
23572403

23582404
if (!skip_group && !goto_next_binlog)
23592405
{
2360-
/* If the last group was skipped, send a HB event */
2406+
/**
2407+
* If the last group was skipped, send a HB event,
2408+
* similarly, HB sent here should not carry TS since the last
2409+
* trx is skipped and we are not sure if we are waiting on update
2410+
*/
23612411
if (last_skip_group &&
23622412
send_last_skip_group_heartbeat(thd, net, packet,
23632413
p_last_skip_coord, &ev_offset,

0 commit comments

Comments
 (0)