Azure Database for PostgreSQL - フレキシブル サーバーで実行速度が遅いクエリをトラブルシューティングして特定する

適用対象: Azure Database for PostgreSQL - フレキシブル サーバー

この記事では、Azure Database for PostgreSQL フレキシブル サーバーで実行速度が遅いクエリをトラブルシューティングして特定する方法について説明します。

この記事では、CPU 使用率が高いシナリオで、次の方法を学びます。

• 実行速度が遅いクエリを特定します。

• それと併せて、実行速度が遅いプロシージャを特定します。 実行速度が遅い同じストアド プロシージャに属するクエリのリストから、低速クエリを特定します。

CPU 使用率が高いシナリオ - 低速クエリを特定する

前提条件

Azure Database for PostgreSQL フレキシブル サーバー インスタンスでトラブルシューティング ガイドと auto_explain 拡張機能を有効にする必要があります。 トラブルシューティング ガイドを有効にするには、こちらで説明されている手順に従います。

auto_explain 拡張機能を有効にするには、次の手順に従います。

1. Azure Database for PostgreSQL フレキシブル サーバー ポータルのサーバー パラメーター ページから、次に示すように、auto_explain 拡張機能を共有プリロード ライブラリに追加します。

   

Note

この変更を行うには、サーバーの再起動が必要になります。

2. auto_explain 拡張機能が共有プリロード ライブラリに追加され、サーバーが再起動したら、Azure Database for PostgreSQL フレキシブル サーバー ポータルのサーバー パラメーター ページから、以下で強調表示されている auto_explain サーバー パラメーターを ON に変更し、残りのパラメーターは既定値のままにします。

   

Note

auto_explain.log_min_duration パラメーターを 0 に更新すると、サーバーで実行されているすべてのクエリのログ記録が開始されます。 これは、データベースのパフォーマンスに影響する可能性があります。 サーバーで低速と見なされる値に対して適切なデュー デリジェンスを行う必要があります。 たとえば、30 秒をしきい値と見なし、30 秒未満で実行されるすべてのクエリがアプリケーションで許容される場合は、このパラメーターを 30000 ミリ秒に更新することをお勧めします。 これにより、サーバーで 30 秒を超えて実行されたクエリがすべてログに記録されます。

シナリオ - 実行速度が遅いクエリを特定する

トラブルシューティング ガイドと auto_explain 拡張機能を有効にしたので、例を用いてシナリオを説明します。

CPU 使用率が 90% に急上昇しているシナリオがあり、スパイクの根本原因を知りたいと考えています。 このシナリオをデバッグするには、以下に示す手順に従います。

1. CPU シナリオによってアラートが表示されたらすぐに、Azure Database for PostgreSQL フレキシブル サーバー ポータルの概要ページの [ヘルプ] タブにあるトラブルシューティング ガイドに移動します。

   

2. 開いたページから [CPU 使用率が高い] タブを選択します。 CPU 使用率が高い場合のトラブルシューティング ガイドが開きます。

   

3. 時間の範囲候補リストを使用して、報告対象の CPU スパイクの時間範囲を選択します。

   

4. [CPU 消費量が上位のクエリ] タブを選択します。

   このタブには、90% の CPU 使用率が生じた期間に実行されたすべてのクエリの詳細が示されます。 スナップショットから、期間中に平均実行時間が最も遅かったクエリは約 2.6 分で、そのクエリは期間中に 22 回実行されたことがわかります。 これが CPU スパイクの原因である可能性が最も高いです。

   

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>;

6. この検討例で、低速であることが判明したクエリは次の内容でした。

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

7. 生成された正確な説明プランを把握するには、Azure Database for PostgreSQL フレキシブル サーバー ログを使用します。 auto explain 拡張機能により、期間中にクエリの実行が完了するたびに、ログにエントリが記録されます。 Azure Database for PostgreSQL フレキシブル サーバー ポータルの概要ページの [Monitoring] タブから [ログ] セクションを選択します。

   

8. 90% の CPU 使用率が見つかった時間範囲を選択します。

   

9. 次のクエリを実行して、特定したクエリの説明分析出力を取得します。

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 ミリ秒によって確認されます。 説明分析出力を使用して、さらにトラブルシューティングを行い、クエリを調整します。

Note

クエリは期間中に 22 回実行され、上記のログは、期間中にキャプチャされたそうしたエントリの 1 つです。

高 CPU シナリオ - 実行速度が遅いプロシージャと、そのプロシージャに関連付けられている低速クエリを特定する

