MySQL 显示SQL执行时间

1.环境

OS: CentOS 6.5 x64

MySQL: 5.6 for Linux (x86_64)

2.打开profiling

打开profiling可以统计资源统计功能。

mysql> set profiling=1;     #打开profiling
Query OK, 0 rows affected, 1 warning (0.07 sec)


mysql> select count(*) from emp;
+----------+
| count(*) |
+----------+
|       14 |
+----------+
1 row in set (0.05 sec)


mysql> show profile;     #显示最近执行的SQL的统计信息
+----------------------+----------+
| Status               | Duration |
+----------------------+----------+
| starting             | 0.052905 |
| checking permissions | 0.004080 |
| Opening tables       | 0.000037 |
| init                 | 0.000025 |
| System lock          | 0.000018 |
| optimizing           | 0.000010 |
| statistics           | 0.000021 |
| preparing            | 0.000017 |
| executing            | 0.000006 |
| Sending data         | 0.000057 |
| end                  | 0.000012 |
| query end            | 0.000013 |
| closing tables       | 0.000013 |
| freeing items        | 0.000287 |
| cleaning up          | 0.000021 |
+----------------------+----------+
15 rows in set, 1 warning (0.09 sec)


mysql> show profiles;     #显示最近执行的SQL列表，默认最多只能显示15条，可以通过修改profiling_history_size进行调整
+----------+------------+--------------------------+
| Query_ID | Duration   | Query                    |
+----------+------------+--------------------------+
|        1 | 0.05752050 | select count(*) from emp |
+----------+------------+--------------------------+
1 row in set, 1 warning (0.02 sec)
#有一个报警

mysql> show warnings;
+---------+------+--------------------------------------------------------------------------------------------------------------+
| Level   | Code | Message                                                                                                      |
+---------+------+--------------------------------------------------------------------------------------------------------------+
| Warning | 1287 | 'SHOW PROFILES' is deprecated and will be removed in a future release. Please use Performance Schema instead |
+---------+------+--------------------------------------------------------------------------------------------------------------+
1 row in set (0.00 sec)
#显示show profiles这样的命令即将过期不再补支持，应该通过Performance Schema进行查询

mysql> use information_schema 

Database changed
mysql> SELECT STATE, FORMAT(DURATION, 6) AS DURATION
    -> FROM INFORMATION_SCHEMA.PROFILING
    -> WHERE QUERY_ID = 2 ORDER BY SEQ;

可以这样查询，但内容不如show profile(s)直观。

mysql> select count(*) from bt;     #再执行一句，这是大表
+----------+
| count(*) |
+----------+
| 47927530 |
+----------+
1 row in set (1 min 49.18 sec)


mysql> show profile;     #显示最近SQL的统计信息
+----------------------+------------+
| Status               | Duration   |
+----------------------+------------+
| starting             |   0.000184 |
| checking permissions |   0.000020 |
| Opening tables       |   0.000030 |
| init                 |   0.000053 |
| System lock          |   0.000019 |
| optimizing           |   0.000013 |
| statistics           |   0.000023 |
| preparing            |   0.000021 |
| executing            |   0.000007 |
| Sending data         | 109.159082 |     #由于是大表，这一步花了109秒多
| end                  |   0.029567 |
| query end            |   0.011552 |
| closing tables       |   0.000044 |
| freeing items        |   0.000623 |
| logging slow query   |   0.000016 |
| cleaning up          |   0.000026 |
+----------------------+------------+
16 rows in set, 1 warning (0.21 sec)


mysql> show profiles;     #看一下现在的语句列表，有两条了
+----------+--------------+--------------------------+
| Query_ID | Duration     | Query                    |
+----------+--------------+--------------------------+
|        1 |   0.02656275 | select count(*) from emp |
|        2 | 108.16862700 | select count(*) from bt  |
+----------+--------------+--------------------------+
2 rows in set, 1 warning (0.10 sec)

mysql> show profile for query 1;     #如果想看第一条SQL的统计信息，就可以这样查询
+----------------------+----------+
| Status               | Duration |
+----------------------+----------+
| starting             | 0.000332 |
| checking permissions | 0.000031 |
| Opening tables       | 0.000044 |
| init                 | 0.000046 |
| System lock          | 0.000032 |
| optimizing           | 0.000019 |
| statistics           | 0.000036 |
| preparing            | 0.000037 |
| executing            | 0.000011 |
| Sending data         | 0.025856 |
| end                  | 0.000039 |
| query end            | 0.000016 |
| closing tables       | 0.000019 |
| freeing items        | 0.000028 |
| cleaning up          | 0.000018 |
+----------------------+----------+
15 rows in set, 1 warning (0.08 sec)

3.profiling语法

show profile有许多选项，且看语法：

SHOW PROFILE [type [, type] ... ]
    [FOR QUERY n]
    [LIMIT row_count [OFFSET offset]]

type:
    ALL
  | BLOCK IO
  | CONTEXT SWITCHES
  | CPU
  | IPC
  | MEMORY
  | PAGE FAULTS
  | SOURCE
  | SWAPS

这些选项的意义如下：

• ALL displays all information

• BLOCK IO displays counts for block input and output operations

• CONTEXT SWITCHES displays counts for voluntary and involuntary context switches

• CPU displays user and system CPU usage times

• IPC displays counts for messages sent and received

• MEMORY is not currently implemented

• PAGE FAULTS displays counts for major and minor page faults

• SOURCE displays the names of functions from the source code, together with the name and line number of the file in which the function occurs

• SWAPS displays swap counts

例如：

mysql> show profile block io,cpu for query 2;     #查看第二条SQL的block io和cpu信息
+----------------------+------------+-----------+------------+--------------+---------------+
| Status               | Duration   | CPU_user  | CPU_system | Block_ops_in | Block_ops_out |
+----------------------+------------+-----------+------------+--------------+---------------+
| starting             |   0.000245 |  0.000000 |   0.000000 |            0 |             0 |
| checking permissions |   0.000030 |  0.000000 |   0.000000 |            0 |             0 |
| Opening tables       |   0.000042 |  0.000000 |   0.000000 |            0 |             0 |
| init                 |   0.000074 |  0.000000 |   0.000000 |            0 |             0 |
| System lock          |   0.000030 |  0.000000 |   0.000000 |            0 |             0 |
| optimizing           |   0.000019 |  0.000000 |   0.000000 |            0 |             0 |
| statistics           |   0.000032 |  0.000000 |   0.000000 |            0 |             0 |
| preparing            |   0.000029 |  0.000000 |   0.000000 |            0 |             0 |
| executing            |   0.000010 |  0.000000 |   0.000000 |            0 |             0 |
| Sending data         | 108.126421 | 33.258944 |   3.981394 |      6507176 |             0 |
| end                  |   0.029766 |  0.001000 |   0.000000 |          424 |             0 |
| query end            |   0.011333 |  0.001000 |   0.000000 |          208 |             0 |
| closing tables       |   0.000041 |  0.000000 |   0.000000 |            0 |             0 |
| freeing items        |   0.000519 |  0.000000 |   0.000000 |            0 |             0 |
| logging slow query   |   0.000014 |  0.000000 |   0.000000 |            0 |             0 |
| cleaning up          |   0.000023 |  0.000000 |   0.000000 |            0 |             0 |
+----------------------+------------+-----------+------------+--------------+---------------+
16 rows in set, 1 warning (0.00 sec)

会话退出后，profiling信息自动清空。