慢查詢日志中的 Lock_Time 從哪里來？
經常關注慢查詢日志的讀者，和 Lock_time 應該算是老相識了，大家對這位老相識了解有多少呢？
研究 Lock_time 之前，我對它的了解，僅限于它表示鎖等待時間。至于它包含哪些鎖等待時間、怎么計算得到的，我并不清楚。
所以，我一直有個困惑：為什么有些 SQL 執(zhí)行時間很長，Lock_time 卻很小（例如：0.001 秒）?
今天我們就一起來看看，Lock_time 包含哪些鎖等待時間、以及是怎么計算得到的？
正文
整體介紹
Lock_time 由兩部分相加得到：
- 表鎖等待時間，如果 SQL 中包含多個表，則是多個表鎖等待時間之和。
- 行鎖等待時間，如果 SQL 執(zhí)行過程中需要對多條記錄加鎖，則是多個行鎖等待時間之和。
對 InnoDB 來說，DML、DQL 對記錄進行增刪改查操作時，如需加鎖，都是加行級別的共享鎖、排他鎖，而不加表級別的共享鎖、排他鎖。
共享鎖又稱作 S 鎖，排他鎖又稱作 X 鎖。
那么，InnoDB 有表級別的共享鎖、排他鎖嗎？
別說，還真有！
不過，不常有！
只有執(zhí)行 LOCK TABLES ... [READ | WRITE]，并且系統變量 innodb_table_locks = 1、auto_commit = 0，InnoDB 才會加表級別的共享鎖、排他鎖。
從代碼注釋和官方文檔對 innodb_table_locks 的介紹來看，執(zhí)行存儲過程和觸發(fā)器時，InnoDB 也可能會加表級別的共享鎖、排他鎖，我們就不展開介紹了。
如果 InnoDB 加了表級別的共享鎖、排他鎖，Lock_time 包含表鎖等待時間，我們比較好理解。
如果我們執(zhí)行 DML、DQL，InnoDB 沒有加表級別的共享鎖、排他鎖，Lock_time 里還包含表鎖等待時間嗎？
這個問題，就得看用什么標準了：
- 嚴格來說，Lock_time 就不包含表鎖等待時間了。
- 不嚴格來說，Lock_time 還是包含表鎖等待時間的（InnoDB 采用了這個標準）。
接下來，我們通過源碼，進入表鎖、行鎖等待時間的實現邏輯，來一睹芳容。
表鎖等待時間
我們先來看一下表鎖等待時間實現邏輯的堆棧：
| > 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:18869Sql_cmd_dml::execute() 調用 lock_tables() 對多個表加鎖。
// 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;
...
}
...
}lock_tables() 調用 mysql_lock_tables() 對多個表加鎖。
// 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() 執(zhí)行完成之后
// 當前時間減去開始時間
// 就是表鎖等待時間
ulonglong lock_end_usec = my_micro_time();
thd->inc_lock_usec(lock_end_usec - lock_start_usec);
...
}mysql_lock_tables() 調用 lock_external() 之前，先把當前時間記錄下來，作為表鎖等待的開始時間。
然后調用 lock_external() 對多個表加鎖。
最后，調用 thd->inc_lock_usec() 把表鎖等待時間累加到 server 層線程對象（thd）的 m_lock_usec 屬性中。
// sql/lock.cc
static int lock_external(THD *thd, TABLE **tables, uint count) {
...
// 循環(huán) 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 值
// 說明執(zhí)行 ha_external_lock() 方法出現了錯誤
// 這里處理善后工作
...
return error;
} else {
(*tables)->db_stat &= ~HA_BLOCK_LOCK;
(*tables)->current_lock = lock_type;
}
}
return 0;
}lock_external() 會迭代 SQL 中的表，每迭代一個表，都調用 ha_external_lock() 對表進行加鎖。
// 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); })
...
}handler::ha_external_lock() 調用表對應存儲引擎的 external_lock() 方法。
對 InnoDB 來說，調用的是 ha_innobase::external_lock()，這個方法的代碼比較多，算是個大雜燴，可以分為三類：
- 加表級別的共享鎖、排他鎖。
- 把當前迭代表所屬表空間的臟頁，同步刷新到磁盤。
- 一些初始化邏輯（執(zhí)行快，花費時間極少）。
ha_innobase::external_lock() 的執(zhí)行時間會計入表鎖等待時間，因為其中可能包含同步刷臟頁操作、執(zhí)行一些初始化邏輯花費的時間，所以，表鎖等待時間并不純粹。
對需要加表鎖的 SQL 來說，表鎖等待時間包含兩部分：
- 加表級別的共享鎖、排他鎖的等待時間。
- 執(zhí)行一些初始化邏輯花費的時間。
如果是 FLUSH TABLES ... WITH READ LOCK 語句，表鎖等待時間還包含：把其中涉及的表所屬表空間的臟頁同步刷新到磁盤所花費的時間。
對不需要加表鎖的 SQL 來說，表鎖等待時間就是執(zhí)行 ha_innobase::external_lock() 中一些初始化邏輯花費的時間。
我們來看看 ha_innobase::external_lock() 主要包含哪些代碼邏輯，對這部分細節(jié)不感興趣的讀者，可以跳過這個小節(jié)。
這個小節(jié)的代碼都來自于 ha_innobase::external_lock()，文件路徑 storage/innobase/handler/ha_innodb.cc。
update_thd(thd);以上代碼，創(chuàng)建 InnoDB 的事務對象（trx_t），保存到 server 層的用戶線程對象（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) &&
// 表示當前執(zhí)行的 SQL 會產生 ROW 格式的 binlog
thd_sqlcom_can_generate_row_events(thd)) {
bool skip = false;
...
if (!skip) {
...
return HA_ERR_LOGGING_IMPOSSIBLE;
}
}上面代碼的判斷條件有點多，我們用一句話來概括一下代碼邏輯：
事務隔離級別為 READ_UNCOMMITTED、READ_COMMITTED 時，如果 SQL 會產生 ROW 格式的 binlog，而用戶設置系統變量 binlog_format 的值為 STATEMENT，要求記錄 STATEMENT 格式的 binlog，ha_innobase::external_lock() 會返回 HA_ERR_LOGGING_IMPOSSIBLE，因為 MySQL 無法處理這樣矛盾的場景。
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;
}InnoDB 讀取記錄時，會根據 m_prebuilt->select_lock_type 的值確定是否加行鎖、加共享鎖還是排他鎖。
lock_type 等于 F_WRLCK，表示 server 層要求加寫鎖，對應到 InnoDB 的鎖類型，就是排他鎖，設置加鎖類型為 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);
}
}lock_type 等于 F_RDLCK，表示 server 層要求加讀鎖，對應到 InnoDB 的鎖類型，就是共享鎖，分兩種情況設置 InnoDB 的加鎖類型：
- 對于 ACL 表，m_prebuilt->no_read_locking 會被設置為 true，表示讀取記錄時不加鎖。
- 如果事務隔離級別是可串行化，并且當前事務需要手動執(zhí)行 COMMIT 語句提交，以及還沒有確定讀取該表記錄時加什么類型的行鎖，設置 InnoDB 加鎖類型為共享鎖。
ACL 表用于訪問權限控制，包含如下這些表：
- user
- db
- tables_priv
- columns_priv
- procs_priv
- proxies_priv
- role_edges
- default_roles
- global_grants
- password_history
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;
...
}只有執(zhí)行 FLUSH TABLES ... WITH READ LOCK 語句時，才會命中代碼中的 case 分支。
row_quiesce_table_start() 會調用 buf_LRU_flush_or_remove_pages()，并把當前加表鎖的表所屬表空間對象傳給該方法，表示把該表空間的臟頁刷新到磁盤。
行鎖等待時間
我們先來看看對一條記錄加行鎖的等待時間是怎么計算的。
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()，行鎖等待邏輯由這個方法實現。
// 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);
...
}
...
}從上面代碼可以看到，計算一條記錄的行鎖等待時間，邏輯比較簡單： 先保存當前行鎖等待的開始時間，獲取到行鎖或等待行鎖超時之后，再用當前時間減去開始時間，就得到了一條記錄的行鎖等待時間。
累計時間
一滴水的夢想是終有一天能夠匯入大海。
表鎖、行鎖等待時間的歸宿是累加起來，最終成為 lock_time，這個過程是通過調用 thd_set_lock_wait_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());
}
}thd_set_lock_wait_time() 調用 thd_storage_lock_wait() 累加表鎖、行鎖等待時間。
// sql/sql_thd_api.cc
void thd_storage_lock_wait(MYSQL_THD thd, long long value) {
thd->inc_lock_usec(value);
}真正干活的是 THD::inc_lock_usec() 方法。
// 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);
}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 屬性中。
lock_time
SQL 執(zhí)行完成之后，dispatch_command() 調用 log_slow_statement() 記錄慢查詢到文件中。
log_slow_statement() 也不是真正干活的，經過多級，最終調用 Query_logger::slow_log_write() 記錄慢查詢到文件中。
// 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);
}
...
}Query_logger::slow_log_write() 被調用時，參數 aggregate 的值都是 false，上面代碼不會進入 if (aggregate) 分支。
if (thd->start_utime) 分支，lock_utime = thd->get_lock_usec()，從當前線程對象（thd）中獲取之前累加的表鎖、行鎖等待時間。
然后，調用 log_slow() 記錄慢查詢到文件中。
// 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;
}Log_to_file_event_handler::log_slow() 最終調用 mysql_slow_log.write_slow() 記錄慢查詢到文件中。
// 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 */
}
...
}經常看慢查詢日志的讀者，想必對這 2 行會非常熟悉：
Query_time: %s Lock_time: %s
Rows_sent: %lu Rows_examined: %lu其中的 Lock_time 就是本文的主題，介紹到這里，總算是和文章標題遙相呼應上了。
總結
Lock_time 由表鎖、行鎖等待時間相加得到。
表鎖等待時間并不純粹，其中包含執(zhí)行一些初始化操作花費的時間。
對 FLUSH TABLES ... WITH READ LOCK 語句來說，還包含把其中涉及的表所屬表空間的臟頁同步刷新到磁盤所花費的時間。
行鎖等待時間很純粹，就是多條記錄的行鎖等待時間之和，或者一條記錄的行鎖等待時間。
本文轉載自微信公眾號「一樹一溪」，可以通過以下二維碼關注。轉載本文請聯系一樹一溪公眾號。
