PostgreSQLを遅くしている犯人はどこだ？：Linuxトラブルシューティング探偵団（3）（3/3 ページ）

» 2008年06月09日 00時00分公開

[下垣徹，NTT OSSセンタ]

出力内容を追いかけろ

　実際に実行してみてどれだけの時間がかかったかは「actual time=」で表示される数値を追いかけることで確認可能です。例えば、前ページのリストの1行目に出力されている「actual time」だけを取り出すと、次のようになります。

                                ↓最初の1件目を取得するまでにかかった時間

        (actual time=9006.586..9011.968 rows=16842 loops=1)

                                              ↑最終的に結果行全体を取得するのにかかった時間

　特に、右側の数値である「最終的に結果行全体を取得するのにかかった時間」では、そのSQLの処理開始からの累積時間で表示されます。このため、当該行の処理が完了するまでにどれだけの時間がかかったかを確認できます。

　これを基に、SQLの中でどの処理に最も時間がかかっていたのかを確認していきましょう。

　Total runtimeが9022.840msであることを念頭に置きつつ、actual time欄を追いかけていきます。図中の青や赤の四角い枠で囲ったところに着目してください。出力内容をツリー構造の上から下に向かって追いかけていき、時間がかかっている個所を探し出します（注5）。

EXPLAIN ANALYZE実行結果の見方,EXPLAIN ANALYZE実行結果の見方（クリックすると拡大します）

　EXPLAIN ANALAYZEの結果を上から順に読んでいくと、（A）で示した行がactual time=239.920..8675.943と出力されており、次の（B）で示した行がactual time=0.011..1521.206 と出力されています。右側の数値で差分を計算すると、（A）の部分の処理時間が長く、Total runtimeの9022.840 msに最も大きく影響を与えていることが分かります。（C）の行の処理時間はactual time=238.938..238.938となっていることからも、（A）の処理時間の長さが際立っていることが分かります。

　大きな改善効果を狙うには、最も時間がかかっている処理から対処を施していくのがチューニングの基本です。そこで改善の前に、なぜこの処理にこんなにも時間がかかるのかを考えてみましょう。

注5：PostgreSQLの内部で実際に行われている処理は、ツリー構造の下から上に向かう順番で行われています

こんなに時間がかかる理由は？

　いったい、この部分の何が悪いのでしょうか？

　（A）のHash Joinは、ハッシュを用いて（B）と（C）から得られる2つのタプルの結合を行う処理です。

　そこで次に、（B）で実行されている全件検索処理であるSeq Scanの結果を見てみると、rowsに気になる数字が書かれていました。ordersテーブルから取得する行（rows）が5184000あると述べています。ずいぶんとたくさんのタプルを取得していますが、本当にこれだけのタプルが必要なのでしょうか？

　EXPLAIN ANALYZEを使って問題を解析するときには、Seq Scanが発生すると、まず「インデックスの張り忘れ」を疑います。そう思ってSQLやテーブル定義を確認しますが、Joinの条件として使われているo_c_idカラムにはインデックスが定義済みです。にもかかわらず、インデックスが使われない……いったい何が問題なのだろう、と考えを進めるわけです。

　そこで、ordersテーブルの件数を調べてみると、以下の結果が得られました。

        DBT1=# SELECT count(*) FROM orders;

        　 count

        ---------

        　5184000

        (1 row)

　5184000件……先ほどのrowsの数値と照らし合わせて考えると、一切絞り込みが行われておらず、全件取得していたのです。

　処理の高速化は、いかに早い段階でアクセスする件数を絞り込めるかがポイントです。今回の場合、Seq Scanのすぐ下には、確かに（D）の「Filter:」の文字から始まる絞り込みを示す処理が存在していません。どうもここに問題がありそうです。

いざ、絞り込んで問題の解決へ

　では、本当にまったく絞り込みができないのかを確認するために、発行したSQLの中から、ordersテーブルに関連するWHERE条件を確認します。今回着目したのは次の個所でした。

        WHERE

        o_c_id = c_id　　　　　　　←（a）

        ...

        AND

        c_id BETWEEN 1 AND 200000　←（b）

