原始碼解析丨一次慢SQL排查

當long_query_time=1時（表info的id為主鍵），出現下面的慢日誌，可能會讓你吃驚

# Time: 2024-01-28T22:52:24.500491+08:00
# User@Host: root[root] @  [127.0.0.1]  Id:     8
# Query_time: 7.760787  Lock_time: 7.757456 Rows_sent: 0  Rows_examined: 0
use apple;
SET timestamp=1706453536;
delete from info where id < 10;

環境資訊

配置	引數
ip	172.17.137.12
hostname	dev
memory	16G
cpu	8C
MySQL version	GreatSQL 8.0.26

慢查詢相關引數

greatsql> select * from performance_schema.global_variables where variable_name in('slow_query_log','log_output','slow_query_log_file','long_query_time','log_queries_not_using_indexes','log_slow_admin_statements','min_examined_row_limit','log_throttle_queries_not_using_indexes') order by variable_name;
+----------------------------------------+-------------------------------------+
| VARIABLE_NAME                          | VARIABLE_VALUE                      |
+----------------------------------------+-------------------------------------+
| log_output                             | FILE                                |
| log_queries_not_using_indexes          | OFF                                 |
| log_slow_admin_statements              | OFF                                 |
| log_throttle_queries_not_using_indexes | 0                                   |
| long_query_time                        | 1.000000                            |
| min_examined_row_limit                 | 0                                   |
| slow_query_log                         | ON                                  |
| slow_query_log_file                    | /root/local/8026/log/slow.log       |
+----------------------------------------+-------------------------------------+
8 rows in set (10.49 sec)

• slow_query_log：慢日誌開關

• log_output：慢日誌儲存方式，FILE或TABLE

• long_query_time：慢日誌閾值

• min_examined_row_limit：設定慢SQL的最小examined掃描行數，建議設定為0，因為有bug：https://bugs.mysql.com/bug.php?id=110804

• log_queries_not_using_indexes：不使用索引的慢查詢日誌是否記錄到索引

• log_slow_admin_statements：在寫入慢速查詢日誌的語句中包含慢速管理語句（create index,drop index,alter table,analyze table,check table,optimize table,repair table）預設是不會記錄的

• log_throttle_queries_not_using_indexes：用於限制每分鐘輸出未使用索引的日誌數量。每分鐘允許記錄到slow log的且未使用索引的sql語句次數，配合long_queries_not_using_indexes開啟使用。

• log_slow_slave_statements：預設OFF，是否開啟主從複製中從庫的慢查詢

根本原因

一、慢日誌寫入大致流程

• dispatch_command(thd)

  • thd->enable_slow_log = true // 初始化enable_slow_log為true

  • thd->set_time // 設定開始時間

  • dispatch_sql_command

  • parse_sql // 語法解析

  • mysql_execute_command // 執行SQL

    • lex->m_sql_cmd->execute // 常見的CRUD操作

  • thd->update_slow_query_status // 判斷是否達到慢日誌閾值。若為慢查詢，則更新thd的server_status狀態，為寫slow_log作準備

  • log_slow_statement

  • log_slow_applicable // 判斷是否寫入慢日誌

    • log_slow_do // 開始寫入

      • slow_log_write

        • log_slow

        • write_slow

二、判斷是否達到慢日誌閾值

• 8.0.26版本的慢日誌判斷標準

void THD::update_slow_query_status() {
  if (my_micro_time() > utime_after_lock + variables.long_query_time)
    server_status | = SERVER_QUERY_WAS_SLOW;
}
// my_micro_time() 獲取當前系統時間點，單位為微妙
// utime_after_lock 為MDL LOCK和row lock等待時間後的時間點，單位為微妙
// variables.long_query_time 慢日誌閾值long_query_time * 1000000 ，單位為微妙
// 等價於：my_micro_time() - utime_after_lock  > variables.long_query_time
// 不包含鎖等待時間

• 8.0.32版本的慢日誌判斷標準（8.0.28開始）

void THD::update_slow_query_status() {
  if (my_micro_time() > start_utime + variables.long_query_time)
    server_status | = SERVER_QUERY_WAS_SLOW;
}
// 判別標準變成了：（語句執行結束的時間 - 語句開始執行時間） > 慢日誌閾值
// my_micro_time() 當前系統時間點，單位為微妙
// start_utime：語句開始執行時間點，單位為微妙
// variables.long_query_time 慢日誌閾值long_query_time * 1000000 ，單位為微妙
// 包含鎖等待時間

從上面可以看出慢日誌的判斷標準發生了根本變化

舉例說明

greatsql> select * from info;
+----+------+
| id | name |
+----+------+
|  1 |    1 |
|  2 |    2 |
|  5 |    5 |
| 60 |    8 |
| 40 |   11 |
| 20 |   20 |
| 30 |   30 |
+----+------+
7 rows in set (0.05 sec)

greatsql> show create table info\G
*************************** 1. row ***************************
       Table: info
