MYSQL 查询sql语句各个阶段的消耗时间

一.profiles

适用于mysql5.5以前的版本，用来查询语句在各个阶段的消耗

打开设置

mysql> set profiling =1;

任意使用一条查询语句

mysql> select count(*) from lg_student_production;

每一条语句都会生成一条queryId

mysql> show profiles;

+----------+------------+--------------------------------------------+
| Query_ID | Duration   | Query                                      |
+----------+------------+--------------------------------------------+
|        1 | 0.00330400 | show databases                             |
|        2 | 0.00013700 | SELECT DATABASE()                          |
|        3 | 0.00036700 | show tables                                |
|        4 | 0.00492625 | select count(*) from lg_student_production |
+----------+------------+--------------------------------------------+

然后我们查看对应Query_ID的语句执行情况
mysql> show profile for query 4;
+----------------------+----------+
| Status               | Duration |
+----------------------+----------+
| starting             | 0.000082 |
| checking permissions | 0.000017 |
| Opening tables       | 0.004718 |
| init                 | 0.000031 |
| System lock          | 0.000013 |
| optimizing           | 0.000006 |
| executing            | 0.000010 |
| end                  | 0.000004 |
| query end            | 0.000005 |
| closing tables       | 0.000010 |
| freeing items        | 0.000020 |
| cleaning up          | 0.000013 |
+----------------------+----------+
12 rows in set, 1 warning (0.00 sec)

mysql> show  profile cpu for query 4;
+----------------------+----------+----------+------------+
| Status               | Duration | CPU_user | CPU_system |
+----------------------+----------+----------+------------+
| starting             | 0.000082 | 0.000052 |   0.000023 |
| checking permissions | 0.000017 | 0.000012 |   0.000005 |
| Opening tables       | 0.004718 | 0.000136 |   0.003360 |
| init                 | 0.000031 | 0.000017 |   0.000008 |
| System lock          | 0.000013 | 0.000008 |   0.000003 |
| optimizing           | 0.000006 | 0.000005 |   0.000002 |
| executing            | 0.000010 | 0.000006 |   0.000003 |
| end                  | 0.000004 | 0.000003 |   0.000001 |
| query end            | 0.000005 | 0.000003 |   0.000001 |
| closing tables       | 0.000010 | 0.000007 |   0.000004 |
| freeing items        | 0.000020 | 0.000014 |   0.000006 |
| cleaning up          | 0.000013 | 0.000008 |   0.000003 |
+----------------------+----------+----------+------------+
12 rows in set, 1 warning (0.00 sec)

你可以注意到底下会有一个warning，让我们来查看一下

mysql> show warnings;
+---------+------+-------------------------------------------------------------------------------------------------------------+
| Level   | Code | Message                                                                                                     |
+---------+------+-------------------------------------------------------------------------------------------------------------+
| Warning | 1287 | 'SHOW PROFILE' is deprecated and will be removed in a future release. Please use Performance Schema instead |
+---------+------+-------------------------------------------------------------------------------------------------------------+
1 row in set (0.00 sec)
 

因为在mysql5.5之后官方推荐了另一种查询方式Performance Schema。

mysql5.6之后的版本建议启动。

二. Performance Schema

首先需要打开数据库

mysql> use performance_schema;
Database changed

mysql> update setup_instruments set enabled='Yes',timed='yes' where name like 'stage%';
ERROR 1175 (HY000): You are using safe update mode and you tried to update a table without a WHERE that uses a KEY column

如果出现这个错误不要紧，我们需要设置一下安全模式

mysql> show variables like 'SQL_SAFE_UPDATES';
+------------------+-------+
| Variable_name    | Value |
+------------------+-------+
| sql_safe_updates | ON    |
+------------------+-------+
1 row in set (0.00 sec)

mysql> set SQL_SAFE_UPDATES=0;
Query OK, 0 rows affected (0.00 sec)

mysql> show variables like 'SQL_SAFE_UPDATES';
+------------------+-------+
| Variable_name    | Value |
+------------------+-------+
| sql_safe_updates | OFF   |
+------------------+-------+
1 row in set (0.01 sec)
这样就好了

在执行一遍，成功

mysql> update setup_instruments set enabled='Yes',timed='yes' where name like 'stage%';

接下来启动历史记录表

mysql> update setup_consumers set enabled='Yes' where name like 'events%';

我们在执行一遍sql查询语句

mysql> select count(*) from undergraduate.lg_student_production;
+----------+
| count(*) |
+----------+
|      775 |
+----------+
1 row in set (0.00 sec)

mysql> SELECT a.THREAD_ID,SQL_TEXT,c.EVENT_NAME,(c.TIMER_END - c.TIMER_START)/1000000000 AS'DURATION (ms)'
    -> FROM events_statements_history_long a
    -> JOIN threads b ON a.`THREAD_ID`=b.`THREAD_ID`
    -> JOIN events_stages_history_long c ON c.`THREAD_ID`=b.`THREAD_ID`
    -> AND c.`EVENT_ID` BETWEEN a.EVENT_ID AND a.END_EVENT_ID
    -> WHERE b.`PROCESSLIST_ID`=CONNECTION_ID()
    -> AND a.EVENT_NAME='statement/sql/select'
    -> ORDER BY a.THREAD_ID,c.EVENT_ID;

MySQL性能架构