如何得到Slave应用relay-log的时间

官方社区版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.