MySQL:8.0.28及其之后慢查询记录算法的重大变化

什么老和慢查询较劲呢，其实我也不想跟它较劲，但是现实是残酷的。

因为通常默认的情况下，如果没有任何监控或者其他日志采集的情况下，诊断问题必须要看的就是慢查询，而且能够追溯历史，这一点比较重要。因此我觉得需要搞懂每一个指标，以及各种奇怪现象的原因，所以就老和慢查询较劲。

一、问题起因

最近在处理一个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的如下delete语句是不会记录到慢查询的，而8.0.28及其之后会记录的。

可以自行测试。

三、追溯代码变化

当查看代码变化的时候发现 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等待时间后的时间，当然会多一些) > 参数long_query_time的设置
• 新版本（8028之后）：当前时间（语句自然执行结束的时间） – start_utime （语句发起时间） > 参数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同源一致性的修复。

原文始发于微信公众号（MySQL学习）：MySQL:8.0.28及其之后慢查询记录算法的重大变化