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

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

// sql/sql_base.cc
bool lock_tables(THD *thd, Table_ref *tables, uint count, uint flags){
  ...
  if (!thd->locked_tables_mode) {
    ...
    if (!(thd->lock =
          mysql_lock_tables(thd, start, (uint)(ptr - start), flags)))
      return true;
    ...
  }
  ...
}

// sql/lock.cc
MYSQL_LOCK *mysql_lock_tables(THD *thd, TABLE **tables, size_t count,
                              uint flags){
  ...
  // 记录开始时间
  ulonglong lock_start_usec = my_micro_time();
  ...
  if (sql_lock->table_count &&
      lock_external(thd, sql_lock->table, sql_lock->table_count)) {
    /* Clear the lock type of all lock data to avoid reusage. */
    reset_lock_data_and_free(&sql_lock);
    goto end;
  }
  ...
  // lock_external() 执行完成之后
  // 当前时间减去开始时间
  // 就是表锁等待时间
  ulonglong lock_end_usec = my_micro_time();
  thd->inc_lock_usec(lock_end_usec - lock_start_usec);
  ...
}

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

// sql/handler.cc
int handler::ha_external_lock(THD *thd, int lock_type){
  ...
  MYSQL_TABLE_LOCK_WAIT(PSI_TABLE_EXTERNAL_LOCK, lock_type,
    { error = external_lock(thd, lock_type); })
  ...
}

update_thd(thd);

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

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

if (lock_type == F_RDLCK) {
  ...
  // 如果当前表是数据字典表
  // 或者被标识为不需要加锁（no_read_locking = true)
  // 设置加锁类型为 LOCK_NONE
  if (m_prebuilt->table->is_dd_table || m_prebuilt->no_read_locking) {
    m_prebuilt->select_lock_type = LOCK_NONE;
    m_stored_select_lock_type = LOCK_NONE;
  // 如果事务隔离级别是可串行化
  } else if (trx->isolation_level == TRX_ISO_SERIALIZABLE &&
    // 并且当前 SQL 还没有确定加锁类型
    m_prebuilt->select_lock_type == LOCK_NONE &&
    // 并且当前事务需要手动提交
    thd_test_options(thd, OPTION_NOT_AUTOCOMMIT | OPTION_BEGIN)) {
    // 设置加锁类型为共享锁
    m_prebuilt->select_lock_type = LOCK_S;
    m_stored_select_lock_type = LOCK_S;
  } else {
    // Retain value set earlier for example via store_lock()
    // which is LOCK_S or LOCK_NONE
    ut_ad(m_prebuilt->select_lock_type == LOCK_S ||
          m_prebuilt->select_lock_type == LOCK_NONE);
  }
}

switch (m_prebuilt->table->quiesce) {
  case QUIESCE_START:
    /* Check for FLUSH TABLE t WITH READ LOCK; */
    if (!srv_read_only_mode && sql_command == SQLCOM_FLUSH &&
        lock_type == F_RDLCK) {
      ...
      row_quiesce_table_start(m_prebuilt->table, trx);
      ...
    }
    break;
  ...
}

// storage/innobase/lock/lock0wait.cc
void lock_wait_suspend_thread(que_thr_t *thr){
  srv_slot_t *slot;
  trx_t *trx;
  // 声明变量，用于保存行锁等待的开始时间
  std::chrono::steady_clock::time_point start_time;
  ...
  if (thr->lock_state == QUE_THR_LOCK_ROW) {
    srv_stats.n_lock_wait_count.inc();
    srv_stats.n_lock_wait_current_count.inc();
    // 设置行锁等待的开始时间
    start_time = std::chrono::steady_clock::now();
  }
  ...
  // 等待行锁
  os_event_wait(slot->event);
  ...
  // 运行到这里，有两种情况：
  // 1. 锁等待超时
  // 2. 已经获取到行锁
  if (thr->lock_state == QUE_THR_LOCK_ROW) {
    // 用当前时间减去行锁等待的开始时间
    // 就是一条记录的行锁等待时间
    const auto diff_time = std::chrono::steady_clock::now() - start_time;
    ...
    /* Record the lock wait time for this thread */
    // 累加线程的行锁等待时间
    // 保存到 mysql_thd 线程中
    // mysql_thd 是 server 层的线程
    thd_set_lock_wait_time(trx->mysql_thd, diff_time);
    ...
  }
  ...
}

// storage/innobase/handler/ha_innodb.cc
void thd_set_lock_wait_time(THD *thd,
                            std::chrono::steady_clock::duration value){
  if (thd) {
    thd_storage_lock_wait(
        thd,
        std::chrono::duration_cast<std::chrono::microseconds>(value).count());
  }
}

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

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

// sql/log.cc
bool Query_logger::slow_log_write(THD *thd, const char *query,
                                  size_t query_length, bool aggregate,
                                  ulonglong lock_usec, ulonglong exec_usec){
  ...
  if (aggregate) {
    query_utime = exec_usec;
    lock_utime = lock_usec;
  } else if (thd->start_utime) {
    query_utime = (current_utime - thd->start_utime);
    lock_utime = thd->get_lock_usec();
  } else {
    query_utime = 0;
    lock_utime = 0;
  }
  ...
  bool error = false;
  for (Log_event_handler **current_handler = slow_log_handler_list;
       *current_handler;) {
    error |= (*current_handler++)->log_slow(
               thd, current_utime,
               (thd->start_time.tv_sec * 1000000ULL) +
               thd->start_time.tv_usec,
               user_host_buff, user_host_len, query_utime,
               lock_utime, is_command, query, query_length);
  }
  ...
}

// sql/log.cc
bool Log_to_file_event_handler::log_slow(
    THD *thd, ulonglong current_utime, ulonglong query_start_utime,
    const char *user_host, size_t user_host_len, ulonglong query_utime,
    ulonglong lock_utime, bool is_command, const char *sql_text,
    size_t sql_text_len){
  if (!mysql_slow_log.is_open()) return false;

  Silence_log_table_errors error_handler;
  thd->push_internal_handler(&error_handler);
  bool retval = mysql_slow_log.write_slow(
      thd, current_utime, query_start_utime, user_host, user_host_len,
      query_utime, lock_utime, is_command, sql_text, sql_text_len);
  thd->pop_internal_handler();
  return retval;
}

// sql/log.cc
bool File_query_log::write_slow(...){
  ...
  if (!thd->copy_status_var_ptr) {
    if (my_b_printf(&log_file,
        "# Query_time: %s  Lock_time: %s"
        " Rows_sent: %lu  Rows_examined: %lu\n",
        query_time_buff, lock_time_buff,
        (ulong)thd->get_sent_row_count(),
        (ulong)thd->get_examined_row_count()) == (uint)-1)
      goto err; /* purecov: inspected */
  }
  ...
}

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