sql 执行时间

今儿哥们找能在mysql看到sql执行时间的工具，在交流中提到了sql yog，但是它只记录到0ms，如果再精确就没有了。然后提到了phpmyadmin，还是可以的。又google了一下发现了这么个东西：MySQL Query Profiler

 

 

mysql> set profiling=1;##一旦执行了这句话，会自动在information_schema库里新建一个表为 PROFILING 来记录sql相关信息

 

 

mysql> use information_schema;
Database changed
mysql> show tables;
+---------------------------------------+
| Tables_in_information_schema          |
+---------------------------------------+
| CHARACTER_SETS                        |
| COLLATIONS                            |
| COLLATION_CHARACTER_SET_APPLICABILITY |
| COLUMNS                               |
| COLUMN_PRIVILEGES                     |
| ENGINES                               |
| EVENTS                                |
| FILES                                 |
| GLOBAL_STATUS                         |
| GLOBAL_VARIABLES                      |
| KEY_COLUMN_USAGE                      |
| PARTITIONS                            |
| PLUGINS                               |
| PROCESSLIST                           |
| PROFILING                             |
| REFERENTIAL_CONSTRAINTS               |
| ROUTINES                              |
| SCHEMATA                              |
| SCHEMA_PRIVILEGES                     |
| SESSION_STATUS                        |
| SESSION_VARIABLES                     |
| STATISTICS                            |
| TABLES                                |
| TABLE_CONSTRAINTS                     |
| TABLE_PRIVILEGES                      |
| TRIGGERS                              |
| USER_PRIVILEGES                       |
| VIEWS                                 |
+---------------------------------------+
28 rows in set (0.00 sec)

 

看到了吧 ，那现在咱们打开这个表看看里面的信息：

mysql> select * from PROFILING limit 5;
+----------+-----+--------------------------------+----------+----------+------------+-------------------+---------------------+--------------+---------------+---------------+-------------------+-------------------+-------------------+-------+------------------+--------------+-------------+
| QUERY_ID | SEQ | STATE                          | DURATION | CPU_USER | CPU_SYSTEM | CONTEXT_VOLUNTARY | CONTEXT_INVOLUNTARY | BLOCK_OPS_IN | BLOCK_OPS_OUT | MESSAGES_SENT | MESSAGES_RECEIVED | PAGE_FAULTS_MAJOR | PAGE_FAULTS_MINOR | SWAPS | SOURCE_FUNCTION  | SOURCE_FILE  | SOURCE_LINE |
+----------+-----+--------------------------------+----------+----------+------------+-------------------+---------------------+--------------+---------------+---------------+-------------------+-------------------+-------------------+-------+------------------+--------------+-------------+
|        1 |   1 | starting                       | 0.000023 | 0.000000 |   0.000000 |                 0 |                   0 |            0 |             0 |             0 |                 0 |                 0 |                 0 |     0 | NULL             | NULL         |        NULL |
|        1 |   2 | checking query cache for query | 0.000035 | 0.000000 |   0.000000 |                 0 |                   0 |            0 |             0 |             0 |                 0 |                 0 |                 0 |     0 | unknown function | sql_cache.cc |        1446 |
|        1 |   3 | checking permissions           | 0.000006 | 0.000000 |   0.000000 |                 0 |                   0 |            0 |             0 |             0 |                 0 |                 0 |                 0 |     0 | unknown function | sql_parse.cc |        5240 |
|        1 |   4 | Opening tables                 | 0.000050 | 0.000000 |   0.000000 |                 0 |                   0 |            0 |             0 |             0 |                 0 |                 0 |                 0 |     0 | unknown function | sql_base.cc  |        4517 |
|        1 |   5 | query end                      | 0.000005 | 0.000000 |   0.000000 |                 0 |                   0 |            0 |             0 |             0 |                 0 |                 0 |                 0 |     0 | unknown function | sql_parse.cc |        5004 |
+----------+-----+--------------------------------+----------+----------+------------+-------------------+---------------------+--------------+---------------+---------------+-------------------+-------------------+-------------------+-------+------------------+--------------+-------------+
5 rows in set (0.00 sec)

mysql>

 

