討論：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鎖。