概要

AlloyDB for PostgreSQLではQuery Insightsという機能があり、実行されたクエリの統計やサンプリングされた実行計画を閲覧することが可能です。
本稿では、CLI上で行うEXPLAIN ANALYZEで確認が出来るクエリプランと比較しつつ、それらが実際どのようにQuery Insights上で見えるのかについて、いくつかのケースをサンプルに解説したいと思います。

前提

Query Insightsとは、以下のページにて解説されているAlloy DBで実行されたクエリについて、その統計情報やサンプリングされた実行計画を閲覧出来るものです。

基本的な機能については上記を含めた公式ドキュメントにてカバーされているため、本稿で取り扱うことはせず、クエリプランで確認出来る詳細な内容について迫りたいと思います。

ここでいうクエリプランとは、Query Insightsの画面で特定のクエリをクリックした際に表示されるクエリプランになります。
一定の単位時間にサンプリングされるクエリの数には制限(1~20/min, デフォルト5)があり、必ずしも全てのクエリがサンプリングされているわけではないことにご注意ください。
Query Insights

サンプリングレートの変更方法については以下のドキュメントでご確認頂けます。

基本情報

では、最も基本的なクエリプランであるSequential Scanを例に取り、具体的にどのような情報が取れるのか、確認していきましょう。

以下は、SELECT data FROM example;といった非常にシンプルなクエリによってテーブル全体をスキャンしたものです。

プランノードを選択し、Detailsを表示することで、細かい実行計画の詳細を閲覧することが出来ます。
Introduction

実際にプランノードのDetailsを選択すると、このように表示されます。
Sequential Scan

Plan Rows、Total CostといったEXPLAINで確認出来る要素のほかに、EXPLAIN ANALYZEで確認可能なActual TimeやActual Rowといった要素が確認出来るのが分かります。
お察しの通り、Query InsightsではEXPLAIN ANALYZE相当の、実行時に実際にどれくらいの行をスキャンしたのか、どのくらい時間がかかっていたのかというレベルの情報も確認することが出来ます。
また、上記の図にもあるように、最もレイテンシが高かったり最もたくさんの行をスキャンしたプランについてはHighest LatencyやHighest row countなどのハイライトが表示され、トラブルシュートしやすくなっています。

例えば上記のプランノードではPlan Rows(2006925)とActual Rows(2097152)が異なっていることが分かると思います。
今回の例ではプラン選択に影響が出るような大きな違いはありませんが、例えばここが大きく違っていた場合、実際にはIndex ScanをするべきだがSequential Scanを選んでしまうなど、効率の良くない実行計画になってしまう場合があります。
この場合、該当のテーブルに対してANALYZEを実行して統計情報を更新することによって、現在のデータにより適したクエリプランになるケースがあります。

他にも、EXPLAIN ANALYZEでは単純なPlan、Actualの対比以外に様々な情報が取得出来ますが、それがどのようにQuery Insightsで確認出来るのか、いくつかの例を紹介します。

各実行計画のパターン

External Mergeのケース

PostgreSQLではソートやGROUP BYといった作業を行う際、work_memに内容を展開して作業を行います。しかしデータ量によってはwork_memが足りず、一時ファイルに書き出して作業を行うケースがあります。

このような場合、EXPLAIN ANALYZEでは、以下のようにSort Method: external merge Disk: 101160kBというように表現されます。

test=> EXPLAIN ANALYZE SELECT * FROM sbtest1 order by pad DESC;
                                                              QUERY PLAN                                                               
---------------------------------------------------------------------------------------------------------------------------------------
 Gather Merge  (cost=148200.50..245429.59 rows=833334 width=190) (actual time=1342.658..2108.282 rows=1000000 loops=1)
   Workers Planned: 2
   Workers Launched: 2
   ->  Sort  (cost=147200.48..148242.15 rows=416667 width=190) (actual time=1181.853..1386.831 rows=333333 loops=3)
         Sort Key: pad DESC
         Sort Method: external merge  Disk: 101160kB
         Worker 0:  Sort Method: external merge  Disk: 45184kB
         Worker 1:  Sort Method: external merge  Disk: 49440kB
         ->  Parallel Seq Scan on sbtest1  (cost=0.00..31398.67 rows=416667 width=190) (actual time=0.005..65.791 rows=333333 loops=3)
 Planning Time: 0.059 ms
 Execution Time: 2185.736 ms
(11 rows)

ではこれをQuery Insightsで見てみましょう。
以下のようになります。
External Merge

