INFORMATION_SCHEMA PROFILING Table

profiling表提供了语句分析信息。 其内容对应于show profiles和show profile语句生成的信息.

13.7.5.31 SHOW PROFILES Syntax

SHOW PROFILES

SHOW PROFILES语句与SHOW PROFILE一起显示分析信息，指示在当前会话过程中执行的语句的资源使用情况。

13.7.5.30 SHOW PROFILE Syntax

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

可以指定可选类型值以显示特定的其他类型的信息（对应PROFILING中字段）：

SHOW PROFILE和SHOW PROFILES语句显示分析信息，指示在当前会话过程中执行的语句的资源使用情况。

Profiling由Profiling会话变量控制，默认值为0（OFF）。 通过将Profiling设置为1或ON可启用分析：

mysql> SET profiling = 1;

SHOW PROFILES显示发送到服务器的最新语句的列表。 列表的大小由profiling_history_size会话变量控制，该变量的默认值为15.最大值为100.将值设置为0具有禁用性能分析的实际效果。

除SHOW PROFILE和SHOW PROFILES之外，所有语句都进行了概要分析，因此您将不会在配置文件列表中找到这些语句。 对于格式错误的执行语句，例如SHOW PROFILING是一个非法语句，如果您尝试执行该语句，则会出现语法错误，但会显示在概要分析列表中。

SHOW PROFILE显示有关单个语句的详细信息，如果没有追加FOR QUERY n子句，输出与最近执行的语句相关；否则展示特定语句的信息。 n的值对应于SHOW PROFILES显示的Query_ID值。

可以给出LIMIT row_count子句以将输出限制为row_count行。如果给定了LIMIT，则可以添加OFFSET偏移以将输出偏移行开始到整组行。

默认情况下，SHOW PROFILE显示状态和持续时间列。

每个会话启用分析。会话结束时，其分析信息丢失。

说了那么多，上面这些已经被废弃啦！！！！

Note:

Action

已知：

mysql root@127.0.0.1:nt> ｓｅｌｅｃｔ * FROM student+------+--------+-------+-------+|   id | name   |   age | sex   ||------+--------+-------+-------||    1 | s1     |    12 | m     ||    2 | s2     |    12 | w     ||    3 | s3     |    11 | w     |+------+--------+-------+-------+3 rows in setTime: 0.004smysql root@127.0.0.1:nt> ｓｅｌｅｃｔ * FROM teacher+------+--------+|   id | name   ||------+--------||    1 | Han    ||    2 | Gou    ||    3 | Eric   |+------+--------+3 rows in setTime: 0.002smysql root@127.0.0.1:nt> ｓｅｌｅｃｔ * FROM course+------+--------------+----------------+|   id |   teacher_id | name           ||------+--------------+----------------||    1 |            1 | Advanced Maths ||    2 |            2 | English        ||    3 |            3 | Arts           ||    4 |            1 | Physics        ||    5 |            3 | Programming    |+------+--------------+----------------+5 rows in setTime: 0.003smysql root@127.0.0.1:nt> ｓｅｌｅｃｔ * FROM score+--------------+-------------+---------+|   student_id |   course_id |   score ||--------------+-------------+---------||            1 |           1 |      78 ||            1 |           2 |      56 ||            1 |           3 |      89 ||            1 |           4 |      60 ||            1 |           5 |      92 ||            2 |           1 |      92 ||            2 |           2 |      60 ||            2 |           3 |      78 ||            2 |           4 |      77 ||            2 |           5 |      95 ||            3 |           1 |      66 ||            3 |           2 |      50 ||            3 |           3 |      78 ||            3 |           4 |      67 ||            3 |           5 |      86 |+--------------+-------------+---------+15 rows in setTime: 0.003s

解：高数比美术分数高的学生信息

ｓｅｌｅｃｔ S.* FROM (ｓｅｌｅｃｔ SC1.STUDENT_ID,SC1.COURSE_ID,SC1.SCORE FROM score SC1) A,     (ｓｅｌｅｃｔ SC2.STUDENT_ID,SC2.COURSE_ID,SC2.SCORE FROM score SC2) B,      student S WHERE A.STUDENT_ID=B.STUDENT_ID AND   A.COURSE_ID=1 AND   B.COURSE_ID=3 AND   A.SCORE>B.SCORE AND   A.STUDENT_ID=S.ID;

