慢查询日志中的 Lock_time 从哪里来？

2023-05-21 · 预计阅读 7 分钟 · MySQL 8.0.32 源码

经常关注慢查询日志的读者，和 Lock_time 应该算是老相识了，大家对这位老相识了解有多少呢？

研究 Lock_time 之前，我对它的了解，仅限于它表示锁等待时间。至于它包含哪些锁等待时间、怎么计算得到的，我并不清楚。

所以，我一直有个困惑：为什么有些 SQL 执行时间很长，Lock_time 却很小（例如：0.001 秒）?

今天我们就一起来看看，Lock_time 包含哪些锁等待时间、以及是怎么计算得到的？

本文基于 MySQL 8.0.32 源码，存储引擎为 InnoDB。
原创不易，如需转载到公众号、博客等，请联系『一树一溪』公众号作者，转载后请标明来源。

目录 [TOC]

正文

1. 整体介绍

Lock_time 由两部分相加得到：

表锁等待时间，如果 SQL 中包含多个表，则是多个表锁等待时间之和。
行锁等待时间，如果 SQL 执行过程中需要对多条记录加锁，则是多个行锁等待时间之和。

对 InnoDB 来说，DML、DQL 对记录进行增删改查操作时，如需加锁，都是加行级别的共享锁、排他锁，而不加表级别的共享锁、排他锁。

共享锁又称作 S 锁，排他锁又称作 X 锁。

那么，InnoDB 有表级别的共享锁、排他锁吗？

别说，还真有！

不过，不常有！

只有执行 LOCK TABLES ... [READ | WRITE]，并且系统变量 innodb_table_locks = 1、auto_commit = 0，InnoDB 才会加表级别的共享锁、排他锁。

从代码注释和官方文档对 innodb_table_locks 的介绍来看，执行存储过程和触发器时，InnoDB 也可能会加表级别的共享锁、排他锁，我们就不展开介绍了。

如果 InnoDB 加了表级别的共享锁、排他锁，Lock_time 包含表锁等待时间，我们比较好理解。

如果我们执行 DML、DQL，InnoDB 没有加表级别的共享锁、排他锁，Lock_time 里还包含表锁等待时间吗？

这个问题，就得看用什么标准了：

严格来说，Lock_time 就不包含表锁等待时间了。
不严格来说，Lock_time 还是包含表锁等待时间的（InnoDB 采用了这个标准）。

接下来，我们通过源码，进入表锁、行锁等待时间的实现逻辑，来一睹芳容。

2. 表锁等待时间

我们先来看一下表锁等待时间实现逻辑的堆栈：

1| > mysql_execute_command(THD*, bool) sql/sql_parse.cc:4688
2| + > Sql_cmd_dml::execute(THD*) sql/sql_select.cc:574
3| + - > lock_tables(...) sql/sql_base.cc:6899
4| + - x > mysql_lock_tables(...) sql/lock.cc:337
5| + - x = > lock_external(THD*, TABLE**, unsigned int) sql/lock.cc:393
6| + - x = | > handler::ha_external_lock(THD*, int) sql/handler.cc:7841
7| + - x = | + > ha_innobase::external_lock(THD*, int) storage/innobase/handler/ha_innodb.cc:18869

Sql_cmd_dml::execute() 调用 lock_tables() 对多个表加锁。

 1// sql/sql_base.cc
 2bool lock_tables(THD *thd, Table_ref *tables, uint count, uint flags) {
 3  ...
 4  if (!thd->locked_tables_mode) {
 5    ...
 6    if (!(thd->lock =
 7          mysql_lock_tables(thd, start, (uint)(ptr - start), flags)))
 8      return true;
 9    ...
10  }
11  ...
12}

lock_tables() 调用 mysql_lock_tables() 对多个表加锁。

 1// sql/lock.cc
 2MYSQL_LOCK *mysql_lock_tables(THD *thd, TABLE **tables, size_t count,
 3                              uint flags) {
 4  ...
 5  // 记录开始时间
 6  ulonglong lock_start_usec = my_micro_time();
 7  ...
 8  if (sql_lock->table_count &&
 9      lock_external(thd, sql_lock->table, sql_lock->table_count)) {
10    /* Clear the lock type of all lock data to avoid reusage. */
11    reset_lock_data_and_free(&sql_lock);
12    goto end;
13  }
14  ...
15  // lock_external() 执行完成之后
16  // 当前时间减去开始时间
17  // 就是表锁等待时间
18  ulonglong lock_end_usec = my_micro_time();
19  thd->inc_lock_usec(lock_end_usec - lock_start_usec);
20  ...
21}