Sort Methodにexternal merge、Sort TypeにDiskと記載されているのがお分かりになるかと思います。
これは、文字通りディスクにデータを書き出してソートを行なっていることを示しており、Actual Total Timeとしても4000msを超えており多くの時間を消費していることが分かるかと思います。

work_memが足りないことが主な原因ですので、これを増加させることが有用です。
ただ、インスタンス単位で設定してしまうと大きなwork_memを必要としないセッションにおいても多量のwork_memを確保してしまうため、不必要にメモリを消費してしまうことになります。
こうしたことを避けるため、セッション単位でSET work_mem=XXX;のようなクエリを実行し、必要なものにだけ大きなwork_memを割り当てるという対策が有効です。
SET LOCALというトランザクション単位で設定出来るものもありますので、詳細については以下の公式ドキュメントを参照頂いたり、インターネット上でSETの具体的な利用方法について言及された記事は幾つかございますので、そちらを確認頂くのも良いかと思います。

勿論、データそのものを減らしたり、スキャン対象となる行そのものを減らせるようにクエリを改善出来れば、そちらも有効です。

Parallel Scanのケース

上記External Mergeのクエリでは、EXPLAIN ANALYZEの結果から他にもParallel Seq Scanが使われていることが分かります。
Parallel Scanであるかどうかは、以下の通りWorker Countが表示されますので、こちらでどの程度のWorkerが走っていたかも含めて確認することが出来ます。(プランノードにGather Mergeが存在しているので、こちらからもParallel Scanが行われていたことが分かるかと思います。)
Parallel Seq Scan

Lossy Bitmap Heap Scanのケース

PostgreSQLでは特定の条件においてBitmap Index Scanというプランが選ばれることがあります。
Bitmap Index Scanではワーキングメモリにビットマップを展開するため、work_memが十分に足りない場合にはLossyという、行単体ではなくページ単位でどのレコード/ページが条件に該当するかを格納するモードを併用します。

この際、当然1ページには複数の行が含まれるわけなので、後ほどIndex Re-checkという処理を通じてページ内にあるレコードのうち条件に該当しないものを削除する処理が加わり、レイテンシの増加につながります。

これはEXPLAIN ANALYZEでは例えば以下のように表現されます。

test=> EXPLAIN ANALYZE SELECT * FROM sbtest1 WHERE k > 700000;
                                                             QUERY PLAN                                                             
------------------------------------------------------------------------------------------------------------------------------------
 Gather  (cost=1096.78..22938.88 rows=7271 width=190) (actual time=0.989..7.544 rows=1901 loops=1)
   Workers Planned: 2
   Workers Launched: 2
   ->  Parallel Bitmap Heap Scan on sbtest1  (cost=96.78..21211.78 rows=3030 width=190) (actual time=0.267..3.727 rows=634 loops=3)
         Recheck Cond: (k > 700000)
         Rows Removed by Index Recheck: 13616
         Heap Blocks: exact=307 lossy=560
         ->  Bitmap Index Scan on k_1  (cost=0.00..94.96 rows=7271 width=0) (actual time=0.574..0.574 rows=1901 loops=1)
               Index Cond: (k > 700000)
 Planning Time: 0.093 ms
 Execution Time: 7.683 ms
(11 rows)

Rows removed by Index Recheckと書いてある数字が、ページ単位で取得したレコードの塊からIndex Recheckによって取り除かれたレコードの数になります。

Query Insightsでは以下のように表記され、Lossyによってページ単位で取得されたものが、Rows Removed by Indexによって後程取り除かれていることが分かります。
Lossy Bitmap Heap Scan

External Mergeの際にも言及しましたが、Lossyが発生する原因としてはwork_memの不足ですので、同様の対策が有効です。

Partition Pruningのケース

PostgreSQLではパーティションという機能があり、例えば日付でパーティションを区切ってWHERE句で特定の日時間隔を指定し、該当しない部分についてはそもそもスキャンの対象にしないといったことが可能です。
この時、クエリの実行に必要ではないパーティションを対象から除外することをPartition Pruningと呼びます。

PostgreSQLと同じく、AlloyDBにおけるPartition Pruningには大きく分けて2通りあり、実行計画時点で除外される静的なものと、実行時点で除外される動的なものがあります。

今回のケースでは、test_partitionという親テーブルにtest_partition_YYYYの形式で2022 ~ 2025の以下4つのパーティションを作成し、これをスキャンする形としています。

