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

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

[下垣徹，NTT OSSセンタ]

前のページへ 1|2|3 次のページへ

性能問題の原因を探る2つのステップ

　では以下の流れで、性能が出なくなっている原因を特定します。

1 どのSQLが遅いのかを見つける
　→log_min_duration_statementを利用

2 そのSQLのどこに時間がかかっているのかを見つける
　→EXPLAIN ANALYZEを利用

　それでは、それぞれについて順を追って説明します。

どのSQLが遅いのか？

　処理に3秒以上かかっている遅いSQLを見つけるために、postgresql.conf内の設定パラメータであるlog_min_duration_statementを設定します。

　log_min_duration_statemetは、設定以上の処理時間が経過したSQLをPostgreSQLのサーバログに出力させるものです。デフォルトは「-1」で無効になっています。例えば、処理に3秒以上かかるSQLを調べたい場合には、以下のように設定します。

log_min_duration_statement = 3s # -1 is disabled, 0 logs all statements

              　　　　　　　　# and their durations, > 0 logs only

              　　　　　　　　# statements running at least this time.

　これにより、3秒以上の時間がかかるSQLをキャプチャすることができます。

　ただし、もし実行されたSQLのほとんどでこの設定値以上の時間がかかる場合、ログへの出力自身がオーバヘッドとなり、かえって性能劣化の引き金となる可能性がありますので、値の設定には配慮が必要です。通常運用中は、10sや20sといった、正常状態ではたどり着かない程度の値を設定しておくことをお勧めします。

　今回、このパラメータを設定したうえでアプリケーションを実行させると、以下のような出力結果を得ることができました。

              LOG:  duration: 9094.865 ms  statement: 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

              ORDER BY c_birthdate DESC;

　ご覧のとおり、実行時間とSQLが出力されていることが分かります。このSQLがアクセスしているテーブルは、customer、orders、cc_xactsの3つです。それぞれのテーブル定義は別ページに示したとおりです。

　では次に、このSQLの中のどの処理に時間がかかっているのかを調査しましょう。

そのSQLのどこに時間がかかっているのか？

　次に、遅いSQLを見つけた後、そのSQLのうちどの部分に問題があるのかを調べます。そのために利用するのが、EXPLAIN ANALYZEです（注2）。次のように、1で問題だと分かったSQLの先頭にEXPLAIN ANALYZEを加えてSQLを実行させます。

EXPLAIN ANALYZE [問題となっているSQL]

　EXPLAIN ANALYZEを実行すると、以下の2つを出力できます。

PostgreSQLが考えたSQLの実行計画（注3）
その実行計画に知って実際にSQLを実行した場合の、DBMSの内部処理の結果

　1と2の違いを見ることで、PostgreSQLが最適だと考えていた実行計画に、実際に問題がなかったかどうかを調べることができます。EXPLAIN ANALYZEを実行した結果は、以下のとおりです。

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

　EXPLAIN ANALYZEの詳細な読み方や利用方法については、マニュアル（注4）を参照してください。ここでは実践的な観点から「どこに時間がかかったのか？」に着目しましょう。

注2：EXPLAIN ANALYZEは実際にSQLを発行します。更新系のクエリに対してEXPLAIN ANALYZEを発行したいが変更は加えられたくない場合には、「BEGIN; ... ROLLBACK」で囲むか、UPDATE/INSERT/DELETEをSELECTに置き換えて発行するなどの工夫をしておくとよいでしょう。

注3：データをどのようなアクセス手段で取得するかの計画のことです。DBMSは内部的にどのデータからどの順にどの手法でアクセスすれば最速でデータを取得できるかを常に考えています

注4：http://www.postgresql.jp/document/pg831doc/html/sql-explain.htmlもしくはhttp://www.postgresql.jp/document/pg831doc/html/using-explain.html

コラム　2つの「rows」の差を基に実行計画が最適かどうかをチェック

　EXPLAIN ANALYZEの結果から、最も時間がかかっている個所を探すのと併せて、そもそも、PostgreSQLが最適な実行計画でSQLを実行しているのかどうかも確認しておきましょう。それにはrowsの値を確認します。

(cost=173199.36..178442.24 rows=200 width=4) (actual time=7617.112..11246.718 rows=662611 loops=1)

悪い例：3けた以上の差がある！→統計情報が正しくない

(cost=173199.36..178442.24 rows=617264 width=4) (actual time=7688.652..11331.980 rows=662611 loops=1)

良い例：近い値を示している→統計情報が正しい

　「悪い例」のように、見積もりとして示される左側のrowsと、実際にヒットした件数を示すrowsの間に2～3けた以上の差がある場合、PostgreSQLが考えた実行計画は、テーブル内のデータ分布の状態を正しく把握した統計情報になっていません。このときにはANALYZEコマンドを実施し、統計情報を最新化しましょう。

　一方正しい統計情報になっている場合、「良い例」のように、左側と右側のrowsの値が近づきます。テーブルに含まれるレコード数が100万件を超えるようなケースや、分布が一定の傾向を示さずにばらばらの状態である場合には、ANALYZEによる統計情報用のサンプル数を増やすために「ALTER TABLE SET STATISTICS」文や設定パラメータ「default_statistics_target」で、設定する値を100より大きくするとよい場合もあります。詳しくはマニュアルを参照してください。

出力内容を追いかけろ

前のページへ 1|2|3 次のページへ