阅读 200

Mysql数据库Slow_log中的lock_Time和Query_time

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

现象展示

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

fae69244bbe2f87993e9806ccb4bf08623a9fafb

或者:

e5445953d7710c45ada5d1bab2bf71fec485182d

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

问题复现

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

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

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

1ff4d75c33654f6a8b4f702b3acd22a0587b23ba

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

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

46fcb570734457dd2db6f80b3582d203075330ec

进行如下测试:

Session1:

534463011cbf354ec4776fddddc57a82d6d582be

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

Session2:

64826de56699e316b3ed0f29fbc3af0e4345fe36

Session2被阻塞

Session1:

1909c53d1552cc809c116b0a60178c1521f9be42

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

Session2:

0c29b5fd7ed27db62ed0710ef4835f18af10b39e

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

Session3:

查询mysql.slow_log,看下结果:

9b9338ec53a23f40ed7b1357603f63dbc7b616ad

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

测试2:设置long_query_time为5s

7f1fa2e886ff3c6c9695e9ba94686a00d5ad9fb3

重复测试1的测试:

Session1:

12efd0200b5be5e7a31365fb20c5878eb58c2c04

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

Session2:

5b8f31735431b00d20649578ff3cf4578e988bf6

Session2阻塞

Session1:

fc090b6243b3765b86590387f59b343549e4c2b0

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

Session2:

1dbf3f4d780a168a2e2607a178be1ee947432c75

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

Session3:

查询mysql.slow_log,看下结果:

8376f68f2605a6a96e4dfd8613de1ce0726bc5d6

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

e3ad8149443b8a325162d90fd20eafc47ef17a72

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

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

7e91ac40b675d8a713c7b070ae0659876a269829

进行如下测试:

Session1:

0de214bac0145ed94df00b97f1ba6a328df2a6ff

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

Session2:

291896bbda3ab24d69b92a14cf9e0b84b3877dd5

Session2被阻塞

Session1:

71366e4b15f66da9126ad0a82cc1688fe7ccf440

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

Session2:

31d6c817ab23316e2c659f87b72cbe4100474211

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

Session3:

查询mysql.slow_log,看下结果:

ac80cfc6e4f11bfa4cbd1d20a7628d8d245359af

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

测试2:设置long_query_time为5s

7f1fa2e886ff3c6c9695e9ba94686a00d5ad9fb3

重复测试1的测试:

Session1:

9ba6f742907da23703a837f8c20eb80ecbf43765

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

Session2:

10eb893fe8488c4b7975ecb378e35037fa974d56

Session2阻塞

Session1:

fc090b6243b3765b86590387f59b343549e4c2b0

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

Session2:

c6f38a8b5660143c858852d83f78285387bb480b

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

Session3:

查询mysql.slow_log,看下结果:

5bfc8605d2603a6a78ad20bc534d10c78a119efb

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

104106f868ebd0fa2945e8fa5f11bc83f78f8aa5

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

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

d699d27ccdd3e851affa63134f5c9bdb1df0b865

进行如下测试:

Session1:

74010215c285b09f082a77125426c958efbdf6f6

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

Session2:

3b118cd15b179c4830dfd9de0559031f4900cd26

Session2被阻塞

Session1:

71366e4b15f66da9126ad0a82cc1688fe7ccf440

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

Session2:

8fb014dc3678e48d042e85498252d62fcc605293

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

Session3:

查询mysql.slow_log,看下结果:

98e39549e3def0bd276daa803cb68f2786ce15f9

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

测试2:设置long_query_time为1s

0001837f31066811a704108e4987b690ca1608c2

重复测试1的测试:

Session1:

080ad7121417b0f5385b58418cfdea3753420e73

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

Session2:

f8ccfdb513e61a14275e6d47749b7426000abb63

Session2阻塞

Session1:

fc090b6243b3765b86590387f59b343549e4c2b0

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

Session2:

66f3c6411d3c3defee149339ab60d8563929dbb3

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

Session3:

查询mysql.slow_log,看下结果:

ef385ea901d4062888a39a3ea859bef294b9b1ac

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

原文链接


关注下面的标签,发现更多相似文章
评论