排查 Azure Database for MySQL 灵活服务器中的查询性能问题

适用于：Azure Database for MySQL - 单一服务器 Azure Database for MySQL - 灵活服务器

查询性能可能会受到多种因素的影响，因此首先务必要了解你在 Azure Database for MySQL 灵活服务器实例中遇到的症状的范围。 例如，对于以下对象，查询性能是否很慢：

• 所有查询都在 Azure Database for MySQL 灵活服务器实例上运行？
• 一组特定的查询？
• 一个特定的查询？

另请注意，对要查询的表的结构或基础数据所做的任何最近更改都可能会影响性能。

启用日志记录功能

在分析单个查询之前，需要定义查询基准。 利用此信息，可在数据库服务器上实现日志记录功能，以跟踪超过你根据应用程序的需求指定的阈值的查询。

对于 Azure Database for MySQL 灵活服务器，建议使用慢查询日志功能来识别需要超过 N 秒来运行的查询。 从慢查询日志中识别查询后，可使用 MySQL 诊断对这些查询进行故障排除。

在开始跟踪长时间运行的查询之前，需要使用 Azure 门户或 Azure CLI 启用 slow_query_log 参数。 启用此参数后，你还应配置 long_query_time 参数的值，以指定查询在被识别为“运行缓慢”查询之前可以运行的秒数。 参数的默认值为 10 秒，但你可以调整该值以满足应用程序 SLA 的需求。

虽然慢查询日志是跟踪长时间运行的查询的绝佳工具，但在某些情况下，它可能无效。 例如，慢查询日志：

• 如果查询数量非常多或查询语句非常大，则该日志会对性能产生负面影响。 相应地调整 long_query_time 参数的值。
• 如果你还启用了 log_queries_not_using_index 参数，该参数指定记录预期检索所有行的查询，则该日志可能没有帮助。 执行完整索引扫描的查询会利用索引，但它们会被记录，因为索引不会限制返回的行数。

从日志检索信息

日志从其创建时开始算起，最多可保留七天。 可通过 Azure 门户或 Azure CLI 列出和下载慢查询日志。 在 Microsoft Azure 门户中，导航到服务器，在“监视”下，选择“服务器日志”，然后选择条目旁边的向下箭头，下载与正在调查的日期和时间关联的日志。

此外，如果慢查询日志通过诊断日志与 Azure Monitor 日志集成，则可在编辑器中运行查询以进一步分析它们：

AzureDiagnostics
| where Resource == '<your server name>'
| where Category == 'MySqlSlowLogs'
| project TimeGenerated, Resource , event_class_s, start_time_t , query_time_d, sql_text_s
| where query_time_d > 10

以下快照描述了一个示例慢查询。

# Time: 2021-11-13T10:07:52.610719Z
# User@Host: root[root] @  [172.30.209.6]  Id: 735026
# Query_time: 25.314811  Lock_time: 0.000000 Rows_sent: 126  Rows_examined: 443308
use employees;
SET timestamp=1596448847;
select * from titles where DATE(from_date) > DATE('1994-04-05') AND title like '%senior%';;

请注意，该查询运行了 26 秒，检查了 443k 多行，返回了 126 行结果。

通常，你应该关注 Query_time 和 Rows_examined 值较高的查询。 但是，如果你注意到查询的 Query_time 较长但 Rows_examined 值较小，这通常表明存在资源瓶颈。 对于这些情况，你应检查是否存在任何 IO 限制，或 CPU 使用情况。

分析查询

识别特定的运行缓慢的查询后，可使用 EXPLAIN 命令和分析收集更多详细信息。

若要检查查询计划，请运行以下命令：

EXPLAIN <QUERY>

除了为查询创建 EXPLAIN 计划外，还可使用 SHOW PROFILE 命令来诊断当前会话中运行的语句的执行。

若要在会话中启用分析并分析特定查询，请运行以下命令集：

SET profiling = 1;
<QUERY>;
SHOW PROFILES;
SHOW PROFILE FOR QUERY <X>;

让我们仔细了解如何使用这些命令来分析查询。 首先，为当前会话启用分析，运行 SET PROFILING = 1 命令：

mysql> SET PROFILING = 1;
Query OK, 0 rows affected, 1 warning (0.00 sec)

接下来，执行一个执行完整表扫描的次优查询：

mysql> select * from sbtest8 where c like '%99098187165%';
+----+---------+-------------------------------------------------------------------------------------------------------------------------+-------------------------------------------------------------+
| id | k       | c                                                                                                                       | pad                                                         |
+----+---------+-------------------------------------------------------------------------------------------------------------------------+-------------------------------------------------------------+
| 10 | 5035785 | 81674956652-89815953173-84507133182-62502329576-99098187165-62672357237-37910808188-52047270287-89115790749-78840418590 | 91637025586-81807791530-84338237594-90990131533-07427691758 |
+----+---------+-------------------------------------------------------------------------------------------------------------------------+-------------------------------------------------------------+
1 row in set (27.60 sec)

