源碼解析丨一次慢SQL排查

来源:https://www.cnblogs.com/greatsql/p/18088776
-Advertisement-
Play Games

當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 ...


當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

您的分享是我們最大的動力!

-Advertisement-
Play Games
更多相關文章
  • 掌握C#中的GUI多線程技巧：WinForms和WPF實例詳解
    概述：本指南詳細解釋了在C#中如何在創建控制項的線程以外的線程中訪問GUI。基礎功能使用`Control.Invoke`（WinForms）或`Dispatcher.Invoke`（WPF），高級功能則利用`SynchronizationContext`實現線程間通信，確保代碼清晰可讀。 在C#中，要 ...
  • 搞懂.NET應用程式管理員許可權：三種簡單方法一網打盡
    概述：.NET應用程式以管理員身份運行的方法包括修改清單文件、項目文件，或在運行時動態請求管理員許可權。清單文件和項目文件通過聲明UAC請求，而動態請求管理員許可權則在程式啟動時檢查並重新啟動。選擇適當的方法取決於項目需求和配置。 在.NET應用程式中強制以管理員身份運行，可以通過清單文件、項目文件或者 ...
  • nginx location匹配規則順序總結
    Nginx的location匹配順序是Nginx配置中非常核心且重要的概念，它決定了Nginx如何處理進入伺服器的請求。理解location匹配順序不僅有助於優化Nginx的性能，還能確保網站或應用的正確運行。下麵將詳細闡述Nginx的location匹配順序，並通過實例加以說明。 Nginx lo ...
  • CentOS系統安裝docker
    來自chatGPT 在CentOS 7.9系統上安裝Docker，你可以遵循以下步驟： 更新你的系統：首先，確保你的系統是最新的。這可以通過運行下麵的命令來實現： sudo yum update 安裝必要的包：為了使得yum源支持https，你需要安裝幾個必要的包： sudo yum install ...
  • Saltstack 最大打開文件數問題之奇怪的 8192
    哈嘍大家好，我是鹹魚。 今天分享一個在壓測過程中遇到的問題，當時排查這個問題費了我們好大的勁，所以我覺得有必要寫一篇文章來記錄一下。 問題出現 周末在進行壓測的時候，測試和開發的同事反映壓測有問題，請求打到 A 服務上被拒絕了。 我們登錄伺服器查看 A 服務的日誌，發現頻繁地報 Too many o ...
  • FreeRTOS教程10 低功耗
    本文主要學習 FreeRTOS 低功耗的相關知識，包括HAL 庫基礎時鐘、FreeRTOS 基礎時鐘、低功耗處理和 Tickless 模式等知識 ...
  • kafka重置偏移量
    背景 近年來隨著國際形勢的變化，信創產業成為我國國家戰略的一部分。一直以來，一直以來，全球 ICT 產業底層標準、架構、產品、生態等要素均由國外公司或機構制定和控制，使我國 ICT 產業乃至廣大用戶面臨被卡脖子、數據泄露、信息安全等諸多風險，尤其是 2018年以來，中興、華為等公司的遭遇成為鮮活的實 ...
  • OGG 抽取進程註冊時報OGG-08221 ORA-00001錯誤總結
    OGG部署時，抽取進程（Extract）註冊到資料庫時遇到下麵錯誤： REGISTER EXTRACT ***** DATABASE ERROR OGG-08221 Cannot register or unregister EXTRACT because of the following SQL ...
