binlog记录SQL执行时间吗，准不准，时间是否包含锁等待时间
讨论：binlog记录SQL执行时间吗，准不准，时间是否包含锁等待时间
MySQL版本号：
Server version: 5.7.29-log MySQL Community Server (GPL)
测试环境如下：
mysql> drop table t1; Query OK, 0 rows affected (0.02 sec) mysql> create table t1(id int primary key auto_increment,name varchar(200)); Query OK, 0 rows affected (0.01 sec) mysql> insert into t1 select null,repeat('a',2000); Query OK, 1 row affected, 1 warning (0.00 sec) Records: 1 Duplicates: 0 Warnings: 1 mysql> insert into t1 select null,repeat('a',2000) from t1; Query OK, 1 row affected, 1 warning (0.01 sec) Records: 1 Duplicates: 0 Warnings: 1 .... 插入100W+条数据，让这个表大一些
找一个DEMO，简单分析下binlog文件，binlog文件本质上是由一个个event组成的，
[root@host101 data]# [root@host101 data]# mysqlbinlog -vv --base64-output=decode-rows mysql-bin.000059 /*!50530 SET @@SESSION.PSEUDO_SLAVE_MODE=1*/; /*!50003 SET @OLD_COMPLETION_TYPE=@@COMPLETION_TYPE,COMPLETION_TYPE=0*/; DELIMITER /*!*/; # at 4 #201107 16:47:03 server id 1 end_log_pos 123 CRC32 0x17ba10af Start: binlog v 4, server v 5.7.29-log created 201107 16:47:03 ---binlog文件中的第一个event，FORMAT_DESCRIPTION_EVENT，生成时机是binlog文件切换时 # Warning: this binlog is either in use or was not closed properly. # at 123 #201107 16:47:03 server id 1 end_log_pos 234 CRC32 0x26a0a898 Previous-GTIDs # 9fef2262-97b1-11ea-92b5-000c29cd3ff3:1-1583, # adc4403d-97b2-11ea-b803-000c298076e0:1-104 ----binlog文件中第二个event，PREVIOUS_GTIDS_LOG_EVENT，用于描述前面所有binary log中包含的GTID SET # at 234 #201107 16:47:05 server id 1 end_log_pos 299 CRC32 0x79365d3f GTID last_committed=0 sequence_number=1 rbr_only=yes /*!50718 SET TRANSACTION ISOLATION LEVEL READ COMMITTED*//*!*/; SET @@SESSION.GTID_NEXT= '9fef2262-97b1-11ea-92b5-000c29cd3ff3:1584'/*!*/; ----binlog文件中第三个event，GTID_LOG_EVENT，用于描述GTID的详细信息，是否为行行为，逻辑时钟详细信息，即last_committed和sequence_number # at 299 #201107 16:47:05 server id 1 end_log_pos 377 CRC32 0x44b83854 Query thread_id=315 exec_time=0 error_code=0 ****---QUERY_EVENT，讨论重点是exec_time，是否是准确时间。**** SET TIMESTAMP=1604738825/*!*/; SET @@session.pseudo_thread_id=315/*!*/; SET @@session.foreign_key_checks=1, @@session.sql_auto_is_null=0, @@session.unique_checks=1, @@session.autocommit=1/*!*/; SET @@session.sql_mode=0/*!*/; SET @@session.auto_increment_increment=1, @@session.auto_increment_offset=2/*!*/; /*!\C utf8 *//*!*/; SET @@session.character_set_client=33,@@session.collation_connection=33,@@session.collation_server=33/*!*/; SET @@session.lc_time_names=0/*!*/; SET @@session.collation_database=DEFAULT/*!*/; BEGIN /*!*/; # at 377 #201107 16:47:05 server id 1 end_log_pos 423 CRC32 0x9bf22279 Table_map: `ceshi`.`t1` mapped to number 108 ----MAP_EVENT，行模式特有的，用做table_id和实际访问表的映射等。 # at 423 #201107 16:47:05 server id 1 end_log_pos 463 CRC32 0xc3e374f6 Write_rows: table id 108 flags: STMT_END_F ---WRITE_ROWS_EVENT，是insert语句生成的event.用于记录insert语句的ager_image实际数据。 ### INSERT INTO `ceshi`.`t1` ### SET ### @1=1 /* INT meta=0 nullable=1 is_null=0 */ # at 463 #201107 16:47:05 server id 1 end_log_pos 494 CRC32 0x86bb8b11 Xid = 14938 COMMIT/*!*/; SET @@SESSION.GTID_NEXT= 'AUTOMATIC' /* added by mysqlbinlog */ /*!*/; DELIMITER ; # End of log file /*!50003 SET COMPLETION_TYPE=@OLD_COMPLETION_TYPE*/; /*!50530 SET @@SESSION.PSEUDO_SLAVE_MODE=0*/;
****---QUERY_EVENT，讨论重点是exec_time，是否是准确时间。****
exec_time是在QUERY_EVENT中记录的，
根据之前学习【深入理解MySQL主从32讲】，结论是：
DML:执行时间记录的是第一条数据更改后的时间，而不是真正本条DML语句执行的时间（一个DML语句可能修改很多条记录），往往这个时间非常短短，不能正确的表示DML语句执行的时间。语句部分记录的是BEGIN。
DDL:执行时间是实际语句的执行时间，部分语句记录的是实际的语句。
1、验证下DML时间统计的结论，命令执行时间10.30秒，
binlog中解析到的exec_time=0 ，之前的结成立，exec_time记录是修改第一条记录的时间，修改一条记录的时间是很快的。
mysql> flush binary logs; Query OK, 0 rows affected (0.02 sec) mysql> update t1 set name=repeat('c',2000); Query OK, 131072 rows affected, 65535 warnings (10.30 sec) Rows matched: 131072 Changed: 131072 Warnings: 131072
binlog
#201107 17:21:09 server id 1 end_log_pos 377 CRC32 0x6f3d46e9 Query thread_id=315 exec_time=0 error_code=0 SET TIMESTAMP=1604740869/*!*/; SET @@session.pseudo_thread_id=315/*!*/; SET @@session.foreign_key_checks=1, @@session.sql_auto_is_null=0, @@session.unique_checks=1, @@session.autocommit=1/*!*/; SET @@session.sql_mode=0/*!*/; SET @@session.auto_increment_increment=1, @@session.auto_increment_offset=2/*!*/; /*!\C utf8 *//*!*/; SET @@session.character_set_client=33,@@session.collation_connection=33,@@session.collation_server=33/*!*/; SET @@session.lc_time_names=0/*!*/; SET @@session.collation_database=DEFAULT/*!*/; BEGIN /*!*/; # at 377 #201107 17:21:09 server id 1 end_log_pos 426 CRC32 0x139eedd0 Table_map: `ceshi`.`t1` mapped to number 119 # at 426 #201107 17:21:09 server id 1 end_log_pos 8328 CRC32 0x07294435 Update_rows: table id 119 # at 8328 #201107 17:21:09 server id 1 end_log_pos 16230 CRC32 0x3fca917d Update_rows: table id 119 # at 16230 #201107 17:21:09 server id 1 end_log_pos 24132 CRC32 0xd40fb927 Update_rows: table id 119 # at 24132
...........
2、验证下DDL命令时间统计，命令执行时间1.57秒,
binlog中exec_time=2 ，应该是把时间四舍五入了，结论成立。
mysql> flush binary logs; Query OK, 0 rows affected (0.01 sec) mysql> alter table t1 add age int; Query OK, 0 rows affected (1.57 sec) Records: 0 Duplicates: 0 Warnings: 0
binlog
#201107 17:24:22 server id 1 end_log_pos 406 CRC32 0x26d06826 Query thread_id=315 exec_time=2 error_code=0 use `ceshi`/*!*/; SET TIMESTAMP=1604741062/*!*/; SET @@session.pseudo_thread_id=315/*!*/; SET @@session.foreign_key_checks=1, @@session.sql_auto_is_null=0, @@session.unique_checks=1, @@session.autocommit=1/*!*/; SET @@session.sql_mode=0/*!*/; SET @@session.auto_increment_increment=1, @@session.auto_increment_offset=2/*!*/; /*!\C utf8 *//*!*/; SET @@session.character_set_client=33,@@session.collation_connection=33,@@session.collation_server=33/*!*/; SET @@session.lc_time_names=0/*!*/; SET @@session.collation_database=DEFAULT/*!*/; alter table t1 add age int /*!*/;
3、之前的实验都是在没有锁发生的情况测试的，如果遇到Innodb行锁，或MDL锁，不知exec_time是否会包含这个时间，测试如下，先删掉之前添回执age列，重新做测试 。
3.1故意让update命令产生行锁等待，看下binlog的exec_time时间。
t1时间
session1:
mysql> begin; Query OK, 0 rows affected (0.00 sec) mysql> select * from t1 where id=1 for update; +----+----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+ | id | name | +----+----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+ | 1 | cccccccccccccccccccccccccccccccccccccccccccccccccccccccccccccccccccccccccccccccccccccccccccccccccccccccccccccccccccccccccccccccccccccccccccccccccccccccccccccccccccccccccccccccccccccccccccccccccccccccc | +----+----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+ 1 row in set (0.01 sec)
t2时间
sessino2:
mysql> use ceshi; Reading table information for completion of table and column names You can turn off this feature to get a quicker startup with -A Database changed mysql> update t1 set name=repeat('d',2000); ----处于锁等待状态
过一会儿(大约10秒钟左右，心中默数的)，
t3时间，session1释放掉锁
mysql> select * from t1 where id=1 for update; +----+----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+ | id | name | +----+----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+ | 1 | cccccccccccccccccccccccccccccccccccccccccccccccccccccccccccccccccccccccccccccccccccccccccccccccccccccccccccccccccccccccccccccccccccccccccccccccccccccccccccccccccccccccccccccccccccccccccccccccccccccccc | +----+----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+ 1 row in set (0.01 sec) mysql> rollback; Query OK, 0 rows affected (0.01 sec)
t4时间，session2持有锁开始更新记录，SQL显示执行了22.11秒（其中包括锁等待时间）
mysql> update t1 set name=repeat('d',2000); Query OK, 131072 rows affected, 65535 warnings (22.11 sec) Rows matched: 131072 Changed: 131072 Warnings: 131072
binlog
#201107 21:37:03 server id 1 end_log_pos 377 CRC32 0x01b20225 Query thread_id=607 exec_time=13 error_code=0 SET TIMESTAMP=1604756223/*!*/; SET @@session.pseudo_thread_id=607/*!*/; SET @@session.foreign_key_checks=1, @@session.sql_auto_is_null=0, @@session.unique_checks=1, @@session.autocommit=1/*!*/; SET @@session.sql_mode=0/*!*/; SET @@session.auto_increment_increment=1, @@session.auto_increment_offset=2/*!*/; /*!\C utf8 *//*!*/; SET @@session.character_set_client=33,@@session.collation_connection=33,@@session.collation_server=33/*!*/; SET @@session.lc_time_names=0/*!*/; SET @@session.collation_database=DEFAULT/*!*/; BEGIN /*!*/; # at 377 #201107 21:37:03 server id 1 end_log_pos 426 CRC32 0x87b8f0c1 Table_map: `ceshi`.`t1` mapped to number 121 # at 426 #201107 21:37:03 server id 1 end_log_pos 8328 CRC32 0xd5053a6d Update_rows: table id 121 # at 8328 #201107 21:37:03 server id 1 end_log_pos 16230 CRC32 0xede6ef25 Update_rows: table id 121 # at 16230 ........
3.1小结：binlog中exec_time记录行锁等待的时间，实际锁等待时间应该就是13秒，但仍然不能代表update 语句实际执行时间， 因为它实际计算的是update语句更新第一条记录需要的时间。
3.2故意让update命令产生MDL锁等待，看下binlog的exec_time时间。
t1时间
session1:锁定t1表
mysql> flush table t1 with read lock; Query OK, 0 rows affected (0.01 sec)
t2时间
session2:做更新，处于卡住状态。
mysql> update t1 set name=repeat('e',2000);
执行个show processlist,确定现在是等待获取MDL锁状态
mysql> show processlist; +-----+---------+-----------------------+--------------------+------------------+-------+---------------------------------------------------------------+-------------------------------------+ | Id | User | Host | db | Command | Time | State | Info | +-----+---------+-----------------------+--------------------+------------------+-------+---------------------------------------------------------------+-------------------------------------+ | 12 | root | 192.168.150.150:36454 | information_schema | Sleep | 26 | | NULL | | 322 | root | 192.168.150.102:56206 | NULL | Binlog Dump GTID | 17926 | Master has sent all binlog to slave; waiting for more updates | NULL | | 323 | root | 192.168.150.103:43044 | NULL | Binlog Dump GTID | 17910 | Master has sent all binlog to slave; waiting for more updates | NULL | | 607 | root | localhost | ceshi | Query | 6 | Waiting for table metadata lock | update t1 set name=repeat('e',2000) | | 609 | root | localhost | ceshi | Sleep | 11 | | NULL | | 620 | monitor | 192.168.150.150:40076 | NULL | Sleep | 0 | | NULL | | 621 | monitor | 192.168.150.150:40078 | NULL | Sleep | 5 | | NULL | | 631 | root | localhost | NULL | Query | 0 | starting | show processlist | +-----+---------+-----------------------+--------------------+------------------+-------+---------------------------------------------------------------+-------------------------------------+ 8 rows in set (0.00 sec)
t3时间
session1:释放MDL锁
mysql> flush table t1 with read lock; Query OK, 0 rows affected (0.01 sec) mysql> unlock tables; Query OK, 0 rows affected (0.01 sec)
t4时间：
session2:执行完成了
mysql> update t1 set name=repeat('e',2000); Query OK, 131072 rows affected, 65535 warnings (2 min 46.26 sec) Rows matched: 131072 Changed: 131072 Warnings: 131072 mysql>
binlog
#201107 21:46:44 server id 1 end_log_pos 54512694 CRC32 0xe9c2432b GTID last_committed=1 sequence_number=2 rbr_only=yes /*!50718 SET TRANSACTION ISOLATION LEVEL READ COMMITTED*//*!*/; SET @@SESSION.GTID_NEXT= '9fef2262-97b1-11ea-92b5-000c29cd3ff3:1615'/*!*/; # at 54512694 #201107 21:46:44 server id 1 end_log_pos 54512772 CRC32 0x47413c2e Query thread_id=607 exec_time=157 error_code=0 SET TIMESTAMP=1604756804/*!*/; BEGIN /*!*/; # at 54512772 #201107 21:46:44 server id 1 end_log_pos 54512821 CRC32 0x7384f6e6 Table_map: `ceshi`.`t1` mapped to number 122 # at 54512821 #201107 21:46:44 server id 1 end_log_pos 54520723 CRC32 0x8570824e Update_rows: table id 122 # at 54520723 #201107 21:46:44 server id 1 end_log_pos 54528625 CRC32 0xeb6a3741 Update_rows: table id 122
3.2小结：binlog中exec_time记录MDL锁等待的时间，实际锁等待时间应该就是157秒，但仍然不能代表update 语句实际执行时间， 因为它实际计算的是update语句更新第一条记录需要的时间。
通过个结论，我们可以后期通过exec_time内容分析当时的DML操作有没有遇到行锁或MDL锁。
4.1
DDL命令不会遇到行锁，但会遇到MDL锁，测试DDL命令在遇到MDL锁的时候，binlog中exec_time是否有记录。
t1时间
session1:
mysql> flush table t1 with read lock; Query OK, 0 rows affected (0.00 sec)
t2时间
session2:
mysql> alter table t1 add age int;
执行个show processlist,确定现在是等待获取MDL锁状态
mysql> show processlist; +-----+---------+-----------------------+--------------------+------------------+-------+---------------------------------------------------------------+----------------------------+ | Id | User | Host | db | Command | Time | State | Info | +-----+---------+-----------------------+--------------------+------------------+-------+---------------------------------------------------------------+----------------------------+ | 12 | root | 192.168.150.150:36454 | information_schema | Sleep | 53 | | NULL | | 322 | root | 192.168.150.102:56206 | NULL | Binlog Dump GTID | 18914 | Master has sent all binlog to slave; waiting for more updates | NULL | | 323 | root | 192.168.150.103:43044 | NULL | Binlog Dump GTID | 18898 | Master has sent all binlog to slave; waiting for more updates | NULL | | 607 | root | localhost | ceshi | Query | 83 | Waiting for table metadata lock | alter table t1 add age int | | 609 | root | localhost | ceshi | Sleep | 94 | | NULL | | 637 | monitor | 192.168.150.150:40180 | NULL | Sleep | 1 | | NULL | | 643 | root | localhost | NULL | Query | 0 | starting | show processlist | +-----+---------+-----------------------+--------------------+------------------+-------+---------------------------------------------------------------+----------------------------+ 7 rows in set (0.00 sec)
t3时间
session1:释放掉持有的MDL锁
mysql> flush table t1 with read lock; Query OK, 0 rows affected (0.00 sec) mysql> unlock tables; Query OK, 0 rows affected (0.00 sec)
t4时间
session2:执行了124.83秒
mysql> alter table t1 add age int; Query OK, 0 rows affected (2 min 4.83 sec) Records: 0 Duplicates: 0 Warnings: 0
binlog
#201107 22:01:55 server id 1 end_log_pos 406 CRC32 0xa73826c4 Query thread_id=607 exec_time=125 error_code=0 use `ceshi`/*!*/; SET TIMESTAMP=1604757715/*!*/; SET @@session.pseudo_thread_id=607/*!*/; SET @@session.foreign_key_checks=1, @@session.sql_auto_is_null=0, @@session.unique_checks=1, @@session.autocommit=1/*!*/; SET @@session.sql_mode=0/*!*/; SET @@session.auto_increment_increment=1, @@session.auto_increment_offset=2/*!*/; /*!\C utf8 *//*!*/; SET @@session.character_set_client=33,@@session.collation_connection=33,@@session.collation_server=33/*!*/; SET @@session.lc_time_names=0/*!*/; SET @@session.collation_database=DEFAULT/*!*/; alter table t1 add age int /*!*/;
3.2总结：binlog中exec_time会计算DDL命令等待MDL锁的时间。
总结：
1、DDL命令和DML命令，在记binlog时exec_time都会算上锁等待的时间（包括行锁和MDL锁）。
2、DML操作的exec_time可以倒推出当时执行命令的时候有没有遇到行锁或MDL锁。
3、由于DDL操作记录的是命令执行所有时间，无法倒推出执行时有没有遇到MDL锁，只能根据经验看，这个命令执行耗时是否不正常，如果不正常，可以怀疑执行时遇到了MDL锁。
