共用方式為

針對 適用於 PostgreSQL 的 Azure 資料庫 中執行緩慢的查詢進行疑難解答和識別 - 彈性伺服器

  • 發行項

適用於：適用於 PostgreSQL 的 Azure 資料庫 - 彈性伺服器

本文說明如何使用 適用於 PostgreSQL 的 Azure 資料庫 彈性伺服器對慢速執行的查詢進行疑難解答和識別。

在高 CPU 使用率案例中，在本文中，您將瞭解如何：

  • 識別執行緩慢的查詢。

  • 識別緩慢執行的程式以及它。 識別屬於相同緩慢執行預存程式之查詢清單中的慢速查詢。

高 CPU 案例 - 識別慢速查詢

必要條件

您必須在 適用於 PostgreSQL 的 Azure 資料庫 彈性伺服器實例上啟用疑難解答指南和auto_explain擴充功能。 若要啟用疑難解答指南，請遵循這裡所述的步驟。

若要啟用auto_explain擴充功能，請遵循下列步驟：

  1. 從 適用於 PostgreSQL 的 Azure 資料庫 彈性伺服器入口網站的 [伺服器參數] 頁面，將auto_explain擴充功能新增至共用預先載入連結庫，如下所示。

    Screenshot of server parameters page with shared preload libraries parameter.

注意

進行這項變更需要重新啟動伺服器。

  1. 將auto_explain延伸模組新增至共用的預先載入連結庫並重新啟動伺服器之後，請將下列醒目提示auto_explain伺服器參數從 適用於 PostgreSQL 的 Azure 資料庫 彈性伺服器入口網站的 [伺服器參數] 頁面變更為 ON ，並將其餘的擴展名保留為預設值，如下所示。

    Screenshot of server parameters page with auto_explain parameters.

注意

將 auto_explain.log_min_duration 參數更新為 0 將會開始記錄伺服器上執行的所有查詢。 這可能會影響資料庫的效能。 必須進行適當的盡職盡責，才能得出伺服器上被視為緩慢的值。 例如，如果 30 秒視為閾值，且應用程式可接受所有低於 30 秒的查詢，則建議將 參數更新為 30000 毫秒。 然後，這會記錄伺服器上執行超過 30 秒的任何查詢。

案例 - 識別執行緩慢的查詢

使用疑難解答指南和auto_explain擴充功能，我們會透過範例的協助來說明案例。

我們有一個案例，CPU 使用率已尖峰達到 90%，而且想要知道尖峰的根本原因。 若要對案例進行偵錯，請遵循下面所述的步驟。

  1. 一旦您收到 CPU 案例的警示，請移至 [適用於 PostgreSQL 的 Azure 資料庫 彈性伺服器入口網站概觀] 頁面上的 [說明] 索引卷標底下的疑難解答指南。

    Screenshot of troubleshooting guides menu.

  2. 從開啟的頁面選取 [高 CPU 使用量] 索引標籤。 高 CPU 使用率疑難解答指南隨即開啟。

    Screenshot of troubleshooting guides menu - tabs.

  3. 使用時間範圍下拉式清單選取所報告 CPU 尖峰的時間範圍。

    Screenshot of troubleshooting guides menu - CPU tab.

  4. 選取 [熱門 CPU 取用查詢] 索引標籤。

    索引標籤會共用在 90% CPU 使用率出現間隔內執行的所有查詢詳細數據。 從快照集來看，查詢看起來像是時間間隔期間平均運行時間最慢的查詢是 ~2.6 分鐘，而查詢在間隔期間執行了 22 次。 這很可能是 CPU 尖峰的原因。

    Screenshot of troubleshooting guides menu - Top CPU consuming queries tab.

  5. 連線 azure_sys資料庫並執行查詢，以使用下列腳本擷取實際的查詢文字。

    psql -h ServerName.postgres.database.azure.com -U AdminUsername -d azure_sys

     SELECT query_sql_text
     FROM query_store.query_texts_view
     WHERE query_text_id = <add query id identified>;
  1. 在已考慮的範例中，發現速度緩慢的查詢如下：
SELECT  c_id, SUM(c_balance) AS total_balance
FROM customer
GROUP BY c_w_id,c_id
order by c_w_id;

  1. 若要了解產生的確切說明計劃，請使用 適用於 PostgreSQL 的 Azure 資料庫 彈性伺服器記錄。 自動說明擴充功能會在每次在間隔期間完成查詢執行時記錄記錄中的專案。 從 [適用於 PostgreSQL 的 Azure 資料庫 彈性伺服器入口網站概觀] 頁面的Monitoring索引卷標中選取 [記錄] 區段。

    Screenshot of troubleshooting guides menu - Logs.

  2. 選取找到 90% CPU 使用率的時間範圍。

    Screenshot of troubleshooting guides menu - Logs Timerange.

  3. 執行下列查詢，以擷取所識別查詢的分析輸出。

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 毫秒。 使用說明分析輸出來進一步進行疑難解答，並微調查詢。

注意