一周排行
    -Advertisement-
    Play Games
  • （開源）都進來！簡單易懂、功能強大的許可權+可視化流程管理系統
    1、預覽地址：http://139.155.137.144:9012 2、qq群:801913255 一、前言 隨著網路的發展，企業對於信息系統數據的保密工作愈發重視，不同身份、角色對於數據的訪問許可權都應該大相徑庭。 列如 1、不同登錄人員對一個數據列表的可見度是不一樣的，如數據列、數據行、數據按鈕 ...
  • 設計模式-C#實現簡單工廠模式
    前言 上一篇文章寫瞭如何使用RabbitMQ做個簡單的發送郵件項目，然後評論也是比較多，也是準備去學習一下如何確保RabbitMQ的消息可靠性，但是由於時間原因，先來說說設計模式中的簡單工廠模式吧！ 在瞭解簡單工廠模式之前，我們要知道C#是一款面向對象的高級程式語言。它有3大特性，封裝、繼承、多態。 ...
  • Nodify學習 一：介紹與使用
    Nodify學習 一：介紹與使用 - 可樂_加冰 - 博客園 (cnblogs.com) Nodify學習 二：添加節點 - 可樂_加冰 - 博客園 (cnblogs.com) 介紹 Nodify是一個WPF基於節點的編輯器控制項，其中包含一系列節點、連接和連接器組件，旨在簡化構建基於節點的工具的過程 ...
  • 使用C#/.NET解析Wiki百科數據實現獲取歷史上的今天
    創建一個webapi項目做測試使用。 創建新控制器，搭建一個基礎框架，包括獲取當天日期、wiki的請求地址等 創建一個Http請求幫助類以及方法，用於獲取指定URL的信息 使用http請求訪問指定url，先運行一下，看看返回的內容。內容如圖右邊所示，實際上是一個Json數據。我們主要解析 大事記 部 ...
  • .NET科普：.NET簡史、.NET Standard以及C#和.NET Framework之間的關係
    最近在不少自媒體上看到有關.NET與C#的資訊與評價，感覺大家對.NET與C#還是不太瞭解，尤其是對2016年6月發佈的跨平臺.NET Core 1.0，更是知之甚少。在考慮一番之後，還是決定寫點東西總結一下，也回顧一下.NET的發展歷史。 首先，你沒看錯，.NET是跨平臺的，可以在Windows、 ...
  • Nodify學習 二：添加節點
    Nodify學習 一：介紹與使用 - 可樂_加冰 - 博客園 (cnblogs.com) Nodify學習 二：添加節點 - 可樂_加冰 - 博客園 (cnblogs.com) 添加節點（nodes） 通過上一篇我們已經創建好了編輯器實例現在我們為編輯器添加一個節點 添加model和viewmode ...
  • 論如何直接用EF Core實現創建更新時間、用戶審計，自動化樂觀併發、軟刪除和樹形查詢（上）
    前言 資料庫併發，數據審計和軟刪除一直是數據持久化方面的經典問題。早些時候，這些工作需要手寫複雜的SQL或者通過存儲過程和觸發器實現。手寫複雜SQL對軟體可維護性構成了相當大的挑戰，隨著SQL字數的變多，用到的嵌套和複雜語法增加，可讀性和可維護性的難度是幾何級暴漲。因此如何在實現功能的同時控制這些S ...
  • C# 使用模式匹配的好處,因為好用所以推薦~
    類型檢查和轉換：當你需要檢查對象是否為特定類型，並且希望在同一時間內將其轉換為那個類型時，模式匹配提供了一種更簡潔的方式來完成這一任務，避免了使用傳統的as和is操作符後還需要進行額外的null檢查。 複雜條件邏輯：在處理複雜的條件邏輯時，特別是涉及到多個條件和類型的情況下，使用模式匹配可以使代碼更 ...
  • 推薦一種批量判斷文件是否存在的快速辦法
    在日常開發中，我們經常需要和文件打交道，特別是桌面開發，有時候就會需要載入大批量的文件，而且可能還會存在部分文件缺失的情況，那麼如何才能快速的判斷文件是否存在呢？如果處理不當的，且文件數量比較多的時候，可能會造成卡頓等情況，進而影響程式的使用體驗。今天就以一個簡單的小例子，簡述兩種不同的判斷文件是否... ...
  • 論如何直接用EF Core實現創建更新時間、用戶審計，自動化樂觀併發、軟刪除和樹形查詢（中）
    前言 資料庫併發，數據審計和軟刪除一直是數據持久化方面的經典問題。早些時候，這些工作需要手寫複雜的SQL或者通過存儲過程和觸發器實現。手寫複雜SQL對軟體可維護性構成了相當大的挑戰，隨著SQL字數的變多，用到的嵌套和複雜語法增加，可讀性和可維護性的難度是幾何級暴漲。因此如何在實現功能的同時控制這些S ...
所有分類