然后，通过运行 SHOW PROFILES 命令来显示所有可用查询配置文件的列表：

mysql> SHOW PROFILES;
+----------+-------------+----------------------------------------------------+
| Query_ID | Duration    | Query                                              |
+----------+-------------+----------------------------------------------------+
|        1 | 27.59450000 | select * from sbtest8 where c like '%99098187165%' |
+----------+-------------+----------------------------------------------------+
1 row in set, 1 warning (0.00 sec)

最后，若要显示查询 1 的配置文件，请运行 SHOW PROFILE FOR QUERY 1 命令。

mysql> SHOW PROFILE FOR QUERY 1;
+----------------------+-----------+
| Status               | Duration  |
+----------------------+-----------+
| starting             |  0.000102 |
| checking permissions |  0.000028 |
| Opening tables       |  0.000033 |
| init                 |  0.000035 |
| System lock          |  0.000018 |
| optimizing           |  0.000017 |
| statistics           |  0.000025 |
| preparing            |  0.000019 |
| executing            |  0.000011 |
| Sending data         | 27.594038 |
| end                  |  0.000041 |
| query end            |  0.000014 |
| closing tables       |  0.000013 |
| freeing items        |  0.000088 |
| cleaning up          |  0.000020 |
+----------------------+-----------+
15 rows in set, 1 warning (0.00 sec)

列出数据库服务器上最常用的查询

每当对查询性能进行故障排除时，了解 Azure Database for MySQL 灵活服务器实例上最常运行的查询会很有帮助。 可使用此信息来衡量是否有任何执行次数排名靠前的查询的运行时间比平时长。 此外，开发人员或 DBA 还可使用此信息来确定任何查询的执行计数和持续时间是否突然增加。

若要列出针对 Azure Database for MySQL 灵活服务器实例执行最多的 10 个查询，请运行以下查询：

SELECT digest_text AS normalized_query,
 count_star AS all_occurrences,
 Concat(Round(sum_timer_wait / 1000000000000, 3), ' s') AS total_time,
 Concat(Round(min_timer_wait / 1000000000000, 3), ' s') AS min_time,
 Concat(Round(max_timer_wait / 1000000000000, 3), ' s') AS max_time,
 Concat(Round(avg_timer_wait / 1000000000000, 3), ' s') AS avg_time,
 Concat(Round(sum_lock_time / 1000000000000, 3), ' s') AS total_locktime,
 sum_rows_affected AS sum_rows_changed,
 sum_rows_sent AS sum_rows_selected,
 sum_rows_examined AS sum_rows_scanned,
 sum_created_tmp_tables,
 sum_select_scan,
 sum_no_index_used,
 sum_no_good_index_used
FROM performance_schema.events_statements_summary_by_digest
ORDER BY sum_timer_wait DESC LIMIT 10;

按总执行时间列出开销最大的 10 个查询

以下查询的输出提供了有关针对数据库服务器运行的 10 个最高开销查询及其在数据库服务器上的执行次数的信息。 它还提供了其他有用信息，例如查询延迟、锁定时间、作为查询运行时一部分创建的临时表的数量等。使用此查询输出可以跟踪数据库上的最高开销查询以及延迟等因素的变化，这可能表明有机会进一步微调查询以帮助避免任何将来的风险。

SELECT REPLACE(event_name, 'statement/sql/', '') AS statement, 
 count_star AS all_occurrences , 
 Concat(Round(sum_timer_wait / 1000000000000, 2), ' s') AS total_latency, 
 Concat(Round(avg_timer_wait / 1000000000000, 2), ' s') AS avg_latency, 
 Concat(Round(sum_lock_time / 1000000000000, 2), ' s') AS total_lock_time  , 
 sum_rows_affected AS sum_rows_changed, 
 sum_rows_sent AS  sum_rows_selected, 
 sum_rows_examined AS  sum_rows_scanned, 
 sum_created_tmp_tables,  sum_created_tmp_disk_tables, 
 IF(sum_created_tmp_tables = 0, 0, Concat( Truncate(sum_created_tmp_disk_tables / 
 sum_created_tmp_tables * 100, 0))) AS 
 tmp_disk_tables_percent, 
 sum_select_scan, 
 sum_no_index_used, 
 sum_no_good_index_used 
FROM performance_schema.events_statements_summary_global_by_event_name 
WHERE event_name LIKE 'statement/sql/%' 
 AND count_star > 0 
ORDER BY sum_timer_wait DESC 
LIMIT 10;

监视 InnoDB 垃圾回收