mysql_lock_tables() 调用 lock_external() 之前，先把当前时间记录下来，作为表锁等待的开始时间。

然后调用 lock_external() 对多个表加锁。

最后，调用 thd->inc_lock_usec() 把表锁等待时间累加到 server 层线程对象（thd）的 m_lock_usec 属性中。

 1// sql/lock.cc
 2static int lock_external(THD *thd, TABLE **tables, uint count) {
 3  ...
 4  // 循环 SQL 中的表
 5  for (i = 1; i <= count; i++, tables++) {
 6    assert((*tables)->reginfo.lock_type >= TL_READ);
 7    // 默认锁类型为写锁
 8    // 对应到 InnoDB 的锁类型就是排他锁（X）
 9    lock_type = F_WRLCK; /* Lock exclusive */
10    // 如果以只读方式打开表的数据文件（.ibd）或者
11    // lock_type 大于等于 TL_READ(2) 并且
12    // lock_type 小于等于 TL_READ_NO_INSERT(5)
13    // 则说明是只读操作，加读锁
14    // 对应到 InnoDB 的锁类型就是共享锁（S）
15    if ((*tables)->db_stat & HA_READ_ONLY ||
16        ((*tables)->reginfo.lock_type >= TL_READ &&
17         (*tables)->reginfo.lock_type <= TL_READ_NO_INSERT))
18      lock_type = F_RDLCK;
19    if ((error = (*tables)->file->ha_external_lock(thd, lock_type))) {
20      // ha_external_lock() 返回非 0 值
21      // 说明执行 ha_external_lock() 方法出现了错误
22      // 这里处理善后工作
23      ...
24      return error;
25    } else {
26      (*tables)->db_stat &= ~HA_BLOCK_LOCK;
27      (*tables)->current_lock = lock_type;
28    }
29  }
30  return 0;
31}

lock_external() 会迭代 SQL 中的表，每迭代一个表，都调用 ha_external_lock() 对表进行加锁。

1// sql/handler.cc
2int handler::ha_external_lock(THD *thd, int lock_type) {
3  ...
4  MYSQL_TABLE_LOCK_WAIT(PSI_TABLE_EXTERNAL_LOCK, lock_type,
5    { error = external_lock(thd, lock_type); })
6  ...
7}

handler::ha_external_lock() 调用表对应存储引擎的 external_lock() 方法。

对 InnoDB 来说，调用的是 ha_innobase::external_lock()，这个方法的代码比较多，算是个大杂烩，可以分为三类：

加表级别的共享锁、排他锁。
把当前迭代表所属表空间的脏页，同步刷新到磁盘。
一些初始化逻辑（执行快，花费时间极少）。

ha_innobase::external_lock() 的执行时间会计入表锁等待时间，因为其中可能包含同步刷脏页操作、执行一些初始化逻辑花费的时间，所以，表锁等待时间并不纯粹。

对需要加表锁的 SQL 来说，表锁等待时间包含两部分：

加表级别的共享锁、排他锁的等待时间。
执行一些初始化逻辑花费的时间。

如果是 FLUSH TABLES ... WITH READ LOCK 语句，表锁等待时间还包含：把其中涉及的表所属表空间的脏页同步刷新到磁盘所花费的时间。

对不需要加表锁的 SQL 来说，表锁等待时间就是执行 ha_innobase::external_lock() 中一些初始化逻辑花费的时间。

我们来看看 ha_innobase::external_lock() 主要包含哪些代码逻辑，对这部分细节不感兴趣的读者，可以跳过这个小节。

这个小节的代码都来自于 ha_innobase::external_lock()，文件路径 storage/innobase/handler/ha_innodb.cc。

1update_thd(thd);