根据QUERY_ID我们就可以进一步来查看具体信息了。

 

mysql> show profiles;
+----------+------------+------------------------------------+
| Query_ID | Duration   | Query                              |
+----------+------------+------------------------------------+
|        1 | 0.00014000 | select count(*) from info_2.users  |
|        2 | 0.00025800 | select count(*) from info_v2.users |
|        3 | 0.00043300 | show databases                     |
|        4 | 0.01406600 | SELECT DATABASE()                  |
|        5 | 0.00010600 | show tablels                       |
|        6 | 0.00682300 | show tables                        |
|        7 | 0.00043500 | show databases                     |
|        8 | 0.00012300 | SELECT DATABASE()                  |
|        9 | 0.00025700 | show tables                        |
|       10 | 0.00122200 | select * from PROFILING            |
|       11 | 0.00006100 | show profiles for query 2          |
+----------+------------+------------------------------------+
11 rows in set (0.00 sec)

mysql>

 

 

看某一个具体的sql的时间为：

 

 

mysql> show profile for query 2;
+--------------------------------+----------+
| Status                         | Duration |
+--------------------------------+----------+
| starting                       | 0.000028 |
| checking query cache for query | 0.000047 |
| checking permissions           | 0.000006 |
| Opening tables                 | 0.000010 |
| System lock                    | 0.000006 |
| Table lock                     | 0.000025 |
| init                           | 0.000013 |
| optimizing                     | 0.000006 |
| executing                      | 0.000012 |
| end                            | 0.000005 |
| query end                      | 0.000003 |
| freeing items                  | 0.000015 |
| storing result in query cache  | 0.000076 |
| logging slow query             | 0.000003 |
| cleaning up                    | 0.000003 |
+--------------------------------+----------+
15 rows in set (0.01 sec)

 

 

这个工具还可以看到cpu的使用情况：

mysql> show profile cpu for query 2;
+--------------------------------+----------+----------+------------+
| Status                         | Duration | CPU_user | CPU_system |
+--------------------------------+----------+----------+------------+
| starting                       | 0.000028 | 0.000000 |   0.000000 |
| checking query cache for query | 0.000047 | 0.000000 |   0.000000 |
| checking permissions           | 0.000006 | 0.000000 |   0.000000 |
| Opening tables                 | 0.000010 | 0.000000 |   0.000000 |
| System lock                    | 0.000006 | 0.000000 |   0.000000 |
| Table lock                     | 0.000025 | 0.000000 |   0.000000 |
| init                           | 0.000013 | 0.000000 |   0.000000 |
| optimizing                     | 0.000006 | 0.000000 |   0.000000 |
| executing                      | 0.000012 | 0.000000 |   0.000000 |
| end                            | 0.000005 | 0.000000 |   0.000000 |
| query end                      | 0.000003 | 0.000000 |   0.000000 |
| freeing items                  | 0.000015 | 0.000000 |   0.000000 |
| storing result in query cache  | 0.000076 | 0.000000 |   0.000000 |
| logging slow query             | 0.000003 | 0.000000 |   0.000000 |
| cleaning up                    | 0.000003 | 0.000000 |   0.000000 |
+--------------------------------+----------+----------+------------+
15 rows in set (0.00 sec)

 

还可以看到内存使用情况：

mysql> show profile MEMORY  for query 2;
+--------------------------------+----------+
| Status                         | Duration |
+--------------------------------+----------+
| starting                       | 0.000028 |
| checking query cache for query | 0.000047 |
| checking permissions           | 0.000006 |
| Opening tables                 | 0.000010 |
| System lock                    | 0.000006 |
| Table lock                     | 0.000025 |
| init                           | 0.000013 |
| optimizing                     | 0.000006 |
| executing                      | 0.000012 |
| end                            | 0.000005 |
| query end                      | 0.000003 |
| freeing items                  | 0.000015 |
| storing result in query cache  | 0.000076 |
| logging slow query             | 0.000003 |
| cleaning up                    | 0.000003 |
+--------------------------------+----------+
15 rows in set (0.00 sec)

 

 

不过 我们测试完毕 最后别忘记了关闭这个：

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

 

 

这么好用的工具，比phpmyadmin强大多了吧！呵呵！