当 InnoDB 垃圾回收被阻止或延迟时，数据库可能会出现严重的清除滞后，这会对存储利用率和查询性能产生负面影响。

InnoDB 回滚段历史记录列表长度 (HLL) 衡量撤消日志中存储的更改记录数。 不断增长的 HLL 值表明 InnoDB 的垃圾回收线程（清除线程）没有跟上写入工作负载，或者清除被长期的查询或事务阻止。

垃圾回收的过度延迟可能会产生严重的负面后果：

• InnoDB 系统表空间将扩展，从而加速基础存储卷的增长。 有时，由于清除被阻止，系统表空间可能会膨胀数 TB。
• 标记为删除的记录不会被及时删除。 这可能会导致 InnoDB 表空间增大并阻止引擎重用这些记录占用的存储。
• 由于 InnoDB 存储结构的增长，所有查询的性能可能会降低，并且 CPU 利用率可能会增加。

因此，监视 HLL 值、模式和趋势非常重要。

查找 HLL 值

可通过运行 show engine innodb status 命令来查找 HLL 值。 该值将在输出中列在 TRANSACTIONS 标题下：

mysql> show engine innodb status\G 
*************************** 1. row *************************** 
 
(...) 
 
------------ 
TRANSACTIONS 
------------ 
Trx id counter 52685768 
Purge done for trx's n:o < 52680802 undo n:o < 0 state: running but idle 
History list length 2964300 
 
(...) 

也可通过查询 information_schema.innodb_metrics 表来确定 HLL 值：

mysql> select count from information_schema.innodb_metrics  
    -> where name = 'trx_rseg_history_len'; 
+---------+ 
|  count  | 
+---------+ 
| 2964300 | 
+---------+ 
1 row in set (0.00 sec)

解释 HLL 值

解释 HLL 值时，请考虑下表中列出的准则：

值	备注
小于 ~10,000	正常值，表明垃圾回收未滞后。
介于 ~10,000 和 ~1,000,000 之间	这些值表明垃圾回收有轻微的滞后。 如果此类值保持稳定且不会增加，则这些值可能是可接受的。
大于 ~1,000,000	应调查这些值，可能需要纠正措施

处理过多的 HLL 值

如果 HLL 显示较大的峰值或出现定期增长模式，请立即调查 Azure Database for MySQL 灵活服务器实例上运行的查询和事务。 然后，可解决可能阻止垃圾回收进程进度的任何工作负载问题。 虽然不能期望数据库没有清除滞后，但是不得让滞后不受控制地增长。

例如，若要从 information_schema.innodb_trx 表中获取事务信息，请运行以下命令：

select * from information_schema.innodb_trx  
order by trx_started asc\G

trx_started 列中的详细信息将帮助你计算事务年限。

mysql> select * from information_schema.innodb_trx  
    -> order by trx_started asc\G 
*************************** 1. row *************************** 
                    trx_id: 8150550 
                 trx_state: RUNNING 
               trx_started: 2021-11-13 20:50:11 
     trx_requested_lock_id: NULL 
          trx_wait_started: NULL 
                trx_weight: 0 
       trx_mysql_thread_id: 19 
                 trx_query: select * from employees where DATE(hire_date) > DATE('1998-04-05') AND first_name like '%geo%';
(…) 

有关当前数据库会话的信息，包括处于会话当前状态的时间，请检查 information_schema.processlist 表。 例如，以下输出显示了一个在过去 1462 秒内一直在主动执行查询的会话：

mysql> select user, host, db, command, time, info  
    -> from information_schema.processlist  
    -> order by time desc\G 
*************************** 1. row *************************** 
   user: test 
   host: 172.31.19.159:38004 
     db: employees 
command: Query 
   time: 1462 
   info: select * from employees where DATE(hire_date) > DATE('1998-04-05') AND first_name like '%geo%';
 
(...) 

建议

• 确保数据库分配了足够的资源来运行查询。 有时，可能需要纵向扩展实例大小，以获得更多的 CPU 核心和额外的内存以适应工作负载。

• 通过将大型或长时间运行的事务分解为较小的事务来避免这些事务。

• 根据工作负载配置innodb_purge_threads 以提高后台清除操作的效率。

  注意

  为每个环境测试对此服务器变量的任何更改，以衡量引擎行为的变化。

• 使用对“主机 CPU 百分比”、“主机内存百分比”和“总连接数”的警报，以便在系统超过任何指定阈值时收到通知。

• 使用 Query Performance Insight 或 Azure 工作簿来识别任何有问题或运行缓慢的查询，然后对其进行优化。

• 对于生产数据库服务器，请定期收集诊断信息，以确保一切顺利运行。 如果不是，请排查并解决你识别的任何问题。

后续步骤

若要查找同行对你的最重要问题的回答，或者要发布或回答问题，请访问 Stack Overflow。