MySQL Replication--复制延迟02--exec_time测试
复制延迟(Seconds_Behind_Master)测试
测试环境： MySQL 5.7.19
测试主从时间差：
检查主从系统时间差，同时在主库和从库执行SELECT NOW()语句： 主库：2019-06-24 10:57:56 从库：2019-06-24 10:58:10 从库比主库提前14秒，主从时间差14秒。
在主库上执行(使用基于语句格式复制)：
select now(); update tb003 set c1=SLEEP(20) where id=1; select now();
主库上上执行效果：
mysql> select now(); +---------------------+ | now() | +---------------------+ | 2019-06-24 11:01:54 | +---------------------+ 1 row in set (0.00 sec) mysql> update tb003 set c1=SLEEP(20) where id=1; Query OK, 1 row affected, 1 warning (20.06 sec) Rows matched: 1 Changed: 1 Warnings: 1 mysql> select now(); +---------------------+ | now() | +---------------------+ | 2019-06-24 11:02:14 | +---------------------+ 1 row in set (0.00 sec)
主库上生成的binlog解析结果:
#190624 11:01:54 server id 1614520 end_log_pos 259 CRC32 0xcf2313f1 GTID last_committed=0 sequence_number=1 rbr_only=no SET @@SESSION.GTID_NEXT= '025fd638-89ea-11e9-a749-40f2e9cf3aaa:9'/*!*/; # at 259 #190624 11:01:54 server id 1614520 end_log_pos 340 CRC32 0xa14a2bcb Query thread_id=3186 exec_time=20 error_code=0 SET TIMESTAMP=1561345314/*!*/; BEGIN /*!*/; # at 340 #190624 11:01:54 server id 1614520 end_log_pos 456 CRC32 0xc283c9af Query thread_id=3186 exec_time=20 error_code=0 use `db001`/*!*/; SET TIMESTAMP=1561345314/*!*/; update tb003 set c1=SLEEP(20) where id=1 /*!*/; # at 456 #190624 11:01:54 server id 1614520 end_log_pos 487 CRC32 0x0f3bdc57 Xid = 10020 COMMIT/*!*/;
从库上relay log解析结果：
BINLOG ' +zwQXQ+4ohgAdwAAAAAAAAAgAAQANS43LjE5LWxvZwAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA AAAAAAAAAAAAAAAAAAAAAAAAEzgNAAgAEgAEBAQEEgAAXwAEGggAAAAICAgCAAAACgoKKioAEjQA Af0UlBk= '/*!*/; # at 313 #190624 11:01:54 server id 1614520 end_log_pos 259 CRC32 0xcf2313f1 GTID last_committed=0 sequence_number=1 rbr_only=no SET @@SESSION.GTID_NEXT= '025fd638-89ea-11e9-a749-40f2e9cf3aaa:9'/*!*/; # at 378 #190624 11:01:54 server id 1614520 end_log_pos 340 CRC32 0xa14a2bcb Query thread_id=3186 exec_time=20 error_code=0 SET TIMESTAMP=1561345314/*!*/; BEGIN /*!*/; # at 459 #190624 11:01:54 server id 1614520 end_log_pos 456 CRC32 0xc283c9af Query thread_id=3186 exec_time=20 error_code=0 use `db001`/*!*/; SET TIMESTAMP=1561345314/*!*/; update tb003 set c1=SLEEP(20) where id=1 /*!*/; # at 575 #190624 11:01:54 server id 1614520 end_log_pos 487 CRC32 0x0f3bdc57 Xid = 10020 COMMIT/*!*/;
从库上生成binlog解析结果(从库上默认binlog_format=row)：
#190624 11:01:54 server id 1614520 end_log_pos 259 CRC32 0x6e1a971f GTID last_committed=0 sequence_number=1 rbr_only=yes /*!50718 SET TRANSACTION ISOLATION LEVEL READ COMMITTED*//*!*/; SET @@SESSION.GTID_NEXT= '025fd638-89ea-11e9-a749-40f2e9cf3aaa:9'/*!*/; # at 259 #190624 11:01:54 server id 1614520 end_log_pos 332 CRC32 0x063cd6ca Query thread_id=3186 exec_time=54 error_code=0 SET TIMESTAMP=1561345314/*!*/; BEGIN /*!*/; # at 332 #190624 11:01:54 server id 1614520 end_log_pos 396 CRC32 0x405b61c7 Rows_query # update tb003 set c1=SLEEP(20) where id=1 # at 396 #190624 11:01:54 server id 1614520 end_log_pos 448 CRC32 0x015803f1 Table_map: `db001`.`tb003` mapped to number 232 # at 448 #190624 11:01:54 server id 1614520 end_log_pos 518 CRC32 0xb59069f9 Update_rows: table id 232 flags: STMT_END_F BINLOG ' Ij0QXR24ohgAQAAAAIwBAACAACh1cGRhdGUgdGIwMDMgc2V0IGMxPVNMRUVQKDIwKSB3aGVyZSBp ZD0xx2FbQA== Ij0QXRO4ohgANAAAAMABAAAAAOgAAAAAAAEABWRiMDAxAAV0YjAwMwADCAMRAQAC8QNYAQ== Ij0QXR+4ohgARgAAAAYCAAAAAOgAAAAAAAEAAgAD///4AQAAAAAAAAABAAAAXRA89fgBAAAAAAAA AAAAAABdED0i+WmQtQ== '/*!*/; ### UPDATE `db001`.`tb003` ### WHERE ### @1=1 /* LONGINT meta=0 nullable=0 is_null=0 */ ### @2=1 /* INT meta=0 nullable=1 is_null=0 */ ### @3=1561345269 /* TIMESTAMP(0) meta=0 nullable=0 is_null=0 */ ### SET ### @1=1 /* LONGINT meta=0 nullable=0 is_null=0 */ ### @2=0 /* INT meta=0 nullable=1 is_null=0 */ ### @3=1561345314 /* TIMESTAMP(0) meta=0 nullable=0 is_null=0 */ # at 518 #190624 11:01:54 server id 1614520 end_log_pos 549 CRC32 0xae037515 Xid = 6241 COMMIT/*!*/;
无论时主库binlog事件中还是从库relaylog事件以及从库binlog事件中记录的时间都是事务语句执行开始时间：
SET TIMESTAMP=1561345314/*!*/; SELECT FROM_UNIXTIME(1561345314); +---------------------------+ | FROM_UNIXTIME(1561345314) | +---------------------------+ | 2019-06-24 11:01:54 | +---------------------------+
exec_time计算：The time from when the query started to when it was logged in the binlog, in seconds.
1、由于SQL语句中使用函数SLEEP(20),因此SQL语句执行时间=SLEEP(20)的执行时间+UPDATE操作的执行时间，而UPDATE操作的执行时间在10ms以内，因此整个SQL语句在主库的执行时间=20S，因此主库binlog的中记录exec_time=20
2、从库的relaylog用来存放主库传递过来的binlog，因此从库relaylog与主库binlog相同，从库relaylog中记录也是exec_time=20
3、由于主库使用binlog_format=statement的复制格式，因此SQL语句被传递到从库并原样执行，同样执行需要20S，但该语句在主库的开始执行时间(the query started)为2019-06-24 11:01:54，而在从库执行结束时间(log in binlog)为2019-06-24 11:02:48，因此从库binlog中记录时间exec_time=54,忽略主从事务日志落盘和网络传输时间，exec_time=54S=主库语句执行时间(20)+从库语句执行时间(20S)+主从时间差(14S)。
在主库上执行(使用基于行格式复制)：
mysql> select now(); +---------------------+ | now() | +---------------------+ | 2019-06-25 08:40:05 | +---------------------+ 1 row in set (0.00 sec) mysql> update tb003 set c1=SLEEP(20) where id in (3,4); Query OK, 2 rows affected (40.04 sec) Rows matched: 2 Changed: 2 Warnings: 0 mysql> select now(); +---------------------+ | now() | +---------------------+ | 2019-06-25 08:40:45 | +---------------------+ 1 row in set (0.00 sec)
产生的binlog解析结果为：
# at 549 #190625 8:40:05 server id 1614520 end_log_pos 614 CRC32 0x037e9b24 GTID last_committed=1 sequence_number=2 rbr_only=yes /*!50718 SET TRANSACTION ISOLATION LEVEL READ COMMITTED*//*!*/; SET @@SESSION.GTID_NEXT= '025fd638-89ea-11e9-a749-40f2e9cf3aaa:65'/*!*/; # at 614 #190625 8:40:05 server id 1614520 end_log_pos 687 CRC32 0xe186daee Query thread_id=837 exec_time=20 error_code=0 SET TIMESTAMP=1561423205/*!*/; BEGIN /*!*/; # at 687 #190625 8:40:05 server id 1614520 end_log_pos 758 CRC32 0x9f76a54a Rows_query # update tb003 set c1=SLEEP(20) where id in (3,4) # at 758 #190625 8:40:05 server id 1614520 end_log_pos 810 CRC32 0x139892d9 Table_map: `db001`.`tb003` mapped to number 108 # at 810 #190625 8:40:05 server id 1614520 end_log_pos 914 CRC32 0xf7980c93 Update_rows: table id 108 flags: STMT_END_F BINLOG ' ZW0RXR24ohgARwAAAPYCAACAAC91cGRhdGUgdGIwMDMgc2V0IGMxPVNMRUVQKDIwKSB3aGVyZSBp ZCBpbiAoMyw0KUqldp8= ZW0RXRO4ohgANAAAACoDAAAAAGwAAAAAAAEABWRiMDAxAAV0YjAwMwADCAMRAQAC2ZKYEw== ZW0RXR+4ohgAaAAAAJIDAAAAAGwAAAAAAAEAAgAD///4AwAAAAAAAAABAAAAXRFrW/gDAAAAAAAA AAAAAABdEW1l+AQAAAAAAAAAAQAAAF0Ra1v4BAAAAAAAAAAAAAAAXRFtZZMMmPc= '/*!*/; ### UPDATE `db001`.`tb003` ### WHERE ### @1=3 /* LONGINT meta=0 nullable=0 is_null=0 */ ### @2=1 /* INT meta=0 nullable=1 is_null=0 */ ### @3=1561422683 /* TIMESTAMP(0) meta=0 nullable=0 is_null=0 */ ### SET ### @1=3 /* LONGINT meta=0 nullable=0 is_null=0 */ ### @2=0 /* INT meta=0 nullable=1 is_null=0 */ ### @3=1561423205 /* TIMESTAMP(0) meta=0 nullable=0 is_null=0 */ ### UPDATE `db001`.`tb003` ### WHERE ### @1=4 /* LONGINT meta=0 nullable=0 is_null=0 */ ### @2=1 /* INT meta=0 nullable=1 is_null=0 */ ### @3=1561422683 /* TIMESTAMP(0) meta=0 nullable=0 is_null=0 */ ### SET ### @1=4 /* LONGINT meta=0 nullable=0 is_null=0 */ ### @2=0 /* INT meta=0 nullable=1 is_null=0 */ ### @3=1561423205 /* TIMESTAMP(0) meta=0 nullable=0 is_null=0 */ # at 914 #190625 8:40:05 server id 1614520 end_log_pos 945 CRC32 0x1f65c801 Xid = 2610 COMMIT/*!*/;
在主库上执行(使用基于行格式复制+两条语句组合事务操作)：
mysql> select now(); +---------------------+ | now() | +---------------------+ | 2019-06-25 08:55:56 | +---------------------+ 1 row in set (0.00 sec) mysql> begin; Query OK, 0 rows affected (0.00 sec) mysql> update tb003 set c1=SLEEP(20) where id =5; Query OK, 1 row affected (20.00 sec) Rows matched: 1 Changed: 1 Warnings: 0 mysql> update tb003 set c1=SLEEP(20) where id =6; Query OK, 1 row affected (20.00 sec) Rows matched: 1 Changed: 1 Warnings: 0 mysql> commit; Query OK, 0 rows affected (0.05 sec) mysql> select now(); +---------------------+ | now() | +---------------------+ | 2019-06-25 08:56:36 | +---------------------+ 1 row in set (0.00 sec)
产生的binlog解析结果为：
# at 945 #190625 8:56:36 server id 1614520 end_log_pos 1010 CRC32 0x5a8cb5f0 GTID last_committed=2 sequence_number=3 rbr_only=yes /*!50718 SET TRANSACTION ISOLATION LEVEL READ COMMITTED*//*!*/; SET @@SESSION.GTID_NEXT= '025fd638-89ea-11e9-a749-40f2e9cf3aaa:66'/*!*/; # at 1010 #190625 8:55:56 server id 1614520 end_log_pos 1083 CRC32 0x5217a928 Query thread_id=838 exec_time=20 error_code=0 SET TIMESTAMP=1561424156/*!*/; BEGIN /*!*/; # at 1083 #190625 8:55:56 server id 1614520 end_log_pos 1148 CRC32 0x1a70cac7 Rows_query # update tb003 set c1=SLEEP(20) where id =5 # at 1148 #190625 8:55:56 server id 1614520 end_log_pos 1200 CRC32 0x4cf6d8c7 Table_map: `db001`.`tb003` mapped to number 108 # at 1200 #190625 8:55:56 server id 1614520 end_log_pos 1270 CRC32 0x033f26f8 Update_rows: table id 108 flags: STMT_END_F BINLOG ' HHERXR24ohgAQQAAAHwEAACAACl1cGRhdGUgdGIwMDMgc2V0IGMxPVNMRUVQKDIwKSB3aGVyZSBp ZCA9NcfKcBo= HHERXRO4ohgANAAAALAEAAAAAGwAAAAAAAEABWRiMDAxAAV0YjAwMwADCAMRAQACx9j2TA== HHERXR+4ohgARgAAAPYEAAAAAGwAAAAAAAEAAgAD///4BQAAAAAAAAABAAAAXRDBV/gFAAAAAAAA AAAAAABdEXEc+CY/Aw== '/*!*/; ### UPDATE `db001`.`tb003` ### WHERE ### @1=5 /* LONGINT meta=0 nullable=0 is_null=0 */ ### @2=1 /* INT meta=0 nullable=1 is_null=0 */ ### @3=1561379159 /* TIMESTAMP(0) meta=0 nullable=0 is_null=0 */ ### SET ### @1=5 /* LONGINT meta=0 nullable=0 is_null=0 */ ### @2=0 /* INT meta=0 nullable=1 is_null=0 */ ### @3=1561424156 /* TIMESTAMP(0) meta=0 nullable=0 is_null=0 */ # at 1270 #190625 8:56:16 server id 1614520 end_log_pos 1335 CRC32 0x3b3202fa Rows_query # update tb003 set c1=SLEEP(20) where id =6 # at 1335 #190625 8:56:16 server id 1614520 end_log_pos 1387 CRC32 0x8b013c05 Table_map: `db001`.`tb003` mapped to number 108 # at 1387 #190625 8:56:16 server id 1614520 end_log_pos 1457 CRC32 0xf7d67996 Update_rows: table id 108 flags: STMT_END_F BINLOG ' MHERXR24ohgAQQAAADcFAACAACl1cGRhdGUgdGIwMDMgc2V0IGMxPVNMRUVQKDIwKSB3aGVyZSBp ZCA9NvoCMjs= MHERXRO4ohgANAAAAGsFAAAAAGwAAAAAAAEABWRiMDAxAAV0YjAwMwADCAMRAQACBTwBiw== MHERXR+4ohgARgAAALEFAAAAAGwAAAAAAAEAAgAD///4BgAAAAAAAAABAAAAXRB9NvgGAAAAAAAA AAAAAABdEXEwlnnW9w== '/*!*/; ### UPDATE `db001`.`tb003` ### WHERE ### @1=6 /* LONGINT meta=0 nullable=0 is_null=0 */ ### @2=1 /* INT meta=0 nullable=1 is_null=0 */ ### @3=1561361718 /* TIMESTAMP(0) meta=0 nullable=0 is_null=0 */ ### SET ### @1=6 /* LONGINT meta=0 nullable=0 is_null=0 */ ### @2=0 /* INT meta=0 nullable=1 is_null=0 */ ### @3=1561424176 /* TIMESTAMP(0) meta=0 nullable=0 is_null=0 */ # at 1457 #190625 8:56:36 server id 1614520 end_log_pos 1488 CRC32 0x8b074201 Xid = 2625 COMMIT/*!*/;
可以发现上面两个操作都执行了40秒，但在事务开始前(BEGIN)的exec_time都仅为20,且事务内部单个操作没有exec_time。
ev->exec_time的计算在sql/log_event.cc中的代码如下：
/*
exec_time calculation has changed to use the same method that is used
to fill out "thd_arg->start_time"
*/
struct timeval end_time;
ulonglong micro_end_time= my_micro_time();
my_micro_time_to_timeval(micro_end_time, &end_time);
exec_time= end_time.tv_sec - thd_arg->start_time.tv_sec;
exec_time在文件sql/log_event.h中的注解如下：
<tr>
<td>exec_time</td>
<td>4 byte unsigned integer</td>
<td>The time from when the query started to when it was logged in the binlog, in seconds.</td>
</tr>