　着目したのは、この（a）（b）の2カ所です。

　まず、c_idに対して（b）の個所で行っているc_id BETWEEN 1 AND 200000は、不等号の条件で「1≦c_id≦200000」を表しています。続いて（a）の個所を確認すると、o_c_idはc_idと=でつながっているわけですから、数学的には「1≦o_c_id≦200000」であることも明らかです。

　しかし今回の結果からは、o_c_idに該当するタプルの絞り込みは行われていません。PostgreSQL 8.3 は、この推測をしてくれないようです。そこで、o_c_idに対して明示的にBETWEEN 1 AND 200000で絞り込みを追加した、次のようなSQLを考えます。

        SELECT   c_fname,

        　　　 c_lname,

        　　　 c_phone,

        　　　 c_email,

        　　　 o_id,

        　　　 o_date,

        　　　 o_sub_total,

        　　　 o_tax,

        　　　 o_total,

        　　　 o_status,

        　　　 cx_type,

        　　　 cx_auth_id

        FROM     　customer,

        　　　 orders,

        　　　 cc_xacts

        WHERE　o_c_id = c_id

        　　　 AND cx_o_id = o_id

        　　　 AND c_birthdate BETWEEN '1950-01-01' AND '1969-12-31'

        　　　 AND c_id between 1 AND 200000

        　　　 AND o_c_id BETWEEN 1 AND 200000  ←この行を追加

        ORDER BY c_birthdate DESC;

　では、このSQLを実行してみましょう。EXPLAIN ANALYZEを実行すると以下のようになりました。

修正後のEXPLAIN ANALYZEの実行結果（クリックすると拡大します）

　先ほどSeq Scanだった部分が、（F）で示すように、インデックスを使ったBitmap Index Scanに変わりました。ヒットしたタプル数もrows=191361となっていて、修正前のSQLでrows=5184000と出ていたものに比べると、ずいぶんと取得件数が少なくなっています。当該個所の実行時間も、actual time=129.493..329.368となり、短くなっていることが分かります。

　最も時間がかかっていたHash Joinの個所が、（G）のとおりactual time=370.368..909.897まで減り、（H）のTotal runtimeも1235.226msとなりました。この結果、目標としていたレスポンスタイム3秒以内という条件をクリアすることができました。

　多くの場合は、PostgreSQLがWHERE句の条件を考慮して自動的に考え、事前に絞り込めるものは絞り込みを掛けようとします。しかし中には、今回の例のように自動的に絞り込みを考えてくれないケースもあります。

　開発の段階でSQLを書く際には、できるだけ明示的に絞り込み条件を記述するように心掛けておくと、あらかじめトラブルを回避することができるでしょう。

常に考えをめぐらせながら解決を

　今回紹介した問題解決の手法をまとめておきます。

■問題個所の特定

log_min_duration_statementを設定し、時間がかかっているSQLを見つけました。
EXPLAIN ANALYZEを使って、どこに一番時間がかかっているのかを見つけました。

■対策の実施と効果の確認

一番時間がかかっている個所に対して、どのような対策を打てるかを考えました。今回の例では、途中段階での絞り込みができていないことを確認したため、明示的に絞り込みを掛けるようにSQLを書き直しました。
修正後のSQLを実行し直して、初めに定めた「レスポンスタイム3秒以内という要件」をクリアしていることを確認しました。

　実際には、「どのような対策を打てるか」を考えるのは難しいと思いますが、EXPLAIN ANALYZEとぐっとにらめっこして、「本当にこんな処理じゃなければならないの？」「もっと早い段階で件数を絞り込めないの？」と思考をめぐらせながら問題解決に取り組んでください。

　また、PostgreSQLのEXPLAIN ANALYZEを詳しく解説したドキュメントがhttp://redivi.com/~bob/oscon2005_pgsql_pdf/OSCON_Explaining_Explain_Public.pdfにありますので、ぜひ参照してください。JPUG（日本PostgreSQLユーザ会）による日本語版もあります。

「次回」へ

「Linuxトラブルシューティング探偵団」バックナンバー