码迷,mamicode.com
首页 > 数据库 > 详细

binlog记录SQL执行时间吗,准不准,时间是否包含锁等待时间

时间:2020-11-08 17:13:49      阅读:26      评论:0      收藏:0      [点我收藏+]

标签:reading   详细   action   l命令   wait   时机   app   sch   iso   

讨论: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锁。

binlog记录SQL执行时间吗,准不准,时间是否包含锁等待时间

标签:reading   详细   action   l命令   wait   时机   app   sch   iso   

原文地址:https://www.cnblogs.com/nanxiang/p/13062989.html

(0)
(0)
   
举报
评论 一句话评论(0
登录后才能评论!
© 2014 mamicode.com 版权所有
迷上了代码!