summaryrefslogtreecommitdiff
path: root/mysql-test/suite/rpl/t/rpl_seconds_behind_master_spike.test
blob: 029625a09adcb0fe9bbaa893c3fb68fdea7eea70 (plain)
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
59
60
61
62
63
64
65
66
67
68
69
70
71
72
73
74
75
76
77
78
79
80
81
82
83
84
85
86
87
88
#
# Purpose:
#   This test validates that a slave's relay log format description event is
# not used to calculate the Seconds_Behind_Master time displayed by
# SHOW SLAVE STATUS.
#
# Methodology:
#   Ensure that a slave's reported Seconds_Behind_Master does not point before
# a time in which we can prove that it has progressed beyond. The slave's
# relay log events are created using the timestamp at which the IO thread was
# created. Therefore, after starting the slave's IO thread, we sleep so any
# proceeding events are forced to have later timestamps. After sleeping, we run
# MDL statements on the master and save the time at which they are binlogged.
# Once the slave executes these MDL commands, we have proven that the slave has
# caught up to this saved timestamp. At this point, if the value of
# Seconds_Behind_Master points before the time in which the MDL events were
# logged, it is invalid.
#
# References:
#   MDEV-16091: Seconds_Behind_Master spikes to millions of seconds
#
--source include/have_debug.inc
--source include/have_innodb.inc
--source include/master-slave.inc

--connection slave
--source include/stop_slave.inc
SET @save_dbug= @@GLOBAL.debug_dbug;
SET @@global.debug_dbug="+d,pause_sql_thread_on_fde";
--source include/start_slave.inc

--let $sleep_time=2
--echo # Future events must be logged at least $sleep_time seconds after
--echo # the slave starts
--sleep $sleep_time

--connection master
--echo # Write events to ensure slave will be consistent with master
create table t1 (a int);
insert into t1 values (1);
--let $t_master_events_logged= `SELECT UNIX_TIMESTAMP()`

--echo # Flush logs on master forces slave to generate a Format description
--echo # event in its relay log
flush logs;

--connection slave
--echo # Ignore FDEs that happen before the CREATE/INSERT commands
SET DEBUG_SYNC='now WAIT_FOR paused_on_fde';
SET DEBUG_SYNC='now SIGNAL sql_thread_continue';
SET DEBUG_SYNC='now WAIT_FOR paused_on_fde';
SET DEBUG_SYNC='now SIGNAL sql_thread_continue';

--echo # On the next FDE, the slave should have the master CREATE/INSERT events
SET DEBUG_SYNC='now WAIT_FOR paused_on_fde';
select count(*)=1 from t1;

--echo # The relay log FDE has been processed - here we check to ensure it was
--echo # not considered in Seconds_Behind_Master calculation
--connection slave1
let $sbm= query_get_value(SHOW SLAVE STATUS, Seconds_Behind_Master, 1);
--let $t_now= `SELECT UNIX_TIMESTAMP()`

# Ensure Seconds_Behind_Master does not point beyond when we have proven the
# events we have proven to have executed. The extra second is needed as a
# buffer because the recorded times are not exact with when the events were
# recorded on the master.
if(`select $sbm > $t_now - $t_master_events_logged + 1`)
{
    die "A relay log event was incorrectly used to set Seconds_Behind_Master";
}

--echo # Safely resume slave SQL thread
SET @@global.debug_dbug='';
SET DEBUG_SYNC='pause_sql_thread_on_fde CLEAR';
SET DEBUG_SYNC='now SIGNAL sql_thread_continue';

# Reset last sql_thread_continue signal
SET DEBUG_SYNC='RESET';

# Cleanup
--connection master
DROP TABLE t1;

--connection slave
SET @@global.debug_dbug=$save_dbug;

--source include/rpl_end.inc