4. 通过 SHOW PROFILE 分析 SQL

MySQL 从 5.0.37 版本开始增加了对 SHOW PROFILES 和 SHOW PROFILE 语句的支持。

通过 have_profiling 参数，能够看到当前 MySQL 是否支持 profile：

mysql> SELECT @@have_profiling;
+------------------+
| @@have_profiling |
+------------------+
| YES              |
+------------------+
1 row in set, 1 warning (0.00 sec)

通过 profiling 参数，可以控制是否启用 profile 功能：

SET PROFILING = 1;
SELECT @@profiling;

-- 设置列表容量大小
SET profiling_history_size := 100;

注意：如果在 datagrip 上使用 profile，如果不设置 profiling_history_size 扩大列表容量，因为 datagrip 增加一些隐式的 sql 调用，因此会非常快速的耗尽列表容量，导致想要分析的目标 SQL 被挤出去，导致 profile 功能无法正常使用！

通过 profile，能够更清楚地了解 SQL 执行的过程。

首先，在一个 innodb 引擎的付款表 payment 上，执行一个 COUNT(*) 查询：

SELECT count(*) FROM payment;
+----------+
| count(*) |
+----------+
|    16044 |
+----------+
1 row in set (0.00 sec)

执行完毕后，通过 SHOW PROFILES 语句，看到当前 SQL 的 Query ID 为 4：

SHOW PROFILES;
+----------+------------+------------------------------+
| Query_ID | Duration   | Query                        |
+----------+------------+------------------------------+
|        1 | 0.00023450 | SELECT @@have_profiling      |
|        2 | 0.00015275 | show warnings                |
|        3 | 0.00018550 | select @profiling            |
|        4 | 0.00257575 | SELECT count(*) FROM payment |
+----------+------------+------------------------------+
4 rows in set, 1 warning (0.00 sec)

通过 SHOW PROFILE FOR QUERY 语句能够看到执行过程中线程的每个状态和消耗的时间：

SHOW PROFILE FOR QUERY 4;
+----------------------+----------+
| Status               | Duration |
+----------------------+----------+
| starting             | 0.000075 |
| checking permissions | 0.000006 |
| Opening tables       | 0.000022 |
| init                 | 0.000010 |
| System lock          | 0.000006 |
| optimizing           | 0.000004 |
| statistics           | 0.000013 |
| preparing            | 0.000009 |
| executing            | 0.000001 |
| Sending data         | 0.002319 |
| end                  | 0.000003 |
| query end            | 0.000006 |
| closing tables       | 0.000005 |
| freeing items        | 0.000086 |
| cleaning up          | 0.000012 |
+----------------------+----------+
15 rows in set, 1 warning (0.00 sec)

Sending data 状态表示 MySQL 线程开始访问数据行并把结果返回给客户端，而不仅仅是返回结果给客户端。由于在 Sending data 状态下，MySQL 线程往往需要做大量的磁盘读取操作，所以经常是整个查询中耗时最长的状态。

为了更清晰地看到排序结果，可以查询 INFORMATION_SCHEMA.PROFILING 表并按照时间做个 DESC 排序：

mysql> SET @query_id := 4;
Query OK, 0 rows affected (0.00 sec)

mysql> SELECT STATE,
    ->        SUM(DURATION)            AS Total_R,
    ->        ROUND(100 * SUM(DURATION) / (
    ->            SELECT SUM(DURATION)
    ->            FROM INFORMATION_SCHEMA.PROFILING
    ->            WHERE QUERY_ID = @query_id
    ->        ), 2)                    AS Pct_R,
    ->        COUNT(*)                 AS Calls,
    ->        SUM(DURATION) / COUNT(*) AS "R/Call"
    -> FROM INFORMATION_SCHEMA.PROFILING
    -> WHERE QUERY_ID = @query_id
    -> GROUP BY STATE
    -> ORDER BY Total_R DESC;
+----------------------+----------+-------+-------+--------------+
| STATE                | Total_R  | Pct_R | Calls | R/Call       |
+----------------------+----------+-------+-------+--------------+
| Sending data         | 0.002319 | 89.99 |     1 | 0.0023190000 |
| freeing items        | 0.000086 |  3.34 |     1 | 0.0000860000 |
| starting             | 0.000075 |  2.91 |     1 | 0.0000750000 |
| Opening tables       | 0.000022 |  0.85 |     1 | 0.0000220000 |
| statistics           | 0.000013 |  0.50 |     1 | 0.0000130000 |
| cleaning up          | 0.000012 |  0.47 |     1 | 0.0000120000 |
| init                 | 0.000010 |  0.39 |     1 | 0.0000100000 |
| preparing            | 0.000009 |  0.35 |     1 | 0.0000090000 |
| query end            | 0.000006 |  0.23 |     1 | 0.0000060000 |
| System lock          | 0.000006 |  0.23 |     1 | 0.0000060000 |
| checking permissions | 0.000006 |  0.23 |     1 | 0.0000060000 |
| closing tables       | 0.000005 |  0.19 |     1 | 0.0000050000 |
| optimizing           | 0.000004 |  0.16 |     1 | 0.0000040000 |
| end                  | 0.000003 |  0.12 |     1 | 0.0000030000 |
| executing            | 0.000001 |  0.04 |     1 | 0.0000010000 |
+----------------------+----------+-------+-------+--------------+
15 rows in set, 16 warnings (0.00 sec)

在获取到最消耗时间的线程状态后，MySQL 支持进一步选择 all、cpu、block io、context switch、page faults 等明细类型来查看 MySQL 在使用什么资源上耗费了过高的时间。

mysql> SHOW PROFILE CPU FOR QUERY 4;
+----------------------+----------+----------+------------+
| Status               | Duration | CPU_user | CPU_system |
+----------------------+----------+----------+------------+
| starting             | 0.000075 | 0.000000 |   0.000000 |
| checking permissions | 0.000006 | 0.000000 |   0.000000 |
| Opening tables       | 0.000022 | 0.000000 |   0.000000 |
| init                 | 0.000010 | 0.000000 |   0.000000 |
| System lock          | 0.000006 | 0.000000 |   0.000000 |
| optimizing           | 0.000004 | 0.000000 |   0.000000 |
| statistics           | 0.000013 | 0.000000 |   0.000000 |
| preparing            | 0.000009 | 0.000000 |   0.000000 |
| executing            | 0.000001 | 0.000000 |   0.000000 |
| Sending data         | 0.002319 | 0.000000 |   0.000000 |
| end                  | 0.000003 | 0.000000 |   0.000000 |
| query end            | 0.000006 | 0.000000 |   0.000000 |
| closing tables       | 0.000005 | 0.000000 |   0.000000 |
| freeing items        | 0.000086 | 0.000000 |   0.000000 |
| cleaning up          | 0.000012 | 0.000000 |   0.000000 |
+----------------------+----------+----------+------------+
15 rows in set, 1 warning (0.00 sec)