Create Table: CREATE TABLE `info` (
  `id` int NOT NULL AUTO_INCREMENT,
  `name` int NOT NULL,
  PRIMARY KEY (`id`),
  UNIQUE KEY `uk_name` (`name`)
) ENGINE=InnoDB AUTO_INCREMENT=61 DEFAULT CHARSET=utf8mb4 COLLATE=utf8mb4_0900_ai_ci
1 row in set (0.02 sec) 

session1	session2
begin;
delete from info where id < 10;
	delete from info where id < 10;
session1等待一段時間超過慢日誌閾值long_query_time
rollback；

• 在8.0.26版本中，是不會記錄session2中的delete from info where id < 10

• 在8.0.32版本中，會記錄session2中的delete from info where id < 10

三、判斷是否寫入慢日誌

void log_slow_statement(THD *thd,
                        struct System_status_var *query_start_status) {
  if (log_slow_applicable(thd)) log_slow_do(thd, query_start_status);
}


//----------------------------------------------------------------

bool log_slow_applicable(THD *thd) {
  DBUG_TRACE;

  /*
    The following should never be true with our current code base,
    but better to keep this here so we don't accidently try to log a
    statement in a trigger or stored function
  */
  if (unlikely(thd->in_sub_stmt)) return false;  // Don't set time for sub stmt

  if (unlikely(thd->killed == THD::KILL_CONNECTION)) return false;

  /*
    Do not log administrative statements unless the appropriate option is
    set.
  */
  if (thd->enable_slow_log && opt_slow_log) {
    bool warn_no_index =
        ((thd->server_status &
          (SERVER_QUERY_NO_INDEX_USED | SERVER_QUERY_NO_GOOD_INDEX_USED)) &&
         opt_log_queries_not_using_indexes &&
         !(sql_command_flags[thd->lex->sql_command] & CF_STATUS_COMMAND));
    bool log_this_query =
        ((thd->server_status & SERVER_QUERY_WAS_SLOW) || warn_no_index) &&
        (thd->get_examined_row_count() >=
         thd->variables.min_examined_row_limit);
    bool suppress_logging = log_throttle_qni.log(thd, warn_no_index);

    if (!suppress_logging && log_this_query) return true;
  }
  return false;
}

• 若log_slow_applicable(thd)返回值為true，則執行log_slow_do(thd, query_start_status)，寫入慢日誌

• if (unlikely(thd->in_sub_stmt)) return false;if (unlikely(thd->killed == THD::KILL_CONNECTION)) return false;

​ a. 子查詢，返回false

​ b. 被kill，返回false

​ c. 解析出錯，返回false

​ d. 執行出錯，返回false

• warn_no_index 表示log_queries_not_using_indexes開啟且（未使用索引或未使用最優索引）

  • thd->server_status 該執行緒狀態

  • SERVER_QUERY_NO_INDEX_USED 表示未使用索引

  • SERVER_QUERY_NO_GOOD_INDEX_USED 表示未使用最優索引

  • opt_log_queries_not_using_indexes 表示log_queries_not_using_indexes引數的值，預設OFF

• !(sql_command_flags[thd->lex->sql_command] & CF_STATUS_COMMAND))表示該語句不是SHOW相關的命令。CF_STATUS_COMMAND常量表示執行的命令為show相關的命令。

• log_this_query = ((thd->server_status & SERVER_QUERY_WAS_SLOW) || warn_no_index) && (thd->get_examined_row_count() >=thd->variables.min_examined_row_limit);

  • (thd->server_status & SERVER_QUERY_WAS_SLOW) 表示該SQL為慢查詢

  • (thd->get_examined_row_count() >=thd->variables.min_examined_row_limit) 表示SQL的掃描資料行數不小於引數min_examined_row_limit 的值，預設為0

• log_throttle_qni.log(thd, warn_no_index) 表示用來計算該條未使用索引的SQL是否需要寫入到slow log，計算需要使用到引數log_throttle_queries_not_using_indexes , 該參數列明允許每分鐘寫入到slow log中的未使用索引的SQL的數量，預設值為0，表示不限制

按照線上配置

• log_throttle_queries_not_using_indexes = 0

• log_queries_not_using_indexes = OFF

• log_slow_admin_statements = OFF

• min_examined_row_limit = 0

• slow_query_log = ON

• long_query_time = 1.000000

那麼在GreatSQL-8.0.26中，是否寫入到慢日誌中，取決於thd->server_status & SERVER_QUERY_WAS_SLOW，即SQL執行總耗時-SQL鎖等待耗時>1秒

那麼在GreatSQL-8.0.32中，是否寫入到慢日誌中，取決於thd->server_status & SERVER_QUERY_WAS_SLOW，即SQL執行總耗時>1秒

---

Enjoy GreatSQL 😃

關於 GreatSQL

GreatSQL是適用於金融級應用的國內自主開源資料庫，具備高效能、高可靠、高易用性、高安全等多個核心特性，可以作為MySQL或Percona Server的可選替換，用於線上生產環境，且完全免費併相容MySQL或Percona Server。

相關連結： GreatSQL社群 Gitee GitHub Bilibili

GreatSQL社群：

社群部落格有獎徵稿詳情：https://greatsql.cn/thread-100-1-1.html

技術交流群：

微信：掃碼新增GreatSQL社群助手微信好友，傳送驗證資訊加群。