分享到

简介

对于在其技术栈中包含数据库的网站和应用程序而言,用户体验的很大一部分可能会受到数据库性能的影响。慢查询可能会延迟数据检索、页面渲染以及与数据层交互的任何其他操作。由于这种潜在的重大影响,了解如何识别和修复这些问题非常重要。

在本文中,我们将讨论在 MySQL 数据库中识别性能不佳的查询的各种方法。这将为优化这些查询并提高其性能奠定基础。

检查活动查询和进程

要首先检查以获得 MySQL 当前运行状态概览的最直接的地方之一是其进程列表

显示完整进程列表

要显示 MySQL 处理线程正在执行的所有当前操作,请键入

SHOW FULL PROCESSLIST;
+----+-----------------+-----------+------+---------+---------+------------------------+-----------------------+
| Id | User | Host | db | Command | Time | State | Info |
+----+-----------------+-----------+------+---------+---------+------------------------+-----------------------+
| 5 | event_scheduler | localhost | NULL | Daemon | 1834441 | Waiting on empty queue | NULL |
| 50 | root | localhost | NULL | Query | 0 | init | show full processlist |
+----+-----------------+-----------+------+---------+---------+------------------------+-----------------------+
2 rows in set (0.00 sec)

上面的输出显示了一个空闲服务器,只有我们自己的查询以及一个长时间运行的事件监听器。活动服务器将显示更多进程,其中一些可能是长时间运行的。如果没有 FULL 修饰符,此命令将仅显示前 100 个进程,这可能会或可能不会截断您的结果,具体取决于您的服务器活动。

一些需要关注的重要部分是 TimeState 列。Time 列计算线程处于所述 State 的秒数。如果您发现进程的 Time 值与您对给定操作的预期不符,则可能是时候进一步调查了。

检查存储引擎状态

另一个要检查的地方是实际的存储引擎状态。

您可以通过键入以下命令找到与给定表关联的存储引擎

SHOW CREATE TABLE <database>.<table>\G

例如,要显示 mysql.time_zone 表使用的存储引擎,请键入

