Mysql数据库Slow_log中的lock_Time和Query_time

实为吾之愚见,望诸君酌之!闻过则喜,与君共勉 

说明:主要用简单的例子来说明,slow log里的lock_time和query_time的关系,得出的结论是:
当一个sql的执行时间(排除lock_time)大于long_query_time的时候,才会被记录到slow log中,并且query_time是累计了lock_time的(如果有lock_time),大概真正的执行时间需要减去lock_time的时间,当一个sql的执行时间(排除lock_time)小于long_query_time的时候(即使他锁等待了3个小时),也不会记录到slow log中的,故锁等待的时间并不决定记不记录slow log,下面的测试多是基于自建mysql进行

现象展示

有时在查slow log的信息时,可能会遇到,下面这种情况:

Mysql数据库Slow_log中的lock_Time和Query_time

或者:

Mysql数据库Slow_log中的lock_Time和Query_time

上面的信息,都出现了lock_time的时间很长的情况,并且sql的执行时间(query_time)也会出现时间很长的情况

 

问题复现

构建测试数据,手动造成锁等待,复现下这类问题

现象1:无自建主键的锁等待

无自建主键测试数据,locking Reads的结果和执行时间:

Mysql数据库Slow_log中的lock_Time和Query_time

上图可以大概判断,select count(1) from MOCK_DATA for update;的执行时间一般会大于小于15S且大于5S

测试1::设置long_query_time为15s:

Mysql数据库Slow_log中的lock_Time和Query_time

进行如下测试:

Session1:

Mysql数据库Slow_log中的lock_Time和Query_time

Session1执行查询,不提交,不回滚

Session2:

Mysql数据库Slow_log中的lock_Time和Query_time

Session2被阻塞

 

Session1:

Mysql数据库Slow_log中的lock_Time和Query_time

等待一段时间后Session1回滚(不要超过锁等待超时时间)

 

Session2:

Mysql数据库Slow_log中的lock_Time和Query_time

Session2执行完成,执行时间是28.95sec

 

Session3:

查询mysql.slow_log,看下结果:

Mysql数据库Slow_log中的lock_Time和Query_time

没有看到session2执行的for update操作的sql

测试2:设置long_query_time为5s

Mysql数据库Slow_log中的lock_Time和Query_time

重复测试1的测试:

Session1:

Mysql数据库Slow_log中的lock_Time和Query_time

Session 1执行查询,不提交不回滚

 

Session2:

Mysql数据库Slow_log中的lock_Time和Query_time

Session2阻塞

 

Session1:

Mysql数据库Slow_log中的lock_Time和Query_time

等待一段时间后Session1回滚(不要超过锁等待超时时间)

 

Session2:

Mysql数据库Slow_log中的lock_Time和Query_time

Session2执行完成,执行时间是47.66sec

 

Session3:

查询mysql.slow_log,看下结果:

Mysql数据库Slow_log中的lock_Time和Query_time

从上图可以看到,session2执行的for update操作的sql记录下来了,其中执行时间(query_time)是47s,在这47s里,锁定的时间(lock_time)是38s

 

结论:

当一个无自建主键的sql的执行时间(排除lock_time)大于long_query_time的时候,才会被记录到slow log中,并且query_time是累计了lock_time的,大概真正的执行时间需要减去lock_time的时间才是(该测试中,执行时间=47s-38s=9s,这个计算可能会有偏差),当一个sql的执行时间(排除lock_time)小于long_query_time的时候(即使他锁等待了3个小时),就不会记录到slow log中

 

现象2:有自建主键的锁等待

有自建主键测试数据,locking Reads的结果和执行时间:

Mysql数据库Slow_log中的lock_Time和Query_time

上图可以大概判断,select count(1) from MOCK_DATA where id<10000000 lock in share mode;的执行时间一般会大于小于15S且大于5S,

测试1::设置long_query_time为15s:

Mysql数据库Slow_log中的lock_Time和Query_time

进行如下测试:

Session1:

Mysql数据库Slow_log中的lock_Time和Query_time

Session1执行查询,不提交,不回滚

Session2:

Mysql数据库Slow_log中的lock_Time和Query_time

Session2被阻塞

 

Session1:

Mysql数据库Slow_log中的lock_Time和Query_time

