針對適用於 PostgreSQL 的 Azure 資料庫中的執行緩慢查詢進行排解並識別問題。

本文說明如何識別及診斷慢速執行查詢的根本原因。

在本文中，您可了解：

如何識別慢速執行的查詢。
如何識別相關的慢速執行程序。識別屬於相同慢速執行預存程序之查詢清單中的慢速查詢。

先決條件

遵循使用疑難排解指南中所述的步驟來啟用疑難排解指南。
透過將 auto_explain 延伸模組加入允許清單 (部分內容可能是機器或 AI 翻譯) 並加以載入 (部分內容可能是機器或 AI 翻譯) 來設定該延伸模組。
設定 auto_explain 延伸模組之後，請變更下列伺服器參數，以控制延伸模組的行為：
- auto_explain.log_analyze 變更為 ON。
- auto_explain.log_buffers 變更為 ON。
- auto_explain.log_min_duration (根據您案例中的合理性)。
- auto_explain.log_timing 變更為 ON。
- auto_explain.log_verbose 變更為 ON。

附註

如果您將 auto_explain.log_min_duration 設定為 0，則延伸模組會開始記錄伺服器上執行的所有查詢。這可能會影響資料庫的效能。必須進行適當的盡職盡責，才能得出伺服器上被視為緩慢的值。例如，如果所有查詢都在 30 秒內完成，而且您的應用程式可以接受，則建議將參數更新為 30,000 毫秒。然後，系統會記錄任何執行時間超過 30 秒的查詢。

識別慢速查詢

有了疑難排解指南和 auto_explain 延伸模組，我們可透過範例的協助來描述案例。

我們有一個案例，其中 CPU 使用率飆升至 90%，並想要判斷飆升的原因。若要偵錯案例，請遵循下列步驟：

一旦您收到 CPU 案例的警示，請在適用於 PostgreSQL 的 Azure 資料庫彈性伺服器實例的資源功能表中，於 [ 監視 ] 區段底下，選取 [疑難解答指南]。
選取 [CPU] 索引標籤。[最佳化高 CPU 使用率] 疑難排解指南隨即開啟。
從 「分析期間（當地時間）」 下拉式清單中，選取您要重點分析的時間範圍。
選取 [查詢] 索引標籤。它會顯示在看到 90% CPU 使用率的間隔內執行的所有查詢詳細資料。從快照集來看，時間間隔內平均執行時間最慢的查詢是 ~2.6 分鐘，而查詢在間隔期間執行了 22 次。該查詢很可能是 CPU 飆升的原因。
若要擷取實際的查詢文字，請連線到 azure_sys 資料庫並執行下列查詢。

    psql -h <server>.postgres.database.azure.com -U <user> -d azure_sys

     SELECT query_sql_text
     FROM query_store.query_texts_view
     WHERE query_text_id = <query_id>;

在考慮的範例中，被發現速度緩慢的查詢為：

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 的日誌記錄。每次查詢在該時間範圍內完成執行時，auto_explain 延伸模組都應該在記錄中寫入一個項目。在資源功能表中的 [監視] 區段下，選取 [記錄]。
選取找到 90% CPU 使用率的時間範圍。
執行下列查詢，以擷取所識別查詢的 EXPLAIN ANALYZE 輸出。

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

訊息資料行會儲存執行計劃，如下列輸出所示：

2024-11-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 分鐘，如疑難排解指南所示。擷取的執行計劃輸出中 150692.864 毫秒的 duration 值證實這點。使用 EXPLAIN ANALYZE 的輸出來進一步疑難排解並微調查詢。

附註

觀察查詢在該間隔期間被執行了 22 次，顯示的日誌中包括在該期間擷取的這些記錄。

識別預存程序中慢速執行的查詢

有了疑難排解指南和 auto_explain 延伸模組，我們可透過範例的協助來說明案例。

我們有一個案例，其中 CPU 使用率飆升至 90%，並想要判斷飆升的原因。若要偵錯案例，請遵循下列步驟：

一旦您收到 CPU 案例的警示，請在適用於 PostgreSQL 的 Azure 資料庫彈性伺服器實例的資源功能表中，於 [ 監視 ] 區段底下，選取 [疑難解答指南]。
選取 [CPU] 索引標籤。[最佳化高 CPU 使用率] 疑難排解指南隨即開啟。
從 「分析期間（當地時間）」 下拉式清單中，選取您要重點分析的時間範圍。
選取 [查詢] 索引標籤。它會顯示在看到 90% CPU 使用率的間隔內執行的所有查詢詳細資料。從快照集來看，時間間隔內平均執行時間最慢的查詢是 ~2.6 分鐘，而查詢在間隔期間執行了 22 次。該查詢很可能是 CPU 飆升的原因。
連線到 azure_sys 資料庫並執行查詢，以使用下列指令碼來擷取實際的查詢文字。

    psql -h <server>.postgres.database.azure.com -U <user> -d azure_sys

     SELECT query_sql_text
     FROM query_store.query_texts_view
     WHERE query_text_id = <query_id>;

在考慮的範例中，被發現速度緩慢的查詢為預存程序：

    call autoexplain_test ();

若要瞭解系統產生的具體執行計劃，請使用 Azure Database for PostgreSQL 的日誌記錄。每次查詢在該時間範圍內完成執行時，auto_explain 延伸模組都應該在記錄中寫入一個項目。在資源功能表中的 [監視] 區段下，選取 [記錄]。然後，在 [時間範圍:] 中，選取您想要聚焦分析的時間範圍。

執行下列查詢，以擷取所識別查詢的 EXPLAIN ANALYZE 輸出。

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

此程序有多個查詢，其醒目提示如下。預存程序中所用的每個查詢的 EXPLAIN ANALYZE 輸出都會記錄起來，以便進一步分析並進行疑難排解。所記錄查詢的執行時間可用來識別預存程序中最慢的查詢。

2024-11-10 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

2024-11-10 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

2024-11-10 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

附註

為了示範目的，只會顯示程序中所用的一些查詢的 EXPLAIN ANALYZE 輸出。概念是使用者可收集記錄中所有查詢的 EXPLAIN ANALYZE 輸出，然後找出其中最慢的查詢並嘗試微調這些查詢。

意見反應

此頁面對您有幫助嗎？

Last updated on 2025-10-07

共用方式為

針對適用於 PostgreSQL 的 Azure 資料庫中的執行緩慢查詢進行排解並識別問題。

先決條件

識別慢速查詢

識別預存程序中慢速執行的查詢

相關內容

意見反應

其他資源