剖析单条查询

SHOW PROFILE

mysql> show variables like "%profiling%";
+------------------------+-------+
| Variable_name | Value |
+------------------------+-------+
| have_profiling | YES |
| profiling | OFF |
| profiling_history_size | 15 |
+------------------------+-------+

mysql> set profiling = 1;
Query OK, 0 rows affected, 1 warning (0.00 sec)
mysql> select * from timedemo;
+---------------------+---------------------+
| ts | ts2 |
+---------------------+---------------------+
| 2016-06-27 13:53:09 | 2016-06-27 12:00:00 |
| 0000-00-00 00:00:00 | 2016-06-27 14:00:00 |
| 2016-06-27 13:54:20 | 2016-06-27 14:00:00 |
+---------------------+---------------------+
3 rows in set (0.00 sec)
mysql> SHOW PROFILES;
+----------+------------+------------------------+
| Query_ID | Duration | Query |
+----------+------------+------------------------+
| 1 | 0.00119675 | show tables |
| 2 | 0.00960675 | select * from timedemo |
+----------+------------+------------------------+
2 rows in set, 1 warning (0.02 sec)
mysql>
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(*) AS Calls,
SUM(DURATION)/COUNT(*) AS "R/Call"
FROM INFORMATION_SCHEMA.PROFILING
WHERE QUERY_ID = @query_id
GROUP BY STATE
ORDER BY Total_R DESC;
+----------------------+----------+
| Status | Duration |
+----------------------+----------+
| starting | 0.000141 |
| checking permissions | 0.000063 |
| Opening tables | 0.000083 |
| init | 0.000081 |
| System lock | 0.000058 |
| optimizing | 0.000054 |
| statistics | 0.000063 |
| preparing | 0.000062 |
| executing | 0.000046 |
| Sending data | 0.008658 |
| end | 0.000052 |
| query end | 0.000043 |
| closing tables | 0.000061 |
| freeing items | 0.000097 |
| cleaning up | 0.000046 |
+----------------------+----------+
15 rows in set, 1 warning (0.02 sec)

mysql> SET @query_id = 2;
Query OK, 0 rows affected (0.00 sec)

mysql> 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(*) AS Calls,
-> SUM(DURATION)/COUNT(*) AS "R/Call"
-> FROM INFORMATION_SCHEMA.PROFILING
-> WHERE QUERY_ID = @query_id
-> GROUP BY STATE
-> ORDER BY Total_R DESC;
+----------------------+----------+-------+-------+--------------+
| STATE | Total_R | Pct_R | Calls | R/Call |
+----------------------+----------+-------+-------+--------------+
| Sending data | 0.008658 | 90.11 | 1 | 0.0086580000 |
| starting | 0.000141 | 1.47 | 1 | 0.0001410000 |
| freeing items | 0.000097 | 1.01 | 1 | 0.0000970000 |
| Opening tables | 0.000083 | 0.86 | 1 | 0.0000830000 |
| init | 0.000081 | 0.84 | 1 | 0.0000810000 |
| checking permissions | 0.000063 | 0.66 | 1 | 0.0000630000 |
| statistics | 0.000063 | 0.66 | 1 | 0.0000630000 |
| preparing | 0.000062 | 0.65 | 1 | 0.0000620000 |
| closing tables | 0.000061 | 0.63 | 1 | 0.0000610000 |
| System lock | 0.000058 | 0.60 | 1 | 0.0000580000 |
| optimizing | 0.000054 | 0.56 | 1 | 0.0000540000 |
| end | 0.000052 | 0.54 | 1 | 0.0000520000 |
| cleaning up | 0.000046 | 0.48 | 1 | 0.0000460000 |
| executing | 0.000046 | 0.48 | 1 | 0.0000460000 |
| query end | 0.000043 | 0.45 | 1 | 0.0000430000 |
+----------------------+----------+-------+-------+--------------+
15 rows in set (0.01 sec)