§ 慢查询 SQL 分析优化
本节介绍如何定位数据库运行时那些性能较差的 SQL（即通常所说的慢查询 SQL），并分析慢查询 SQL，以及对这些 SQL 进行优化。
§ 慢查询 SQL 相关设置
在默认设置模式下，是不会记录慢查询 SQL 的，需要自行配置，可以参考以下 my.cnf 设置模板：
[mysqld]
slow_query_log = 1
slow_query_log_file = slow.log
log_slow_extra = 1
log_slow_verbosity = FULL
long_query_time = 0.01
log_queries_not_using_indexes = 1
log_throttle_queries_not_using_indexes = 60
min_examined_row_limit = 100
log_slow_admin_statements = 1
log_slow_slave_statements = 1
1
2
3
4
5
6
7
8
9
10
11
2
3
4
5
6
7
8
9
10
11
各个选项分别简介如下：
| 选项 | 简介 |
|---|---|
| slow_query_log | 总开关，是否启用 slow query log。 |
| slow_query_log_file | 设置 slow query log的文件名。 |
| log_slow_extra | MySQL 8.0.14 起新增选项，支持在 slow query log 中记录更多信息，例如线程ID、读写字节数、是否有临时表、是否有排序等。只有当 log_output=FILE 时才有效，如果是设置为 TABLE 则无效。 |
| log_slow_verbosity | Percona/GreatSQL 数据库特有选项，和 log_slow_extra 类似，可以设置为 FULL，记录更详细的信息，便于分析慢查询 SQL 的性能瓶颈。 |
| log_slow_admin_statements | 是否记录 ALTER TABLE/ANALYZE TABLE等 DDL 管理指令的慢查询。 |
| log_slow_slave_statements | 是否记录主从复制中，从节点上 sql_thread 线程应用 SQL 时产生的慢查询。只有当 binlog_format=STATEMENT 才生效，设置为 ROW/MIXED 时都不生效。 |
| long_query_time | SQL 运行耗时超过该阈值时，就会被判定为慢查询。单位是：秒。当设置为 0 时，会记录所有的请求。 |
| log_queries_not_using_indexes | 当执行的 SQL 没有可用索引时，也被判定为慢查询。 |
| log_throttle_queries_not_using_indexes | 当选项 log_queries_not_using_indexes=ON 时，每分钟记录的慢查询可能会很多，本选项用于设置每分钟最多记录几次这样的慢查询。 |
| min_examined_row_limit | 符合条件的慢查询 SQL，当扫描行数低于本选项阈值时，不再被认定为是慢查询。 |
一条经典的慢查询 SQL 记录如下：
# Time: 2022-07-26T09:59:16.979869+08:00
# User@Host: root[root] @ localhost [] Id: 945574
# Query_time: 0.001096 Lock_time: 0.000127 Rows_sent: 199 Rows_examined: 1600 Thread_id: 945574 Errno: 0 Killed: 0 Bytes_received: 0 Bytes_sent: 25143 Read_first: 1 Read_last: 0 Read_key: 1601 Read_next: 0 Read_prev: 0 Read_rnd: 0 Read_rnd_next: 1801 Sort_merge_passes: 0 Sort_range_count: 0 Sort_rows: 0 Sort_scan_count: 0 Created_tmp_disk_tables: 0 Created_tmp_tables: 1 Start: 2022-07-26T09:59:16.978773+08:00 End: 2022-07-26T09:59:16.979869+08:00 Schema: sbtest Rows_affected: 0
# Tmp_tables: 1 Tmp_disk_tables: 0 Tmp_table_sizes: 0
# InnoDB_trx_id: 0
# Full_scan: Yes Full_join: No Tmp_table: Yes Tmp_table_on_disk: No
# Filesort: No Filesort_on_disk: No Merge_passes: 0
# InnoDB_IO_r_ops: 0 InnoDB_IO_r_bytes: 0 InnoDB_IO_r_wait: 0.000000
# InnoDB_rec_lock_wait: 0.000000 InnoDB_queue_wait: 0.000000
# InnoDB_pages_distinct: 24
SET timestamp=1658800756;
select c, count(*) from t1 group by c;
1
2
3
4
5
6
7
8
9
10
11
12
2
3
4
5
6
7
8
9
10
11
12
从上述日志中可以看到几个信息：
- 这条 SQL 的耗时 0.001096 秒，即 1 毫秒。
- 返回结果有 199 行，总共需要扫描 1600 行数据。如果扫描行数很多，但返回行数很少，说明该SQL效率很低，可能索引不当。
- Read_* 等几个指标表示这个 SQL 读记录的方式，是否顺序读、随机读等。
- Sort_* 等几个指标表示该 SQL 是否产生了排序，及其代价。如果有且代价较大，需要想办法优化。
- *Tmp* 等几个指标表示该 SQL 是否产生临时表，及其代价。如果有且代价较大，需要想办法优化。
- Full_scan/Full_join 表示是否产生了全表扫描或全表 JOIN，如果有且 SQL 耗时较大，需要想办法优化。
- InnoDB_IO_* 等几个指标表示 InnoDB 逻辑读相关数据。
- InnoDB_rec_lock_wait 表示是否有行锁等待。
- InnoDB_queue_wait 表示是否有排队等待。
- InnoDB_pages_distinct 表示该 SQL 总共读取了多少个 InnoDB page，是个非常重要的指标。
甚至还可以设置 log_slow_verbosity = 'FULL,profiling'，在慢查询日志中，记录详细的探针（profiling）信息，例如：
# Time: 2022-07-26T10:35:15.599728+08:00
# User@Host: root[root] @ localhost [] Id: 950529
# Query_time: 0.001020 Lock_time: 0.000118 Rows_sent: 199 Rows_examined: 1600 Thread_id: 950529 Errno: 0 Killed: 0 Bytes_received: 0 Bytes_sent: 25143 Read_first: 1 Read_last: 0 Read_key: 1601 Read_next: 0 Read_prev: 0 Read_rnd: 0 Read_rnd_next: 1801 Sort_merge_passes: 0 Sort_range_count: 0 Sort_rows: 0 Sort_scan_count: 0 Created_tmp_disk_tables: 0 Created_tmp_tables: 1 Start: 2022-07-26T10:35:15.598708+08:00 End: 2022-07-26T10:35:15.599728+08:00 Schema: sbtest Rows_affected: 0
# Tmp_tables: 1 Tmp_disk_tables: 0 Tmp_table_sizes: 0
# Profile_starting: 0.000070 Profile_starting_cpu: 0.000069 Profile_Executing_hook_on_transaction_begin.: 0.000006 Profile_Executing_hook_on_transaction_begin._cpu: 0.000006 Profile_starting: 0.000009 Profile_starting_cpu: 0.000009 Profile_checking_permissions: 0.000003 Profile_checking_permissions_cpu: 0.000003 Profile_Opening_tables: 0.000028 Profile_Opening_tables_cpu: 0.000028 Profile_init: 0.000003 Profile_init_cpu: 0.000002 Profile_System_lock: 0.000006 Profile_System_lock_cpu: 0.000006 Profile_optimizing: 0.000003 Profile_optimizing_cpu: 0.000003 Profile_statistics: 0.000010 Profile_statistics_cpu: 0.000010 Profile_preparing: 0.000007 Profile_preparing_cpu: 0.000007 Profile_Creating_tmp_table: 0.000026 Profile_Creating_tmp_table_cpu: 0.000026 Profile_executing: 0.000823 Profile_executing_cpu: 0.000807 Profile_end: 0.000003 Profile_end_cpu: 0.000003 Profile_query_end: 0.000002 Profile_query_end_cpu: 0.000002 Profile_waiting_for_handler_commit: 0.000008 Profile_waiting_for_handler_commit_cpu: 0.000010 Profile_closing_tables: 0.000006 Profile_closing_tables_cpu: 0.000005 Profile_freeing_items: 0.000009 Profile_freeing_items_cpu: 0.000009 Profile_logging_slow_query: 0.000001 Profile_logging_slow_query_cpu: 0.000001
# Profile_total: 0.001024 Profile_total_cpu: 0.001007
# InnoDB_trx_id: 0
# Full_scan: Yes Full_join: No Tmp_table: Yes Tmp_table_on_disk: No
# Filesort: No Filesort_on_disk: No Merge_passes: 0
# InnoDB_IO_r_ops: 0 InnoDB_IO_r_bytes: 0 InnoDB_IO_r_wait: 0.000000
# InnoDB_rec_lock_wait: 0.000000 InnoDB_queue_wait: 0.000000
# InnoDB_pages_distinct: 24
SET timestamp=1658802915;
select c, count(*) from t1 group by c;
1
2
3
4
5
6
7
8
9
10
11
12
13
14
2
3
4
5
6
7
8
9
10
11
12
13
14
这样可以通过探针信息更快定位该 SQL 的性能瓶颈可能在什么地方了。
更详细解读请参考：Slow Query Log (opens new window)。
§ 利用 pt-query-digest 分析慢查询 SQL
pt-query-digest 是 Percona 出品的 pt-toolkit 工具集中的一个工具，主要用于分析慢查询 SQL。除了慢查询外，它还可以分析 binlog、general log，也可以通过 SHOW PROCESSLIST 或者通过 tcpdump 抓取的通信数据包进行实时分析。
安装过程略过，请参考文档：Installing Percona Toolkit (opens new window)。
本文中以简单分析 slow query log 文件为例：
pt-query-digest /data/GreatSQL/slow.log > /tmp/slow-digest.txt
1
可以不用加任何额外参数，直接分析，并将分析结果输出到另一个文件，在这个文件中可以直接展示各查询的执行时间、次数、占比等信息，例如：
/* 工具分析日志消耗的用户时间、系统时间，以及物理内存，虚拟内存大小 */
# 15.7s user time, 360ms system time, 41.25M rss, 186.59M vsz
# Current date: Sat Jan 7 23:11:32 2022
# Hostname: greatsql
# Files: slow.log
/* 共有多少条慢查询，格式化之后共有435条SQL */
# Overall: 29.40k total, 435 unique, 0 QPS, 0x concurrency _______________
# Attribute total min max avg 95% stddev median
# ============ ======= ======= ======= ======= ======= ======= =======
/* 所有SQL总耗时、最小耗时、平均耗时，95%耗时，平均方差，中位数耗时 */
# Exec time 37138s 500ms 142s 1s 3s 2s 705ms
/* 锁等待耗时 */
# Lock time 3535s 0 135s 120ms 609ms 927ms 224us
/* 发送到客户端数据量 */
# Rows sent 435.22M 0 1.70M 15.16k 65.68k 52.60k 0
/* 扫描数据量 *
# Rows examine 1.45G 0 3.40M 51.87k 65.68k 71.73k 65.68k
/* insert/update/delete 影响的行数 */
# Rows affecte 1.87M 0 1.70M 66.53 2.90 10.07k 1.96
/* 发送字节数 */
# Bytes sent 32.88G 0 57.75M 1.14M 2.88M 4.74M 51.63
/* SQL大小 */
# Query size 7.75M 6 1014.67k 276.42 487.09 6.15k 124.25
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
首先是汇总的统计信息。
其次是根据响应总耗时排序，就可以看到哪些 SQL 可能存在性能瓶颈：
# Profile
/* 排名、SQL语句ID/标识符、响应总耗时、占比、总请求数、平均每次请求耗时、响应时间Variance-to-mean的比率、SQL语句 */
# Rank Query ID Response time Calls R/Call V/M Item
# ==== ================== ================ ===== ====== ===== ============
# 1 0xCBFFFDC5A18B5CD4 13077.1621 35.2% 14945 0.8750 0.44 UPDATE wp_statistics_visit
# 2 0x813031B8BBC3B329 4878.6998 13.1% 2245 2.1731 5.10 COMMIT
# 3 0x67A347A2812914DF 2798.8377 7.5% 1515 1.8474 7.88 SELECT wp_statistics_visitor
# 4 0xD1A3ED0A00CB8636 2261.3010 6.1% 3807 0.5940 0.03 SELECT wp_statistics_visit
# 5 0x0359C20B19D50ED6 937.8136 2.5% 505 1.8571 0.56 UPDATE wp_statistics_visitor
# 6 0x8A0E5C140D1FEAE6 883.8182 2.4% 433 2.0412 2.44 UPDATE aws_sessions
# 7 0x94350EA2AB8AAC34 817.2749 2.2% 292 2.7989 22.57 UPDATE wp_options
# 8 0xA766EE8F7AB39063 657.8637 1.8% 348 1.8904 2.49 SELECT wp_terms wp_term_taxonomy wp_term_relationships
# 9 0xE35B37A6116CF667 657.3250 1.8% 322 2.0414 4.78 SELECT drupal_cache_field
# 10 0x3249292D0F4247BD 655.1189 1.8% 237 2.7642 7.89 INSERT drupal_cache_page
# 11 0xC6E83D2D23B205EB 548.1317 1.5% 263 2.0842 4.72 DELETE pre_common_session
# 12 0xC88DD5CE28F8574B 535.7342 1.4% 189 2.8346 10.93 INSERT pre_common_session
# 13 0x7FF1B2B54A693E87 509.4790 1.4% 287 1.7752 5.14 SELECT INFORMATION_SCHEMA.FILES INFORMATION_SCHEMA.PARTITIONS
# 14 0x0D7200302E76DA57 449.4795 1.2% 125 3.5958 42.33 INSERT drupal_captcha_sessions
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
接下来是具体某条SQL的分析情况，平均及最大耗时，平均及最大扫描行数，不同响应耗时区间占比情况等：
# Query 1: 0 QPS, 0x concurrency, ID 0xCBFFFDC5A18B5CD4 at byte 9260279 __
# This item is included in the report because it matches --limit.
# Scores: V/M = 0.44
# Attribute pct total min max avg 95% stddev median
# ============ === ======= ======= ======= ======= ======= ======= =======
# Count 50 14945
# Exec time 35 13077s 500ms 11s 875ms 2s 623ms 640ms
# Lock time 83 2955s 89us 7s 198ms 900ms 481ms 247us
# Rows sent 0 0 0 0 0 0 0 0
# Rows examine 66 986.11M 67.36k 67.72k 67.57k 65.68k 0 65.68k
# Rows affecte 1 32.31k 1 7 2.21 2.90 0.51 1.96
# Bytes sent 0 758.93k 52 52 52 52 0 52
# Query size 23 1.80M 126 126 126 126 0 126
# String:
# Databases greatsql
# Hosts greatsql
# Last errno 0
# Time 2022-07-13... (1/0%), 2022-07-13... (1/0%)... 14943 more
# Users greatsql
# Query_time distribution
# 1us
# 10us
# 100us
# 1ms
# 10ms
# 100ms ################################################################
# 1s ################
# 10s+ #
# Tables
# SHOW TABLE STATUS FROM `greatsql` LIKE 'wp_statistics_visit'\G
# SHOW CREATE TABLE `greatsql`.`wp_statistics_visit`\G
UPDATE wp_statistics_visit SET `visit` = `visit` + 1, `last_visit` = '2021-10-17 00:04:53' WHERE `last_counter` = '2021-10-17'\G
# Converted for EXPLAIN
# EXPLAIN /*!50100 PARTITIONS*/
select `visit` = `visit` + 1, `last_visit` = '2021-10-17 00:04:53' from wp_statistics_visit where `last_counter` = '2021-10-17'\G
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
在最后，甚至还直接把 UPDATE 改写成 SELECT，方便直接查看该 SQL 的执行计划。
pt-query-digest 分析结果中已经做好排序，按照这个顺序优先对排在前面的慢查询SQL进行优化，对数据库性能提升会有显著效果。
P.S，还可以利用 pt-query-digest 工具将慢查询 SQL 分析后写入数据库，并结合 Anemometer 构建慢查询管理系统。
§ 慢查询 SQL 优化
接下来以一个慢查询 SQL 为例，来看看如何优化。
首先，查看该 SQL 的执行计划：
greatsql> EXPLAIN SELECT c, COUNT(*) FROM t1 GROUP BY c\G
id: 1
select_type: SIMPLE
table: t1
partitions: NULL
type: ALL
possible_keys: NULL
key: NULL
key_len: NULL
ref: NULL
rows: 1613
filtered: 100.00
Extra: Using temporary
1
2
3
4
5
6
7
8
9
10
11
12
13
2
3
4
5
6
7
8
9
10
11
12
13
可以看到，执行计划表明这条 SQL 需要进行全表扫描，没有索引可用，并且会产生临时表。
针对上述情况，且上面的 SQL 也比较简单，只需要对 c 列添加索引即可：
greatsql> ALTER TABLE t1 ADD INDEX (c);
-- 再次查看执行计划
greatsql> explain select c, count(*) from t1 group by c\G
*************************** 1. row ***************************
id: 1
select_type: SIMPLE
table: t1
partitions: NULL
type: index
possible_keys: c
key: c
key_len: 480
ref: NULL
rows: 1613
filtered: 100.00
Extra: Using index
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
可以看到，已经能走索引，并且没有临时表了。
生产环境中的业务 SQL 一般比这种更复杂，SQL 优化需要根据实际情况灵活变化，通常不只是添加索引这么简单。
另外，在 GreatSQL 中还支持通过设置以下几个参数来实现自动轮转 slow query log 功能：
- max_slowlog_size，设置每个 slow query log 文件大小，默认值为 0，即表示不自动轮转。
- max_slowlog_files，设置开启 slow query log 自动轮转后，最多保留的文件数目。
启用 slow query log 自动轮转后，每个 slow query log 都会添加和 binlog 文件类似的序号后缀，例如：slow_query_log_file.000001。
参考资料：
- EXPLAIN执行计划中要重点关注哪些要素 (opens new window)
- PROCESSLIST中哪些状态要引起关注 (opens new window)
- Slow query log rotation and expiration (opens new window)
扫码关注微信公众号
