排查和识别 Azure Database for PostgreSQL 灵活服务器中运行缓慢的查询

项目
07/12/2024

适用于：Azure Database for PostgreSQL - 灵活服务器

本文介绍如何使用 Azure Database for PostgreSQL 灵活服务器对运行缓慢的查询进行故障排除和识别。

对于 CPU 使用率过高的场景，本文介绍如何：

识别运行缓慢的查询。
识别与之一起运行缓慢的过程。在属于同一运行缓慢的存储过程的查询列表中识别运行缓慢的查询。

CPU 使用率过高的场景 - 识别运行缓慢的查询

先决条件

必须在 Azure Database for PostgreSQL 灵活服务器实例上启用故障排除指南和 auto_explain 扩展。若要启用故障排除指南，请按照此处提到的步骤操作。

若要启用 auto_explain 扩展，请执行以下步骤：

进入 Azure Database for PostgreSQL 灵活服务器门户上的服务器参数页吗，将 auto_explain 扩展添加到共享预加载库，如下所示。

注意

进行此更改需要重启服务器。

将 auto_explain 扩展添加到共享预加载库并重启服务器后，在 Azure Database for PostgreSQL 灵活服务器门户上的服务器参数页中，请将以下突出显示的 auto_explain 服务器参数更改为 ON，并将剩余的扩展保留默认值，如下所示。

注意

将 auto_explain.log_min_duration 参数更新为 0 将开始记录服务器上执行的所有查询。这可能会影响数据库的性能。必须进行适当的审慎调查才能得出在服务器上被视为缓慢的值。例如，如果将 30 秒视为阈值，并且应用程序可以接受运行时间低于 30 秒的所有查询，则建议将参数更新为 30000 毫秒。然后，这会记录服务器上执行时间超过 30 秒的任何查询。

场景 - 识别运行缓慢的查询

有了故障排除指南和 auto_explain 扩展，我们将借助示例来解释该场景。

我们有一个 CPU 使用率飙升到 90% 的场景，并且想知道导致该峰值的根本原因。要调试该场景，请按照以下所述的步骤进行操作。

一旦 CPU 方案发出警报，请转到 Azure Database for PostgreSQL 灵活服务器门户概述页的“帮助”选项卡下的故障排除指南。
从打开的页面中选择“CPU 使用率过高”选项卡。 “CPU 使用率过高故障排除指南”随即打开。
使用时间范围下拉列表选择报告的 CPU 峰值的时间范围。
选择“CPU 消耗靠前的查询”选项卡。

该选项卡共享 CPU 使用率达到 90% 的时间间隔内运行的所有查询的详细信息。从快照来看，该时间间隔内平均执行时间最慢的查询约为 2.6 分钟，该查询在该时间间隔内运行了 22 次。这很可能是 CPU 峰值的原因。
连接到 azure_sys 数据库，并使用以下脚本执行查询以检索实际查询文本。

    psql -h ServerName.postgres.database.chinacloudapi.cn -U AdminUsername -d azure_sys

     SELECT query_sql_text
     FROM query_store.query_texts_view
     WHERE query_text_id = <add query id identified>;

在所考虑的示例中，发现下面的查询运行缓慢：

SELECT  c_id, SUM(c_balance) AS total_balance
FROM customer
GROUP BY c_w_id,c_id
order by c_w_id;

若要了解生成的确切说明计划，请使用 Azure Database for PostgreSQL 灵活服务器日志。每次在时间间隔内完成查询执行时，自动解释扩展都会在日志中记录一个条目。从 Azure Database for PostgreSQL 灵活服务器门户概述页的 Monitoring 选项卡中选择“日志”部分。
选择出现 CPU 利用率达到 90% 的时间范围。
执行以下查询，以检索所标识查询的说明分析输出。

AzureDiagnostics
| where Category contains  'PostgreSQLLogs'
| where Message contains "<add snippet of SQL text identified or add table name involved in the query>"
| project TimeGenerated, Message

消息列将存储执行计划，如下所示：

2023-10-10 19:56:46 UTC-6525a8e7.2e3d-LOG: duration: 150692.864 ms plan:

Query Text: SELECT c_id, SUM(c_balance) AS total_balance
FROM customer
GROUP BY c_w_id,c_id
order by c_w_id;
GroupAggregate (cost=1906820.83..2131820.83 rows=10000000 width=40) (actual time=70930.833..129231.950 rows=10000000 loops=1)
Output: c_id, sum(c_balance), c_w_id
Group Key: customer.c_w_id, customer.c_id
Buffers: shared hit=44639 read=355362, temp read=77521 written=77701
-> Sort (cost=1906820.83..1931820.83 rows=10000000 width=13) (actual time=70930.821..81898.430 rows=10000000 loops=1)
Output: c_id, c_w_id, c_balance
Sort Key: customer.c_w_id, customer.c_id
Sort Method: external merge Disk: 225104kB
Buffers: shared hit=44639 read=355362, temp read=77521 written=77701
-> Seq Scan on public.customer (cost=0.00..500001.00 rows=10000000 width=13) (actual time=0.021..22997.697 rows=10000000 loops=1)
Output: c_id, c_w_id, c_balance