請注意，查詢在間隔期間執行了 22 次，以上顯示的記錄是間隔期間所擷取的其中一個專案。

高 CPU 案例 - 識別與程式相關聯的緩慢執行程式和慢速查詢

在第二個案例中，發現預存程式運行時間很慢，目標是識別並調整預存程式一部分的慢速執行查詢。

必要條件

您必須在 適用於 PostgreSQL 的 Azure 資料庫 彈性伺服器實例上啟用疑難解答指南和auto_explain擴充功能，作為必要條件。 若要啟用疑難解答指南，請遵循這裡所述的步驟。

若要啟用auto_explain擴充功能，請遵循下列步驟：

  1. 從 適用於 PostgreSQL 的 Azure 資料庫 彈性伺服器入口網站的 [伺服器參數] 頁面，將auto_explain擴充功能新增至共用預先載入連結庫，如下所示。

    Screenshot of server parameters page with shared preload libraries parameter - Procedure.

注意

進行這項變更需要重新啟動伺服器。

  1. 將auto_explain擴充功能新增至共用的預先載入連結庫並重新啟動伺服器之後，請將下列醒目提示 auto_explain的伺服器參數從 適用於 PostgreSQL 的 Azure 資料庫 彈性伺服器入口網站的 [伺服器參數] 頁面變更為 ON ，並將其餘的擴展名保留為預設值，如下所示。

    Screenshot of server parameters blade with auto_explain parameters - Procedure.

注意

  • 將 auto_explain.log_min_duration 參數更新為 0 將會開始記錄伺服器上執行的所有查詢。 這可能會影響資料庫的效能。 必須進行適當的盡職盡責，才能得出伺服器上被視為緩慢的值。 例如，如果 30 秒視為閾值，且應用程式可接受所有低於 30 秒的查詢，則建議將 參數更新為 30000 毫秒。 然後，這會記錄伺服器上執行超過 30 秒的任何查詢。
  • 參數 auto_explain.log_nested_statements 會將巢狀語句（在函式或程式內執行的語句）視為記錄。 關閉時，只會記錄最上層查詢計劃。 

案例 - 識別預存程式中執行緩慢的查詢

使用疑難解答指南和auto_explain擴充功能，我們會透過範例的協助來說明案例。

我們有一個案例，CPU 使用率已尖峰達到 90%，而且想要知道尖峰的根本原因。 若要對案例進行偵錯，請遵循下面所述的步驟。

  1. 一旦您收到 CPU 案例的警示，請移至 [適用於 PostgreSQL 的 Azure 資料庫 彈性伺服器入口網站概觀] 頁面上的 [說明] 索引卷標底下的疑難解答指南。

    Screenshot of troubleshooting guides menu.

  2. 從開啟的頁面選取 [高 CPU 使用量] 索引標籤。 高 CPU 使用率疑難解答指南隨即開啟。

    Screenshot of troubleshooting guides tabs.

  3. 使用時間範圍下拉式清單選取所報告 CPU 尖峰的時間範圍。

    Screenshot of troubleshooting guides - CPU tab.

  4. 選取 [熱門 CPU 取用查詢] 索引標籤。

    索引標籤會共用在 90% CPU 使用率出現間隔內執行的所有查詢詳細數據。 從快照集來看，查詢看起來就像時間間隔期間平均運行時間最慢的查詢是 ~6.3 分鐘，而查詢在間隔期間執行了 35 次。 這很可能是 CPU 尖峰的原因。

    Screenshot of troubleshooting guides - CPU tab - queries.

    請務必從下列快照集記下，如下所示的查詢類型為「公用程式」。 一般而言，公用程式可以是在間隔期間執行的預存程式或函式。

  5. 連線 azure_sys資料庫，並使用下列腳本執行查詢以擷取實際的查詢文字。

    psql -h ServerName.postgres.database.azure.com -U AdminUsername -d azure_sys

     SELECT query_sql_text
     FROM query_store.query_texts_view
     WHERE query_text_id = <add query id identified>;
  1. 在已考慮的範例中，發現速度緩慢的查詢是預存程式，如下所述：
    call autoexplain_test ();

  1. 若要瞭解針對屬於預存程式之查詢所產生的確切說明，請使用 適用於 PostgreSQL 的 Azure 資料庫 彈性伺服器記錄。 自動說明擴充功能會在每次在間隔期間完成查詢執行時記錄記錄中的專案。 從 Monitoring [適用於 PostgreSQL 的 Azure 資料庫 彈性伺服器入口網站概觀] 頁面的索引卷標中選取 [記錄] 區段。

    Screenshot of troubleshooting guides menu - Logs.

  2. 選取找到 90% CPU 使用率的時間範圍。

    Screenshot of troubleshooting guides menu - Logs Time range.

  3. 執行下列查詢，以擷取所識別查詢的已說明分析輸出。

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

注意

請注意，為了示範目的，請說明只共用程式中使用的少數查詢分析輸出。 其概念是可以收集說明分析記錄中所有查詢的輸出，然後找出其中最慢的查詢，並嘗試微調它們。

相關內容