test_partition_2022
test_partition_2023
test_partition_2024
test_partition_2025

動的Partition Pruningの場合

動的なものは、例えばサブクエリやパラメータでWHEREの値を持ってくるものが挙げられますが、これはEXPLAIN ANALYZEでは(never executed)として表示されます。

test=> EXPLAIN ANALYZE SELECT * FROM test_partition WHERE date > (SELECT date from date_table limit 1);
                                                                   QUERY PLAN                                                                   
------------------------------------------------------------------------------------------------------------------------------------------------
 Append  (cost=0.01..8022.14 rows=109226 width=52) (actual time=3.852..13.671 rows=65536 loops=1)
   InitPlan 1 (returns $0)
     ->  Limit  (cost=0.00..0.01 rows=1 width=4) (actual time=0.014..0.015 rows=1 loops=1)
           ->  Seq Scan on date_table  (cost=0.00..32.60 rows=2260 width=4) (actual time=0.013..0.013 rows=1 loops=1)
   ->  Seq Scan on test_partition_2022 test_partition_1  (cost=0.00..2990.40 rows=43691 width=52) (never executed)
         Filter: (date > $0)
   ->  Seq Scan on test_partition_2023 test_partition_2  (cost=0.00..1495.20 rows=21845 width=52) (never executed)
         Filter: (date > $0)
   ->  Seq Scan on test_partition_2024 test_partition_3  (cost=0.00..1495.20 rows=21845 width=52) (actual time=3.816..3.816 rows=0 loops=1)
         Filter: (date > $0)
         Rows Removed by Filter: 65536
   ->  Seq Scan on test_partition_2025 test_partition_4  (cost=0.00..1495.20 rows=21845 width=52) (actual time=0.015..5.924 rows=65536 loops=1)
         Filter: (date > $0)
 Planning Time: 0.114 ms
 Execution Time: 16.025 ms
(15 rows)

これはQuery Insightsの場合、LatencyとCostが双方表示されている場合Scanされた、Costのみの場合実際にはスキャンされなかった、として判別可能です。
Partition Pruning Dynamic

静的Partition Pruningの場合

静的なPartition Pruningの場合、EXPLAIN ANALYZEは以下のようになり、そもそも実行計画時点でスキャン対象から取り除かれていることが見て取れます。

test=> EXPLAIN ANALYZE SELECT * FROM test_partition WHERE date BETWEEN '2023-01-31' AND '2024-01-31';
                                                                  QUERY PLAN                                                                   
-----------------------------------------------------------------------------------------------------------------------------------------------
 Append  (cost=0.00..1822.88 rows=32769 width=52) (actual time=1.788..6.622 rows=32768 loops=1)
   ->  Seq Scan on test_partition_2023 test_partition_1  (cost=0.00..829.52 rows=1 width=52) (actual time=1.780..1.780 rows=0 loops=1)
         Filter: ((date >= '2023-01-31'::date) AND (date <= '2024-01-31'::date))
         Rows Removed by Filter: 32768
   ->  Seq Scan on test_partition_2024 test_partition_2  (cost=0.00..829.52 rows=32768 width=52) (actual time=0.007..2.900 rows=32768 loops=1)
         Filter: ((date >= '2023-01-31'::date) AND (date <= '2024-01-31'::date))
 Planning Time: 0.133 ms
 Execution Time: 7.754 ms

Query Insightsで見た場合も、クエリプランとしてノードがそもそも表示されないことが分かります。
Partition Pruning Static

(補足)高度なQuery Insightsについて

AlloyDBには高度なQuery Insightsという機能があり、これを利用すると待機イベントの統計やアクティブなクエリの分析、並びにキャプチャするSQLコマンドの長さを伸長することなどが可能です。
また、標準のQuery Insightsでは情報の保持期限が7日ですが、高度なQuery Insightsでは30日に伸長されます。

本稿では細部には触れませんが、高度なQuery Insightsの有効化にあたっては以下の点にご留意ください。

Query Insightsの情報は一度リセットされる
高度なQuery Insightsの有効化に際しインスタンスの再起動が行われるため、クライアントの切断や既存のオペレーションがキャンセルされる
プライマリインスタンスで保存されるデータの容量が約180GB程度増加する(課金が増加する)
- リードプールノードの数次第で、最大700GB程度まで増加します。

終わりに

AlloyDBのQuery Insightsは、クエリに関係する問題点を可視化、分析する有効なツールです。
本稿が皆様のトラブルシューティングの一助となることを願っています。

Discussion