您好,欢迎来到花图问答。
搜索
您的当前位置:首页Mysql数据库Slow_log中的lock_Time和Quer

Mysql数据库Slow_log中的lock_Time和Quer

来源:花图问答

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

现象展示

有时在查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中

Copyright © 2019- huatuowenda.com 版权所有 湘ICP备2023022495号-1

违法及侵权请联系:TEL:199 1889 7713 E-MAIL:2724546146@qq.com

本站由北京市万商天勤律师事务所王兴未律师提供法律服务