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 [[code]type

[,

type

] ... ]
[FOR QUERY

n

]
[LIMIT

row_count

[OFFSET

offset

]]

type

:
ALL
| BLOCK IO
| CONTEXT SWITCHES
| CPU
| IPC
| MEMORY
| PAGE FAULTS
| SOURCE
| SWAPS[/code]
这些选项的意义如下：

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信息自动清空。