以上代码，创建 InnoDB 的事务对象（trx_t），保存到 server 层的用户线程对象（thd）中。

 1// lock_type == F_WRLCK，意味着需要加写锁
 2// 这里用于表示需要记录 binlog
 3if (lock_type == F_WRLCK &&
 4    // 表示不支持 STATEMENT 格式的 binlog
 5    // table_flags() 方法会判断事务隔离级别
 6    !(table_flags() & HA_BINLOG_STMT_CAPABLE) &&
 7    // 系统变量 binlog_format = STATEMENT
 8    // 表示用户需要记录 STATEMENT 格式的 binlog
 9    thd_binlog_format(thd) == BINLOG_FORMAT_STMT &&
10    // 表示需要为当前连接指定的数据库记录 binlog
11    // use <db> 或者连接数据库时指定了数据库
12    thd_binlog_filter_ok(thd) &&
13    // 表示当前执行的 SQL 会产生 ROW 格式的 binlog
14    thd_sqlcom_can_generate_row_events(thd)) {
15  bool skip = false;
16  ...
17  if (!skip) {
18    ...
19    return HA_ERR_LOGGING_IMPOSSIBLE;
20  }
21}

上面代码的判断条件有点多，我们用一句话来概括一下代码逻辑：

事务隔离级别为 READ_UNCOMMITTED、READ_COMMITTED 时，如果 SQL 会产生 ROW 格式的 binlog，而用户设置系统变量 binlog_format 的值为 STATEMENT，要求记录 STATEMENT 格式的 binlog，ha_innobase::external_lock() 会返回 HA_ERR_LOGGING_IMPOSSIBLE，因为 MySQL 无法处理这样矛盾的场景。

1if (lock_type == F_WRLCK) {
2  /* If this is a SELECT, then it is in UPDATE TABLE ...
3  or SELECT ... FOR UPDATE */
4  m_prebuilt->select_lock_type = LOCK_X;
5  m_stored_select_lock_type = LOCK_X;
6}

InnoDB 读取记录时，会根据 m_prebuilt->select_lock_type 的值确定是否加行锁、加共享锁还是排他锁。

lock_type 等于 F_WRLCK，表示 server 层要求加写锁，对应到 InnoDB 的锁类型，就是排他锁，设置加锁类型为 LOCK_X。

 1if (lock_type == F_RDLCK) {
 2  ...
 3  // 如果当前表是数据字典表
 4  // 或者被标识为不需要加锁（no_read_locking = true)
 5  // 设置加锁类型为 LOCK_NONE
 6  if (m_prebuilt->table->is_dd_table || m_prebuilt->no_read_locking) {
 7    m_prebuilt->select_lock_type = LOCK_NONE;
 8    m_stored_select_lock_type = LOCK_NONE;
 9  // 如果事务隔离级别是可串行化
10  } else if (trx->isolation_level == TRX_ISO_SERIALIZABLE &&
11    // 并且当前 SQL 还没有确定加锁类型
12    m_prebuilt->select_lock_type == LOCK_NONE &&
13    // 并且当前事务需要手动提交
14    thd_test_options(thd, OPTION_NOT_AUTOCOMMIT | OPTION_BEGIN)) {
15    // 设置加锁类型为共享锁
16    m_prebuilt->select_lock_type = LOCK_S;
17    m_stored_select_lock_type = LOCK_S;
18  } else {
19    // Retain value set earlier for example via store_lock()
20    // which is LOCK_S or LOCK_NONE
21    ut_ad(m_prebuilt->select_lock_type == LOCK_S ||
22          m_prebuilt->select_lock_type == LOCK_NONE);
23  }
24}

lock_type 等于 F_RDLCK，表示 server 层要求加读锁，对应到 InnoDB 的锁类型，就是共享锁，分两种情况设置 InnoDB 的加锁类型：

对于 ACL 表，m_prebuilt->no_read_locking 会被设置为 true，表示读取记录时不加锁。
如果事务隔离级别是可串行化，并且当前事务需要手动执行 COMMIT 语句提交，以及还没有确定读取该表记录时加什么类型的行锁，设置 InnoDB 加锁类型为共享锁。

ACL 表用于访问权限控制，包含如下这些表：

