show profiles mysql查询优化之profile

show profiles mysql查询优化之profile

当mysql遇到性能瓶颈时，从mysql本身出发去优化大致分为两个方面。一个是调整mysql的配置参数，另一个是优化查询sql了。

查看sql运行时间是必不可少的，这时候profile就相当重要了。

1、查看profile是否打开，以下三种方法都的可以的。

mysql> show profiles;
Empty set, 1 warning (0.00 sec)

mysql> show variables like "profiling%";
+------------------------+-------+
| Variable_name          | Value |
+------------------------+-------+
| profiling              | OFF   |
| profiling_history_size | 15    |
+------------------------+-------+
2 rows in set (0.00 sec)

mysql> 

mysql> select @@profiling;
+-------------+
| @@profiling |
+-------------+
|           0 |
+-------------+
1 row in set, 1 warning (0.00 sec)

mysql>

以上结果可以看出，profile没有打开。我们在当前Session会话状态打开profile；

2、当前Session会话状态打开profile

开启 Query Profiler 功能之后，MySQL 就会自动记录所有执行的 Query 的 profile 信息了。

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

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

mysql> 

3、查看sql运行时间

获取系统中保存的所有 Query 的 profile 概要信息

mysql> show databases;
+---------------------+
| Database            |
+---------------------+
| yw_mdmall           |
+---------------------+
1 rows in set (0.00 sec)

mysql> use yw_mdmall;
Database changed
mysql> select id from yw_order limit 10;
+----+
| id |
+----+
|  2 |
|  3 |
|  4 |
|  5 |
|  6 |
|  7 |
|  8 |
|  9 |
| 10 |
| 11 |
+----+
10 rows in set (0.00 sec)

mysql> show profiles;
+----------+------------+----------------------------------+
| Query_ID | Duration   | Query                            |
+----------+------------+----------------------------------+
|        1 | 0.00036950 | show databases                   |
|        2 | 0.00010925 | SELECT DATABASE()                |
|        3 | 0.00021900 | select id from yw_order limit 10 |
+----------+------------+----------------------------------+
3 rows in set, 1 warning (0.00 sec)

mysql> 

查看最后一条sql的执行详细信息

通过执行 “SHOW PROFILE” 命令获取当前系统中保存的多个 Query 的 profile 的概要信息。

mysql> show profile;
+----------------------+----------+
| Status               | Duration |
+----------------------+----------+
| starting             | 0.000055 |
| checking permissions | 0.000009 |
| Opening tables       | 0.000023 |
| init                 | 0.000017 |
| System lock          | 0.000008 |
| optimizing           | 0.000006 |
| statistics           | 0.000013 |
| preparing            | 0.000012 |
| executing            | 0.000003 |
| Sending data         | 0.000038 |
| end                  | 0.000005 |
| query end            | 0.000007 |
| closing tables       | 0.000008 |
| freeing items        | 0.000012 |
| cleaning up          | 0.000005 |
+----------------------+----------+
15 rows in set, 1 warning (0.00 sec)

mysql> 

查看指定 Query_ID 对应sql的执行详细信息

mysql> show profile for query 3;
+----------------------+----------+
| Status               | Duration |
+----------------------+----------+
| starting             | 0.000055 |
| checking permissions | 0.000009 |
| Opening tables       | 0.000023 |
| init                 | 0.000017 |
| System lock          | 0.000008 |
| optimizing           | 0.000006 |
| statistics           | 0.000013 |
| preparing            | 0.000012 |
| executing            | 0.000003 |
| Sending data         | 0.000038 |
| end                  | 0.000005 |
| query end            | 0.000007 |
| closing tables       | 0.000008 |
| freeing items        | 0.000012 |
| cleaning up          | 0.000005 |
+----------------------+----------+
15 rows in set, 1 warning (0.00 sec)

mysql> show profile for query 2;
+----------------------+----------+
| Status               | Duration |
+----------------------+----------+
| starting             | 0.000041 |
| checking permissions | 0.000008 |
| Opening tables       | 0.000007 |
| init                 | 0.000012 |
| optimizing           | 0.000006 |
| executing            | 0.000008 |
| end                  | 0.000005 |
| query end            | 0.000004 |
| closing tables       | 0.000004 |
| freeing items        | 0.000011 |
| cleaning up          | 0.000005 |
+----------------------+----------+
11 rows in set, 1 warning (0.00 sec)

mysql> 
mysql> show profile for query 1;
+----------------------+----------+
| Status               | Duration |
+----------------------+----------+
| starting             | 0.000032 |
| checking permissions | 0.000006 |
| Opening tables       | 0.000042 |
| init                 | 0.000008 |
| System lock          | 0.000005 |
| optimizing           | 0.000004 |
| statistics           | 0.000010 |
| preparing            | 0.000011 |
| executing            | 0.000185 |
| Sending data         | 0.000023 |
| end                  | 0.000005 |
| query end            | 0.000004 |
| closing tables       | 0.000003 |
| removing tmp table   | 0.000013 |
| closing tables       | 0.000004 |
| freeing items        | 0.000011 |
| cleaning up          | 0.000005 |
+----------------------+----------+
17 rows in set, 1 warning (0.00 sec)

查看最后一条sql的执行 cpu、io、内存、交换内存等 信息

