MySQL 5.7 Profiles 执行性能分析
注意：profiles从8.0废弃，官方推荐使用 performance_schema
我们可以通过开启SET profiling = 1，来精调分析1条SQL执行过程中各个阶段的详细耗时，以及CPU、IO等花费。
-- 开启 （会话级）
SET profiling = 1;
-- 执行几个查询
select * from orders o ;
select count(*) from order_items oi ;
-- 查看各查询的执行概况
SHOW PROFILES;
Query_ID|Duration |Query |
--------|----------|---------------------------------------------------------------------------------------------------------------------------|
4|0.00612075|/* ApplicationName=DBeaver Enterprise 7.2.0 - SQLEditor <Script-4.sql> */ select * from orders o ¶LIMIT 0, 200 |
5|0.00011325|/* ApplicationName=DBeaver Enterprise 7.2.0 - SQLEditor <Script-4.sql> */ SHOW WARNINGS |
6| 0.005943|/* ApplicationName=DBeaver Enterprise 7.2.0 - SQLEditor <Script-4.sql> */ SELECT DATABASE() |
7| 2.892235|/* ApplicationName=DBeaver Enterprise 7.2.0 - SQLEditor <Script-4.sql> */ select count(*) from order_items oi ¶LIMIT 0, 200|
8|0.00072575|/* ApplicationName=DBeaver Enterprise 7.2.0 - SQLEditor <Script-4.sql> */ SHOW WARNINGS |
9|0.00022475|/* ApplicationName=DBeaver Enterprise 7.2.0 - SQLEditor <Script-4.sql> */ SELECT DATABASE() |
10|0.00020575|/* ApplicationName=DBeaver Enterprise 7.2.0 - SQLEditor <Script-4.sql> */ SET SQL_SELECT_LIMIT=200 |
11|0.00016225|/* ApplicationName=DBeaver Enterprise 7.2.0 - SQLEditor <Script-4.sql> */ SET SQL_SELECT_LIMIT=DEFAULT |
12|0.00008125|/* ApplicationName=DBeaver Enterprise 7.2.0 - SQLEditor <Script-4.sql> */ SHOW WARNINGS |
13| 0.000164|/* ApplicationName=DBeaver Enterprise 7.2.0 - SQLEditor <Script-4.sql> */ SELECT DATABASE() |
14| 0.0001435|/* ApplicationName=DBeaver Enterprise 7.2.0 - SQLEditor <Script-4.sql> */ SET SQL_SELECT_LIMIT=200 |
15|0.00011175|/* ApplicationName=DBeaver Enterprise 7.2.0 - SQLEditor <Script-4.sql> */ SET SQL_SELECT_LIMIT=DEFAULT |
16| 0.0001025|/* ApplicationName=DBeaver Enterprise 7.2.0 - SQLEditor <Script-4.sql> */ SHOW WARNINGS |
17|0.00018325|/* ApplicationName=DBeaver Enterprise 7.2.0 - SQLEditor <Script-4.sql> */ SELECT DATABASE() |
18| 0.000131|/* ApplicationName=DBeaver Enterprise 7.2.0 - SQLEditor <Script-4.sql> */ SET SQL_SELECT_LIMIT=200 |
我们可以看到7号查询最耗时。
-- 查看某条 SQL 的详细时间分布
SHOW PROFILE FOR QUERY 7;
Status |Duration|
--------------------|--------|
starting |0.001543|
checking permissions|0.000017|
Opening tables |0.001516|
init |0.000021|
System lock |0.000008|
optimizing |0.000461|
statistics |0.000023|
preparing |0.000434|
executing |0.000009|
Sending data |2.887903|
end |0.000019|
query end |0.000015|
closing tables |0.000013|
freeing items |0.000233|
cleaning up |0.000023|
大部分时间都花在"Sending data" ，这个阶段内部实际发生的事情：
① 向存储引擎要数据（扫描索引/表、回表）
↓
② 拿到一行 → Server 层逐行处理：
- 用 WHERE 剩余条件过滤（Using where 就在这）
- 做排序、分组、聚合
↓
③ 处理完的行放进结果缓冲区
↓
④ 重复 ①-③，直到扫完
查看执行计划，explain select count(*) from order_items oi;
id|select_type|table|partitions|type |possible_keys|key |key_len|ref|rows |filtered|Extra |
--|-----------|-----|----------|-----|-------------|--------------|-------|---|-------|--------|-----------|
1|SIMPLE |oi | |index| |idx_created_at|5 | |2989004| 100.0|Using index|
扫了这么多行，难怪慢。
-- 按特定维度查看
SHOW PROFILE CPU, BLOCK IO FOR QUERY 7;
Status |Duration|CPU_user|CPU_system|Block_ops_in|Block_ops_out|
--------------------|--------|--------|----------|------------|-------------|
starting |0.000051|0.000000| 0.000000| | |
checking permissions|0.000004|0.000000| 0.000000| | |
Opening tables |0.000015|0.000000| 0.000000| | |
init |0.000010|0.000000| 0.000000| | |
System lock |0.000005|0.000000| 0.000000| | |
optimizing |0.000003|0.000000| 0.000000| | |
statistics |0.000010|0.000000| 0.000000| | |
preparing |0.000007|0.000000| 0.000000| | |
executing |0.000001|0.000000| 0.000000| | |
Sending data |1.994349|1.078125| 0.343750| | |
end |0.000018|0.000000| 0.000000| | |
query end |0.000016|0.000000| 0.000000| | |
closing tables |0.000015|0.000000| 0.000000| | |
freeing items |0.000242|0.000000| 0.000000| | |
cleaning up |0.000021|0.000000| 0.000000| | |
BLOCK IO 统计在 Windows 上拿不到——它是靠 Linux 的 /proc/<pid>/io 实现的，Windows 上恒为空。这不是你的 SQL 没有磁盘 I/O，是 5.7 在 Windows 上根本不提供这个数据。 以后在生产（Linux）上就能看到真实的磁盘读写块数了。
Duration = 1.994 s （墙钟时间）
CPU_user = 1.078 s （用户态 CPU）
CPU_system = 0.344 s （内核态 CPU）
─────────────────────────────
CPU 合计 = 1.422 s ≈ 71% 的时间在烧 CPU！
这个比例说明：这条 SQL 不是"慢在等磁盘"，而是慢在算。如果它是纯粹的 I/O 等待型（比如回表大量随机读），CPU 占比会很低——时间都耗在等磁盘响应上，CPU 闲得发慌。反过来，CPU 占比高说明 Server 层在逐行干重活。
Duration 1.994s
CPU 合计 1.422s → 这部分在干活（遍历叶子链、累加计数）
差值 0.572s → 这部分在等 I/O（索引页不在 Buffer Pool，等磁盘读进来）
所以时间是两部分：约 0.6s 等磁盘读 77MB 索引（idx_created_at 的大小，之前查过），约 1.4s 是 CPU 在遍历 3M 条索引记录。
注意：CPU 花的不只是"累加"。COUNT(*) 每行的工作是：
存储引擎沿 idx_created_at 叶子链表走
→ 读一条索引记录（校验、解包）
→ 返回给 Server 层
→ Server 计数器 +1
→ 取下一条
循环 300 万次
累加本身是纳秒级的，贵的是这个循环跑了 300 万遍——每遍都有函数调用、记录解包、链表跳转的开销。这就是为什么"扫描行数"永远是 SQL 优化第一指标。
可以顺便做两个实验：
实验A：跑第二次，感受 Buffer Pool
SELECT COUNT(*) FROM order_items;
-- 再执行一遍同样的 SQL
第二次应该明显快于第一次——索引页第一次已经被装进 Buffer Pool（128M 装 77MB 索引没问题），I/O 等待那 0.6s 基本消失。这直接验证原理 4。
实验B：近似计数，零成本
SELECT TABLE_ROWS FROM information_schema.TABLES
WHERE TABLE_SCHEMA = 'sql_tuning_lab' AND TABLE_NAME = 'order_items';
-- 瞬时返回 ~2,989,004（估算值，误差几个百分点）
这就是生产上"订单表总共有多少条"这种场景的正确做法——业务上很少真的需要精确到个位的总数，需要的时候用缓存（Redis）或计数表维护，而不是每次扫全表。
浙公网安备 33010602011771号