user
db
tables_priv
columns_priv
procs_priv
proxies_priv
role_edges
default_roles
global_grants
password_history

 1switch (m_prebuilt->table->quiesce) {
 2  case QUIESCE_START:
 3    /* Check for FLUSH TABLE t WITH READ LOCK; */
 4    if (!srv_read_only_mode && sql_command == SQLCOM_FLUSH &&
 5        lock_type == F_RDLCK) {
 6      ...
 7      row_quiesce_table_start(m_prebuilt->table, trx);
 8      ...
 9    }
10    break;
11  ...
12}

只有执行 FLUSH TABLES ... WITH READ LOCK 语句时，才会命中代码中的 case 分支。

row_quiesce_table_start() 会调用 buf_LRU_flush_or_remove_pages()，并把当前加表锁的表所属表空间对象传给该方法，表示把该表空间的脏页刷新到磁盘。

3. 行锁等待时间

我们先来看看对一条记录加行锁的等待时间是怎么计算的。

InnoDB 读取一条记录时，如需加行锁，会调用 sel_set_rec_lock() 进行加锁。

如果其它事务持有该记录的行锁，sel_set_rec_lock() 会返回 DB_LOCK_WAIT，row_search_mvcc() 调用 row_mysql_handle_errors() 处理锁等待逻辑。

row_mysql_handle_errors() 调用 lock_wait_suspend_thread()，行锁等待逻辑由这个方法实现。

 1// storage/innobase/lock/lock0wait.cc
 2void lock_wait_suspend_thread(que_thr_t *thr) {
 3  srv_slot_t *slot;
 4  trx_t *trx;
 5  // 声明变量，用于保存行锁等待的开始时间
 6  std::chrono::steady_clock::time_point start_time;
 7  ...
 8  if (thr->lock_state == QUE_THR_LOCK_ROW) {
 9    srv_stats.n_lock_wait_count.inc();
10    srv_stats.n_lock_wait_current_count.inc();
11    // 设置行锁等待的开始时间
12    start_time = std::chrono::steady_clock::now();
13  }
14  ...
15  // 等待行锁
16  os_event_wait(slot->event);
17  ...
18  // 运行到这里，有两种情况：
19  // 1. 锁等待超时
20  // 2. 已经获取到行锁
21  if (thr->lock_state == QUE_THR_LOCK_ROW) {
22    // 用当前时间减去行锁等待的开始时间
23    // 就是一条记录的行锁等待时间
24    const auto diff_time = std::chrono::steady_clock::now() - start_time;
25    ...
26    /* Record the lock wait time for this thread */
27    // 累加线程的行锁等待时间
28    // 保存到 mysql_thd 线程中
29    // mysql_thd 是 server 层的线程
30    thd_set_lock_wait_time(trx->mysql_thd, diff_time);
31    ...
32  }
33  ...
34}

从上面代码可以看到，计算一条记录的行锁等待时间，逻辑比较简单：
先保存当前行锁等待的开始时间，获取到行锁或等待行锁超时之后，再用当前时间减去开始时间，就得到了一条记录的行锁等待时间。

4. 累计时间

一滴水的梦想是终有一天能够汇入大海。

表锁、行锁等待时间的归宿是累加起来，最终成为 lock_time，这个过程是通过调用 thd_set_lock_wait_time() 实现的。

1// storage/innobase/handler/ha_innodb.cc
2void thd_set_lock_wait_time(THD *thd,
3                            std::chrono::steady_clock::duration value) {
4  if (thd) {
5    thd_storage_lock_wait(
6        thd,
7        std::chrono::duration_cast<std::chrono::microseconds>(value).count());
8  }
9}

thd_set_lock_wait_time() 调用 thd_storage_lock_wait() 累加表锁、行锁等待时间。

1// sql/sql_thd_api.cc
2void thd_storage_lock_wait(MYSQL_THD thd, long long value) {
3  thd->inc_lock_usec(value);
4}

真正干活的是 THD::inc_lock_usec() 方法。

1// sql/sql_class.cc
2void THD::inc_lock_usec(ulonglong lock_usec) {
3  m_lock_usec += lock_usec;
4  MYSQL_SET_STATEMENT_LOCK_TIME(m_statement_psi, m_lock_usec);
5}

server 层每获取到一个表锁，都会调用 thd_set_lock_wait_time()，累加表锁等待时间。

最终会调用 THD::inc_lock_usec() 把表锁等待时间累加到 server 层的线程对象 thd 的 m_lock_usec 属性中。

