本文首發個人公眾號《andyqian》, 期待你的關注～

前言

在之前的文章中，我們提到過一些慢SQL優化的步驟。其中就包括：使用 explain 關鍵字來查看執行計劃，是否命中索引。

通過計算某列的區分度，來判斷該列是否適合新建索引。

這都是一些比較好的方法。但我們還是不知道，慢SQL，到底慢在哪個環節？在每個環節中耗時是多少？

根據木桶定理，我們應該找到耗時最長，性能最低，也就是最慢的環節，才能分析出慢SQL為什么這么慢，以便更加有效的解決這個問題。帶著這個疑問，我們一起來看看今天給大家介紹的這個利器。

開啟性能分析

show profiles 這個命令非常強大，能清晰的展示每條SQL的持續時間。通常結合show profile 命令可以更加詳細的展示其耗時信息。這樣就能很容易的分析出，到底慢在哪個環節了。比較遺憾的是，在MySQL中，該命令默認是關閉狀態的。在使用之前，我們首先得啟用它：開啟命令：

set profiling = ON;

或：

set profiling = 1;

查看是否生效：

mysql> show variables like "profiling";

+---------------+-------+

| Variable_name | Value |

+---------------+-------+

| profiling | ON |

+---------------+-------+

1 row in set (0.00 sec)

Value的取值范圍有兩個：其中 ON 為開啟狀態，OFF為關閉狀態。

值得注意的是：通過上述命令開啟后僅在當前會話有效。

show profiles

show profiles 其作用為顯示當前會話服務器最新收到的15條SQL的性能信息。

其中包括：持續時間，以及Query_ID。我們可以通過Query_ID分析其性能

如下所示：

mysql> show profiles;

+----------+------------+---------------------------------+

| Query_ID | Duration | Query |

+----------+------------+---------------------------------+

| 1 | 0.00385450 | show variables like "profiling" |

| 2 | 0.00170050 | show variables like "profiling" |

| 3 | 0.00038025 | select * from t_base_user |

+----------+------------+---------------------------------+

其中：Query_ID 表示執行SQL的唯一標識。

Duration 表示持續時間，默認單位為秒。

Query 就是我們所執行的SQL語句。

注意：show profiles 語句 默認顯示的是服務端接收到的最新的15條語句。

我們可以通過以下語句進行修改默認值：

set profiling_history_size =20;

profiling_history_size最大取值取值范圍為[0,100]。

當超過100時，則會設置自動設置為最大值100。

當小于0時，則會自動設置最小值為0。

當其等于0時，其效果等同于 set profiling=0，關閉性能分析模式。

現在通過 show profiles 命令查看到了SQL的執行時間，但這是一個總時間，每一步的耗時怎么看呢？別急，我們再來看看show profile 命令的用法。

show profile

還記得show profiles命令中的 Query_ID字段嗎？我們現在就通過Query_ID來查看下持續時間的構成。

例如：我們查看Query_ID 等于 3 的詳細持續時間構成。

如下所示：

mysql> show profile for query 3;

+----------------------+----------+

| Status | Duration |

+----------------------+----------+

| starting | 0.000081 |

| checking permissions | 0.000012 |

| Opening tables | 0.000028 |

| init | 0.000029 |

| System lock | 0.000017 |

| optimizing | 0.000006 |

| statistics | 0.000025 |

| preparing | 0.000018 |

| executing | 0.000004 |

| Sending data | 0.000087 |

| end | 0.000007 |

| query end | 0.000012 |

| closing tables | 0.000013 |

| freeing items | 0.000023 |

| cleaning up | 0.000021 |

+----------------------+----------+

15 rows in set, 1 warning (0.00 sec)

通過上述結果，我們可以非常清楚的查看每一步的耗時，其中(Druation的單位為秒)。這樣，當我們遇到一條慢SQL時，就能很清楚的知道，為什么慢，慢在哪一步了。

備注： 上述結果集中的Status就不再詳細解析了，這里其實展示的是SQL的執行過程，經歷的步驟，通過字面就能很快知道其意思。

上面我們使用的是默認展示結果。其實，我們也指定展示結果，如：CPU，IO，線程上下文切換等等。

可選參數如下：all： 展示所有信息。

block io： 展示io的輸入輸出信息。

context switches： 展示線程的上線文切換信息。

cpu ：顯示SQL 占用的CPU信息。

ipc： 顯示統計消息的發送與接收計數信息。

page faults：顯示主要與次要的頁面錯誤。

memory：本意是顯示內存信息，但目前還未實現。

swaps： 顯示交換次數。

sources：顯示源代碼中的函數名稱，以及函數發生的文件的名稱和行。

上面參數可以組合使用，其中用 , 號分割。如下所示：

mysql> show profile block io,cpu for query 3;

+----------------------+----------+----------+------------+--------------+---------------+

| Status | Duration | CPU_user | CPU_system | Block_ops_in | Block_ops_out |

+----------------------+----------+----------+------------+--------------+---------------+

| starting | 0.000081 | 0.000036 | 0.000044 | 0 | 0 |

| checking permissions | 0.000012 | 0.000005 | 0.000006 | 0 | 0 |

| Opening tables | 0.000028 | 0.000013 | 0.000015 | 0 | 0 |

| init | 0.000029 | 0.000013 | 0.000016 | 0 | 0 |

| System lock | 0.000017 | 0.000008 | 0.000009 | 0 | 0 |

| optimizing | 0.000006 | 0.000002 | 0.000003 | 0 | 0 |

| statistics | 0.000025 | 0.000011 | 0.000013 | 0 | 0 |

| preparing | 0.000018 | 0.000008 | 0.000010 | 0 | 0 |

| executing | 0.000004 | 0.000002 | 0.000002 | 0 | 0 |

| Sending data | 0.000087 | 0.000040 | 0.000048 | 0 | 0 |

| end | 0.000007 | 0.000003 | 0.000003 | 0 | 0 |

| query end | 0.000012 | 0.000006 | 0.000007 | 0 | 0 |

| closing tables | 0.000013 | 0.000005 | 0.000006 | 0 | 0 |

| freeing items | 0.000023 | 0.000011 | 0.000013 | 0 | 0 |

| cleaning up | 0.000021 | 0.000009 | 0.000011 | 0 | 0 |

+----------------------+----------+----------+------------+--------------+---------------+

15 rows in set, 1 warning (0.00 sec)

當結果顯示的比較多時，你也可以通過 limit 選項，來顯示指定的行數。如下所示：

mysql> show profile block io,cpu for query 3 limit 2;

+----------------------+----------+----------+------------+--------------+---------------+

| Status | Duration | CPU_user | CPU_system | Block_ops_in | Block_ops_out |

+----------------------+----------+----------+------------+--------------+---------------+

| starting | 0.000081 | 0.000036 | 0.000044 | 0 | 0 |

| checking permissions | 0.000012 | 0.000005 | 0.000006 | 0 | 0 |

+----------------------+----------+----------+------------+--------------+---------------+

2 rows in set, 1 warning (0.00 sec)

現在我們就可以很清楚的知道，慢SQL到底慢在哪？可以進行針對性的優化。我們對優化后的SQL語句也能查看其持續時間，是否符合我們的指標。

PS： 最近在面試過程中，問及SQL優化時，有很多的同學對執行計劃，區分度的概念都不是很清楚。甚至覺得執行計劃中有執行時間，這就很離譜了，對不對。我希望我的讀者朋友們不要被這種低級錯誤擋住理想的offer。

相關閱讀: