mysql 下 show profile 备忘

来源：互联网发布：研究所升级数据编辑：程序博客网时间：2024/05/21 22:15

mysql 中可利用 show profile 进行性能分析

show profile 功能默认状态下为关闭，因消耗一定资源

查询方法

mysql> select @@profiling;
+-------------+
| @@profiling |
+-------------+
| 0 | 0 = 关闭 1 = 启用
+-------------+
1 row in set (0.00 sec)

打开方法

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

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

启用 profiling 功能后就可以对 SQL 进行分析。

为避免之前已经把 SQL 存放在 QCACHE 中，建议在执行 SQL 时，强制 SELECT 语句不进行 QCACHE 检测

如下面 SQL

mysql> select sql_no_cache distinct prewarebro0_.ID as ID471_, prewarebro0_.SPECIFICATION_ID as SPECIFIC2_471_, prewarebro0_.SPECIES_ID as SPECIES3_471_, prewarebro0_.SPECIES_CODE as SPECIES4_471_, prewarebro0_.DETAIL_URL as DETAIL5_471_, prewarebro0_.SALEPRICE as SALEPRICE471_, prewarebro0_.TYPE as TYPE471_, prewarebro0_.CREATE_TIME as CREATE8_471_, prewarebro0_.PICTUREURL as PICTUREURL471_, prewarebro0_.USER_KO as USER10_471_ from PRE_WARE_BROSWERS prewarebro0_ cross join WARE_DIRECTORY_SUMA waredirect1_ cross join WARE_CON_DIECTORY warecondir2_ cross join WARE_MOUNTED waremounte3_ cross join WARE_CATALOG specificat4_ where waredirect1_.ID=warecondir2_.SUMA_ID and warecondir2_.ID=waremounte3_.CON_CODE and prewarebro0_.SPECIFICATION_ID=waremounte3_.MOUNT_CODE and prewarebro0_.SPECIFICATION_ID=specificat4_.ID and waredirect1_.STATUS='1' and waremounte3_.STATUS='1' and specificat4_.STATUS=1 and prewarebro0_.USER_KO='38a89ba4e0595ff0d06ab0744f64344f' order by prewarebro0_.CREATE_TIME desc limit 3 ;
Empty set (0.51 sec)

当执行完 SQL 之后，可以对该 SQL 进行分析，如

mysql> show profile;
+----------------------+----------+
| Status               | Duration |
+----------------------+----------+
| starting             | 0.000793 |
| checking permissions | 0.000012 |
| checking permissions | 0.000006 |
| checking permissions | 0.000005 |
| checking permissions | 0.000005 |
| checking permissions | 0.000010 |
| Opening tables       | 0.000132 |
| System lock          | 0.000047 |
| init                 | 0.000160 |
| optimizing           | 0.000084 |
| statistics           | 0.000264 |
| preparing            | 0.000146 |
| Creating tmp table   | 0.000100 |
| executing            | 0.000008 |
| Copying to tmp table | 0.515277 |
| Sorting result       | 0.000045 |
| Sending data         | 0.000039 |
| end                  | 0.000012 |
| removing tmp table   | 0.000019 |
| end                  | 0.000008 |
| query end            | 0.000014 |
| closing tables       | 0.000055 |
| freeing items        | 0.000087 |
| logging slow query   | 0.000005 |
| cleaning up          | 0.000014 |
+----------------------+----------+
25 rows in set (0.00 sec)

我们看到了，明显就是 copying to tmp table 值比较不正常，不进行字面解释了

看看当前我们电脑缓存了多少可以进行分析的 SQL

mysql> show profiles;
+----------+------------+------------------------------------------+
| Query_ID | Duration   | Query                                    |
+----------+------------+------------------------------------------+
|        1 | 0.00026925 | select * from ware_stocks where id < 15 |
|        2 | 0.00032250 | SELECT DATABASE()                        |
|        3 | 0.00102075 | show databases                           |
|        4 | 0.00388575 | show tables                              |
|        5 | 0.00021200 | select * from ware_stocks where id < 15 |
|        6 | 0.01826000 | select * from ware_stocks where id < 55 |
|        7 | 0.02039825 | select * from ware_stocks where id < 155 |
|        8 | 0.03401675 | select * from ware_stocks where id > 3   |
+----------+------------+------------------------------------------+
8 rows in set (0.00 sec)

上面记录了一共 8 条 SQL 分析，假如要分析某一条，那么可以执行 (参考上表中 ID 值进行分析)

mysql> show profile for query 8;
+--------------------------------+----------+
| Status                         | Duration |
+--------------------------------+----------+
| starting                       | 0.000164 |
| Waiting for query cache lock   | 0.000010 |
| checking query cache for query | 0.000197 |
| checking permissions           | 0.000026 |
| Opening tables                 | 0.000094 |
| System lock                    | 0.000038 |
| Waiting for query cache lock   | 0.000095 |
| init                           | 0.000122 |
| optimizing                     | 0.000025 |
| statistics                     | 0.000073 |
| preparing                      | 0.000032 |
| executing                      | 0.000008 |
| Sending data                   | 0.010331 |
| Waiting for query cache lock   | 0.000020 |
| Sending data                   | 0.005885 |
| Waiting for query cache lock   | 0.000011 |
| Sending data                   | 0.005877 |
| Waiting for query cache lock   | 0.000010 |
| Sending data                   | 0.005998 |
| Waiting for query cache lock   | 0.000011 |
| Sending data                   | 0.004589 |
| end                            | 0.000022 |
| query end                      | 0.000031 |
| closing tables                 | 0.000050 |
| freeing items                  | 0.000038 |
| Waiting for query cache lock   | 0.000010 |
| freeing items                  | 0.000213 |
| Waiting for query cache lock   | 0.000009 |
| freeing items                  | 0.000005 |
| storing result in query cache | 0.000009 |
| logging slow query             | 0.000006 |
| cleaning up                    | 0.000010 |
+--------------------------------+----------+
32 rows in set (0.01 sec)

