INFORMATION_SCHEMA.PROFILING

来源：动视网责编：小采时间：2020-11-09 08:54:29

INFORMATION_SCHEMA.PROFILING

INFORMATION_SCHEMA.PROFILING:INFORMATION_SCHEMA PROFILING TablePROFILING表提供了语句分析信息。其内容对应于SHOW PROFILES和SHOW PROFILE语句生成的信息.INFORMATION_SCHEMA NameSHOW NameNotesQUERY_IDQuery_ID标识SEQ具有相同QUERY_ID值的

推荐度：

点击下载本文 文档为doc格式

导读INFORMATION_SCHEMA.PROFILING:INFORMATION_SCHEMA PROFILING TablePROFILING表提供了语句分析信息。其内容对应于SHOW PROFILES和SHOW PROFILE语句生成的信息.INFORMATION_SCHEMA NameSHOW NameNotesQUERY_IDQuery_ID标识SEQ具有相同QUERY_ID值的

Action

已知：

mysql root@127.0.0.1:nt> SELECT * FROM student
+------+--------+-------+-------+| id | name | age | sex |
|------+--------+-------+-------|| 1 | s1 | 12 | m |
| 2 | s2 | 12 | w |
| 3 | s3 | 11 | w |
+------+--------+-------+-------+3 rows in setTime: 0.004s
mysql root@127.0.0.1:nt> SELECT * FROM teacher
+------+--------+| id | name |
|------+--------|| 1 | Han |
| 2 | Gou |
| 3 | Eric |
+------+--------+3 rows in setTime: 0.002s
mysql root@127.0.0.1:nt> SELECT * 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.003s
mysql root@127.0.0.1:nt> SELECT * FROM score
+--------------+-------------+---------+| student_id | course_id | score |
|--------------+-------------+---------|| 1 | 1 | 78 |
| 1 | 2 | 56 |
| 1 | 3 |  |
| 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

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

SELECT S.* 
FROM (SELECT SC1.STUDENT_ID,SC1.COURSE_ID,SC1.SCORE FROM score SC1) A,
 (SELECT 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> SELECT @@profiling
+---------------+
| @@profiling |
|---------------|
| 0 |
+---------------+
1 row in set
Time: 0.002s
mysql root@127.0.0.1:nt> SET profiling = 1
Query OK, 0 rows affected
Time: 0.001s
mysql root@127.0.0.1:nt> SELECT S.*
 -> FROM (SELECT SC1.STUDENT_ID,SC1.COURSE_ID,SC1.SCORE FROM score SC1) A,
 -> (SELECT 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 set
Time: 0.007s
mysql root@127.0.0.1:nt> SHOW PROFILES
+------------+------------+---------------+
| Query_ID | Duration | Query |
|------------+------------+---------------|
| 1 | 4.5e-05 | SHOW WARNINGS |
| 2 | 0.000603 | SELECT S.*
FROM (SELECT SC1.STUDENT_ID,SC1.COURSE_ID,SC1.SCORE FROM score SC1) A,
 (SELECT 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 |
+------------+------------+---------------+
2 rows in set
Time: 0.002s
mysql 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 set
Time: 0.005s

上面的结果太丑

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

使用下面的SQL：

SELECT STATE, SUM(DURATION) AS TOTAL_R,
 ROUND(100 * SUM(DURATION)/(SELECT 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.PROFILING
WHERE QUERY_ID=@query_id
GROUP BY STATE
ORDER 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 set
Time: 0.018s

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

statistics：服务器正在计算统计信息以开发查询执行计划。如果一个线程长时间处于这种状态，服务器可能是磁盘绑定的，执行其他工作
starting
Sending data：线程正在读取和处理SELECT语句的行，并向客户端发送数据。由于在此状态期间发生的操作往往执行大量的磁盘访问（读取），所以在给定查询的整个生命周期内通常是最长的运行状态
freeing items：线程已经执行了一个命令。在这种状态下完成的项目的一些释放涉及查询缓存。这种状态通常是清理
init：这发生在ALTER TABLE，DELETE，INSERT，SELECT或UPDATE语句的初始化之前。处于此状态的服务器采取的操作包括刷新二进制日志，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 set
Time: 0.009s

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

INFORMATION_SCHEMA.PROFILING

推荐度：

点击下载本文 文档为doc格式

标签： information profiling information_schema

热门焦点

INFORMATION_SCHEMA.PROFILING

INFORMATION_SCHEMA.PROFILING

Action

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

INFORMATION_SCHEMA.PROFILING

最新推荐

猜你喜欢

热门推荐