查询运行了大约 2.5 分钟（如故障排除指南中所示），并通过提取的执行计划输出中的 duration 值 150692.864 ms 进行了确认。使用解释分析输出进一步排除故障并优化查询。

注意

请注意，该查询在该时间间隔内运行了 22 次，上面显示的日志是在该时间间隔内捕获的此类条目之一。

CPU 使用率过高的场景 - 识别运行缓慢的过程和与该过程关联的运行缓慢的查询

在第二种场景下，发现一个存储过程执行时间缓慢，目标是识别和优化该存储过程中包含的运行缓慢的查询。

先决条件

必须先在 Azure Database for PostgreSQL 灵活服务器实例上启用故障排除指南和 auto_explain 扩展。若要启用故障排除指南，请按照此处提到的步骤操作。

若要启用 auto_explain 扩展，请执行以下步骤：

进入 Azure Database for PostgreSQL 灵活服务器门户上的服务器参数页吗，将 auto_explain 扩展添加到共享预加载库，如下所示。

注意

进行此更改需要重启服务器。

将 auto_explain 扩展添加到共享预加载库并重启服务器后，在 Azure Database for PostgreSQL 灵活服务器门户上的服务器参数页中，请将以下突出显示的 auto_explain 服务器参数更改为 ON，并将剩余的扩展保留默认值，如下所示。

注意

将 auto_explain.log_min_duration 参数更新为 0 将开始记录服务器上执行的所有查询。这可能会影响数据库的性能。必须进行适当的审慎调查才能得出在服务器上被视为缓慢的值。例如，如果将 30 秒视为阈值，并且应用程序可以接受运行时间低于 30 秒的所有查询，则建议将参数更新为 30000 毫秒。然后，这会记录服务器上执行时间超过 30 秒的任何查询。
参数 auto_explain.log_nested_statements 会导致考虑记录嵌套语句（在函数或过程内执行的语句）。当它关闭时，仅记录顶级查询计划。

场景 - 识别存储过程中运行缓慢的查询

有了故障排除指南和 auto_explain 扩展，我们将借助示例来解释该场景。

我们有一个 CPU 使用率飙升到 90% 的场景，并且想知道导致该峰值的根本原因。要调试该场景，请按照以下所述的步骤进行操作。

一旦 CPU 方案发出警报，请转到 Azure Database for PostgreSQL 灵活服务器门户概述页的“帮助”选项卡下的故障排除指南。
从打开的页面中选择“CPU 使用率过高”选项卡。 “CPU 使用率过高故障排除指南”随即打开。
使用时间范围下拉列表选择报告的 CPU 峰值的时间范围。
选择“CPU 消耗靠前的查询”选项卡。

该选项卡共享 CPU 使用率达到 90% 的时间间隔内运行的所有查询的详细信息。从快照来看，该时间间隔内平均执行时间最慢的查询约为 6.3 分钟，该查询在该时间间隔内运行了 35 次。这很可能是 CPU 峰值的原因。