mysql root@127.0.0.1:nt> ｓｅｌｅｃｔ @@profiling+---------------+|   @@profiling ||---------------||             0 |+---------------+1 row in setTime: 0.002smysql root@127.0.0.1:nt> SET profiling = 1Query OK, 0 rows affectedTime: 0.001smysql root@127.0.0.1:nt> ｓｅｌｅｃｔ S.*                      -> FROM (ｓｅｌｅｃｔ SC1.STUDENT_ID,SC1.COURSE_ID,SC1.SCORE FROM score SC1) A,                      ->      (ｓｅｌｅｃｔ SC2.STUDENT_ID,SC2.COURSE_ID,SC2.SCORE FROM score SC2) B,                      ->      student S                      -> WHERE A.STUDENT_ID=B.STUDENT_ID                      -> AND   A.COURSE_ID=1                      -> AND   B.COURSE_ID=3                      -> AND   A.SCORE>B.SCORE                      -> AND   A.STUDENT_ID=S.ID;+------+--------+-------+-------+|   id | name   |   age | sex   ||------+--------+-------+-------||    2 | s2     |    12 | w     |+------+--------+-------+-------+1 row in setTime: 0.007smysql root@127.0.0.1:nt> SHOW PROFILES+------------+------------+---------------+|   Query_ID |   Duration | Query         ||------------+------------+---------------||          1 |   4.5e-05  | SHOW WARNINGS ||          2 |   0.000603 | ｓｅｌｅｃｔ S.*FROM (ｓｅｌｅｃｔ SC1.STUDENT_ID,SC1.COURSE_ID,SC1.SCORE FROM score SC1) A,     (ｓｅｌｅｃｔ SC2.STUDENT_ID,SC2.COURSE_ID,SC2.SCORE FROM score SC2) B,     student SWHERE A.STUDENT_ID=B.STUDENT_IDAND   A.COURSE_ID=1AND   B.COURSE_ID=3AND   A.SCORE>B.SCOREAND   A.STUDENT_ID=S.ID               |+------------+------------+---------------+2 rows in setTime: 0.002smysql root@127.0.0.1:nt> SHOW PROFILE FOR QUERY 2+----------------------+------------+| Status               |   Duration ||----------------------+------------|| starting             |   0.000134 || checking permissions |   1.1e-05  || checking permissions |   4e-06    || checking permissions |   7e-06    || Opening tables       |   2.4e-05  || init                 |   5.2e-05  || System lock          |   1.1e-05  || optimizing           |   1.5e-05  || statistics           |   0.000161 || preparing            |   2.7e-05  || executing            |   4e-06    || Sending data         |   6.4e-05  || end                  |   6e-06    || query end            |   7e-06    || closing tables       |   8e-06    || freeing items        |   5.4e-05  || cleaning up          |   1.4e-05  |+----------------------+------------+17 rows in setTime: 0.005s

上面的结果太丑

mysql root@127.0.0.1:nt> set @query_id=2Query OK, 0 rows affectedTime: 0.001s

使用下面的SQL：

ｓｅｌｅｃｔ STATE, SUM(DURATION) AS TOTAL_R,    ROUND(100 * SUM(DURATION)/(ｓｅｌｅｃｔ SUM(DURATION)                               FROM information_schema.PROFILING                               WHERE QUERY_ID=@query_id),          2    ) AS PCT_R,    COUNT(*) CALLS,    SUM(DURATION)/COUNT(*) AS "R/CALL"FROM information_schema.PROFILINGWHERE QUERY_ID=@query_idGROUP BY STATEORDER BY TOTAL_R DESC;

mycli执行上面的sql：