等待一段时间后Session1回滚(不要超过锁等待超时时间)

 

Session2:

Mysql数据库Slow_log中的lock_Time和Query_time

Session2执行完成,执行时间是31.04sec

 

Session3:

查询mysql.slow_log,看下结果:

Mysql数据库Slow_log中的lock_Time和Query_time

没有看到最新测试的session2执行的for update操作的sql,只有之前测试的那条记录

测试2:设置long_query_time为5s

Mysql数据库Slow_log中的lock_Time和Query_time

重复测试1的测试:

Session1:

Mysql数据库Slow_log中的lock_Time和Query_time

Session 1执行查询,不提交不回滚

 

Session2:

Mysql数据库Slow_log中的lock_Time和Query_time

Session2阻塞

 

Session1:

Mysql数据库Slow_log中的lock_Time和Query_time

等待一段时间后Session1回滚(不要超过锁等待超时时间)

 

Session2:

Mysql数据库Slow_log中的lock_Time和Query_time

Session2执行完成,执行时间是1min 0.40sec

 

Session3:

查询mysql.slow_log,看下结果:

Mysql数据库Slow_log中的lock_Time和Query_time

从上图可以看到,最新测试的session2执行的for update操作的sql记录下来了,其中执行时间(query_time)是1分钟,在这1分钟里,锁定的时间(lock_time)是51s

 

结论:

当使用主键查询的一个sql的执行时间(排除lock_time)大于long_query_time的时候,才会被记录到slow log中,并且query_time是累计了lock_time的,大概真正的执行时间需要减去lock_time的时间,当一个sql的执行时间(排除lock_time)小于long_query_time的时候(即使他锁等待了3个小时),就不会记录到slow log中

 

现象3:secondary index的锁等待

Secondary index测试数据,locking Reads的结果和执行时间:

Mysql数据库Slow_log中的lock_Time和Query_time

上图可以大概判断,select count(1) from MOCK_DATA where ram_num=7 for update;的执行时间一般会大于小于10S且大于1S,

测试1::设置long_query_time为10s:

Mysql数据库Slow_log中的lock_Time和Query_time

进行如下测试:

Session1:

Mysql数据库Slow_log中的lock_Time和Query_time

Session1执行查询,不提交,不回滚

Session2:

Mysql数据库Slow_log中的lock_Time和Query_time

Session2被阻塞

 

Session1:

Mysql数据库Slow_log中的lock_Time和Query_time

等待一段时间后Session1回滚(不要超过锁等待超时时间)

 

Session2:

Mysql数据库Slow_log中的lock_Time和Query_time

Session2执行完成,执行时间是1min 44.02sec

 

Session3:

查询mysql.slow_log,看下结果:

Mysql数据库Slow_log中的lock_Time和Query_time

没有看到最新测试的session2执行的for update操作的sql,只有之前测试的那条记录

测试2:设置long_query_time为1s

Mysql数据库Slow_log中的lock_Time和Query_time

重复测试1的测试:

Session1:

Mysql数据库Slow_log中的lock_Time和Query_time

Session 1执行查询,不提交不回滚

 

Session2:

Mysql数据库Slow_log中的lock_Time和Query_time

Session2阻塞

 

Session1:

Mysql数据库Slow_log中的lock_Time和Query_time

等待一段时间后Session1回滚(不要超过锁等待超时时间)

 

Session2:

Mysql数据库Slow_log中的lock_Time和Query_time

Session2执行完成,执行时间是1min 6.66sec

 

Session3:

查询mysql.slow_log,看下结果:

Mysql数据库Slow_log中的lock_Time和Query_time

从上图可以看到,最新测试的session2执行的for update操作的sql记录下来了,其中执行时间(query_time)是1分06秒,在这1分06秒里,锁定的时间(lock_time)是1分02秒

 

结论:

当使用secondary index查询的一个sql的执行时间(排除lock_time)大于long_query_time的时候,才会被记录到slow log中,并且query_time是累计了lock_time的,大概真正的执行时间需要减去lock_time的时间,当一个sql的执行时间(排除lock_time)小于long_query_time的时候(即使他锁等待了3个小时),就不会记录到slow log中

 

上一篇:rds 签名机制事例及补充说明


下一篇:【限时福利】云上爆款,企业爆款 活动——新零售上云全攻略