Mysql数据库Slow_log中的lock_Time和Query_time

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

现象展示

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

或者:

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

问题复现

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

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

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

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

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

进行如下测试:

Session1:

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

Session2:

Session2被阻塞

Session1:

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

Session2:

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

Session3:

查询mysql.slow_log,看下结果:

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

测试2:设置long_query_time为5s

重复测试1的测试:

Session1:

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

Session2:

Session2阻塞

Session1:

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

Session2:

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

Session3:

查询mysql.slow_log,看下结果:

从上图可以看到,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的结果和执行时间:

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

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

进行如下测试:

Session1:

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

Session2:

Session2被阻塞

Session1:

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

Session2:

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

Session3:

查询mysql.slow_log,看下结果:

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

测试2:设置long_query_time为5s

重复测试1的测试:

Session1:

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

Session2:

Session2阻塞

Session1:

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

Session2:

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

Session3:

查询mysql.slow_log,看下结果:

从上图可以看到,最新测试的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的结果和执行时间:

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

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

进行如下测试:

Session1:

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

Session2:

Session2被阻塞

Session1:

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

Session2:

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

Session3:

查询mysql.slow_log,看下结果:

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

测试2:设置long_query_time为1s

重复测试1的测试:

Session1:

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

Session2:

Session2阻塞

Session1:

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

Session2:

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

Session3:

查询mysql.slow_log,看下结果:

从上图可以看到,最新测试的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中

云栖团队博客稿源:云栖团队博客 (源链) | 关于 | 阅读提示

本站遵循[CC BY-NC-SA 4.0]。如您有版权、意见投诉等问题,请通过eMail联系我们处理。
酷辣虫 » 后端存储 » Mysql数据库Slow_log中的lock_Time和Query_time

喜欢 (0)or分享给?

专业 x 专注 x 聚合 x 分享 CC BY-NC-SA 4.0

使用声明 | 英豪名录