NEWSニュース&ブログ

【Redshift】遅いクエリの謎を解け!性能分析入門(原因究明編)

この記事は最終更新から1年以上経過しています。内容が古くなっている可能性があります。

投稿日:2024/03/22

こんにちは!ソリューションサービス事業部の西田です。

今回は Amazon Redshift(※)の「性能劣化問題」原因究明 編をお届けします!
  ※AWS が提供するデータウェアハウスサービス。以降、Redshift

前回の時点で、事象発生時間帯に怪しいクエリ(query=2018321)が存在していることまでは
STL_ALERT_EVENT_LOG  を確認したことで明らかになりました!

ただ、このクエリの正体や、何が悪さしているのかといった謎については、
これから解き明かしていく必要がありそうです。

※まだ読まれていない方は、前回(以下)の記事を先にご一読いただくことをお勧めします。

 【Redshift】遅いクエリの謎を解け!性能分析入門(原因調査編)

※本記事でご案内する方法はあくまで一例です。

 性能劣化の状況によっては、本ブログ記事に記載の対応方法よりも更に最適な
 アプローチがあるかもしれないことを念頭に、ご参考ください。

対象者:

 ・Redshift を利用(他のデータウェアハウスサービスは対象外)

 ・クエリ(SQL)が管理者ユーザー(例:awsuser)で実行できること

 ・「自力で性能劣化問題の解決に挑戦したい!」という志しの高い方

原因究明方法:

では早速、原因を究明するために、実際に問題となっているクエリの詳細を確認していきましょう!

まずはクエリ(query=2018321)がどのぐらいの回数で実行されたかや、
最大/平均実行時間、実行されたクエリ文を見てみます。

~以降、記載されているクエリは管理者ユーザー(例:awsuser)で実行しています ~

SELECT
query,
COUNT(*) AS exec_count,                                                     -- 実行回数
MAX(DATEDIFF(microseconds, starttime, endtime)) AS max_exec_time_microsec,  -- 最大実行時間
AVG(DATEDIFF(microseconds, starttime, endtime)) AS avg_exec_time_microsec,  -- 平均実行時間
querytxt                                                                    -- クエリ文
FROM
stl_query
where
query=2018321                                                               -- 確認した query 値を指定
group BY query,querytxt;

stl_query はクエリ情報の履歴が確認できるテーブルです。

※今回は含めていませんが、↑のクエリに starttimeendtime を条件に追加して、
 事象発生時間帯だけに絞ってみるのもオススメです!

query exec_count max_exec_time_microsec avg_exec_time_microsec querytxt
2018321 1 6055193 6055193

select * from test_table where id =1 limit 100


querytxt 列を見てみると、どうやら test_table というテーブルに対して、
id=1 で絞って参照しようとしているみたいですね~

また、1回(exec_count)だけ実行されていて、6055193 マイクロ秒(約6秒)要していることが判明しました。
(テストテーブルのくせに生意気な!!)

ちなみに余談ですが、このテーブルには、id 列(一意の値)と value 列があって、
以下のようなデータが全部で1000万件入っています。

【格納例】

id value
20 Test Value 0000000020

続いて、クエリプラン(※)から、このクエリがどんなステップで実行されているか見てみましょう。


  ※ここでは詳細な説明は省略しますが、クエリプランとはテーブルのスキャン・結合・集計など、
   クエリを実行する手順(ステップ)を示します。詳細は公式ドキュメントをご参照ください。

まずは過去の履歴から追ってみようと思うので、stl_explain という過去(事象発生時)の
クエリプランを参照できるテーブルから確認してみます。
現在クエリプランを取得する方法として EXPLAIN があります。次回の記事で試します!)

SELECT plannode || ' ' || info as SqlPlan
FROM stl_explain
WHERE query = 2018321 -- 確認した query の値を指定
ORDER BY nodeid;
sqlplan
—– Update statistics by running the ANALYZE command on these tables —–
—– Tables missing statistics: test_table —–
XN Limit (cost=0.00..250.00 rows=100 width=408)
-> XN Seq Scan on test_table (cost=0.00..125000.00 rows=50000 width=408) Filter: (id = 1)


実運用で実行されているクエリの場合、クエリプランはもっと複雑で長文になる可能性が十分にありますが、
今回は至ってシンプルです。

ただ、どんなクエリプランだって見るべき所は大体同じ(ハズ)です!

どこのステップで、時間を要していそうか(コストが高そうか)や 多くのレコードにアクセスしていそうか
に着目して確認してみましょう!

  ※もっとクエリプランの見方について知りたい方は「クエリプランステップの確認」をご参照ください。

今回のクエリプランでは、「XN Seq Scan on test_table」とあるので、シーケンシャルスキャン
(=テーブル全体を順番にスキャンして条件に合致する行を探す方法)を示しています。

つまり、test_table というテーブルの全ての行を順に読み込み、
id=1 のレコードを抽出しようとしているようです。
1000万件も格納されている訳ですし、なんか無駄な読み込みが発生していそうですよね。。

前回、「ソートキー が見つからない or 正しく設定されていない場合に
Very selective query filter非常に選択的なフィルター)が発生する」と
STL_ALERT_EVENT_LOG が教えてくれましたよね。

ってなわけで、問題となっているクエリの中で参照しているテーブル(test_table)に
ソートキーが存在するかチェックしてみましょう。

SELECT tablename, "column", type, encoding, distkey, sortkey
FROM pg_table_def
WHERE tablename = 'test_table'; -- クエリプランで確認したテーブル名を指定
tablename column type encoding distkey sortkey
test_table id bigint az64

true

0

test_table value character varying(255) lzo

false

0


sortkey=0 となっていることから、id 列には現在ソートキーが存在しないと判断できます。
STL_ALERT_EVENT_LOG(solution 列)の予想的中です!お見事!!

まとめ:

今回、遂に原因が判明しました!
test_table の id 列に ソートキー が不在なことで、この事件(性能劣化)は起きていそうです。
 

次回は、具体的な対処(ソートキーの作成)を実施し、性能が果たして本当に改善するのかどうか、
実際にこの目で確かめてみましょう!

乞うご期待☆

 
次の記事:Redshift遅いクエリの謎を解け!性能分析入門(解決編)



西田 幸平(2021年入社)
株式会社システムサポート フューチャーイノベーション事業本部 ソリューションサービス事業部所属
DB(Oracle Database, SQL Server 等)やクラウド(Azure, AWS)を中心とした案件に従事
好きな言葉は『寝る子は育つ』