请务必注意以下快照中突出显示的查询类型为 `Utility``。通常，实用工具可以是时间间隔内运行的存储过程或函数。
连接到 azure_sys 数据库并执行查询，以使用以下脚本检索实际查询文本。

    psql -h ServerName.postgres.database.chinacloudapi.cn -U AdminUsername -d azure_sys

     SELECT query_sql_text
     FROM query_store.query_texts_view
     WHERE query_text_id = <add query id identified>;

在所考虑的示例中，发现速度缓慢的查询是一个存储过程，如下所述：

    call autoexplain_test ();

若要了解为属于存储过程的查询生成的确切说明，请使用 Azure Database for PostgreSQL 灵活服务器日志。每次在时间间隔内完成查询执行时，自动解释扩展都会在日志中记录一个条目。从 Azure Database for PostgreSQL 灵活服务器门户概述页的 Monitoring 选项卡中选择“日志”部分。
选择出现 CPU 利用率达到 90% 的时间范围。
执行以下查询，检索所识别查询的解释分析输出。

AzureDiagnostics
| where Category contains  'PostgreSQLLogs'
| where Message contains "<add a snippet of SQL text identified or add table name involved in the queries related to stored procedure>"
| project TimeGenerated, Message

该过程有多个查询，下面突出显示了这些查询。将记录存储过程中使用的每个查询的解释分析输出，以便进一步分析和排除故障。记录的查询的执行时间可用于识别存储过程中最慢的查询。

2023-10-11 17:52:45 UTC-6526d7f0.7f67-LOG: duration: 38459.176 ms plan:

Query Text: insert into customer_balance SELECT c_id, SUM(c_balance) AS total_balance FROM customer GROUP BY c_w_id,c_id order by c_w_id
Insert on public.customer_balance (cost=1906820.83..2231820.83 rows=0 width=0) (actual time=38459.173..38459.174 rows=0 loops=1)Buffers: shared hit=10108203 read=454055 dirtied=54058, temp read=77521 written=77701 WAL: records=10000000 fpi=1 bytes=640002197
    -> Subquery Scan on "*SELECT*" (cost=1906820.83..2231820.83 rows=10000000 width=36) (actual time=20415.738..29514.742 rows=10000000 loops=1)
        Output: "*SELECT*".c_id, "*SELECT*".total_balance Buffers: shared hit=1 read=400000, temp read=77521 written=77701
            -> GroupAggregate (cost=1906820.83..2131820.83 rows=10000000 width=40) (actual time=20415.737..28574.266 rows=10000000 loops=1)
                Output: customer.c_id, sum(customer.c_balance), customer.c_w_id Group Key: customer.c_w_id, customer.c_id Buffers: shared hit=1 read=400000, temp read=77521 written=77701
                -> Sort (cost=1906820.83..1931820.83 rows=10000000 width=13) (actual time=20415.723..22023.515 rows=10000000 loops=1)
                    Output: customer.c_id, customer.c_w_id, customer.c_balance Sort Key: customer.c_w_id, customer.c_id Sort Method: external merge Disk: 225104kB Buffers: shared hit=1 read=400000, temp read=77521 written=77701
                     -> Seq Scan on public.customer (cost=0.00..500001.00 rows=10000000 width=13) (actual time=0.310..15061.471 rows=10000000 loops=1) Output: customer.c_id, customer.c_w_id, customer.c_balance Buffers: shared hit=1 read=400000

2023-10-11 17:52:07 UTC-6526d7f0.7f67-LOG: duration: 61939.529 ms plan:
Query Text: delete from customer_balance
Delete on public.customer_balance (cost=0.00..799173.51 rows=0 width=0) (actual time=61939.525..61939.526 rows=0 loops=1) Buffers: shared hit=50027707 read=620942 dirtied=295462 written=71785 WAL: records=50026565 fpi=34 bytes=2711252160
    -> Seq Scan on public.customer_balance (cost=0.00..799173.51 rows=15052451 width=6) (actual time=3185.519..35234.061 rows=50000000 loops=1)
        Output: ctid Buffers: shared hit=27707 read=620942 dirtied=26565 written=71785 WAL: records=26565 fpi=34 bytes=11252160


2023-10-11 17:51:05 UTC-6526d7f0.7f67-LOG: duration: 10387.322 ms plan:
Query Text: select max(c_id) from customer
Finalize Aggregate (cost=180185.84..180185.85 rows=1 width=4) (actual time=10387.220..10387.319 rows=1 loops=1) Output: max(c_id) Buffers: shared hit=37148 read=1204 written=69
    -> Gather (cost=180185.63..180185.84 rows=2 width=4) (actual time=10387.214..10387.314 rows=1 loops=1)
        Output: (PARTIAL max(c_id)) Workers Planned: 2 Workers Launched: 0 Buffers: shared hit=37148 read=1204 written=69
        -> Partial Aggregate (cost=179185.63..179185.64 rows=1 width=4) (actual time=10387.012..10387.013 rows=1 loops=1) Output: PARTIAL max(c_id) Buffers: shared hit=37148 read=1204 written=69
            -> Parallel Index Only Scan using customer_i1 on public.customer (cost=0.43..168768.96 rows=4166667 width=4) (actual time=0.446..7676.356 rows=10000000 loops=1)
               Output: c_w_id, c_d_id, c_id Heap Fetches: 24 Buffers: shared hit=37148 read=1204 written=69

注意

请注意，出于演示目的，说明只共享过程中使用的少数查询的分析输出。思路是可以收集日志中所有查询的解释分析输出，然后识别其中最慢的查询，并尝试优化它们。

通过

排查和识别 Azure Database for PostgreSQL 灵活服务器中运行缓慢的查询

CPU 使用率过高的场景 - 识别运行缓慢的查询

先决条件

场景 - 识别运行缓慢的查询

CPU 使用率过高的场景 - 识别运行缓慢的过程和与该过程关联的运行缓慢的查询

先决条件

场景 - 识别存储过程中运行缓慢的查询

相关内容

其他资源