SHOW CREATE TABLE mysql.time_zone`\G
*************************** 1. row ***************************
Table: time_zone
Create Table: CREATE TABLE `time_zone` (
`Time_zone_id` int unsigned NOT NULL AUTO_INCREMENT,
`Use_leap_seconds` enum('Y','N') CHARACTER SET utf8 COLLATE utf8_general_ci NOT NULL DEFAULT 'N',
PRIMARY KEY (`Time_zone_id`)
) /*!50100 TABLESPACE `mysql` */ ENGINE=InnoDB DEFAULT CHARSET=utf8mb3 STATS_PERSISTENT=0 ROW_FORMAT=DYNAMIC COMMENT='Time zones'
1 row in set (0.01 sec)

ENGINE=InnoDB 表示该表正在使用 InnoDB 存储引擎。这是大多数配置中的默认存储引擎,因此您可能需要检查其状态。

您可以通过键入以下命令显示 InnoDB 引擎的状态

SHOW ENGINE INNODB STATUS\G
*************************** 1. row ***************************
Type: InnoDB
Name:
Status:
=====================================
2022-02-26 11:55:52 139992513984256 INNODB MONITOR OUTPUT
=====================================
Per second averages calculated from the last 16 seconds
-----------------
BACKGROUND THREAD
-----------------
srv_master_thread loops: 1 srv_active, 0 srv_shutdown, 1835091 srv_idle
srv_master_thread log flush and writes: 0
----------
SEMAPHORES
----------
OS WAIT ARRAY INFO: reservation count 555
OS WAIT ARRAY INFO: signal count 457
RW-shared spins 0, rounds 0, OS waits 0
RW-excl spins 0, rounds 0, OS waits 0
RW-sx spins 0, rounds 0, OS waits 0
Spin rounds per wait: 0.00 RW-shared, 0.00 RW-excl, 0.00 RW-sx
------------
TRANSACTIONS
------------
Trx id counter 8778
Purge done for trx's n:o < 8713 undo n:o < 0 state: running but idle
History list length 0
LIST OF TRANSACTIONS FOR EACH SESSION:
---TRANSACTION 421467955133656, not started
0 lock struct(s), heap size 1128, 0 row lock(s)
---TRANSACTION 421467955132848, not started
0 lock struct(s), heap size 1128, 0 row lock(s)
---TRANSACTION 421467955132040, not started
0 lock struct(s), heap size 1128, 0 row lock(s)
--------
FILE I/O
--------
I/O thread 0 state: waiting for completed aio requests (insert buffer thread)
I/O thread 1 state: waiting for completed aio requests (log thread)
I/O thread 2 state: waiting for completed aio requests (read thread)
I/O thread 3 state: waiting for completed aio requests (read thread)
I/O thread 4 state: waiting for completed aio requests (read thread)
I/O thread 5 state: waiting for completed aio requests (read thread)
I/O thread 6 state: waiting for completed aio requests (write thread)
I/O thread 7 state: waiting for completed aio requests (write thread)
I/O thread 8 state: waiting for completed aio requests (write thread)
I/O thread 9 state: waiting for completed aio requests (write thread)
Pending normal aio reads: [0, 0, 0, 0] , aio writes: [0, 0, 0, 0] ,
ibuf aio reads:, log i/o's:, sync i/o's:
Pending flushes (fsync) log: 0; buffer pool: 0
1779 OS file reads, 3384 OS file writes, 1870 OS fsyncs
0.00 reads/s, 0 avg bytes/read, 0.00 writes/s, 0.00 fsyncs/s
-------------------------------------
INSERT BUFFER AND ADAPTIVE HASH INDEX
-------------------------------------
Ibuf: size 1, free list len 0, seg size 2, 0 merges
merged operations:
insert 0, delete mark 0, delete 0
discarded operations:
insert 0, delete mark 0, delete 0
Hash table size 34679, node heap has 2 buffer(s)
Hash table size 34679, node heap has 9 buffer(s)
Hash table size 34679, node heap has 9 buffer(s)
Hash table size 34679, node heap has 15 buffer(s)
Hash table size 34679, node heap has 7 buffer(s)
Hash table size 34679, node heap has 3 buffer(s)
Hash table size 34679, node heap has 4 buffer(s)
Hash table size 34679, node heap has 6 buffer(s)
0.00 hash searches/s, 0.00 non-hash searches/s
---
LOG
---
Log sequence number 38540718
Log buffer assigned up to 38540718
Log buffer completed up to 38540718
Log written up to 38540718
Log flushed up to 38540718
Added dirty pages up to 38540718
Pages flushed up to 38540718
Last checkpoint at 38540718
2197 log i/o's done, 0.00 log i/o's/second
----------------------
BUFFER POOL AND MEMORY
----------------------
Total large memory allocated 0
Dictionary memory allocated 473011
Buffer pool size 8192
Free buffers 6241
Database pages 1896
Old database pages 719
Modified db pages 0
Pending reads 0
Pending writes: LRU 0, flush list 0, single page 0
Pages made young 8, not young 0
0.00 youngs/s, 0.00 non-youngs/s
Pages read 1754, created 142, written 926
0.00 reads/s, 0.00 creates/s, 0.00 writes/s
No buffer pool page gets since the last printout
Pages read ahead 0.00/s, evicted without access 0.00/s, Random read ahead 0.00/s
LRU len: 1896, unzip_LRU len: 0
I/O sum[0]:cur[0], unzip sum[0]:cur[0]
--------------
ROW OPERATIONS
--------------
0 queries inside InnoDB, 0 queries in queue
0 read views open inside InnoDB
Process ID=59529, Main thread ID=139992560166656 , state=sleeping
Number of rows inserted 0, updated 0, deleted 0, read 0
0.00 inserts/s, 0.00 updates/s, 0.00 deletes/s, 0.00 reads/s
Number of system rows inserted 0, updated 317, deleted 0, read 6128
0.00 inserts/s, 0.00 updates/s, 0.00 deletes/s, 0.00 reads/s
----------------------------
END OF INNODB MONITOR OUTPUT
============================
1 row in set (0.00 sec)

输出将包含有关引擎正在使用的资源、正在执行的进程等等的大量信息。您可以使用它来了解执行中是否存在瓶颈,或者争用中的进程数量是否导致性能问题。

启用慢查询日志

获取有关长时间运行或执行缓慢的查询的更多信息的一种方法是使用慢查询日志。慢查询日志告诉 MySQL 记录何时查询超过某个执行阈值。它对于查明运行不佳的特定查询非常有用,而无需实时在进程列表中捕获它。

检查 MySQL 是否正在记录慢查询

您应该做的第一件事是验证慢查询日志的当前状态。如果慢查询日志已启用,则无需执行任何操作。

您可以通过键入以下命令检查是否启用了慢查询日志

SHOW GLOBAL VARIABLES LIKE 'slow_query_log%';
+---------------------+------------------------------------+
| Variable_name | Value |
+---------------------+------------------------------------+
| slow_query_log | OFF |
| slow_query_log_file | /var/lib/mysql/mysqlutils-slow.log |
+---------------------+------------------------------------+
2 rows in set (0.01 sec)

上面的输出表明当前未记录慢查询,因为该功能已关闭。

如果慢查询日志已开启,您的输出将如下所示

+---------------------+-------------------------------+
| Variable_name | Value |
+---------------------+-------------------------------+
| slow_query_log | ON |
| slow_query_log_file | /var/log/mysql/mysql-slow.log |
+---------------------+-------------------------------+
2 rows in set (0.02 sec)

现在您知道了当前状态,您可以根据需要更改它。

配置 MySQL 以记录慢查询

在我们继续之前,重要的是要注意,虽然慢查询日志非常有用,但它可能会对性能产生额外的性能影响。 MySQL 必须执行额外的操作来定时每个查询并将结果记录到日志中。这可能会影响性能并意外地填满硬盘空间。

始终记录慢查询可能不是一个好主意。相反,在您主动调查问题时启用该功能,并在完成后禁用它。

考虑到这一点,您可以通过修改 MySQL 服务器的配置文件来配置慢查询日志。您也可以交互式地修改这些值,但在配置中设置良好的默认值将使以后更容易交互式地调整。

打开 MySQL 的配置文件。在大多数基于 Debian Linux 的系统中,配置文件将位于 /etc/mysql/mysql.conf.d/mysqld.conf

sudo vim /etc/mysql/mysql.conf.d/mysqld.conf

我们将要修改或可能添加以下设置

变量设置描述
slow_query_logON切换是否启用慢查询。
slow_query_log_file/var/log/mysql/mysql-slow.log将记录慢查询的日志文件。
long_query_time(秒数)查询被视为“慢”查询之前必须超过的阈值,以秒为单位。
min_examined_row_limit(行数)查询必须考虑的行数才能成为慢查询候选者。
log_slow_admin_statementsON切换管理命令是否也受日志记录的影响。
log_queries_not_using_indexesON切换是否在查询未查阅索引时记录查询。
log_slow_extraON对于 MySQL 服务器版本 8.0.14 或更高版本,此选项切换是否记录有关查询的附加信息。
log_slow_replica_statementsON对于 MySQL 服务器版本 8.0.26 或更高版本,此选项切换是否记录在副本上执行的慢语句。这仅适用于 binlog_format 设置为 STATEMENTMIXED 的语句。
log_slow_slave_statementsON对于 MySQL 服务器版本 8.0.25 或更早版本,此选项切换是否记录在副本上执行的慢语句。这仅适用于 binlog_format 设置为 STATEMENTMIXED 的语句。

因此,例如,如果我们想打开所有可选日志记录并记录检查至少 100 行并且执行时间为 2 秒或更长时间的任何语句,我们可以使用以下设置

; enable MySQL to log slow queries
slow_query_log = ON
; query log location
slow_query_log_file = /var/log/mysql/mysql-slow.log
; amount of seconds that a query must surpass to be logged
long_query_time = 2
; minimum number of rows affected for a query to be logged
min_examined_row_limit = 100
; include administrative commands in the logs
log_slow_admin_statements = ON
; also log queries that are not using indexes
log_queries_not_using_indexes = ON
; for MySQL servers version 8.0.14 or later, we can
; get extra information by setting this
log_slow_extra = ON
; Also log slow statements that have executed on
; the replica
; This only will log statements if `binlog_format` is
; set to `STATEMENT` or `MIXED` and the statement is
; logged in statement format
; RE: https://dev.mysqlserver.cn/doc/refman/8.0/en/replication-options-replica.html#sysvar_log_slow_replica_statements
; This option name depends on your MySQL version:
; versions >= 8.0.26: log_slow_replica_statements
; versions < 8.0.26: log_slow_slave_statements
; log_slow_slave_statements = ON
log_slow_replica_statements = ON

保存并关闭文件后,您可以通过键入以下命令来验证您的配置更改

sudo mysqld --validate-config

如果未返回错误,则您的 MySQL 服务器配置文件在语法上有效。您可以通过键入以下命令重新启动 MySQL 服务器进程

sudo systemctl restart mysql

您可以通过重新运行原始发现查询来验证慢查询现在是否已启用

SHOW GLOBAL VARIABLES LIKE 'slow_query_log%';

一旦您配置了您想要的慢查询,您就可以根据需要在 MySQL 本身中启用和禁用它。调整值的语法如下所示

SET GLOBAL slow_query_log = 'OFF';

使用 mysqldumpslow 分析慢查询日志

一旦您有了慢查询日志生成的日志,您可以使用几种不同的方法对其进行分析,以找出问题的确切位置。

分析日志的最简单方法是使用 mysqldumpslow 实用程序,因为它包含在 MySQL 服务器安装中。要使用它,您可以将其指向您生成的慢查询日志

sudo mysqldumpslow /var/log/mysql/mysql-slow.log
Reading mysql slow query log from /var/log/mysql/mysql-slow.log
Count: 4 Time=4.25s (17s) Lock=0.00s (0s) Rows=1.0 (4), root[root]@localhost
select sleep(N)

上面的输出显示,根据我们的标准,我们有四个查询被认为是“慢”查询。它们都是 SELECT SLEEP(); 查询的变体,命令中带有不同的数字(用 N 占位符表示)(如果您想测试此功能,请确保 min_examined_row_limit 未设置)。执行语句的实际时间约为 17 秒。

mysqldumpslow 命令包含一些选项来控制输出的排序和显示。例如,您可以使用 -t 选项将结果限制为前 “N” 个结果。例如,以下显示了前五个结果

sudo mysqldumpslow -t 5 /var/log/mysql/mysql-slow.log

您可以使用 -s 选项更改排序顺序。您可以按查询时间 (t)、锁定时间 (l)、发送的行数 (r) 或这些指标的平均值 (atalar 分别) 进行排序。默认情况下,mysqldumpslow 按平均查询时间 (at) 排序。

要按锁定时间量显示前三个查询,您可以键入

sudo mysqldumpslow -t 3 -s l /var/log/mysql/mysql-slow.log

使用 pt-query-digest 分析慢查询日志

另一个流行的用于分析慢查询日志的实用程序是 Percona 开发的 pt-query-digest 工具。pt-query-digest 工具是 Percona Toolkit 的一部分,Percona Toolkit 是一组开源命令行工具,旨在帮助数据库管理员更轻松地管理数据库。

第一步是将 Percona Toolkit 下载到您的服务器。您可以通过在 Percona Toolkit 下载页面上选择您想要的工具包版本和您将要使用的平台来找到相应的文件。

下载并安装适合您平台的工具包版本后,您应该可以访问 pt-query-digest 工具。

针对您的慢查询日志运行 pt-query-digest 会生成比 mysqldumpslow 更多的输出

sudo pt-query-digest /var/log/mysql/mysql-slow.log
# A software update is available:
# 680ms user time, 100ms system time, 44.71M rss, 59.35M vsz
# Current date: Sat Feb 26 13:06:41 2022
# Hostname: mysqlutils
# Files: /var/log/mysql/mysql-slow.log
# Overall: 4 total, 1 unique, 0.07 QPS, 0.30x concurrency ________________
# Time range: 2022-02-26T12:44:35 to 2022-02-26T12:45:32
# Attribute total min max avg 95% stddev median
# ============ ======= ======= ======= ======= ======= ======= =======
# Exec time 17s 2s 8s 4s 8s 2s 6s
# Lock time 0 0 0 0 0 0 0
# Rows sent 4 1 1 1 1 0 1
# Rows examine 4 1 1 1 1 0 1
# Bytes sent 224 56 56 56 56 0 56
# Query size 60 15 15 15 15 0 15
# Bytes receiv 0 0 0 0 0 0 0
# Created tmp 0 0 0 0 0 0 0
# Created tmp 0 0 0 0 0 0 0
# Errno 0 0 0 0 0 0 0
# Read first 0 0 0 0 0 0 0
# Read key 0 0 0 0 0 0 0
# Read last 0 0 0 0 0 0 0
# Read next 0 0 0 0 0 0 0
# Read prev 0 0 0 0 0 0 0
# Read rnd 0 0 0 0 0 0 0
# Read rnd nex 0 0 0 0 0 0 0
# Sort merge p 0 0 0 0 0 0 0
# Sort range c 0 0 0 0 0 0 0
# Sort rows 0 0 0 0 0 0 0
# Sort scan co 0 0 0 0 0 0 0
# Profile
# Rank Query ID Response time Calls R/Call V/M
# ==== =================================== ============== ===== ====== ===
# 1 0x59A74D08D407B5EDF9A57DD5A41825CA 17.0039 100.0% 4 4.2510 1.12 SELECT
# Query 1: 0.07 QPS, 0.30x concurrency, ID 0x59A74D08D407B5EDF9A57DD5A41825CA at byte 1266
# This item is included in the report because it matches --limit.
# Scores: V/M = 1.12
# Time range: 2022-02-26T12:44:35 to 2022-02-26T12:45:32
# Attribute pct total min max avg 95% stddev median
# ============ === ======= ======= ======= ======= ======= ======= =======
# Count 100 4
# Exec time 100 17s 2s 8s 4s 8s 2s 6s
# Lock time 0 0 0 0 0 0 0 0
# Rows sent 100 4 1 1 1 1 0 1
# Rows examine 100 4 1 1 1 1 0 1
# Bytes sent 100 224 56 56 56 56 0 56
# Query size 100 60 15 15 15 15 0 15
# Bytes receiv 0 0 0 0 0 0 0 0
# Created tmp 0 0 0 0 0 0 0 0
# Created tmp 0 0 0 0 0 0 0 0
# Errno 0 0 0 0 0 0 0 0
# Read first 0 0 0 0 0 0 0 0
# Read key 0 0 0 0 0 0 0 0
# Read last 0 0 0 0 0 0 0 0
# Read next 0 0 0 0 0 0 0 0
# Read prev 0 0 0 0 0 0 0 0
# Read rnd 0 0 0 0 0 0 0 0
# Read rnd nex 0 0 0 0 0 0 0 0
# Sort merge p 0 0 0 0 0 0 0 0
# Sort range c 0 0 0 0 0 0 0 0
# Sort rows 0 0 0 0 0 0 0 0
# Sort scan co 0 0 0 0 0 0 0 0
# String:
# End 2022-02-26... (1/25%), 2022-02-26... (1/25%)... 2 more
# Hosts localhost
# Start 2022-02-26... (1/25%), 2022-02-26... (1/25%)... 2 more
# Users root
# Query_time distribution
# 1us
# 10us
# 100us
# 1ms
# 10ms
# 100ms
# 1s ################################################################
# 10s+
# EXPLAIN /*!50100 PARTITIONS*/
select sleep(8)\G

输出显示执行时间、查询大小、锁定时间、检查和发送的行数等等。pt-query-digest 命令有很多不同的选项,用于塑造输出并仅显示您感兴趣的项目。浏览手册页以了解可能的功能。

结论

能够发现查询执行中的瓶颈对于维护数据库和应用程序的性能至关重要。当发生性能下降时,拥有定位这些问题区域并找出其影响程度的策略非常重要。

MySQL 生态系统构建了许多工具来简化这些任务。查看活动进程和存储引擎状态,以及启用和分析慢查询日志信息,为您提供定位最昂贵查询所需的信息。在我们的下一份指南中,我们将讨论如何实际优化您发现的查询,以及在保持最佳性能时需要记住哪些事项。

关于作者
Justin Ellingwood

Justin Ellingwood

自 2013 年以来,Justin 一直在撰写关于数据库、Linux、基础设施和开发者工具的文章。他目前与妻子和两只兔子住在柏林。他通常不必以第三人称写作,这对所有相关方来说都是一种解脱。