作者：手辨
实为吾之愚见,望诸君酌之!闻过则喜，与君共勉
说明：主要用简单的例子来说明，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的信息时，可能会遇到，下面这种情况：
或者：
上面的信息，都出现了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中
