如何獲得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;

View Code

而後往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]# 

View Code

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/*!*/;

View Code

在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]> 

View Code

正是因爲設置了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.