另外，还可以独立地分析某项资源，方便参考

o ALL displays all information

o BLOCK IO displays counts for block input and output operations

o CONTEXT SWITCHESdisplays counts for voluntary and involuntary
context switches

o CPU displays user and system CPU usage times

o IPC displays counts for messages sent and received

o MEMORY is not currently implemented

o PAGE FAULTS displays counts for major and minor page faults

o 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

o SWAPS displays swap counts

参考之前信息，我们看看 Copying to tmp table的IO情况

mysql> show profile block io for query 9;
+----------------------+----------+--------------+---------------+
| Status               | Duration | Block_ops_in | Block_ops_out |
+----------------------+----------+--------------+---------------+
| starting             | 0.000483 |            0 |             0 |
| checking permissions | 0.000012 |            0 |             0 |
| checking permissions | 0.000006 |            0 |             0 |
| checking permissions | 0.000006 |            0 |             0 |
| checking permissions | 0.000006 |            0 |             0 |
| checking permissions | 0.000010 |            0 |             0 |
| Opening tables       | 0.000162 |            0 |             0 |
| System lock          | 0.000056 |            0 |             0 |
| init                 | 0.000179 |            0 |             0 |
| optimizing           | 0.000074 |            0 |             0 |
| statistics           | 0.000225 |            0 |             0 |
| preparing            | 0.000173 |            0 |             0 |
| Creating tmp table   | 0.000127 |            0 |             0 |
| executing            | 0.000008 |            0 |             0 |
| Copying to tmp table | 0.837154 |            0 |             8 | 产生 8 次的 IO 了用于创建 TMP TABLE 了
| Sorting result       | 0.000059 |            0 |             0 |
| Sending data         | 0.000050 |            0 |             0 |
| end                  | 0.000017 |            0 |             0 |
| removing tmp table   | 0.000025 |            0 |             0 |
| end                  | 0.000012 |            0 |             0 |
| query end            | 0.000018 |            0 |             0 |
| closing tables       | 0.000071 |            0 |             0 |
| freeing items        | 0.000097 |            0 |             0 |
| logging slow query   | 0.000006 |            0 |             0 |
| cleaning up          | 0.000012 |            0 |             0 |
+----------------------+----------+--------------+---------------+
25 rows in set (0.00 sec)

参考 CPU

mysql> show profile CPU for query 9;
+----------------------+----------+----------+------------+
| Status               | Duration | CPU_user | CPU_system |
+----------------------+----------+----------+------------+
| starting             | 0.000483 | 0.000000 |   0.000000 |
| checking permissions | 0.000012 | 0.000000 |   0.000000 |
| checking permissions | 0.000006 | 0.000000 |   0.000000 |
| checking permissions | 0.000006 | 0.000000 |   0.000000 |
| checking permissions | 0.000006 | 0.000000 |   0.000000 |
| checking permissions | 0.000010 | 0.000000 |   0.000000 |
| Opening tables       | 0.000162 | 0.002000 |   0.000000 |
| System lock          | 0.000056 | 0.000000 |   0.000000 |
| init                 | 0.000179 | 0.000000 |   0.000000 |
| optimizing           | 0.000074 | 0.000000 |   0.000000 |
| statistics           | 0.000225 | 0.000000 |   0.000000 |
| preparing            | 0.000173 | 0.000000 |   0.000000 |
| Creating tmp table   | 0.000127 | 0.000000 |   0.000000 |
| executing            | 0.000008 | 0.000000 |   0.000000 |
| Copying to tmp table | 0.837154 | 1.166823 |   0.001000| 也严重消耗了 CPU
| Sorting result       | 0.000059 | 0.000000 |   0.000000 |
| Sending data         | 0.000050 | 0.000000 |   0.000000 |
| end                  | 0.000017 | 0.000000 |   0.000000 |
| removing tmp table   | 0.000025 | 0.000000 |   0.000000 |
| end                  | 0.000012 | 0.000000 |   0.000000 |
| query end            | 0.000018 | 0.000000 |   0.000000 |
| closing tables       | 0.000071 | 0.000000 |   0.000000 |
| freeing items        | 0.000097 | 0.000000 |   0.000000 |
| logging slow query   | 0.000006 | 0.000000 |   0.000000 |
| cleaning up          | 0.000012 | 0.000000 |   0.000000 |
+----------------------+----------+----------+------------+
25 rows in set (0.01 sec)

总结, 分析后，切记 set profiling = 0 , 另外可以配合 explain 更方便地对执行计划进行分析。