mysql> show profile cpu,block io,memory,swaps,context switches,source for query 3;
+----------------------+----------+----------+------------+-------------------+---------------------+--------------+---------------+-------+-----------------------+------------------+-------------+
| Status               | Duration | CPU_user | CPU_system | Context_voluntary | Context_involuntary | Block_ops_in | Block_ops_out | Swaps | Source_function       | Source_file      | Source_line |
+----------------------+----------+----------+------------+-------------------+---------------------+--------------+---------------+-------+-----------------------+------------------+-------------+
| starting             | 0.000055 | 0.000000 |   0.000000 |                 0 |                   0 |            0 |             0 |     0 | NULL                  | NULL             |        NULL |
| checking permissions | 0.000009 | 0.000000 |   0.000000 |                 0 |                   0 |            0 |             0 |     0 | check_access          | sql_parse.cc     |        5268 |
| Opening tables       | 0.000023 | 0.000000 |   0.000000 |                 0 |                   0 |            0 |             0 |     0 | open_tables           | sql_base.cc      |        4934 |
| init                 | 0.000017 | 0.000000 |   0.000000 |                 0 |                   0 |            0 |             0 |     0 | mysql_prepare_select  | sql_select.cc    |        1050 |
| System lock          | 0.000008 | 0.000000 |   0.000000 |                 0 |                   0 |            0 |             0 |     0 | mysql_lock_tables     | lock.cc          |         304 |
| optimizing           | 0.000006 | 0.000000 |   0.000000 |                 0 |                   0 |            0 |             0 |     0 | optimize              | sql_optimizer.cc |         138 |
| statistics           | 0.000013 | 0.000000 |   0.000000 |                 0 |                   0 |            0 |             0 |     0 | optimize              | sql_optimizer.cc |         362 |
| preparing            | 0.000012 | 0.000000 |   0.000000 |                 0 |                   0 |            0 |             0 |     0 | optimize              | sql_optimizer.cc |         485 |
| executing            | 0.000003 | 0.000000 |   0.000000 |                 0 |                   0 |            0 |             0 |     0 | exec                  | sql_executor.cc  |         110 |
| Sending data         | 0.000038 | 0.000000 |   0.000000 |                 0 |                   0 |            0 |             0 |     0 | exec                  | sql_executor.cc  |         190 |
| end                  | 0.000005 | 0.000000 |   0.000000 |                 0 |                   0 |            0 |             0 |     0 | mysql_execute_select  | sql_select.cc    |        1105 |
| query end            | 0.000007 | 0.000000 |   0.000000 |                 0 |                   0 |            0 |             0 |     0 | mysql_execute_command | sql_parse.cc     |        4967 |
| closing tables       | 0.000008 | 0.000000 |   0.000000 |                 0 |                   0 |            0 |             0 |     0 | mysql_execute_command | sql_parse.cc     |        5015 |
| freeing items        | 0.000012 | 0.000000 |   0.000000 |                 0 |                   0 |            0 |             0 |     0 | mysql_parse           | sql_parse.cc     |        6294 |
| cleaning up          | 0.000005 | 0.000000 |   0.000000 |                 0 |                   0 |            0 |             0 |     0 | dispatch_command      | sql_parse.cc     |        1774 |
+----------------------+----------+----------+------------+-------------------+---------------------+--------------+---------------+-------+-----------------------+------------------+-------------+
15 rows in set, 1 warning (0.00 sec)

mysql>

mysql> show profile block io,cpu for query 3;
+----------------------+----------+----------+------------+--------------+---------------+
| Status               | Duration | CPU_user | CPU_system | Block_ops_in | Block_ops_out |
+----------------------+----------+----------+------------+--------------+---------------+
| starting             | 0.000056 | 0.000000 |   0.000000 |            0 |             0 |
| checking permissions | 0.000009 | 0.000000 |   0.000000 |            0 |             0 |
| Opening tables       | 0.000023 | 0.000000 |   0.000000 |            0 |             0 |
| init                 | 0.000017 | 0.000000 |   0.000000 |            0 |             0 |
| System lock          | 0.000008 | 0.000000 |   0.000000 |            0 |             0 |
| optimizing           | 0.000006 | 0.000000 |   0.000000 |            0 |             0 |
| statistics           | 0.000012 | 0.000000 |   0.000000 |            0 |             0 |
| preparing            | 0.000012 | 0.000000 |   0.000000 |            0 |             0 |
| executing            | 0.000003 | 0.000000 |   0.000000 |            0 |             0 |
| Sending data         | 0.000039 | 0.000000 |   0.000000 |            0 |             0 |
| end                  | 0.000005 | 0.000000 |   0.000000 |            0 |             0 |
| query end            | 0.000007 | 0.000000 |   0.000000 |            0 |             0 |
| closing tables       | 0.000009 | 0.000000 |   0.000000 |            0 |             0 |
| freeing items        | 0.000012 | 0.000000 |   0.000000 |            0 |             0 |
| cleaning up          | 0.000004 | 0.000000 |   0.000000 |            0 |             0 |
+----------------------+----------+----------+------------+--------------+---------------+
15 rows in set, 1 warning (0.00 sec)

mysql>

小结：要想优化一条 Query，我们就需要清楚的知道这条 Query 的性能瓶颈到底在哪里，是消耗的 CPU计算太多，还是需要的的 IO 操作太多？要想能够清楚的了解这些信息，在 MySQL 5.0 和 MySQL 5.1正式版中已经可以非常容易做到了（Mysql 5.0.37 之后，自带SHOW PROFILES and SHOW PROFILE 功能模块），那就是通过 Query Profiler 功能。

MySQL 的 Query Profiler 是一个使用非常方便的 Query 诊断分析工具，通过该工具可以获取一条Query 在整个执行过程中多种资源的消耗情况，如 CPU，IO，IPC，SWAP 等，以及发生的 PAGE FAULTS，CONTEXT SWITCHE 等等，同时还能得到该 Query 执行过程中 MySQL 所调用的各个函数在源文件中的位置。

show profiles mysql查询优化之profile