InnoDB 每获取到一条记录的行锁，或者行锁等待超时，都会调用 thd_set_lock_wait_time()，累加行锁等待时间。

最终会调用 THD::inc_lock_usec() 把行锁等待时间累加到 server 层的线程对象 thd 的 m_lock_usec 属性中。

5. lock_time

SQL 执行完成之后，dispatch_command() 调用 log_slow_statement() 记录慢查询到文件中。

log_slow_statement() 也不是真正干活的，经过多级，最终调用 Query_logger::slow_log_write() 记录慢查询到文件中。

 1// sql/log.cc
 2bool Query_logger::slow_log_write(THD *thd, const char *query,
 3                                  size_t query_length, bool aggregate,
 4                                  ulonglong lock_usec, ulonglong exec_usec) {
 5  ...
 6  if (aggregate) {
 7    query_utime = exec_usec;
 8    lock_utime = lock_usec;
 9  } else if (thd->start_utime) {
10    query_utime = (current_utime - thd->start_utime);
11    lock_utime = thd->get_lock_usec();
12  } else {
13    query_utime = 0;
14    lock_utime = 0;
15  }
16  ...
17  bool error = false;
18  for (Log_event_handler **current_handler = slow_log_handler_list;
19       *current_handler;) {
20    error |= (*current_handler++)->log_slow(
21               thd, current_utime,
22               (thd->start_time.tv_sec * 1000000ULL) +
23               thd->start_time.tv_usec,
24               user_host_buff, user_host_len, query_utime,
25               lock_utime, is_command, query, query_length);
26  }
27  ...
28}

Query_logger::slow_log_write() 被调用时，参数 aggregate 的值都是 false，上面代码不会进入 if (aggregate) 分支。

if (thd->start_utime) 分支，lock_utime = thd->get_lock_usec()，从当前线程对象（thd）中获取之前累加的表锁、行锁等待时间。

然后，调用 log_slow() 记录慢查询到文件中。

 1// sql/log.cc
 2bool Log_to_file_event_handler::log_slow(
 3    THD *thd, ulonglong current_utime, ulonglong query_start_utime,
 4    const char *user_host, size_t user_host_len, ulonglong query_utime,
 5    ulonglong lock_utime, bool is_command, const char *sql_text,
 6    size_t sql_text_len) {
 7  if (!mysql_slow_log.is_open()) return false;
 8
 9  Silence_log_table_errors error_handler;
10  thd->push_internal_handler(&error_handler);
11  bool retval = mysql_slow_log.write_slow(
12      thd, current_utime, query_start_utime, user_host, user_host_len,
13      query_utime, lock_utime, is_command, sql_text, sql_text_len);
14  thd->pop_internal_handler();
15  return retval;
16}

Log_to_file_event_handler::log_slow() 最终调用 mysql_slow_log.write_slow() 记录慢查询到文件中。

 1// sql/log.cc
 2bool File_query_log::write_slow(...) {
 3  ...
 4  if (!thd->copy_status_var_ptr) {
 5    if (my_b_printf(&log_file,
 6        "# Query_time: %s  Lock_time: %s"
 7        " Rows_sent: %lu  Rows_examined: %lu\n",
 8        query_time_buff, lock_time_buff,
 9        (ulong)thd->get_sent_row_count(),
10        (ulong)thd->get_examined_row_count()) == (uint)-1)
11      goto err; /* purecov: inspected */
12  }
13  ...
14}

经常看慢查询日志的读者，想必对这 2 行会非常熟悉：

1Query_time: %s  Lock_time: %s
2Rows_sent: %lu  Rows_examined: %lu

其中的 Lock_time 就是本文的主题，介绍到这里，总算是和文章标题遥相呼应上了。

6. 总结

Lock_time 由表锁、行锁等待时间相加得到。

表锁等待时间并不纯粹，其中包含执行一些初始化操作花费的时间。

对 FLUSH TABLES ... WITH READ LOCK 语句来说，还包含把其中涉及的表所属表空间的脏页同步刷新到磁盘所花费的时间。

行锁等待时间很纯粹，就是多条记录的行锁等待时间之和，或者一条记录的行锁等待时间。

欢迎扫码关注公众号，我们一起学习更多 MySQL 知识：