+----------------------+-----------+---------+---------+------------+| STATE                |   TOTAL_R |   PCT_R |   CALLS |     R/CALL ||----------------------+-----------+---------+---------+------------|| statistics           |  0.000161 |   26.7  |       1 | 0.000161   || starting             |  0.000134 |   22.22 |       1 | 0.000134   || Sending data         |  6.4e-05  |   10.61 |       1 | 6.4e-05    || freeing items        |  5.4e-05  |    8.96 |       1 | 5.4e-05    || init                 |  5.2e-05  |    8.62 |       1 | 5.2e-05    || preparing            |  2.7e-05  |    4.48 |       1 | 2.7e-05    || Opening tables       |  2.4e-05  |    3.98 |       1 | 2.4e-05    || checking permissions |  2.2e-05  |    3.65 |       3 | 7.3333e-06 || optimizing           |  1.5e-05  |    2.49 |       1 | 1.5e-05    || cleaning up          |  1.4e-05  |    2.32 |       1 | 1.4e-05    || System lock          |  1.1e-05  |    1.82 |       1 | 1.1e-05    || closing tables       |  8e-06    |    1.33 |       1 | 8e-06      || query end            |  7e-06    |    1.16 |       1 | 7e-06      || end                  |  6e-06    |    1    |       1 | 6e-06      || executing            |  4e-06    |    0.66 |       1 | 4e-06      |+----------------------+-----------+---------+---------+------------+15 rows in setTime: 0.018s

可以看出来，时间消耗占比最高依次：

1. statistics：服务器正在计算统计信息以开发查询执行计划。如果一个线程长时间处于这种状态，服务器可能是磁盘绑定的，执行其他工作

2. starting

3. Sending data：线程正在读取和处理ｓｅｌｅｃｔ语句的行，并向客户端发送数据。由于在此状态期间发生的操作往往执行大量的磁盘访问（读取），所以在给定查询的整个生命周期内通常是最长的运行状态

4. freeing items：线程已经执行了一个命令。在这种状态下完成的项目的一些释放涉及查询缓存。这种状态通常是清理

5. init：这发生在ALTER TABLE，ｄｅｌｅｔｅ，ｉｎｓｅｒｔ，ｓｅｌｅｃｔ或ｕｐｄａｔｅ语句的初始化之前。处于此状态的服务器采取的操作包括刷新二进制日志，InnoDB日志和一些查询缓存清理操作。

对于最终状态，可能会发生以下操作：

• 在表中的数据更改后删除查询缓存条目

• 将事件写入二进制日志

• 释放内存缓冲区，包括Blob

下面看看记录2对应的CPU信息

mysql root@127.0.0.1:nt> SHOW PROFILE CPU FOR QUERY 2+----------------------+------------+------------+--------------+| Status               |   Duration |   CPU_user |   CPU_system ||----------------------+------------+------------+--------------|| starting             |   0.000134 |   0.000126 |      8e-06   || checking permissions |   1.1e-05  |   4e-06    |      6e-06   || checking permissions |   4e-06    |   2e-06    |      3e-06   || checking permissions |   7e-06    |   4e-06    |      2e-06   || Opening tables       |   2.4e-05  |   2.3e-05  |      2e-06   || init                 |   5.2e-05  |   4.8e-05  |      3e-06   || System lock          |   1.1e-05  |   8e-06    |      2e-06   || optimizing           |   1.5e-05  |   1.4e-05  |      2e-06   || statistics           |   0.000161 |   0.000113 |      5.3e-05 || preparing            |   2.7e-05  |   1.9e-05  |      3e-06   || executing            |   4e-06    |   2e-06    |      3e-06   || Sending data         |   6.4e-05  |   6.3e-05  |      1e-06   || end                  |   6e-06    |   3e-06    |      3e-06   || query end            |   7e-06    |   5e-06    |      1e-06   || closing tables       |   8e-06    |   7e-06    |      1e-06   || freeing items        |   5.4e-05  |   1.3e-05  |      4.2e-05 || cleaning up          |   1.4e-05  |   1.2e-05  |      2e-06   |+----------------------+------------+------------+--------------+17 rows in setTime: 0.009s

Qs:为什么show profiles结果中的duration和直接执行的时间差距那么大？