2 番目のシナリオでは、ストアド プロシージャの実行が遅いことを見つけます。目的は、ストアド プロシージャの一部である実行速度の遅いクエリを特定して調整することです。

前提条件

前提条件として、Azure Database for PostgreSQL フレキシブル サーバー インスタンスでトラブルシューティング ガイドと auto_explain 拡張機能を有効にする必要があります。 トラブルシューティング ガイドを有効にするには、こちらで説明されている手順に従います。

auto_explain 拡張機能を有効にするには、次の手順に従います。

1. Azure Database for PostgreSQL フレキシブル サーバー ポータルのサーバー パラメーター ページから、次に示すように、auto_explain 拡張機能を共有プリロード ライブラリに追加します。

   

Note

この変更を行うには、サーバーの再起動が必要になります。

2. auto_explain 拡張機能が共有プリロード ライブラリに追加され、サーバーが再起動したら、Azure Database for PostgreSQL フレキシブル サーバー ポータルのサーバー パラメーター ページから、以下で強調表示されている auto_explain サーバー パラメーターを ON に変更し、残りのパラメーターは既定値のままにします。

   

Note

• auto_explain.log_min_duration パラメーターを 0 に更新すると、サーバーで実行されているすべてのクエリのログ記録が開始されます。 これは、データベースのパフォーマンスに影響する可能性があります。 サーバーで低速と見なされる値に対して適切なデュー デリジェンスを行う必要があります。 たとえば、30 秒をしきい値と見なし、30 秒未満で実行されるすべてのクエリがアプリケーションで許容される場合は、このパラメーターを 30000 ミリ秒に更新することをお勧めします。 これにより、サーバーで 30 秒を超えて実行されたクエリがすべてログに記録されます。
• パラメーター auto_explain.log_nested_statements を指定して、入れ子になったステートメント (関数またはプロシージャ内で実行されるステートメント) をログ記録対象にします。 オフにすると、最上位レベルのクエリ プランのみがログに記録されます。 

シナリオ - ストアド プロシージャ内の実行速度が遅いクエリを特定する

トラブルシューティング ガイドと auto_explain 拡張機能を有効にしたので、例を用いてシナリオを説明します。

CPU 使用率が 90% に急上昇しているシナリオがあり、スパイクの根本原因を知りたいと考えています。 このシナリオをデバッグするには、以下に示す手順に従います。

1. CPU シナリオによってアラートが表示されたらすぐに、Azure Database for PostgreSQL フレキシブル サーバー ポータルの概要ページの [ヘルプ] タブにあるトラブルシューティング ガイドに移動します。

   

2. 開いたページから [CPU 使用率が高い] タブを選択します。 CPU 使用率が高い場合のトラブルシューティング ガイドが開きます。

   

3. 時間の範囲候補リストを使用して、報告対象の CPU スパイクの時間範囲を選択します。

   

4. [CPU 消費量が上位のクエリ] タブを選択します。

   このタブには、90% の CPU 使用率が生じた期間に実行されたすべてのクエリの詳細が示されます。 スナップショットから、期間中に平均実行時間が最も遅かったクエリは約 6.3 分で、そのクエリは期間中に 35 回実行されたことがわかります。 これが CPU スパイクの原因である可能性が最も高いです。

   

   スナップショット下部から、下部で強調表示されているクエリの種類が "ユーティリティ" であることに注意してください。 一般に、ユーティリティは、期間中に実行されるストアド プロシージャまたは関数です。

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>;

6. この検討例で、低速であることが判明したクエリは、次に示すストアド プロシージャでした。

    call autoexplain_test ();

7. ストアド プロシージャの一部であるクエリに対して生成された正確な説明プランを把握するには、Azure Database for PostgreSQL フレキシブル サーバー ログを使用します。 auto explain 拡張機能により、期間中にクエリの実行が完了するたびに、ログにエントリが記録されます。 Azure Database for PostgreSQL フレキシブル サーバー ポータルの概要ページの [Monitoring] タブから [ログ] セクションを選択します。

   

8. 90% の CPU 使用率が見つかった時間範囲を選択します。

   

9. 次のクエリを実行して、特定したクエリの説明分析出力を取得します。

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

Note

デモンストレーションが目的のため、プロシージャで使用されているほんの少しのクエリの説明分析出力のみが示されていることに注意してください。 考え方は、ログからすべてのクエリの説明分析出力を収集し、その中で最も遅いものを特定し、調整を試みることができるというものです。

関連するコンテンツ

• CPU 使用率が高い場合
• 自動バキュームのチューニング