什么老和慢查询较劲呢，因为通常默认的情况下，如果没有任何监控或者其他日志采集的情况下，诊断问题必须要看的就是慢查询，而且能够追溯历史，这一点比较重要。
因此我觉得需要搞懂每一个指标，以及各种奇怪现象的原因，所以就老和慢查询较劲。
一、问题起因
最近在处理一个case的时候，发现8.0.31版本的慢查询超乎认知了，也就能出现如下的慢查询（模拟的），
# User@Host: root[root] @ localhost [] Id: 9
# Query_time: 5.393639 Lock_time: 5.393379 Rows_sent: 0 Rows_examined: 0
use mytttt;
SET timestamp=1673001377;
delete from t1;
这一点看起来不可思议，因为在老版本中，记录慢查询的标准是：
- Query_time - Lock_time > 参数long_query_time
才会记录慢查询，显然这里两者相减是不可能记录慢查询的，看起来8.0.31版本的慢查询记录的算法变了，变成了Query_time > 参数long_query_time 就记录了。
二、简单举例
举个简单的例子8.0.28之前 S2的如下语句是不会记录慢查询的，而8.0.28及其之后 会记录的。
| S1 | S2 |
|---|---|
| begin | |
| delete from t1; | |
| delete from t1;(简单行堵塞) | |
| S1等待一段时间超过慢查询设置 | |
| commit； | |
| 执行完成 |
可以自行测试。
三、追溯代码变化
当查看代码变化的时候发现 8.0.27-8.0.28的这部分有如下变动：
void THD::update_slow_query_status() {
- if (my_micro_time() > utime_after_lock + variables.long_query_time)
+ if (my_micro_time() > start_utime + variables.long_query_time)
server_status |= SERVER_QUERY_WAS_SLOW; //标记位慢查询
}
简单来说就是如下：
- 老版本（8028之前）：当前时间（语句自然执行结束的时间） - utime_after_lock (可以简单理解为MDL LOCK和row lock等待时间后的时间，当然会多一些) > variables.long_query_time（参数是设置）
- 新版本（8028之后）：当前时间（语句自然执行结束的时间） - start_utime （语句发起时间） > variables.long_query_time（参数是设置）
显然这一点点小的变动，就导致了这种现象，感觉真有有点不讲武德，重点的概念貌似不应该变动，还是那句话时代抛弃了你连招呼都不打一个，尴尬。
当然这种修改我觉得是符合大家的习惯的，慢查询嘛，语句执行多久就应该按多久来判定，也算积极的修改吧。
四、和修复BUG的联动
继续查看release note的时候发现这是修复一个BUG引入的：
The LOCK_TIME returned by the performance schema was under evaluated, missing time spent in rows locks, and time spent when locking multiple tables. As of this release, LOCK_TIME accounts for:
all the time waited on SQL TABLES
all the time waited on DATA locks
LOCK_TIME is now reported consistently in the slow log and the performance schema. (Bug #33236909)
还记得前面我说这两个lock time和慢查询的lock time不一致吗？看来是修复了，原来这也算BUG啊，早知道我也去提交BUG了，当时的文章如下；
很早以前就注意过这个SUM_LOCK_TIME，当时测试没啥用，就没管了，最近稍微看了一下，为什么没用。如下。
慢查询的lock_time
来自于2个函数
A:THD::set_time_after_lock:mysql_lock_tables 后设置，MDL LOCK获取之后，流程到这里的时候设置utime_after_lock
B:thd_storage_lock_wait:引擎层设置lock time，也就是在innodb行被堵塞后设置也就是在原有的utime_after_lock基础上加上锁等待的时间
慢查询记录lock time时候用使用
(A+B)- start_time:因此一般lock time包含了MDL LOCK和row lock的时间，当然不完全相等，因为A是一个流程值。
performance中的SUM_LOCK_TIME
和lock time的不同在于其只包含了A，也就是时间是 A - start_time，也就是去掉引擎层的等待时间，innodb就是row lock，其来源也是THD::set_time_after_lock打开看就明白了。
mysql_lock_tables
->THD::set_time_after_lock
->pfs_set_statement_lock_time_v2
->inline_mysql_set_statement_lock_time
看来是修复了。
五、相关修复方式
简单的看了一下修改，包含在THD中新增了一个成员变量
+ /**
+ Time spent waiting for TABLE locks and DATA locks.
+ Expressed in microseconds.
+ */
+ ulonglong m_lock_usec;
新增方法和去掉的方法如下，而老的utime_after_lock变量被去掉了，
-void THD::set_time_after_lock() {
+void THD::inc_lock_usec(ulonglong lock_usec)
而每次lock time的增加就变成表用THD::inc_lock_usec函数。
LOCK_TIME的计算方法好像没有太多的变化，只是Server layer更加精确了这点体现在如下：
MYSQL_LOCK *mysql_lock_tables函数
+ ulonglong lock_start_usec = my_micro_time();//局部变量
+
DBUG_PRINT("info", ("thd->proc_info %s", thd->proc_info()));
if (sql_lock->table_count &&
lock_external(thd, sql_lock->table, sql_lock->table_count)) {
@@ -368,7 +370,9 @@ end:
if (thd->variables.session_track_transaction_info > TX_TRACK_NONE)
track_table_access(thd, tables, count);
- thd->set_time_after_lock();
+ ulonglong lock_end_usec = my_micro_time();//局部变量
+ thd->inc_lock_usec(lock_end_usec - lock_start_usec); //相减
+
return sql_lock;
而Storage Engine计算没有变化依旧为
void thd_storage_lock_wait(MYSQL_THD thd, long long value) {
- thd->utime_after_lock += value;
+ thd->inc_lock_usec(value);
}
而performance的lock time和slow log的 lock time成了同源，因为THD::inc_lock_usec 函数会自动进行处理，不管Storage Engine还是Server layer的lock time增加都是这个函数
+ MYSQL_SET_STATEMENT_LOCK_TIME(m_statement_psi, m_lock_usec);
也就是调用
static inline void inline_mysql_set_statement_lock_time(
PSI_statement_locker *locker, ulonglong count) {
if (likely(locker != nullptr)) {
PSI_STATEMENT_CALL(set_statement_lock_time)(locker, count);
}
}
最终完成了slow log lock time和performance schema lock time同源一致性的修复。
网友评论