官方社区版MySQL 5.7.19 基于Row+Position搭建的一主一从异步复制结构：Master->{Slave}
| ROLE | HOSTNAME | BASEDIR | DATADIR | IP | PORT |
| Master | ZST1 | /usr/local/mysql | /data/mysql/mysql3307/data | 192.168.85.132 | 3307 |
| Slave | ZST2 | /usr/local/mysql | /data/mysql/mysql3307/data | 192.168.85.133 | 3307 |
最初是想核实延迟复制的master_delay=N以哪个时间作为基准计算，想到如果在Slave的表中添加一个以current_timestamp为默认值的时间列，从库在应用relay-log时将"当前"时间写入。将它和表中原来的时间字段作对比，就可以知道延迟时间。想法貌似不错，但...自以为是...很悲催~
# 测试表结构 mydba@192.168.85.133,3307 [replcrash]> show create table py_user; +---------+----------------------------------------------+ | Table | Create Table | +---------+----------------------------------------------+ | py_user | CREATE TABLE `py_user` ( `uid` int(11) NOT NULL AUTO_INCREMENT, `name` varchar(32) DEFAULT NULL, `add_time` datetime DEFAULT CURRENT_TIMESTAMP, `server_id` varchar(10) DEFAULT NULL, PRIMARY KEY (`uid`) ) ENGINE=InnoDB AUTO_INCREMENT=4105 DEFAULT CHARSET=utf8 | +---------+----------------------------------------------+ 1 row in set (0.00 sec) # Slave开启延迟复制 mydba@192.168.85.133,3307 [replcrash]> change master to master_delay = 30; # 添加参考列 mydba@192.168.85.133,3307 [replcrash]> alter table py_user add ins_time datetime default current_timestamp;
然后往Master写入新数据，并到Slave查看数据
# Slave数据 mydba@192.168.85.133,3307 [replcrash]> select * from py_user; +-----+--------------------------+---------------------+-----------+---------------------+ | uid | name | add_time | server_id | ins_time | +-----+--------------------------+---------------------+-----------+---------------------+ | 1 | BD9U7I9W68BTDIXWEEUQNYRX | 2017-12-19 11:07:40 | 1323307 | 2017-12-19 11:07:40 | | 2 | 9722XBCKISXDBSRDA5VA0A | 2017-12-19 11:07:42 | 1323307 | 2017-12-19 11:07:42 | +-----+--------------------------+---------------------+-----------+---------------------+ 2 rows in set (0.00 sec) # general-log [root@ZST2 data]# cat mysql-general.log /usr/local/mysql/bin/mysqld, Version: 5.7.19-log (MySQL Community Server (GPL)). started with: Tcp port: 3307 Unix socket: /tmp/mysql3307.sock Time Id Command Argument ... 2017-12-19T03:07:46.515218Z 17 Query truncate table py_user 2017-12-19T03:08:10.516900Z 17 Query BEGIN 2017-12-19T03:08:10.517318Z 17 Query COMMIT /* implicit, from Xid_log_event */ 2017-12-19T03:08:12.517930Z 17 Query BEGIN 2017-12-19T03:08:12.518383Z 17 Query COMMIT /* implicit, from Xid_log_event */ 2017-12-19T03:08:27.614844Z 3 Query select * from py_user [root@ZST2 data]#
general-log可以看出Slave确实是晚于Master 30秒才应用，但新写入的记录对应的ins_time并没有滞后add_time 30秒
为什么会出现这种情况？解析relay-log查看日志中是如何记录的
# Slave上的relay-log信息 [root@ZST2 data]# mysqlbinlog -v -vv --base64-output=decode-rows relay-bin.000009 ... # at 2803 #171219 11:07:42 server id 1323307 end_log_pos 19664 CRC32 0x6fdfa523 Query thread_id=26 exec_time=0 error_code=0 SET TIMESTAMP=1513652862/*!*/; BEGIN /*!*/; # at 2888 #171219 11:07:42 server id 1323307 end_log_pos 19727 CRC32 0x9edb1d95 Table_map: `replcrash`.`py_user` mapped to number 231 # at 2951 #171219 11:07:42 server id 1323307 end_log_pos 19803 CRC32 0x18252616 Write_rows: table id 231 flags: STMT_END_F ### INSERT INTO `replcrash`.`py_user` ### SET ### @1=2 /* INT meta=0 nullable=0 is_null=0 */ ### @2='9722XBCKISXDBSRDA5VA0A' /* VARSTRING(96) meta=96 nullable=1 is_null=0 */ ### @3='2017-12-19 11:07:42' /* DATETIME(0) meta=0 nullable=1 is_null=0 */ ### @4='1323307' /* VARSTRING(30) meta=30 nullable=1 is_null=0 */ # at 3027 #171219 11:07:42 server id 1323307 end_log_pos 19834 CRC32 0x5e49e8d9 Xid = 295 COMMIT/*!*/; # Slave上的binlog信息 [root@ZST2 logs]# mysqlbinlog -v -vv --base64-output=decode-rows mysql-bin.000005 ... # at 19029 #171219 11:07:42 server id 1323307 end_log_pos 19100 CRC32 0x70e91679 Query thread_id=26 exec_time=30 error_code=0 SET TIMESTAMP=1513652862/*!*/; BEGIN /*!*/; # at 19100 #171219 11:07:42 server id 1323307 end_log_pos 19165 CRC32 0x9fcf7ba6 Table_map: `replcrash`.`py_user` mapped to number 231 # at 19165 #171219 11:07:42 server id 1323307 end_log_pos 19246 CRC32 0x17e542da Write_rows: table id 231 flags: STMT_END_F ### INSERT INTO `replcrash`.`py_user` ### SET ### @1=2 /* INT meta=0 nullable=0 is_null=0 */ ### @2='9722XBCKISXDBSRDA5VA0A' /* VARSTRING(96) meta=96 nullable=1 is_null=0 */ ### @3='2017-12-19 11:07:42' /* DATETIME(0) meta=0 nullable=1 is_null=0 */ ### @4='1323307' /* VARSTRING(30) meta=30 nullable=1 is_null=0 */ ### @5='2017-12-19 11:07:42' /* DATETIME(0) meta=0 nullable=1 is_null=0 */ # at 19246 #171219 11:07:42 server id 1323307 end_log_pos 19277 CRC32 0x8557b6ea Xid = 249 COMMIT/*!*/;
在relay-log/binlog中可以看到SET TIMESTAMP=1513652862/*!*/;
mydba@192.168.85.133,3307 [replcrash]> set timestamp=1513652862;select now();set timestamp=0;select now(); Query OK, 0 rows affected (0.00 sec) +---------------------+ | now() | +---------------------+ | 2017-12-19 11:07:42 | +---------------------+ 1 row in set (0.00 sec) Query OK, 0 rows affected (0.00 sec) +---------------------+ | now() | +---------------------+ | 2017-12-20 10:48:49 | +---------------------+ 1 row in set (0.00 sec) mydba@192.168.85.133,3307 [replcrash]>
正是由于设置了TIMESTAMP，从库ins_time列使用current_timestamp默认值时就得到当时的时间。SBR的环境中，时间相关的函数(now(),current_date(),current_time()等)，都能安全的复制到Slave的原因也是因为binlog中记录有timestamp
因此上面添加列获取Slave应用relay-log的时间肯定行不通。如果只是偶尔查看的话，可以从general-log中提取~.~
master_delay = N
An event received from the master is not executed until at least N seconds later than its execution on the master. The exceptions are that there is no delay for format description events or log file rotation events, which affect only the internal state of the SQL thread.